Strange looking preference activity in livewallpaper

Started by kkl, May 28, 2013, 04:45:58 AM

Previous topic - Next topic

kkl

Hi Egon,

Thanx for the update. I tried the beta version with the fix, it seems like there is memory leak in live wallpaper.

EgonOlsen

Caused by what? Remember that you still have to dispose the FrameBuffer.

kkl

I can't tell exactly what causes that, but I'm guessing VBOs and other objects are lost due to gl context changed and not being disposed. Since the WallpaperService object will stay as long as the livewallpaper is set to the phone, the lost VBOs or other objects are not be garbage collected within the WallpaperService object, IMHO.

Yes, I believe I did dispose the framebuffer.

Just in case, here's the debug log I recorded.

07-13 17:52:26.555: V/Kision(2283): Preference onPause(): com.kisionlab.tapleaves.WallpaperPreferenceActivity@4307aad8
07-13 17:52:26.890: D/GLWallpaperService(2283): onSurfaceDestroyed()
07-13 17:52:26.905: I/jPCT-AE(2283): [ 1373709146911 ] - WARNING: Unable to dispose gl related resources because the current context has changed!
07-13 17:52:26.905: I/jPCT-AE(2283): Renderer disposed!
07-13 17:52:26.905: I/jPCT-AE(2283): GLRenderer disposed with id 3 on Thread[main,5,main]
07-13 17:52:26.905: V/Kision(2283): onUniverseDestroyed! com.kisionlab.tapleaves.SceneSettingRenderer@42413898
07-13 17:52:26.905: V/Kision(2283): Engine onDestroy(): com.kisionlab.tapleaves.WallpaperService$WallpaperEngine@431b5b50 true
07-13 17:52:26.905: W/WallpaperService(2283): Ignoring updateSurface: destroyed
07-13 17:52:27.090: V/WallpaperService(2283): Display Width=480   Height=800
07-13 17:52:27.090: V/Kision(2283): Engine onResume(): com.kisionlab.tapleaves.WallpaperService$WallpaperEngine@42390d30 false
07-13 17:52:27.120: V/Kision(2283): onUniverseCreated! com.kisionlab.tapleaves.SceneSettingRenderer@42393538
07-13 17:52:27.120: V/Kision(2283): onUniverseChanged! com.kisionlab.tapleaves.SceneSettingRenderer@42393538
07-13 17:52:27.120: I/jPCT-AE(2283): Visibility lists disposed!
07-13 17:52:27.120: I/jPCT-AE(2283): [ 1373709147129 ] - WARNING: Unable to dispose gl related resources because the current context has changed!
07-13 17:52:27.120: I/jPCT-AE(2283): Renderer disposed!
07-13 17:52:27.125: I/jPCT-AE(2283): GLRenderer disposed with id 2 on Thread[GLThread 19049,5,main]
07-13 17:52:27.125: I/jPCT-AE(2283): GLRenderer created with id 4 on Thread[GLThread 19049,5,main]
07-13 17:52:27.125: I/jPCT-AE(2283): GL context is 1131742352
07-13 17:52:27.125: I/jPCT-AE(2283): OpenGL vendor:     ARM
07-13 17:52:27.125: I/jPCT-AE(2283): OpenGL renderer:   Mali-400 MP
07-13 17:52:27.125: I/jPCT-AE(2283): OpenGL version:    OpenGL ES-CM 1.1
07-13 17:52:27.125: I/jPCT-AE(2283): OpenGL renderer initialized (using 2/8 texture stages)
07-13 17:52:27.130: I/jPCT-AE(2283): Allocating native memory for 64*64 texture(true/false/false/false/): 16384 bytes!
07-13 17:52:27.135: I/jPCT-AE(2283): New texture's id is: 9
07-13 17:52:27.135: I/jPCT-AE(2283): New texture uploaded: com.threed.jpct.Texture@4320c0e0 in thread Thread[GLThread 19049,5,main]
07-13 17:52:27.135: I/jPCT-AE(2283): OpenGL context has changed(2)...recovering for renderer 4/2!
07-13 17:52:27.135: I/jPCT-AE(2283): Creating buffers...
07-13 17:52:27.140: I/jPCT-AE(2283): OpenGL context has changed(2)...recovering for renderer 4/2!
07-13 17:52:27.140: I/jPCT-AE(2283): Creating buffers...
07-13 17:52:27.140: I/jPCT-AE(2283): Allocating native memory for 128*128 texture(true/false/false/false/): 65536 bytes!
07-13 17:52:27.145: I/jPCT-AE(2283): New texture's id is: 10
07-13 17:52:27.145: I/jPCT-AE(2283): New texture uploaded: com.threed.jpct.Texture@423857f8 in thread Thread[GLThread 19049,5,main]
07-13 17:52:27.145: I/jPCT-AE(2283): OpenGL context has changed(2)...recovering for renderer 4/2!
07-13 17:52:27.145: I/jPCT-AE(2283): Creating buffers...
07-13 17:52:27.150: I/jPCT-AE(2283): OpenGL context has changed(2)...recovering for renderer 4/2!
07-13 17:52:27.150: I/jPCT-AE(2283): Creating buffers...
07-13 17:52:27.150: I/jPCT-AE(2283): OpenGL context has changed(2)...recovering for renderer 4/2!
07-13 17:52:27.150: I/jPCT-AE(2283): Creating buffers...
07-13 17:52:27.150: I/jPCT-AE(2283): OpenGL context has changed(2)...recovering for renderer 4/2!
07-13 17:52:27.150: I/jPCT-AE(2283): Creating buffers...
07-13 17:52:27.150: I/jPCT-AE(2283): OpenGL context has changed(2)...recovering for renderer 4/2!
07-13 17:52:27.150: I/jPCT-AE(2283): Creating buffers...
07-13 17:52:27.150: I/jPCT-AE(2283): Allocating native memory for 1024*1024 texture(true/false/false/false/): 4194304 bytes!
07-13 17:52:27.190: D/dalvikvm(2283): GC_FOR_ALLOC freed 8988K, 32% free 20870K/30535K, paused 40ms, total 40ms
07-13 17:52:27.195: I/dalvikvm-heap(2283): Grow heap (frag case) to 25.015MB for 4194320-byte allocation
07-13 17:52:27.235: D/dalvikvm(2283): GC_CONCURRENT freed 876K, 22% free 24089K/30535K, paused 12ms+4ms, total 41ms
07-13 17:52:27.235: D/dalvikvm(2283): WAIT_FOR_CONCURRENT_GC blocked 26ms
07-13 17:52:27.260: D/dalvikvm(2283): GC_FOR_ALLOC freed <1K, 22% free 24089K/30535K, paused 23ms, total 23ms
07-13 17:52:27.260: I/dalvikvm-heap(2283): Grow heap (frag case) to 28.160MB for 4194320-byte allocation
07-13 17:52:27.260: D/dalvikvm(2283): WAIT_FOR_CONCURRENT_GC blocked 55ms
07-13 17:52:27.305: D/dalvikvm(2283): GC_FOR_ALLOC freed 0K, 8% free 28185K/30535K, paused 41ms, total 41ms
07-13 17:52:27.385: I/jPCT-AE(2283): New texture's id is: 11
07-13 17:52:27.385: D/AbsListView(2283): [unregisterDoubleTapMotionListener]
07-13 17:52:27.385: I/MotionRecognitionManager(2283):   .unregisterListener : / listener count = 0->0, ubvf 9budiwrd5ordgfl5BakTrklMrfo$,@,+-.ebb(
07-13 17:52:27.400: I/jPCT-AE(2283): New texture uploaded: com.threed.jpct.Texture@423a4488 in thread Thread[GLThread 19049,5,main]
07-13 17:52:27.400: I/jPCT-AE(2283): OpenGL context has changed(2)...recovering for renderer 4/2!
07-13 17:52:27.400: I/jPCT-AE(2283): Creating buffers...
07-13 17:52:27.400: I/jPCT-AE(2283): Allocating native memory for 1024*1024 texture(true/false/false/false/): 4194304 bytes!
07-13 17:52:27.420: D/dalvikvm(2283): GC_CONCURRENT freed 14K, 8% free 28175K/30535K, paused 72ms+4ms, total 115ms
07-13 17:52:27.420: D/dalvikvm(2283): WAIT_FOR_CONCURRENT_GC blocked 19ms
07-13 17:52:27.440: D/dalvikvm(2283): GC_FOR_ALLOC freed 8192K, 35% free 19983K/30535K, paused 22ms, total 22ms
07-13 17:52:27.445: I/dalvikvm-heap(2283): Grow heap (frag case) to 24.150MB for 4194320-byte allocation
07-13 17:52:27.465: D/dalvikvm(2283): GC_FOR_ALLOC freed 0K, 22% free 24079K/30535K, paused 24ms, total 24ms
07-13 17:52:27.490: D/dalvikvm(2283): GC_FOR_ALLOC freed 0K, 22% free 24079K/30535K, paused 21ms, total 21ms
07-13 17:52:27.490: I/dalvikvm-heap(2283): Grow heap (frag case) to 28.150MB for 4194320-byte allocation
07-13 17:52:27.680: D/dalvikvm(2283): GC_CONCURRENT freed 0K, 8% free 28175K/30535K, paused 154ms+5ms, total 189ms
07-13 17:52:27.680: D/dalvikvm(2283): WAIT_FOR_CONCURRENT_GC blocked 36ms
07-13 17:52:27.680: D/dalvikvm(2283): WAIT_FOR_CONCURRENT_GC blocked 36ms
07-13 17:52:27.680: D/dalvikvm(2283): WAIT_FOR_CONCURRENT_GC blocked 37ms
07-13 17:52:27.680: D/dalvikvm(2283): WAIT_FOR_CONCURRENT_GC blocked 37ms
07-13 17:52:27.680: V/Kision(2283): Preference onStop(): com.kisionlab.tapleaves.WallpaperPreferenceActivity@4307aad8
07-13 17:52:27.685: V/Kision(2283): Preference onDestroy(): com.kisionlab.tapleaves.WallpaperPreferenceActivity@4307aad8
07-13 17:52:27.695: I/jPCT-AE(2283): New texture's id is: 12
07-13 17:52:27.710: I/jPCT-AE(2283): New texture uploaded: com.threed.jpct.Texture@4239e220 in thread Thread[GLThread 19049,5,main]
07-13 17:52:27.710: I/jPCT-AE(2283): OpenGL context has changed(2)...recovering for renderer 4/2!
07-13 17:52:27.710: I/jPCT-AE(2283): Creating buffers...
07-13 17:52:27.710: I/jPCT-AE(2283): Allocating native memory for 8*8 texture(true/false/false/false/): 256 bytes!
07-13 17:52:27.710: I/jPCT-AE(2283): New texture's id is: 13
07-13 17:52:27.710: I/jPCT-AE(2283): New texture uploaded: com.threed.jpct.Texture@431ca698 in thread Thread[GLThread 19049,5,main]
07-13 17:52:27.710: I/jPCT-AE(2283): OpenGL context has changed(2)...recovering for renderer 4/2!
07-13 17:52:27.710: I/jPCT-AE(2283): Creating buffers...
07-13 17:52:27.715: I/jPCT-AE(2283): Allocating native memory for 64*64 texture(true/false/false/false/): 16384 bytes!
07-13 17:52:27.715: I/jPCT-AE(2283): New texture's id is: 14
07-13 17:52:27.715: I/jPCT-AE(2283): New texture uploaded: com.threed.jpct.Texture@431d4720 in thread Thread[GLThread 19049,5,main]
07-13 17:52:27.715: I/jPCT-AE(2283): OpenGL context has changed(2)...recovering for renderer 4/2!
07-13 17:52:27.715: I/jPCT-AE(2283): Creating buffers...
07-13 17:52:27.715: I/jPCT-AE(2283): OpenGL context has changed(2)...recovering for renderer 4/2!
07-13 17:52:27.715: I/jPCT-AE(2283): Creating buffers...
07-13 17:52:27.715: I/jPCT-AE(2283): OpenGL context has changed(2)...recovering for renderer 4/2!
07-13 17:52:27.715: I/jPCT-AE(2283): Creating buffers...
07-13 17:52:27.715: I/jPCT-AE(2283): OpenGL context has changed(2)...recovering for renderer 4/2!
07-13 17:52:27.715: I/jPCT-AE(2283): Creating buffers...
07-13 17:52:27.715: I/jPCT-AE(2283): OpenGL context has changed(2)...recovering for renderer 4/2!
07-13 17:52:27.715: I/jPCT-AE(2283): Creating buffers...
07-13 17:52:27.715: I/jPCT-AE(2283): OpenGL context has changed(2)...recovering for renderer 4/2!
07-13 17:52:27.715: I/jPCT-AE(2283): Creating buffers...
07-13 17:52:27.715: I/jPCT-AE(2283): OpenGL context has changed(2)...recovering for renderer 4/2!
07-13 17:52:27.715: I/jPCT-AE(2283): Creating buffers...
07-13 17:52:27.715: I/jPCT-AE(2283): OpenGL context has changed(2)...recovering for renderer 4/2!
07-13 17:52:27.715: I/jPCT-AE(2283): Creating buffers...
07-13 17:52:27.720: I/jPCT-AE(2283): OpenGL context has changed(2)...recovering for renderer 4/2!
07-13 17:52:27.720: I/jPCT-AE(2283): Creating buffers...
07-13 17:52:27.720: I/jPCT-AE(2283): OpenGL context has changed(2)...recovering for renderer 4/2!
07-13 17:52:27.720: I/jPCT-AE(2283): Creating buffers...


The log above is made based on this test case:
1. Open preference activity while live wallpaper is set to phone.
2. Press home button

kkl

When GLRenderer is disposed, it is disposed on Main Thread (GLRenderer disposed with id 3 on Thread[main,5,main]), but when it is created, it's in GLThread (GLRenderer created with id 4 on Thread[GLThread 19049,5,main]). Does this cause the gl pointing to the wrong resources and dispose the wrong one?

EgonOlsen

The vbos and similar structures that are bound to the GL context should be disposed when the GL context becomes invalid. The actual data in native memory isn't bound to the context anyway. The problem with all this context shit (sorry, i can't call it other than that) is, that i couldn't find any location other than the rendering thread where you can actually dispose these resources and that isn't an option in most cases.
Have you tried to debug the memory leak in Eclipse? Maybe it's something completely different anyway.

kkl

Sorry for replying late. Was busy these few days.

I tested out with eclipse MAT and both cases (disposing framebuffer and other stuff at engine's onDestroy() and the end of rendering thread respectively) seem to be almost same. Still new in eclipse MAT, BTW.

However, the memory status in android seems to be different though.
1. Dispose at engine's onDestroy() with jpct-ae beta: Memory can go as low as 80-90MB.
2. Dispose at the end of rendering thread: Memory gets low but maintains around 150MB.

*Both cases are tested when live wallpaper is set to phone and home button is pressed at wallpaper preference activity.

BTW, why is it a bad idea to dispose at rendering thread?

EgonOlsen

Quote from: kkl on July 18, 2013, 05:36:31 PM
BTW, why is it a bad idea to dispose at rendering thread?
Not sure if it is...are you judging this based on the memory usage? However...this "leak"...is it really a leak, so that after some iterations, there's no memory left? Or it just that more memory is being used than you think it should?

kkl

QuoteHowever...this "leak"...is it really a leak, so that after some iterations, there's no memory left

I couldn't be sure about that too. But it just seems to take more memory than usual. The memory left seems to maintain at one extent.

QuoteOr it just that more memory is being used than you think it should
I guess so. The same objects and same textures should take equal amount of memory, shouldn't it?