Maybe a bug? Blank screen after Home button pressed

[EgonOlsen]

No, it doesn't bind anything to the package name. It identifies the renderer and the gl context based on an id that should be unique. You might want to download this version: http://jpct.de/download/beta/jpct_ae.jar...it has better debug output for this id.

However, the nullpointer that you are getting indicates that the FrameBuffer you are using has no gl context. This can only happen when you are using an instance of FrameBuffer that has been disposed.

[K24A3]

Ok I'll try that jar later on and post the logs.

The GLWalpaperService stops the OpenGL rendering pump when onPause is called so I don't know why my onDrawFrame function is called while the framebuffer is being re-created. It crashes with the clear framebuffer function as well sometimes so it seems to be a timing issue, but I'm not using multiple threads. Anyway we'll see what the logs tell us.

[K24A3]

Ok I installed the new Jar and the latest GLWallpaperService and added my own logging when the renderer calls are made.

The attached log is when I have the wallpaper currently running fine in the background, then go into the wallpaper picker and choose my wallpaper again. When the wallpaper appears in the wallpaper picker screen there are no textures and every 3D object is a solid color.

When I click 'Set Wallpaper', the wallpaper is working perfectly again on the homescreen.

[attachment deleted by admin]

[EgonOlsen]

...but you haven't set the Logger to debug mode, have you?

[K24A3]

Oops its on Verbose, I'll do it again.

Edit: new log attached. Not much difference though.

[attachment deleted by admin]

[K24A3]

I've created a test case that loses it's textures when re-choosing the wallpaper as displayed in the attachment.

I'll send the test case to you in a moment. Many thanks for helping, I've spent hours trying to get it reliable.

[attachment deleted by admin]

[EgonOlsen]

Oops its on Verbose, I'll do it again.

Edit: new log attached. Not much difference though.

This doesn't look right...there's no debug output as far as i can see. Make sure that you did

Logger.setLogLevel(Logger.LL_DEBUG); right at the beginning of your Activity.

[K24A3]

I see now ok I put it in the wallpaperservice engine contructor. New log file.
I'll send the test case anyway as reference.

[attachment deleted by admin]

[EgonOlsen]

The log looks actually fine except for one disposal of VisibilityList which i'm not sure of. I'll have a look at the test case later. Does it fail on PowerVR too, because i don't have an NVidia based devices?

[K24A3]

I tried vigorously to get it to fail on the PowerVR but it's 100% reliable  I'm almost certain I've seen that texture problem on the PVR as well. However a lot of code was updated/changed recently so I'm out of ideas.

I'll test it on an Omap Tablet running Honeycomb tomorrow to see if it's an nVidia bug or perhaps a honeycomb bug (Which wouldn't surprise me since Honeycomb to Android is like Vista to Microsoft).

[EgonOlsen]

Can't reproduce the problem on Nexus S with ICS....but i had a closer look at the log that you send me, and some things are really strange with the output. But at first: This log isn't taken from the beta version that i uploaded...it prints out messages that are long gone while others are missing. So please double check your setup to ensure that you are using the latest version.

Anyway, the log contains two things that puzzles me:

Code Select Expand



02-01 21:22:43.820: I/jPCT-AE(15360): Visibility lists disposed!
02-01 21:22:43.820: I/jPCT-AE(15360): Unloaded texture: 1
02-01 21:22:43.820: I/jPCT-AE(15360): Unloaded texture: 2
02-01 21:22:43.820: I/jPCT-AE(15360): Unloaded texture: 3
02-01 21:22:43.820: I/jPCT-AE(15360): Unloaded texture: 4
02-01 21:22:43.820: I/jPCT-AE(15360): Unloaded texture: 5
02-01 21:22:43.820: I/jPCT-AE(15360): Unloaded texture: 6
02-01 21:22:43.820: I/jPCT-AE(15360): All texture data unloaded from gpu!
02-01 21:22:43.820: I/jPCT-AE(15360): Disposing VBOs!
02-01 21:22:43.820: I/jPCT-AE(15360): Renderer disposed!
02-01 21:22:43.820: I/jPCT-AE(15360): Static references cleared...
02-01 21:22:43.820: I/jPCT-AE(15360): OpenGL vendor:     NVIDIA Corporation
02-01 21:22:43.820: I/jPCT-AE(15360): OpenGL renderer:   NVIDIA AP
02-01 21:22:43.820: I/jPCT-AE(15360): OpenGL version:    OpenGL ES-CM 1.1
02-01 21:22:43.820: I/jPCT-AE(15360): OpenGL renderer initialized (using 2 texture stages)

....

02-01 21:22:43.910: I/jPCT-AE(15360): Visibility lists disposed!


The first part looks fine...the old framebuffer gets disposed, the new comes up...and then, something disposes a visibility list again. That doesn't make much sense, because if there were multiple lists (which i doubt for this application), they should be disposed one after the other. And not one after creating the new buffer. The other thing is even stranger:

Code Select Expand



02-01 21:22:43.820: I/jPCT-AE(15360): Visibility lists disposed!
02-01 21:22:43.820: I/jPCT-AE(15360): Unloaded texture: 1
02-01 21:22:43.820: I/jPCT-AE(15360): Unloaded texture: 2
02-01 21:22:43.820: I/jPCT-AE(15360): Unloaded texture: 3
02-01 21:22:43.820: I/jPCT-AE(15360): Unloaded texture: 4
02-01 21:22:43.820: I/jPCT-AE(15360): Unloaded texture: 5
02-01 21:22:43.820: I/jPCT-AE(15360): Unloaded texture: 6
02-01 21:22:43.820: I/jPCT-AE(15360): All texture data unloaded from gpu!
02-01 21:22:43.820: I/jPCT-AE(15360): Disposing VBOs!
02-01 21:22:43.820: I/jPCT-AE(15360): Renderer disposed!
02-01 21:22:43.820: I/jPCT-AE(15360): Static references cleared...
02-01 21:22:43.820: I/jPCT-AE(15360): OpenGL vendor:     NVIDIA Corporation
02-01 21:22:43.820: I/jPCT-AE(15360): OpenGL renderer:   NVIDIA AP
02-01 21:22:43.820: I/jPCT-AE(15360): OpenGL version:    OpenGL ES-CM 1.1
02-01 21:22:43.820: I/jPCT-AE(15360): OpenGL renderer initialized (using 2 texture stages)

02-01 21:22:43.820: I/jPCT-AE(15360): Memory usage before compacting: 9503 KB used out of 9607 KB

....

02-01 21:22:43.910: I/jPCT-AE(15360): Visibility lists disposed!
02-01 21:22:43.970: D/dalvikvm(15360): GC_CONCURRENT freed 0K, 5% free 10201K/10695K, paused 4ms+3ms
02-01 21:22:43.970: I/jPCT-AE(15360): New texture's id is: 7
02-01 21:22:43.970: I/jPCT-AE(15360): New texture uploaded: com.threed.jpct.Texture@4069f520 in thread Thread[GLThread 9,5,main]
02-01 21:22:43.970: I/jPCT-AE(15360): [ 1328091763987 ] - WARNING: OpenGL context has changed...trying to recover...
02-01 21:22:43.980: I/jPCT-AE(15360): New texture's id is: 8
02-01 21:22:43.980: I/jPCT-AE(15360): New texture uploaded: com.threed.jpct.Texture@4069a658 in thread Thread[GLThread 9,5,main]
02-01 21:22:43.980: I/jPCT-AE(15360): [ 1328091763994 ] - WARNING: OpenGL context has changed...trying to recover...
02-01 21:22:43.980: I/jPCT-AE(15360): [ 1328091763995 ] - WARNING: OpenGL context has changed...trying to recover...
02-01 21:22:43.980: I/jPCT-AE(15360): Object 'object6' shares VBOs with object 'object5'
02-01 21:22:43.980: I/jPCT-AE(15360): [ 1328091763996 ] - WARNING: OpenGL context has changed...trying to recover...
02-01 21:22:43.980: I/jPCT-AE(15360): Object 'object9' shares VBOs with object 'object5'
02-01 21:22:43.980: I/jPCT-AE(15360): [ 1328091763996 ] - WARNING: OpenGL context has changed...trying to recover...
02-01 21:22:43.980: I/jPCT-AE(15360): Object 'object10' shares VBOs with object 'object5'
02-01 21:22:43.980: I/jPCT-AE(15360): [ 1328091763997 ] - WARNING: OpenGL context has changed...trying to recover...
02-01 21:22:43.980: I/jPCT-AE(15360): Object 'object11' shares VBOs with object 'object5'
02-01 21:22:43.980: I/jPCT-AE(15360): [ 1328091763997 ] - WARNING: OpenGL context has changed...trying to recover...
02-01 21:22:43.980: I/jPCT-AE(15360): Object 'object12' shares VBOs with object 'object5'

...

02-01 21:22:44.320: I/jPCT-AE(15360): Memory usage after compacting: 9099 KB used out of 11335 KB



Focus on the messages from the MemoryHelper: How can this be? How can the MemoryHelper start to compact (which happens in your code after creating the new FrameBuffer, which the log reflects)...but then, a draw-call seems to happen as all data is uploaded to the GPU again and THEN the MemoryHelper finishes it's work. This can only happen if the onDraw-call and the call to onSurfaceChanged happen in different threads. Can it be that onDraw() runs in the old thread but with a new FrameBuffer? So that the engine detects that it should upload the texture again (because of the context change) but it does so in the wrong thread?
This doesn't happen in my tests...everything runs in order as it's supposed to run. I suggest to add two different outputs: In addition to the one that logs the start of a method, also log the end. And also log start and end of onDraw(). In addition, log the actual thread at least in onDraw() and in the onSurface...()-methods. Maybe that will help...

[K24A3]

I'm calling MemoryHelper.compact() in onSurfaceCreated to accurately measure the memory usage before and after loading the 3D objects, so maybe you are right, the GC may be causing problems in the few milliseconds the frame buffer is disposed and recreated. I'll remove it and see if that solves the problem.

[EgonOlsen]

No, that's not exactly what i meant...it's not possible for all these "OpenGL context..." messages to appear between the two lines from the MemoryHelper if it doesn't happen in another thread...which it isn't supposed to do. It would be really helpful if you could add the additional logging that i suggested, because then we know...

[K24A3]

I did a file binary compare of the Jar in the project and the one you posted above, both are identical. Perhaps that Jar above is not the beta?

I'll add those extra logging lines and post the full log.

[EgonOlsen]

Maybe i've picked some old version by accident...i've uploaded it again. Now it IS the new one...