OK.. so I've confirmed it's not my process. Here's an example (apologies for the length of the log)
03-31 11:46:12.587: DEBUG/dalvikvm(16714): GC_CONCURRENT freed 325K, 5% free 8827K/9208K, paused 10ms+4ms, total 34ms 03-31 11:46:12.594: DEBUG/656565(16714): Table:account Count:7 Migration Time:48 03-31 11:46:12.610: DEBUG/656565(16714): Table:advice Count:3 Migration Time:15 03-31 11:46:12.758: DEBUG/656565(16714): Table:category Count:128 Migration Time:153 03-31 11:46:12.868: DEBUG/dalvikvm(16714): GC_CONCURRENT freed 403K, 5% free 8840K/9272K, paused 14ms+6ms, total 43ms 03-31 11:46:12.962: DEBUG/656565(16714): Table:transaction_bankcc Count:116 Migration Time:202 03-31 11:46:12.969: DEBUG/656565(16714): Table:budget_overall Count:1 Migration Time:6 03-31 11:46:12.985: DEBUG/656565(16714): Table:budget Count:14 Migration Time:13 03-31 11:46:12.993: DEBUG/656565(16714): Table:fi_login Count:3 Migration Time:9 03-31 11:46:13.001: DEBUG/656565(16714): Table:spending Count:1 Migration Time:13 03-31 11:46:13.008: DEBUG/656565(16714): Table:alert Count:3 Migration Time:5 03-31 11:46:13.040: DEBUG/dalvikvm(16714): GC_CONCURRENT freed 395K, 5% free 8842K/9272K, paused 4ms+19ms, total 51ms 03-31 11:46:13.040: DEBUG/1010(16714): Throwable t:android.database.CursorIndexOutOfBoundsException: Index 0 requested, with a size of 0 03-31 11:46:13.040: INFO/MintDBAdaptor(16714): Upgrading database from version 6 to 12 03-31 11:46:13.040: INFO/MintDBAdaptor(16714): running migration7.sql 03-31 11:46:13.071: INFO/MintDBAdaptor(16714): running migration8.sql 03-31 11:46:13.071: INFO/MintDBAdaptor(16714): running migration9.sql 03-31 11:46:13.094: INFO/MintDBAdaptor(16714): running migration10.sql 03-31 11:46:13.094: INFO/MintDBAdaptor(16714): running migration11.sql 03-31 11:46:13.102: INFO/MintDBAdaptor(16714): running migration12.sql 03-31 11:46:13.587: DEBUG/dalvikvm(16758): GC_CONCURRENT freed 406K, 6% free 8774K/9260K, paused 2ms+2ms, total 69ms 03-31 11:46:13.610: DEBUG/dalvikvm(16714): GC_CONCURRENT freed 360K, 5% free 8929K/9316K, paused 4ms+9ms, total 98ms 03-31 11:46:14.040: DEBUG/dalvikvm(16714): GC_CONCURRENT freed 294K, 4% free 9067K/9388K, paused 5ms+6ms, total 42ms 03-31 11:46:14.508: DEBUG/dalvikvm(16714): GC_FOR_ALLOC freed 137K, 5% free 9136K/9568K, paused 23ms, total 23ms 03-31 11:46:14.532: DEBUG/dalvikvm(16714): GC_FOR_ALLOC freed 148K, 6% free 9137K/9632K, paused 22ms, total 22ms 03-31 11:46:14.555: DEBUG/dalvikvm(16714): GC_FOR_ALLOC freed 61K, 5% free 9229K/9632K, paused 24ms, total 24ms 03-31 11:46:14.688: DEBUG/dalvikvm(16714): GC_CONCURRENT freed 377K, 5% free 9348K/9756K, paused 3ms+4ms, total 38ms 03-31 11:46:14.969: INFO/Database(16714): sqlite returned: error code = 17, msg = statement aborts at 26: [INSERT INTO budget_overall(id, performanceStatus) VALUES(?, ?);] database schema has changed 03-31 11:46:15.790: DEBUG/dalvikvm(16714): GC_CONCURRENT freed 635K, 7% free 9181K/9844K, paused 3ms+2ms, total 33ms 03-31 11:46:15.962: DEBUG/123(16714): Modified From::Mar:31 07:15 2013 :1364739342001 03-31 11:46:16.102: DEBUG/dalvikvm(16714): GC_CONCURRENT freed 433K, 7% free 9161K/9844K, paused 2ms+2ms, total 26ms 03-31 11:46:16.829: DEBUG/dalvikvm(16714): GC_FOR_ALLOC freed 159K, 7% free 9250K/9844K, paused 22ms, total 22ms 03-31 11:46:16.852: DEBUG/dalvikvm(16714): GC_FOR_ALLOC freed 40K, 6% free 9269K/9844K, paused 19ms, total 19ms 03-31 11:46:17.227: DEBUG/dalvikvm(16714): GC_FOR_ALLOC freed 59K, 6% free 9299K/9844K, paused 26ms, total 26ms 03-31 11:46:17.227: INFO/dalvikvm-heap(16714): Grow heap (frag case) to 9.236MB for 136844-byte allocation 03-31 11:46:17.258: DEBUG/dalvikvm(16714): GC_FOR_ALLOC freed 89K, 7% free 9344K/9980K, paused 29ms, total 29ms 03-31 11:46:17.407: DEBUG/dalvikvm(16714): GC_FOR_ALLOC freed <1K, 7% free 9344K/9980K, paused 23ms, total 23ms 03-31 11:46:17.415: INFO/dalvikvm-heap(16714): Grow heap (frag case) to 9.258MB for 115094-byte allocation 03-31 11:46:17.430: DEBUG/dalvikvm(16714): GC_FOR_ALLOC freed 0K, 7% free 9456K/10096K, paused 22ms, total 22ms 03-31 11:46:17.454: DEBUG/dalvikvm(16714): GC_FOR_ALLOC freed 133K, 8% free 9322K/10096K, paused 21ms, total 21ms 03-31 11:46:17.469: DEBUG/dalvikvm(16714): GC_FOR_ALLOC freed <1K, 7% free 9435K/10096K, paused 14ms, total 15ms 03-31 11:46:17.469: INFO/dalvikvm-heap(16714): Grow heap (frag case) to 9.403MB for 172636-byte allocation 03-31 11:46:17.485: DEBUG/dalvikvm(16714): GC_FOR_ALLOC freed 112K, 8% free 9491K/10268K, paused 14ms, total 14ms 03-31 11:46:17.501: DEBUG/dalvikvm(16714): GC_FOR_ALLOC freed 168K, 9% free 9435K/10268K, paused 14ms, total 14ms 03-31 11:46:17.555: DEBUG/dalvikvm(16714): GC_CONCURRENT freed 383K, 7% free 9564K/10268K, paused 3ms+2ms, total 34ms 03-31 11:46:17.555: DEBUG/dalvikvm(16714): WAIT_FOR_CONCURRENT_GC blocked 10ms 03-31 11:46:17.688: DEBUG/dalvikvm(16714): GC_CONCURRENT freed 237K, 6% free 9734K/10268K, paused 3ms+2ms, total 26ms 03-31 11:46:18.024: INFO/dalvikvm(16714): Total arena pages for JIT: 11 03-31 11:46:18.024: INFO/dalvikvm(16714): Total arena pages for JIT: 12 03-31 11:46:18.024: INFO/dalvikvm(16714): Total arena pages for JIT: 13 03-31 11:46:18.024: INFO/dalvikvm(16714): Total arena pages for JIT: 14 03-31 11:46:18.024: INFO/dalvikvm(16714): Total arena pages for JIT: 15 03-31 11:46:18.024: INFO/dalvikvm(16714): Total arena pages for JIT: 16 03-31 11:46:18.024: INFO/dalvikvm(16714): Total arena pages for JIT: 17 03-31 11:46:18.071: DEBUG/dalvikvm(16714): GC_CONCURRENT freed 940K, 11% free 9232K/10268K, paused 2ms+3ms, total 33ms 03-31 11:46:18.493: INFO/dalvikvm(16714): Total arena pages for JIT: 18 03-31 11:46:20.657: DEBUG/dalvikvm(16758): GC_CONCURRENT freed 432K, 6% free 8749K/9268K, paused 4ms+7ms, total 33ms 03-31 11:46:27.704: DEBUG/dalvikvm(16758): GC_CONCURRENT freed 383K, 6% free 8774K/9236K, paused 2ms+1ms, total 23ms 03-31 11:46:29.008: DEBUG/dalvikvm(16714): GC_CONCURRENT freed 354K, 8% free 9286K/10088K, paused 3ms+3ms, total 31ms When this was recorded, the process ID for my process was 16810 ( http://cl.ly/image/1X0I3e2W423k). Most (although interestingly not all) of the above logs are for process ID 16714 which we can see is actually the Mint app. Not only is it hammering the GC but it also seems to be doing database migrations :/ This is all fine IF it runs in a resource limited space (i.e. limited CPU, RAM & Disk) but it appears to not be the case as either one or all of these resources may be blocking causing lag in the game. Not sure what the 16758 process is. This is just a small sample (covering about 10 seconds) of an otherwise much larger log with several GC calls. Is anyone able to shed some light on whether this is expected/normal behavior, or if there's anything that can be done to mitigate? Thanks. P.S. I don't see the same behavior on older 2.3 devices, but this is not a very controlled experiment as the older devices tend not to have many apps whereas the newer (4.2.2) device (which is a Galaxy Nexus btw) is my every day device so has more apps. On Sun, Mar 31, 2013 at 9:42 AM, Anthony Prieur <anthony.pri...@gmail.com>wrote: > The frame drop looks huge as since Gingerbread the GC is clamied to work > concurrently. > > > On Sun, Mar 31, 2013 at 4:38 PM, Jason Polites <jason.poli...@gmail.com>wrote: > >> I'm 90% sure it wasn't, but I make this claim based on profiling heap >> allocations and I don't think I confirmed that the process ID was actually >> different. I'll confirm (or otherwise) this and post back. >> On Mar 31, 2013 2:52 AM, "RichardC" <richard.crit...@googlemail.com> >> wrote: >> >>> Is/was 2590 your process? >>> >>> On Sunday, March 31, 2013 8:07:50 AM UTC+1, Jason wrote: >>>> >>>> Hey folks, >>>> >>>> So I'm in the midst of creating a game and I'm hitting some occasional >>>> slow down which "seems" to be a result of GC calls triggered by other >>>> processes on the device. I have profiled *my* app and am 100% certain >>>> there are no allocations going on while the game is running, but in certain >>>> circumstances (i.e. most of the time) logcat is spewing out GC_CONCURRENT >>>> freed...blah blah entries. Here's a typical output from the console: >>>> >>>> 03-30 23:58:58.868: DEBUG/dalvikvm(2590): GC_CONCURRENT freed 407K, 6% >>>> free 8758K/9224K, paused 5ms+3ms, total 29ms >>>> 03-30 23:59:05.970: DEBUG/dalvikvm(2590): GC_CONCURRENT freed 408K, 6% >>>> free 8757K/9228K, paused 4ms+2ms, total 30ms >>>> 03-30 23:59:13.063: DEBUG/dalvikvm(2590): GC_CONCURRENT freed 407K, 6% >>>> free 8757K/9224K, paused 4ms+4ms, total 33ms >>>> 03-30 23:59:20.142: DEBUG/dalvikvm(2590): GC_CONCURRENT freed 407K, 6% >>>> free 8757K/9228K, paused 5ms+3ms, total 30ms >>>> 03-30 23:59:27.227: DEBUG/dalvikvm(2590): GC_CONCURRENT freed 407K, 6% >>>> free 8757K/9224K, paused 6ms+2ms, total 31ms >>>> 03-30 23:59:34.306: DEBUG/dalvikvm(2590): GC_CONCURRENT freed 407K, 6% >>>> free 8757K/9232K, paused 4ms+2ms, total 23ms >>>> 03-30 23:59:41.392: DEBUG/dalvikvm(2590): GC_CONCURRENT freed 407K, 6% >>>> free 8757K/9224K, paused 4ms+2ms, total 27ms >>>> 03-30 23:59:48.470: DEBUG/dalvikvm(2590): GC_CONCURRENT freed 407K, 6% >>>> free 8757K/9232K, paused 5ms+2ms, total 30ms >>>> >>>> Now I have no idea which processes are to blame, but I did notice that >>>> when "other" events on the device occur it can lead to a spike in (I >>>> assume) CPU usage which causes a visible drop in frame rate in the game. >>>> >>>> For example my wifi connection dropped out one time and the logs went >>>> crazy with other processes complaining about a lost connection and trying >>>> desperately to tell me about it. This caused a fairly severe jolt in the >>>> game dropping the frame rate from 60fps to around 20fps for about a minute >>>> while everything settled down and got on with things. >>>> >>>> I had noted on a previous >>>> thread<https://groups.google.com/forum/?fromgroups=#!searchin/android-developers/Garbage$20collector$20suspend/android-developers/85yj9CZEqH4/YIiElemqiuoJ>a >>>> statement from Dianne Hackborn: >>>> >>>> *"as of 1.6 such GCs in a background process can not together take >>>> more than ~10% of the CPU from any foreground process that wants to run." >>>> * >>>> >>>> This sounds good, but I'm wondering if this is still the case as of >>>> 4.2.2? I am seeing behavior that appears to indicate this may not the >>>> case. >>>> >>>> Is there anything I can do to ensure other processes are not using more >>>> than 10% of CPU (or any number really)? Or some other >>>> restrictions/priorities that might help alleviate this external resource >>>> usage? >>>> >>>> Thanks, >>>> >>>> Jason. >>>> >>> -- >>> -- >>> 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 >>> --- >>> You received this message because you are subscribed to a topic in the >>> Google Groups "Android Developers" group. >>> To unsubscribe from this topic, visit >>> https://groups.google.com/d/topic/android-developers/yQVg0WzChko/unsubscribe?hl=en >>> . >>> To unsubscribe from this group and all its topics, send an email to >>> android-developers+unsubscr...@googlegroups.com. >>> For more options, visit https://groups.google.com/groups/opt_out. >>> >>> >>> >> -- >> -- >> 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 >> --- >> You received this message because you are subscribed to a topic in the >> Google Groups "Android Developers" group. >> To unsubscribe from this topic, visit >> https://groups.google.com/d/topic/android-developers/yQVg0WzChko/unsubscribe?hl=en >> . >> To unsubscribe from this group and all its topics, send an email to >> android-developers+unsubscr...@googlegroups.com. >> For more options, visit https://groups.google.com/groups/opt_out. >> >> >> > > -- > -- > 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 > --- > You received this message because you are subscribed to a topic in the > Google Groups "Android Developers" group. > To unsubscribe from this topic, visit > https://groups.google.com/d/topic/android-developers/yQVg0WzChko/unsubscribe?hl=en > . > To unsubscribe from this group and all its topics, send an email to > android-developers+unsubscr...@googlegroups.com. > For more options, visit https://groups.google.com/groups/opt_out. > > > -- Ozzy's Odyssey! A new game for Android https://market.android.com/details?id=com.carboncrystal.odyssey http://www.carboncrystal.com/ <http://www.carboncrystal.com/droid-odyssey/> -- -- 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 --- You received this message because you are subscribed to the Google Groups "Android Developers" group. To unsubscribe from this group and stop receiving emails from it, send an email to android-developers+unsubscr...@googlegroups.com. For more options, visit https://groups.google.com/groups/opt_out.
