frequent garbage collection

[bnovc]

Are patterns of GC like this expected?

D/dalvikvm( 1095): GC freed 271 objects / 10328 bytes in 473ms
D/dalvikvm( 1095): GC freed 37 objects / 1632 bytes in 100ms
D/dalvikvm( 1095): GC freed 2 objects / 48 bytes in 56ms

This is opening on an almost empty application (just a TextView) and
those all happen within milliseconsd when it is opened.

This doesn't consistently happen, but I've seen it from time to time.

Wouldn't it be better to only do one pass?

[fadden]

On Oct 22, 1:29 pm, bnovc <m.bn...@gmail.com> wrote:
> Are patterns of GC like this expected?
>
> D/dalvikvm( 1095): GC freed 271 objects / 10328 bytes in 473ms
> D/dalvikvm( 1095): GC freed 37 objects / 1632 bytes in 100ms
> D/dalvikvm( 1095): GC freed 2 objects / 48 bytes in 56ms
>
> This is opening on an almost empty application (just a TextView) and
> those all happen within milliseconsd when it is opened.

If you "adb logcat -v time" you can see the timestamps associated with
the log messages.

This sort of behavior is usually associated with explicit calls to
System.gc(), unless your application is right up against the memory
limit and the VM has no choice but to GC constantly.

[Barry Hayes]

Yeah, I think the answer to "expected" is "yes."
"What you want" might be some other answer ..

Where in particular are you seeing this?

--
bhayes yat cs dot stanford dot edu is what you should put in your
contact files -- it'll forward to me no matter where I move

[bnovc]

I am seeing it when opening applications mostly. I have quite a bit of
free memory when I am doing it.

Here is a slightly different example, where multiple processes are
being GCed when one starts up:

10-29 16:11:33.060 D/dalvikvm( 1502): GC freed 50 objects / 1864 bytes
in 590ms
10-29 16:11:33.080 D/dalvikvm( 1824): GC freed 1014 objects / 85152
bytes in 697ms
10-29 16:11:33.090 D/dalvikvm( 1789): GC freed 228 objects / 9544
bytes in 535ms
10-29 16:11:33.130 D/dalvikvm( 1265): GC freed 200 objects / 10184
bytes in 739ms
10-29 16:11:33.140 D/dalvikvm( 1319): GC freed 78 objects / 3224 bytes
in 647ms
10-29 16:11:33.160 D/dalvikvm( 1395): GC freed 736 objects / 54048
bytes in 747ms
10-29 16:11:33.160 D/dalvikvm( 1486): GC freed 103 objects / 4952
bytes in 706ms
10-29 16:11:33.180 D/dalvikvm( 1299): GC freed 35 objects / 1216 bytes
in 746ms
10-29 16:11:33.230 D/dalvikvm( 1208): GC freed 11498 objects / 827320
bytes in 689ms

which vastly increases the bootup time of the application.

I suppose I'll add some backtraces to the "GC freed" area and see what
is invoking all of these when I get time.

Thanks for the information.

(Sorry for the delayed response)

[fadden]

On Oct 29, 2:39 pm, bnovc <m.bn...@gmail.com> wrote:
> Here is a slightly different example, where multiple processes are
> being GCed when one starts up:
>
> 10-29 16:11:33.060 D/dalvikvm( 1502): GC freed 50 objects / 1864 bytes
> in 590ms
> 10-29 16:11:33.080 D/dalvikvm( 1824): GC freed 1014 objects / 85152
> bytes in 697ms

[...]

There is some code in system_server that causes periodic GCs of apps
-- has to do with management of objects whose lifetime depends on
objects in other processes -- but it's usually pretty good about
distributing the GCs over time. Having 9 different processes GC all
at once is unexpected. The number and size of objects collected
reinforces the idea that this was an explicit GC rather than one
forced by allocations.

> I suppose I'll add some backtraces to the "GC freed" area and see what
> is invoking all of these when I get time.

If you're tinkering with stuff in the sources, a stack trace from
Runtime.gc() might be easier to manage. If you can make this happen
reliably, connect a debugger to one of the background apps and set a
breakpoint there. That way you don't have to fiddle with the sources
at all.