Good point. Some quick trials here do seem to indicate that the GC firing in a different process doesn't stop the world for a game like the GC firing in the game's does. So GC from other processes isn't as bad. Tested on a Droid running Android 2.0.1.
A stretch of logged draw requests with airplane mode on and no GC interference looks like this, logging once every 60 calls: I/AndUtil ( 3325): game thread, draw request delay times = average: 19, max: 34, min: 13. I/AndUtil ( 3325): game thread, draw request delay times = average: 18, max: 41, min: 7. I/AndUtil ( 3325): game thread, draw request delay times = average: 17, max: 34, min: 10. I/AndUtil ( 3325): game thread, draw request delay times = average: 18, max: 34, min: 9. I/AndUtil ( 3325): game thread, draw request delay times = average: 18, max: 37, min: 6. I/AndUtil ( 3325): game thread, draw request delay times = average: 17, max: 35, min: 9. I/AndUtil ( 3325): game thread, draw request delay times = average: 18, max: 36, min: 9. I/AndUtil ( 3325): game thread, draw request delay times = average: 19, max: 35, min: 13. I/AndUtil ( 3325): game thread, draw request delay times = average: 19, max: 35, min: 5. I/AndUtil ( 3325): game thread, draw request delay times = average: 16, max: 33, min: 10. I/AndUtil ( 3325): game thread, draw request delay times = average: 17, max: 35, min: 4. I/AndUtil ( 3325): game thread, draw request delay times = average: 16, max: 19, min: 14. I/AndUtil ( 3325): game thread, draw request delay times = average: 16, max: 31, min: 9. I/AndUtil ( 3325): game thread, draw request delay times = average: 16, max: 19, min: 14. I/AndUtil ( 3325): game thread, draw request delay times = average: 18, max: 33, min: 4. I/AndUtil ( 3325): game thread, draw request delay times = average: 19, max: 35, min: 9. I/AndUtil ( 3325): game thread, draw request delay times = average: 19, max: 34, min: 12. I/AndUtil ( 3325): game thread, draw request delay times = average: 17, max: 36, min: 6. I/AndUtil ( 3325): game thread, draw request delay times = average: 16, max: 19, min: 14. I/AndUtil ( 3325): game thread, draw request delay times = average: 16, max: 30, min: 8. I/AndUtil ( 3325): game thread, draw request delay times = average: 17, max: 34, min: 9. I/AndUtil ( 3325): game thread, draw request delay times = average: 16, max: 30, min: 11. I/AndUtil ( 3325): game thread, draw request delay times = average: 16, max: 18, min: 15. I/AndUtil ( 3325): game thread, draw request delay times = average: 16, max: 29, min: 9. I/AndUtil ( 3325): game thread, draw request delay times = average: 16, max: 19, min: 14. I/AndUtil ( 3325): game thread, draw request delay times = average: 17, max: 35, min: 8. I/AndUtil ( 3325): game thread, draw request delay times = average: 17, max: 35, min: 14. I/AndUtil ( 3325): game thread, draw request delay times = average: 17, max: 37, min: 13. I/AndUtil ( 3325): game thread, draw request delay times = average: 19, max: 34, min: 13. I/AndUtil ( 3325): game thread, draw request delay times = average: 20, max: 37, min: 7. I/AndUtil ( 3325): game thread, draw request delay times = average: 20, max: 42, min: 13. I/AndUtil ( 3325): game thread, draw request delay times = average: 19, max: 34, min: 14. I/AndUtil ( 3325): game thread, draw request delay times = average: 18, max: 35, min: 8. I/AndUtil ( 3325): game thread, draw request delay times = average: 18, max: 34, min: 9. I/AndUtil ( 3325): game thread, draw request delay times = average: 20, max: 49, min: 5. I/AndUtil ( 3325): game thread, draw request delay times = average: 21, max: 33, min: 14. I/AndUtil ( 3325): game thread, draw request delay times = average: 21, max: 35, min: 8. I/AndUtil ( 3325): game thread, draw request delay times = average: 20, max: 37, min: 5. I/AndUtil ( 3325): game thread, draw request delay times = average: 20, max: 36, min: 12. I/AndUtil ( 3325): game thread, draw request delay times = average: 19, max: 36, min: 11. I/AndUtil ( 3325): game thread, draw request delay times = average: 17, max: 35, min: 9. I/AndUtil ( 3325): game thread, draw request delay times = average: 17, max: 33, min: 10. I/AndUtil ( 3325): game thread, draw request delay times = average: 18, max: 38, min: 5. I/AndUtil ( 3325): game thread, draw request delay times = average: 17, max: 35, min: 10. I/AndUtil ( 3325): game thread, draw request delay times = average: 19, max: 35, min: 8. I/AndUtil ( 3325): game thread, draw request delay times = average: 19, max: 33, min: 10. I/AndUtil ( 3325): game thread, draw request delay times = average: 19, max: 37, min: 4. Airplane mode off and a different app that posts a runnable to a handler delayed by 3000 ms over and over in the background to trigger a GC looks like this: I/TestFireGCRegularly( 3402): Firing GC in other process. D/dalvikvm( 3402): GC freed 6 objects / 152 bytes in 96ms I/AndUtil ( 3325): game thread, draw request delay times = average: 18, max: 40, min: 4. I/AndUtil ( 3325): game thread, draw request delay times = average: 16, max: 21, min: 12. I/AndUtil ( 3325): game thread, draw request delay times = average: 17, max: 35, min: 4. I/TestFireGCRegularly( 3402): Firing GC in other process. D/dalvikvm( 3402): GC freed 2 objects / 48 bytes in 114ms I/AndUtil ( 3325): game thread, draw request delay times = average: 18, max: 44, min: 8. I/AndUtil ( 3325): game thread, draw request delay times = average: 19, max: 35, min: 12. I/AndUtil ( 3325): game thread, draw request delay times = average: 19, max: 33, min: 14. I/TestFireGCRegularly( 3402): Firing GC in other process. D/dalvikvm( 3402): GC freed 2 objects / 48 bytes in 168ms D/dalvikvm( 1089): GC freed 1295 objects / 87760 bytes in 175ms I/AndUtil ( 3325): game thread, draw request delay times = average: 20, max: 51, min: 11. I/AndUtil ( 3325): game thread, draw request delay times = average: 21, max: 37, min: 13. I/TestFireGCRegularly( 3402): Firing GC in other process. I/AndUtil ( 3325): game thread, draw request delay times = average: 20, max: 33, min: 14. D/dalvikvm( 3402): GC freed 2 objects / 48 bytes in 87ms I/AndUtil ( 3325): game thread, draw request delay times = average: 19, max: 45, min: 13. D/dalvikvm( 1125): GC freed 1349 objects / 59576 bytes in 179ms I/AndUtil ( 3325): game thread, draw request delay times = average: 20, max: 41, min: 8. I/TestFireGCRegularly( 3402): Firing GC in other process. D/dalvikvm( 3402): GC freed 2 objects / 48 bytes in 84ms I/AndUtil ( 3325): game thread, draw request delay times = average: 20, max: 37, min: 7. I/AndUtil ( 3325): game thread, draw request delay times = average: 20, max: 42, min: 12. I/AndUtil ( 3325): game thread, draw request delay times = average: 20, max: 35, min: 13. I/TestFireGCRegularly( 3402): Firing GC in other process. D/dalvikvm( 3402): GC freed 2 objects / 48 bytes in 101ms I/AndUtil ( 3325): game thread, draw request delay times = average: 19, max: 47, min: 11. D/dalvikvm( 1513): GC freed 280 objects / 14344 bytes in 163ms I/AndUtil ( 3325): game thread, draw request delay times = average: 20, max: 37, min: 14. I/TestFireGCRegularly( 3402): Firing GC in other process. D/dalvikvm( 3402): GC freed 2 objects / 48 bytes in 130ms I/AndUtil ( 3325): game thread, draw request delay times = average: 20, max: 50, min: 13. I/AndUtil ( 3325): game thread, draw request delay times = average: 19, max: 52, min: 8. I/AndUtil ( 3325): game thread, draw request delay times = average: 18, max: 33, min: 14. D/dalvikvm( 1525): GC freed 43 objects / 2128 bytes in 160ms I/TestFireGCRegularly( 3402): Firing GC in other process. D/dalvikvm( 3402): GC freed 2 objects / 48 bytes in 71ms I/AndUtil ( 3325): game thread, draw request delay times = average: 17, max: 33, min: 14. I/AndUtil ( 3325): game thread, draw request delay times = average: 17, max: 34, min: 14. D/AlarmManagerService( 1026): Kernel timezone updated to 240 minutes west of GMT D/NetworkLocationProvider( 1026): onCellLocationChanged [504,0,0,22,2] D/dalvikvm( 1078): GC freed 13203 objects / 599312 bytes in 131ms I/AndUtil ( 3325): game thread, draw request delay times = average: 18, max: 71, min: 3. I/TestFireGCRegularly( 3402): Firing GC in other process. D/dalvikvm( 3402): GC freed 2 objects / 48 bytes in 101ms I/AndUtil ( 3325): game thread, draw request delay times = average: 19, max: 72, min: 3. I/AndUtil ( 3325): game thread, draw request delay times = average: 19, max: 49, min: 8. I/TestFireGCRegularly( 3402): Firing GC in other process. D/dalvikvm( 3402): GC freed 2 objects / 48 bytes in 107ms I/AndUtil ( 3325): game thread, draw request delay times = average: 20, max: 38, min: 8. D/dalvikvm( 1201): GC freed 82 objects / 5328 bytes in 132ms I/AndUtil ( 3325): game thread, draw request delay times = average: 20, max: 36, min: 11. I/AndUtil ( 3325): game thread, draw request delay times = average: 20, max: 37, min: 8. I/TestFireGCRegularly( 3402): Firing GC in other process. D/dalvikvm( 3402): GC freed 2 objects / 48 bytes in 85ms I/AndUtil ( 3325): game thread, draw request delay times = average: 18, max: 38, min: 8. I/AndUtil ( 3325): game thread, draw request delay times = average: 16, max: 34, min: 12. I/AndUtil ( 3325): game thread, draw request delay times = average: 17, max: 43, min: 6. I/TestFireGCRegularly( 3402): Firing GC in other process. D/dalvikvm( 3402): GC freed 2 objects / 48 bytes in 123ms I/AndUtil ( 3325): game thread, draw request delay times = average: 17, max: 52, min: 13. Airplane mode on, GC explicitly called in the same process every 3000 ms, shows delay spikes that exceed the entire GC time whereas the previous track didn't: I/TestFireGCRegularly( 3588): Firing GC in same process. D/dalvikvm( 3588): GC freed 41 objects / 2040 bytes in 67ms I/AndUtil ( 3588): game thread, draw request delay times = average: 19, max: 84, min: 3. I/AndUtil ( 3588): game thread, draw request delay times = average: 18, max: 37, min: 9. I/TestFireGCRegularly( 3588): Firing GC in same process. D/dalvikvm( 3588): GC freed 32 objects / 1504 bytes in 82ms I/AndUtil ( 3588): game thread, draw request delay times = average: 19, max: 121, min: 4. I/AndUtil ( 3588): game thread, draw request delay times = average: 18, max: 35, min: 9. I/AndUtil ( 3588): game thread, draw request delay times = average: 18, max: 36, min: 8. I/TestFireGCRegularly( 3588): Firing GC in same process. D/dalvikvm( 3588): GC freed 41 objects / 2048 bytes in 62ms I/AndUtil ( 3588): game thread, draw request delay times = average: 18, max: 84, min: 4. I/AndUtil ( 3588): game thread, draw request delay times = average: 19, max: 36, min: 4. I/AndUtil ( 3588): game thread, draw request delay times = average: 20, max: 36, min: 11. I/TestFireGCRegularly( 3588): Firing GC in same process. D/dalvikvm( 3588): GC freed 43 objects / 2104 bytes in 80ms I/AndUtil ( 3588): game thread, draw request delay times = average: 17, max: 116, min: 4. I/AndUtil ( 3588): game thread, draw request delay times = average: 18, max: 38, min: 9. I/TestFireGCRegularly( 3588): Firing GC in same process. D/dalvikvm( 3588): GC freed 29 objects / 1416 bytes in 88ms I/AndUtil ( 3588): game thread, draw request delay times = average: 19, max: 122, min: 4. I/AndUtil ( 3588): game thread, draw request delay times = average: 20, max: 35, min: 3. I/AndUtil ( 3588): game thread, draw request delay times = average: 19, max: 33, min: 12. I/TestFireGCRegularly( 3588): Firing GC in same process. D/dalvikvm( 3588): GC freed 42 objects / 2080 bytes in 71ms I/AndUtil ( 3588): game thread, draw request delay times = average: 20, max: 105, min: 4. I/AndUtil ( 3588): game thread, draw request delay times = average: 20, max: 34, min: 14. I/TestFireGCRegularly( 3588): Firing GC in same process. D/dalvikvm( 3588): GC freed 28 objects / 1384 bytes in 69ms I/AndUtil ( 3588): game thread, draw request delay times = average: 20, max: 95, min: 4. I/AndUtil ( 3588): game thread, draw request delay times = average: 19, max: 34, min: 14. I/AndUtil ( 3588): game thread, draw request delay times = average: 18, max: 34, min: 12. I/TestFireGCRegularly( 3588): Firing GC in same process. D/dalvikvm( 3588): GC freed 40 objects / 2008 bytes in 66ms I/AndUtil ( 3588): game thread, draw request delay times = average: 19, max: 85, min: 4. I/AndUtil ( 3588): game thread, draw request delay times = average: 18, max: 47, min: 4. I/TestFireGCRegularly( 3588): Firing GC in same process. D/dalvikvm( 3588): GC freed 32 objects / 1504 bytes in 68ms I/AndUtil ( 3588): game thread, draw request delay times = average: 20, max: 89, min: 4. I/AndUtil ( 3588): game thread, draw request delay times = average: 18, max: 34, min: 7. I/AndUtil ( 3588): game thread, draw request delay times = average: 19, max: 42, min: 12. I/TestFireGCRegularly( 3588): Firing GC in same process. D/dalvikvm( 3588): GC freed 44 objects / 2136 bytes in 63ms I/AndUtil ( 3588): game thread, draw request delay times = average: 17, max: 84, min: 3. I/AndUtil ( 3588): game thread, draw request delay times = average: 18, max: 39, min: 10. I/AndUtil ( 3588): game thread, draw request delay times = average: 19, max: 38, min: 11. I/TestFireGCRegularly( 3588): Firing GC in same process. D/dalvikvm( 3588): GC freed 41 objects / 2040 bytes in 71ms I/AndUtil ( 3588): game thread, draw request delay times = average: 18, max: 95, min: 3. I/AndUtil ( 3588): game thread, draw request delay times = average: 18, max: 34, min: 11. I/TestFireGCRegularly( 3588): Firing GC in same process. D/dalvikvm( 3588): GC freed 33 objects / 1536 bytes in 89ms I/AndUtil ( 3588): game thread, draw request delay times = average: 19, max: 122, min: 4. I/AndUtil ( 3588): game thread, draw request delay times = average: 18, max: 35, min: 11. I/AndUtil ( 3588): game thread, draw request delay times = average: 18, max: 36, min: 10. I/TestFireGCRegularly( 3588): Firing GC in same process. D/dalvikvm( 3588): GC freed 40 objects / 2016 bytes in 71ms I/AndUtil ( 3588): game thread, draw request delay times = average: 19, max: 87, min: 3. I/AndUtil ( 3588): game thread, draw request delay times = average: 18, max: 34, min: 11. I/AndUtil ( 3588): game thread, draw request delay times = average: 17, max: 34, min: 14. I/TestFireGCRegularly( 3588): Firing GC in same process. D/dalvikvm( 3588): GC freed 41 objects / 2040 bytes in 65ms I/AndUtil ( 3588): game thread, draw request delay times = average: 19, max: 84, min: 3. I/AndUtil ( 3588): game thread, draw request delay times = average: 20, max: 33, min: 14. I/TestFireGCRegularly( 3588): Firing GC in same process. D/dalvikvm( 3588): GC freed 28 objects / 1376 bytes in 84ms I/AndUtil ( 3588): game thread, draw request delay times = average: 20, max: 118, min: 4. I/AndUtil ( 3588): game thread, draw request delay times = average: 18, max: 35, min: 9. I/AndUtil ( 3588): game thread, draw request delay times = average: 18, max: 53, min: 4. I/TestFireGCRegularly( 3588): Firing GC in same process. D/dalvikvm( 3588): GC freed 46 objects / 2208 bytes in 68ms I/AndUtil ( 3588): game thread, draw request delay times = average: 18, max: 84, min: 5. I/AndUtil ( 3588): game thread, draw request delay times = average: 17, max: 36, min: 10. I/AndUtil ( 3588): game thread, draw request delay times = average: 18, max: 33, min: 5. I/TestFireGCRegularly( 3588): Firing GC in same process. D/dalvikvm( 3588): GC freed 45 objects / 2168 bytes in 79ms I/AndUtil ( 3588): game thread, draw request delay times = average: 20, max: 115, min: 4. I/AndUtil ( 3588): game thread, draw request delay times = average: 19, max: 33, min: 14. I/TestFireGCRegularly( 3588): Firing GC in same process. D/dalvikvm( 3588): GC freed 31 objects / 1480 bytes in 66ms I/AndUtil ( 3588): game thread, draw request delay times = average: 18, max: 86, min: 4. I/AndUtil ( 3588): game thread, draw request delay times = average: 17, max: 34, min: 9. I/AndUtil ( 3588): game thread, draw request delay times = average: 17, max: 37, min: 5. I/TestFireGCRegularly( 3588): Firing GC in same process. D/dalvikvm( 3588): GC freed 43 objects / 2104 bytes in 62ms I/AndUtil ( 3588): game thread, draw request delay times = average: 17, max: 81, min: 4. I/AndUtil ( 3588): game thread, draw request delay times = average: 18, max: 57, min: 10. I/AndUtil ( 3588): game thread, draw request delay times = average: 19, max: 34, min: 8. I/TestFireGCRegularly( 3588): Firing GC in same process. D/dalvikvm( 3588): GC freed 45 objects / 2168 bytes in 79ms I/AndUtil ( 3588): game thread, draw request delay times = average: 19, max: 105, min: 4. I/AndUtil ( 3588): game thread, draw request delay times = average: 18, max: 38, min: 6. I/TestFireGCRegularly( 3588): Firing GC in same process. D/dalvikvm( 3588): GC freed 34 objects / 1576 bytes in 92ms I/AndUtil ( 3588): game thread, draw request delay times = average: 19, max: 126, min: 4. I/AndUtil ( 3588): game thread, draw request delay times = average: 17, max: 36, min: 12. I/AndUtil ( 3588): game thread, draw request delay times = average: 18, max: 33, min: 9. I/TestFireGCRegularly( 3588): Firing GC in same process. D/dalvikvm( 3588): GC freed 42 objects / 2080 bytes in 60ms I/AndUtil ( 3588): game thread, draw request delay times = average: 19, max: 80, min: 4. I/AndUtil ( 3588): game thread, draw request delay times = average: 20, max: 50, min: 9. I/AndUtil ( 3588): game thread, draw request delay times = average: 16, max: 34, min: 10. I/TestFireGCRegularly( 3588): Firing GC in same process. D/dalvikvm( 3588): GC freed 39 objects / 1976 bytes in 61ms I/AndUtil ( 3588): game thread, draw request delay times = average: 17, max: 80, min: 4. On Mar 14, 4:55 pm, Mark Murphy <mmur...@commonsware.com> wrote: > markusn82 wrote: > > Mark Murphy, it doesn't sound like you were trying to be productive in > > your original post. > > Actually, I was. Still am, as a matter of fact. > > > Rather, I was trying to > > make real suggestions for a real problem that exists. > > Likewise, mostly in the latter half of the post. > > > Despite all these efforts the game still ends up having spikes in its > > FPS due to the garbage collector. When the GC executes from other > > processes, it always takes up ~100-300 ms.. thats a deal breaker for a > > real-time game. > > The ~100-300ms isn't that meaningful of a figure, though. Frame rate > won't drop because of elapsed time of the foreign process' GC operation. > Frame rate will drop if, during that time, too much CPU is utilized by > GC, or access to some cross-process resource is blocked by GC, or > something along those lines. Lacking any of that, it doesn't matter if a > foreign process' GC takes 100ms or 100 minutes. > > I would watch the video that Mr. Nanek pointed out, but my ISP is having > difficulty with some Google properties, YouTube among them, so my > download rate is atrocious. However, from the slides and the snippet > I've seen, the focus is on a game's own GC, not the GC from foreign > processes. > > Multiple posts from Ms. Hackborn indicate that background processes' > threads are in a background scheduling class that limits their CPU > utilization. I am assuming that the frame rate effects you are seeing > are severe, not just a 10% or so drop that might just be background > process CPU time. > > So, I see the following possibilities: > > 1. That background scheduling class is not working in general. > > 2. That background scheduling class is not affecting GC operations > (e.g., the GC thread is in the foreground class regardless of whether > the process is foreground or background). > > 3. One process' GC locks some system resource that your game depends > upon (which would shock the heck out of me). > > 4. The code generating the problematic GC is not in the background > scheduling class (e.g., it called startForeground() and has an active > Notification), though my understanding is that even this has a lower > priority than the true foreground process. > > 5. It's not GC, but something else that is going on that coincides with > the GC. > > If there are other possibilities that I have missed, please point them > out. And, if you have already done this sort of testing and haven't > mentioned the results yet, please do! > > Most of these should be testable theories. I'll be happy to run some > tests, but I'm going to need some program that measures the impact of > background processes on the foreground. I can cook up something, but it > won't closely resemble a real-time game that heavily uses the NDK. This > is what I was getting at in my second post -- in order to address this > problem, we need some way to reproduce it and measure it. > > So, I'll poke at this some, but if somebody knows of an app (preferably > with source) that uses 2D/3D graphics and logs its timestamped frame > rates somewhere, that would be helpful, for me and for anyone else who > might actually work on this problem. > > BTW, is there an openhttp://b.android.comissue on this? > > -- > Mark Murphy (a Commons > Guy)http://commonsware.com|http://twitter.com/commonsguy > > Android Training...At Your Office:http://commonsware.com/training -- You received this message because you are subscribed to the Google Groups "Android Developers" group. To post to this group, send email to android-developers@googlegroups.com To unsubscribe from this group, send email to android-developers+unsubscr...@googlegroups.com For more options, visit this group at http://groups.google.com/group/android-developers?hl=en
