Hotspot-gc-dev

Popular Threads From Hotspot-gc-dev:

What influences young generation pause times?

Request for review: 6941923: RFE: Handling large log files produced by long running Java Applications

Heap OOM for no apparent reason?

G1GC Full GCs

Hg: jdk7/hotspot-gc/hotspot: 2 new changesets

List Statistics

Total Threads: 1110
Total Posts: 987

Phrases Used to Find This Thread

Page 1 of 1

20-04-2010 02:20 PM

Hotspot-gc-dev member admin is online now

User

20-04-2010 03:04 PM

Hotspot-gc-dev member admin is online now

User

20-04-2010 05:04 PM

Hotspot-gc-dev member admin is online now

User

20-04-2010 06:27 PM

Hotspot-gc-dev member admin is online now

User

20-04-2010 06:51 PM

Hotspot-gc-dev member admin is online now

User

20-04-2010 07:00 PM

Hotspot-gc-dev member admin is online now

User

20-04-2010 07:11 PM

Hotspot-gc-dev member admin is online now

User

20-04-2010 09:10 PM

Hotspot-gc-dev member admin is online now

User

20-04-2010 09:30 PM

Hotspot-gc-dev member admin is online now

User

#10

20-04-2010 09:39 PM

Hotspot-gc-dev member admin is online now

User

#11

20-04-2010 09:56 PM

Hotspot-gc-dev member admin is online now

User

#12

20-04-2010 10:14 PM

Hotspot-gc-dev member admin is online now

User

#13

20-04-2010 10:53 PM

Hotspot-gc-dev member admin is online now

User

#14

20-04-2010 11:37 PM

Hotspot-gc-dev member admin is online now

User

Hi

My understanding is that young gen pause times are related to the size of
the set of live objects but what does this really mean? for example does
it mean number of objects in the live set? total size [of them]?

and what other factors influence the young gen pause time?

Cheers
Matt

Matt Khan
--------------------------------------------------
___________________________________________________

Posted on the Hotspot-gc-dev mailing list. Go to http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-dev to subscribe. Matt,

For most applications, object copying is the predominant cost during
young GCs. Basically, the more objects survive the collection and need
to be copied, the higher the young GC times will be. Young GCs do not
touch the dead objects in the young generation so the number of overall
objects in the young generation will not really affect pause times, just
the number of live ones.

There are other costs during young GCs, like scanning the application
thread stacks, scanning the card table to find old-to-young references,
etc. However, typically, those costs are very small compared to copying
the live objects.

Hope this helps,

Tony

Matt Khan wrote:
>
> Hi
>
> My understanding is that young gen pause times are related to the size
> of the set of live objects but what does this really mean? for example
> does it mean number of objects in the live set? total size [of them]?
>
> and what other factors influence the young gen pause time?
>
> Cheers
> Matt
>
> Matt Khan
> --------------------------------------------------
___________________________________________________

Posted on the Hotspot-gc-dev mailing list. Go to http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-dev to subscribe. Hi Tony

>> Basically, the more objects survive the collection and need to be
copied, the higher the young GC times will be.
so when does a concurrent collector enter a STW pause?

for example if I look at figure 6, p10 in the memory management white
paper (http://java.sun.com/products/hotspot/whitepaper.html) then that
makes it look like there is a single STW pause per young collection that
is made shorter because there are n threads doing the work. Is that an
accurate depiction of when it pauses or just a convenient visualisation?

My reason for asking is that my app doesn't exhibit this single pause per
young collection, instead I see a succession of short pauses between GC
logs (example below) & I'd like to understand what causes those pauses.
This app is using CMS (params used below) but there is no CMS activity
reported at this time because v little enters the tenured generation and
hence there is no collection required.

Total time for which application threads were stopped: 0.0051359 seconds
Application time: 99.9576332 seconds
2010-04-13T19:14:53.185+0000: 368542.855: [GC 368542.855: [ParNew
Desired survivor size 14450688 bytes, new threshold 1 (max 1)
- age 1: 3377144 bytes, 3377144 total
: 2986668K->4491K(2998976K), 0.0254753 secs] 3076724K->94963K(3130048K)
icms_dc=0 , 0.0259072 secs] [Time
s: user=0.25 sys=0.01, real=0.03 secs]
Total time for which application threads were stopped: 0.0330759 seconds
Application time: 190.7387185 seconds
Total time for which application threads were stopped: 0.0060798 seconds
Application time: 9.2698867 seconds
Total time for which application threads were stopped: 0.0051861 seconds
Application time: 290.7195886 seconds
Total time for which application threads were stopped: 0.0065455 seconds
Application time: 9.2792321 seconds
Total time for which application threads were stopped: 0.0051541 seconds
Application time: 290.7292153 seconds
Total time for which application threads were stopped: 0.0063071 seconds
Application time: 9.2696694 seconds
Total time for which application threads were stopped: 0.0052036 seconds
Application time: 290.7093779 seconds
Total time for which application threads were stopped: 0.0065365 seconds
Application time: 9.2793591 seconds
Total time for which application threads were stopped: 0.0051265 seconds
Application time: 290.7301471 seconds
Total time for which application threads were stopped: 0.0070431 seconds
Application time: 9.2694376 seconds
Total time for which application threads were stopped: 0.0051428 seconds
Application time: 119.4074368 seconds
Total time for which application threads were stopped: 0.0059739 seconds
Application time: 39.8647697 seconds
2010-04-13T19:40:52.550+0000: 370102.218: [GC 370102.219: [ParNew
Desired survivor size 14450688 bytes, new threshold 1 (max 1)
- age 1: 2911824 bytes, 2911824 total

-Xms3072m
-Xmx3072m
-Xmn2944m
-XX:+DisableExplicitGC
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-XX:+PrintGCApplicationStoppedTime
-XX:+PrintGCApplicationConcurrentTime
-XX:MaxTenuringThreshold=1
-XX:SurvivorRatio=190
-XX:TargetSurvivorRatio=90
-XX:+UseConcMarkSweepGC
-XX:+UseParNewGC

Cheers
Matt

Matt Khan
--------------------------------------------------
___________________________________________________

Posted on the Hotspot-gc-dev mailing list. Go to http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-dev to subscribe. If you allow some intermission... is the young-gen collector smart enough to
avoid semispace copying in some favorable conditions? Let's say I am lucky
and when young-GC is triggered, after marking I have [LLLLLLLLLLDDDD] where
L=live objects, D=dead. it's stupid to copy the block [LLLLLLLLLL] to
another space. I'd expect the collector to have some heuristic like: look at
the top address and total size of the remaining live data, and if it is
densely populated (say >90% live space - e.g. [LLLDLLLLLLDDDD]), just finish
GC without any compaction or semispace flipping.

I would expect this scenario to happen in the real world with very small
frequency, because young-GC must be triggered at a "lucky" time, e.g. after
some application transactions commit and before any newer transaction begins
- but if the collector already accounts the live set size at the marking
phase, the cost to attempt this new optimization is virtually zero. And we
might hint the VM to make sure the optimal case doesn't depend on good luck.
The JVM could expose an API that allows an application (or a container) to
request a "lightweight GC", i.e., perform only young-GC, and only if the
young-gen is >N% full. E.g., System.fastGC(0.8) for N=80%. A JavaEE
application server could invoke this when it detects idle periods (zero
running transactions / zero background processes doing anything important);
or even after every transaction commit if the VM uses TLABs (in that case we
only collect the TLAB; the whole thing only makes sense for large enough
TLABs). For single-threaded processes (Ok, almost-single-threaded...) it's
much simpler, just call the lightweight-GC API at special places where major
activity ends and tons of allocated data are liberated, e.g. after the
render-frame step of your game loop, or after importing each file in your
batch ETL program, etc.

A+
Osvaldo

2010/4/20 Matt Khan <>

> Hi Tony
>
> >> Basically, the more objects survive the collection and need to be
> copied, the higher the young GC times will be.
> so when does a concurrent collector enter a STW pause?
>
> for example if I look at figure 6, p10 in the memory management white
> paper (http://java.sun.com/products/hotspot/whitepaper.html) then that
> makes it look like there is a single STW pause per young collection that
> is made shorter because there are n threads doing the work. Is that an
> accurate depiction of when it pauses or just a convenient visualisation?
>
> My reason for asking is that my app doesn't exhibit this single pause per
> young collection, instead I see a succession of short pauses between GC
> logs (example below) & I'd like to understand what causes those pauses.
> This app is using CMS (params used below) but there is no CMS activity
> reported at this time because v little enters the tenured generation and
> hence there is no collection required.
>
> Total time for which application threads were stopped: 0.0051359 seconds
> Application time: 99.9576332 seconds
> 2010-04-13T19:14:53.185+0000: 368542.855: [GC 368542.855: [ParNew
> Desired survivor size 14450688 bytes, new threshold 1 (max 1)
> - age 1: 3377144 bytes, 3377144 total
> : 2986668K->4491K(2998976K), 0.0254753 secs] 3076724K->94963K(3130048K)
> icms_dc=0 , 0.0259072 secs] [Time
> s: user=0.25 sys=0.01, real=0.03 secs]
> Total time for which application threads were stopped: 0.0330759 seconds
> Application time: 190.7387185 seconds
> Total time for which application threads were stopped: 0.0060798 seconds
> Application time: 9.2698867 seconds
> Total time for which application threads were stopped: 0.0051861 seconds
> Application time: 290.7195886 seconds
> Total time for which application threads were stopped: 0.0065455 seconds
> Application time: 9.2792321 seconds
> Total time for which application threads were stopped: 0.0051541 seconds
> Application time: 290.7292153 seconds
> Total time for which application threads were stopped: 0.0063071 seconds
> Application time: 9.2696694 seconds
> Total time for which application threads were stopped: 0.0052036 seconds
> Application time: 290.7093779 seconds
> Total time for which application threads were stopped: 0.0065365 seconds
> Application time: 9.2793591 seconds
> Total time for which application threads were stopped: 0.0051265 seconds
> Application time: 290.7301471 seconds
> Total time for which application threads were stopped: 0.0070431 seconds
> Application time: 9.2694376 seconds
> Total time for which application threads were stopped: 0.0051428 seconds
> Application time: 119.4074368 seconds
> Total time for which application threads were stopped: 0.0059739 seconds
> Application time: 39.8647697 seconds
> 2010-04-13T19:40:52.550+0000: 370102.218: [GC 370102.219: [ParNew
> Desired survivor size 14450688 bytes, new threshold 1 (max 1)
> - age 1: 2911824 bytes, 2911824 total
>
> -Xms3072m
> -Xmx3072m
> -Xmn2944m
> -XX:+DisableExplicitGC
> -XX:+PrintGCDetails
> -XX:+PrintGCDateStamps
> -XX:+PrintGCApplicationStoppedTime
> -XX:+PrintGCApplicationConcurrentTime
> -XX:MaxTenuringThreshold=1
> -XX:SurvivorRatio=190
> -XX:TargetSurvivorRatio=90
> -XX:+UseConcMarkSweepGC
> -XX:+UseParNewGC
>
> Cheers
> Matt
>
> Matt Khan
> --------------------------------------------------
___________________________________________________

Posted on the Hotspot-gc-dev mailing list. Go to http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-dev to subscribe. Matt,

The pauses that you see seem to be non-GC safepoints. Maybe they are
biased lock revocation safepoints. If the log doesn't show a [GC...]
line at a safepoint, then there is not GC activity during it (at least I
can't think of an occasion when this would be the case).

Tony

Matt Khan wrote:
> Hi Tony
>
>
>>> Basically, the more objects survive the collection and need to be
>>>
> copied, the higher the young GC times will be.
> so when does a concurrent collector enter a STW pause?
>
> for example if I look at figure 6, p10 in the memory management white
> paper (http://java.sun.com/products/hotspot/whitepaper.html) then that
> makes it look like there is a single STW pause per young collection that
> is made shorter because there are n threads doing the work. Is that an
> accurate depiction of when it pauses or just a convenient visualisation?
>
> My reason for asking is that my app doesn't exhibit this single pause per
> young collection, instead I see a succession of short pauses between GC
> logs (example below) & I'd like to understand what causes those pauses.
> This app is using CMS (params used below) but there is no CMS activity
> reported at this time because v little enters the tenured generation and
> hence there is no collection required.
>
> Total time for which application threads were stopped: 0.0051359 seconds
> Application time: 99.9576332 seconds
> 2010-04-13T19:14:53.185+0000: 368542.855: [GC 368542.855: [ParNew
> Desired survivor size 14450688 bytes, new threshold 1 (max 1)
> - age 1: 3377144 bytes, 3377144 total
> : 2986668K->4491K(2998976K), 0.0254753 secs] 3076724K->94963K(3130048K)
> icms_dc=0 , 0.0259072 secs] [Time
> s: user=0.25 sys=0.01, real=0.03 secs]
> Total time for which application threads were stopped: 0.0330759 seconds
> Application time: 190.7387185 seconds
> Total time for which application threads were stopped: 0.0060798 seconds
> Application time: 9.2698867 seconds
> Total time for which application threads were stopped: 0.0051861 seconds
> Application time: 290.7195886 seconds
> Total time for which application threads were stopped: 0.0065455 seconds
> Application time: 9.2792321 seconds
> Total time for which application threads were stopped: 0.0051541 seconds
> Application time: 290.7292153 seconds
> Total time for which application threads were stopped: 0.0063071 seconds
> Application time: 9.2696694 seconds
> Total time for which application threads were stopped: 0.0052036 seconds
> Application time: 290.7093779 seconds
> Total time for which application threads were stopped: 0.0065365 seconds
> Application time: 9.2793591 seconds
> Total time for which application threads were stopped: 0.0051265 seconds
> Application time: 290.7301471 seconds
> Total time for which application threads were stopped: 0.0070431 seconds
> Application time: 9.2694376 seconds
> Total time for which application threads were stopped: 0.0051428 seconds
> Application time: 119.4074368 seconds
> Total time for which application threads were stopped: 0.0059739 seconds
> Application time: 39.8647697 seconds
> 2010-04-13T19:40:52.550+0000: 370102.218: [GC 370102.219: [ParNew
> Desired survivor size 14450688 bytes, new threshold 1 (max 1)
> - age 1: 2911824 bytes, 2911824 total
>
> -Xms3072m
> -Xmx3072m
> -Xmn2944m
> -XX:+DisableExplicitGC
> -XX:+PrintGCDetails
> -XX:+PrintGCDateStamps
> -XX:+PrintGCApplicationStoppedTime
> -XX:+PrintGCApplicationConcurrentTime
> -XX:MaxTenuringThreshold=1
> -XX:SurvivorRatio=190
> -XX:TargetSurvivorRatio=90
> -XX:+UseConcMarkSweepGC
> -XX:+UseParNewGC
>
> Cheers
> Matt
>
> Matt Khan
> --------------------------------------------------
___________________________________________________

Posted on the Hotspot-gc-dev mailing list. Go to http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-dev to subscribe. You could use -XX:+PrintSafepointStatistics etc. to figure these out.

-- ramki

On 04/20/10 10:51, Tony Printezis wrote:
> Matt,
>
> The pauses that you see seem to be non-GC safepoints. Maybe they are
> biased lock revocation safepoints. If the log doesn't show a [GC...]
> line at a safepoint, then there is not GC activity during it (at least I
> can't think of an occasion when this would be the case).
>
> Tony
>
> Matt Khan wrote:
>> Hi Tony
>>
>>
>>>> Basically, the more objects survive the collection and need to be
>>>>
>> copied, the higher the young GC times will be.
>> so when does a concurrent collector enter a STW pause?
>>
>> for example if I look at figure 6, p10 in the memory management white
>> paper (http://java.sun.com/products/hotspot/whitepaper.html) then that
>> makes it look like there is a single STW pause per young collection that
>> is made shorter because there are n threads doing the work. Is that an
>> accurate depiction of when it pauses or just a convenient visualisation?
>>
>> My reason for asking is that my app doesn't exhibit this single pause per
>> young collection, instead I see a succession of short pauses between GC
>> logs (example below) & I'd like to understand what causes those pauses.
>> This app is using CMS (params used below) but there is no CMS activity
>> reported at this time because v little enters the tenured generation and
>> hence there is no collection required.
>>
>> Total time for which application threads were stopped: 0.0051359 seconds
>> Application time: 99.9576332 seconds
>> 2010-04-13T19:14:53.185+0000: 368542.855: [GC 368542.855: [ParNew
>> Desired survivor size 14450688 bytes, new threshold 1 (max 1)
>> - age 1: 3377144 bytes, 3377144 total
>> : 2986668K->4491K(2998976K), 0.0254753 secs] 3076724K->94963K(3130048K)
>> icms_dc=0 , 0.0259072 secs] [Time
>> s: user=0.25 sys=0.01, real=0.03 secs]
>> Total time for which application threads were stopped: 0.0330759 seconds
>> Application time: 190.7387185 seconds
>> Total time for which application threads were stopped: 0.0060798 seconds
>> Application time: 9.2698867 seconds
>> Total time for which application threads were stopped: 0.0051861 seconds
>> Application time: 290.7195886 seconds
>> Total time for which application threads were stopped: 0.0065455 seconds
>> Application time: 9.2792321 seconds
>> Total time for which application threads were stopped: 0.0051541 seconds
>> Application time: 290.7292153 seconds
>> Total time for which application threads were stopped: 0.0063071 seconds
>> Application time: 9.2696694 seconds
>> Total time for which application threads were stopped: 0.0052036 seconds
>> Application time: 290.7093779 seconds
>> Total time for which application threads were stopped: 0.0065365 seconds
>> Application time: 9.2793591 seconds
>> Total time for which application threads were stopped: 0.0051265 seconds
>> Application time: 290.7301471 seconds
>> Total time for which application threads were stopped: 0.0070431 seconds
>> Application time: 9.2694376 seconds
>> Total time for which application threads were stopped: 0.0051428 seconds
>> Application time: 119.4074368 seconds
>> Total time for which application threads were stopped: 0.0059739 seconds
>> Application time: 39.8647697 seconds
>> 2010-04-13T19:40:52.550+0000: 370102.218: [GC 370102.219: [ParNew
>> Desired survivor size 14450688 bytes, new threshold 1 (max 1)
>> - age 1: 2911824 bytes, 2911824 total
>>
>> -Xms3072m
>> -Xmx3072m
>> -Xmn2944m
>> -XX:+DisableExplicitGC
>> -XX:+PrintGCDetails
>> -XX:+PrintGCDateStamps
>> -XX:+PrintGCApplicationStoppedTime
>> -XX:+PrintGCApplicationConcurrentTime
>> -XX:MaxTenuringThreshold=1
>> -XX:SurvivorRatio=190
>> -XX:TargetSurvivorRatio=90
>> -XX:+UseConcMarkSweepGC
>> -XX:+UseParNewGC
>>
>> Cheers
>> Matt
>>
>> Matt Khan
>> --------------------------------------------------
___________________________________________________

Posted on the Hotspot-gc-dev mailing list. Go to http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-dev to subscribe. Osvaldo,

You misunderstand how a copying GC (which is the algorithm our young gen
GCs implement) works. It does not first mark the live objects, and then
copies them. Instead, it copies the objects as it comes across them
(i.e., at the same time it discovers they are live). So, there is no
opportunity to find big blocks of live objects and not copy them. The
end of the GC would be the only time you would be able to do that but,
by then, you've already copied all the objects anyway.

Regarding calling young GCs explicitly from an application: I can see
how, in the case of single-threaded applications, the application might
know "We are between transactions and, maybe, we have lots of garbage
and not much live in the young gen. So let's do a young GC to clean up
the young gen at maybe low overhead since we'll copy very little."
However, how will this work in the case of multi-threaded applications,
which are the vast majority of applications we see from our customers? A
thread might be between transactions, but what about the other 50, 300,
or even 2,000 threads? If a particular time is good to do a young GC for
a particular thread, it does not mean that it's also good for the rest.
Additionally, I would be willing to bet money that if we provided such
an API, library writers will abuse it thinking that "hey, the end of
this library call will be a great time to do a young GC!", without
taking into consideration that many other threads could be doing
something totally different at the same time (we've seen way too many
libraries that call System.gc() already...).

My two cents,

Tony

Osvaldo Doederlein wrote:
> If you allow some intermission... is the young-gen collector smart
> enough to avoid semispace copying in some favorable conditions? Let's
> say I am lucky and when young-GC is triggered, after marking I have
> [LLLLLLLLLLDDDD] where L=live objects, D=dead. it's stupid to copy the
> block [LLLLLLLLLL] to another space. I'd expect the collector to have
> some heuristic like: look at the top address and total size of the
> remaining live data, and if it is densely populated (say >90% live
> space - e.g. [LLLDLLLLLLDDDD]), just finish GC without any compaction
> or semispace flipping.
>
> I would expect this scenario to happen in the real world with very
> small frequency, because young-GC must be triggered at a "lucky" time,
> e.g. after some application transactions commit and before any newer
> transaction begins - but if the collector already accounts the live
> set size at the marking phase, the cost to attempt this new
> optimization is virtually zero. And we might hint the VM to make sure
> the optimal case doesn't depend on good luck. The JVM could expose an
> API that allows an application (or a container) to request a
> "lightweight GC", i.e., perform only young-GC, and only if the
> young-gen is >N% full. E.g., System.fastGC(0.8) for N=80%. A JavaEE
> application server could invoke this when it detects idle periods
> (zero running transactions / zero background processes doing anything
> important); or even after every transaction commit if the VM uses
> TLABs (in that case we only collect the TLAB; the whole thing only
> makes sense for large enough TLABs). For single-threaded processes
> (Ok, almost-single-threaded...) it's much simpler, just call the
> lightweight-GC API at special places where major activity ends and
> tons of allocated data are liberated, e.g. after the render-frame step
> of your game loop, or after importing each file in your batch ETL
> program, etc.
>
> A+
> Osvaldo
>
> 2010/4/20 Matt Khan < >
>
> Hi Tony
>
> >> Basically, the more objects survive the collection and need to be
> copied, the higher the young GC times will be.
> so when does a concurrent collector enter a STW pause?
>
> for example if I look at figure 6, p10 in the memory management white
> paper (http://java.sun.com/products/hotspot/whitepaper.html) then that
> makes it look like there is a single STW pause per young
> collection that
> is made shorter because there are n threads doing the work. Is that an
> accurate depiction of when it pauses or just a convenient
> visualisation?
>
> My reason for asking is that my app doesn't exhibit this single
> pause per
> young collection, instead I see a succession of short pauses
> between GC
> logs (example below) & I'd like to understand what causes those
> pauses.
> This app is using CMS (params used below) but there is no CMS activity
> reported at this time because v little enters the tenured
> generation and
> hence there is no collection required.
>
> Total time for which application threads were stopped: 0.0051359
> seconds
> Application time: 99.9576332 seconds
> 2010-04-13T19:14:53.185+0000: 368542.855: [GC 368542.855: [ParNew
> Desired survivor size 14450688 bytes, new threshold 1 (max 1)
> - age 1: 3377144 bytes, 3377144 total
> : 2986668K->4491K(2998976K), 0.0254753 secs]
> 3076724K->94963K(3130048K)
> icms_dc=0 , 0.0259072 secs] [Time
> s: user=0.25 sys=0.01, real=0.03 secs]
> Total time for which application threads were stopped: 0.0330759
> seconds
> Application time: 190.7387185 seconds
> Total time for which application threads were stopped: 0.0060798
> seconds
> Application time: 9.2698867 seconds
> Total time for which application threads were stopped: 0.0051861
> seconds
> Application time: 290.7195886 seconds
> Total time for which application threads were stopped: 0.0065455
> seconds
> Application time: 9.2792321 seconds
> Total time for which application threads were stopped: 0.0051541
> seconds
> Application time: 290.7292153 seconds
> Total time for which application threads were stopped: 0.0063071
> seconds
> Application time: 9.2696694 seconds
> Total time for which application threads were stopped: 0.0052036
> seconds
> Application time: 290.7093779 seconds
> Total time for which application threads were stopped: 0.0065365
> seconds
> Application time: 9.2793591 seconds
> Total time for which application threads were stopped: 0.0051265
> seconds
> Application time: 290.7301471 seconds
> Total time for which application threads were stopped: 0.0070431
> seconds
> Application time: 9.2694376 seconds
> Total time for which application threads were stopped: 0.0051428
> seconds
> Application time: 119.4074368 seconds
> Total time for which application threads were stopped: 0.0059739
> seconds
> Application time: 39.8647697 seconds
> 2010-04-13T19:40:52.550+0000: 370102.218: [GC 370102.219: [ParNew
> Desired survivor size 14450688 bytes, new threshold 1 (max 1)
> - age 1: 2911824 bytes, 2911824 total
>
> -Xms3072m
> -Xmx3072m
> -Xmn2944m
> -XX:+DisableExplicitGC
> -XX:+PrintGCDetails
> -XX:+PrintGCDateStamps
> -XX:+PrintGCApplicationStoppedTime
> -XX:+PrintGCApplicationConcurrentTime
> -XX:MaxTenuringThreshold=1
> -XX:SurvivorRatio=190
> -XX:TargetSurvivorRatio=90
> -XX:+UseConcMarkSweepGC
> -XX:+UseParNewGC
>
> Cheers
> Matt
>
> Matt Khan
> --------------------------------------------------
___________________________________________________

Posted on the Hotspot-gc-dev mailing list. Go to http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-dev to subscribe. Hi Tony,

Osvaldo,
>
> You misunderstand how a copying GC (which is the algorithm our young gen
> GCs implement) works. It does not first mark the live objects, and then
> copies them. Instead, it copies the objects as it comes across them (i.e.,
> at the same time it discovers they are live). So, there is no opportunity to
> find big blocks of live objects and not copy them. The end of the GC would
> be the only time you would be able to do that but, by then, you've already
> copied all the objects anyway.
>

That's right, but (as my thinking went) just one possible implementation -
but I failed to notice that an ideal solution would require combining both
algorithms in some way that is not possible without a hit for the non-lucky
case of needing to copy.

> Regarding calling young GCs explicitly from an application: I can see how,
> in the case of single-threaded applications, the application might know "We
> are between transactions and, maybe, we have lots of garbage and not much
> live in the young gen. So let's do a young GC to clean up the young gen at
> maybe low overhead since we'll copy very little." However, how will this
> work in the case of multi-threaded applications, which are the vast majority
> of applications we see from our customers? A thread might be between
> transactions, but what about the other 50, 300, or even 2,000 threads? If a
> particular time is good to do a young GC

Not all multithreaded apps are heavily multithreaded; for each mammoth
website with 2000 concurrent transactions, you'll find a thousand corporate
apps with peaks of 5 concurrent transactions and very frequent full-idle
periods. Well, admittedly for these apps, cutting the cost of young-GCs
copying is irrelevant; it's the former, larger apps that need it. I guess at
least my speculation about (big) TLAB collection is valid? And what about
the large number of non-EE apps - remarkably media-heavy / RIA / games,
which are typically "almost-single-threaded" = event dispatch thread plus
two or three application threads, typically tightly controlled (so it's
trivial and cheap to force all these threads to stop in a barrier when you
want to clean up). These apps are often very sensitive to latency: a
stop-the-world 50ms pause at the wrong time are sufficient to result in
visible or audible stuttering.

[Java GC should not care only for the Enterprise side. If you peek into some
dev communities - e.g. javagaming.org - people are always whining about
insufficient control over GC behavior. What we want is something like RTSJ's
scoped heaps - you "enter" some execution phase, allocate lots of Young
objects, then you "leave" this phase and request GC that will be basically
free - but of course, we need something that works in the JavaSE and JavaME
platforms, without the complexities and mutator costs of RTSJ.]

> for a particular thread, it does not mean that it's also good for the rest.
> Additionally, I would be willing to bet money that if we provided such an
> API, library writers will abuse it thinking that "hey, the end of this
> library call will be a great time to do a young GC!", without taking into
> consideration that many other threads could be doing something totally
> different at the same time (we've seen way too many libraries that call
> System.gc() already...).
>

This is true, but I guess the problem could be handled by the Security
manager and/or VM options, maybe allowing only certain packages to induce GC
in any way. There is precedent for that (-XX:+DisableExplicitGC, and default
configuration of app servers to use that option). The problem exisits but
it's not new in any "lightweight GC API" proposal - even to current date I
sometimes find some app code that invokes Good Old System.gc(). Please let's
not use the "developers will shoot themselves in the foot" argument, to not
provide a solution for a very painful problem. :)

A+
Osvaldo

>
> My two cents,
>
> Tony
>
> Osvaldo Doederlein wrote:
>
>> If you allow some intermission... is the young-gen collector smart enough
>> to avoid semispace copying in some favorable conditions? Let's say I am
>> lucky and when young-GC is triggered, after marking I have [LLLLLLLLLLDDDD]
>> where L=live objects, D=dead. it's stupid to copy the block [LLLLLLLLLL] to
>> another space. I'd expect the collector to have some heuristic like: look at
>> the top address and total size of the remaining live data, and if it is
>> densely populated (say >90% live space - e.g. [LLLDLLLLLLDDDD]), just finish
>> GC without any compaction or semispace flipping.
>>
>> I would expect this scenario to happen in the real world with very small
>> frequency, because young-GC must be triggered at a "lucky" time, e.g. after
>> some application transactions commit and before any newer transaction begins
>> - but if the collector already accounts the live set size at the marking
>> phase, the cost to attempt this new optimization is virtually zero. And we
>> might hint the VM to make sure the optimal case doesn't depend on good luck.
>> The JVM could expose an API that allows an application (or a container) to
>> request a "lightweight GC", i.e., perform only young-GC, and only if the
>> young-gen is >N% full. E.g., System.fastGC(0.8) for N=80%. A JavaEE
>> application server could invoke this when it detects idle periods (zero
>> running transactions / zero background processes doing anything important);
>> or even after every transaction commit if the VM uses TLABs (in that case we
>> only collect the TLAB; the whole thing only makes sense for large enough
>> TLABs). For single-threaded processes (Ok, almost-single-threaded...) it's
>> much simpler, just call the lightweight-GC API at special places where major
>> activity ends and tons of allocated data are liberated, e.g. after the
>> render-frame step of your game loop, or after importing each file in your
>> batch ETL program, etc.
>>
>> A+
>> Osvaldo
>>
>> 2010/4/20 Matt Khan < >
>>
>>
>> Hi Tony
>>
>> >> Basically, the more objects survive the collection and need to be
>> copied, the higher the young GC times will be.
>> so when does a concurrent collector enter a STW pause?
>>
>> for example if I look at figure 6, p10 in the memory management white
>> paper (http://java.sun.com/products/hotspot/whitepaper.html) then that
>> makes it look like there is a single STW pause per young
>> collection that
>> is made shorter because there are n threads doing the work. Is that an
>> accurate depiction of when it pauses or just a convenient
>> visualisation?
>>
>> My reason for asking is that my app doesn't exhibit this single
>> pause per
>> young collection, instead I see a succession of short pauses
>> between GC
>> logs (example below) & I'd like to understand what causes those
>> pauses.
>> This app is using CMS (params used below) but there is no CMS activity
>> reported at this time because v little enters the tenured
>> generation and
>> hence there is no collection required.
>>
>> Total time for which application threads were stopped: 0.0051359
>> seconds
>> Application time: 99.9576332 seconds
>> 2010-04-13T19:14:53.185+0000: 368542.855: [GC 368542.855: [ParNew
>> Desired survivor size 14450688 bytes, new threshold 1 (max 1)
>> - age 1: 3377144 bytes, 3377144 total
>> : 2986668K->4491K(2998976K), 0.0254753 secs]
>> 3076724K->94963K(3130048K)
>> icms_dc=0 , 0.0259072 secs] [Time
>> s: user=0.25 sys=0.01, real=0.03 secs]
>> Total time for which application threads were stopped: 0.0330759
>> seconds
>> Application time: 190.7387185 seconds
>> Total time for which application threads were stopped: 0.0060798
>> seconds
>> Application time: 9.2698867 seconds
>> Total time for which application threads were stopped: 0.0051861
>> seconds
>> Application time: 290.7195886 seconds
>> Total time for which application threads were stopped: 0.0065455
>> seconds
>> Application time: 9.2792321 seconds
>> Total time for which application threads were stopped: 0.0051541
>> seconds
>> Application time: 290.7292153 seconds
>> Total time for which application threads were stopped: 0.0063071
>> seconds
>> Application time: 9.2696694 seconds
>> Total time for which application threads were stopped: 0.0052036
>> seconds
>> Application time: 290.7093779 seconds
>> Total time for which application threads were stopped: 0.0065365
>> seconds
>> Application time: 9.2793591 seconds
>> Total time for which application threads were stopped: 0.0051265
>> seconds
>> Application time: 290.7301471 seconds
>> Total time for which application threads were stopped: 0.0070431
>> seconds
>> Application time: 9.2694376 seconds
>> Total time for which application threads were stopped: 0.0051428
>> seconds
>> Application time: 119.4074368 seconds
>> Total time for which application threads were stopped: 0.0059739
>> seconds
>> Application time: 39.8647697 seconds
>> 2010-04-13T19:40:52.550+0000: 370102.218: [GC 370102.219: [ParNew
>> Desired survivor size 14450688 bytes, new threshold 1 (max 1)
>> - age 1: 2911824 bytes, 2911824 total
>>
>> -Xms3072m
>> -Xmx3072m
>> -Xmn2944m
>> -XX:+DisableExplicitGC
>> -XX:+PrintGCDetails
>> -XX:+PrintGCDateStamps
>> -XX:+PrintGCApplicationStoppedTime
>> -XX:+PrintGCApplicationConcurrentTime
>> -XX:MaxTenuringThreshold=1
>> -XX:SurvivorRatio=190
>> -XX:TargetSurvivorRatio=90
>> -XX:+UseConcMarkSweepGC
>> -XX:+UseParNewGC
>>
>> Cheers
>> Matt
>>
>> Matt Khan
>> --------------------------------------------------
___________________________________________________

Posted on the Hotspot-gc-dev mailing list. Go to http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-dev to subscribe. >> You might need a VM with this fix. 6782663: Data produced by
PrintGCApplicationConcurrentTime and PrintGCApplicationStoppedTime is not
accurate
OK so that's the early access for 6u21 by the looks of it. I'll repeat a
run on that JVM (and with the safepoint stats).

>> If the log doesn't show a [GC...] line at a safepoint, then there is
not GC activity during it
does this mean that the actual time stopped due to GC is the one
immediately after the GC line?

>> You could use -XX:+PrintSafepointStatistics etc. to figure these out.
which other flags should I look at?

Cheers
Matt

Matt Khan
--------------------------------------------------
___________________________________________________

Posted on the Hotspot-gc-dev mailing list. Go to http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-dev to subscribe. On 04/20/10 13:30, Matt Khan wrote:
>
> >> You might need a VM with this fix. 6782663: Data produced by
> PrintGCApplicationConcurrentTime and PrintGCApplicationStoppedTime is
> not accurate
> OK so that's the early access for 6u21 by the looks of it. I'll repeat
> a run on that JVM (and with the safepoint stats).
>
> >> If the log doesn't show a [GC...] line at a safepoint, then there
> is not GC activity during it
> does this mean that the actual time stopped due to GC is the one
> immediately after the GC line?

As you can see more than GC can contribute to a STW so the "time
stopped" might include
other times that don't log any message. The GC entries in the log
print their own times.
>
>
> >> You could use -XX:+PrintSafepointStatistics etc. to figure these out.
> which other flags should I look at?
I don't know of any others.
>
> Cheers
> Matt
>
> Matt Khan
> --------------------------------------------------
___________________________________________________

Posted on the Hotspot-gc-dev mailing list. Go to http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-dev to subscribe. On 04/20/10 13:30, Matt Khan wrote:
...
> >> You could use -XX:+PrintSafepointStatistics etc. to figure these out.
> which other flags should I look at?

product(bool, PrintSafepointStatistics, false, \
"print statistics about safepoint synchronization") \
\
product(intx, PrintSafepointStatisticsCount, 300, \
"total number of safepoint statistics collected " \
"before printing them out") \

The o/p might go to stdout, rather than to the gc log file in
case you have the one redirected and not the other.

Once you know what those safepoints are for, you can use more specific
flags to see what's happening there (for example as Tony conjectured
perhaps biased locking; or global deoptimization due to class loading etc.)

-- ramki
_______________________________________________
___________________________________________________

Posted on the Hotspot-gc-dev mailing list. Go to http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-dev to subscribe. perhaps this should be on the runtime list but since it's relevant to this
thread I'll ask here....

I'm periodically getting output like

RevokeBias [ 238 0 1]
[ 0 0 0] [ 0 7] 0

headed by one of these

Total time for wh [ 0 0 0] [ 0 14] 0

the lines are overwhelmingly RevokeBias or BulkRevokeBias

Can you explain what these values are? I'm not especially familiar with
the hotspot source code so am unsure where I'd find this info in the src
alone.

Cheers
Matt

Matt Khan
--------------------------------------------------
___________________________________________________

Posted on the Hotspot-gc-dev mailing list. Go to http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-dev to subscribe. On 04/20/2010 02:11 PM, Tony Printezis wrote:
> Additionally, I would be willing to bet money that if we provided such
> an API, library writers will abuse it thinking that "hey, the end of
> this library call will be a great time to do a young GC!", without
> taking into consideration that many other threads could be doing
> something totally different at the same time (we've seen way too many
> libraries that call System.gc() already...).

While I wasn't talking about young GC's, a couple of years ago I
submitted a proposal to to this list to add a new RuntimePermission
that would allow execution of explicit GCs [1]. Without such
permission, the System.gc() call would simply return without doing
anything. Ideally the signature would be modified to return a boolean
"true if performed", "false if not", and even more ideally, a more
comprehensive GC API could be provided.

Such an approach would allow the addition of some explicit GC control
from applications, without allowing abuse by random libraries.

While a couple of people chimed in that they too would like some
explicit GC control, the proposal was ignored.

[1] http://markmail.org/message/cpmpwoodbcmspesc

I'd at least like to hear some reasons why something like this can't
be done or isn't a good idea. I think it would be a great feature for
many people.

Cheers,
Raman
) On 04/20/10 14:14, Matt Khan wrote:
>
> perhaps this should be on the runtime list but since it's relevant to
> this thread I'll ask here....
>
> I'm periodically getting output like
>
> RevokeBias [ 238 0 1]
> [ 0 0 0] [ 0 7] 0
>
> headed by one of these
>
> Total time for wh [ 0 0 0] [ 0 14] 0
>
> the lines are overwhelmingly RevokeBias or BulkRevokeBias
>
> Can you explain what these values are? I'm not especially familiar with
> the hotspot source code so am unsure where I'd find this info in the src
> alone.

If you are asking about the columns in each record, check the header
line which should have been printed earlier. If you use a more recent
JVM (hs18) you should see the column headings printed more frequently
than the sole initial appearance in the log produced by older jvm's.

For background on biased locking and associated flags, and what
is involved in bias revocation etc, read
http://portal.acm.org/citation.cfm?doid=1167473.1167496

Experiment with -XX:-UseBiasedLocking if it's not working well for
you, or if it is interfering with your predictability
objectives (read the article for when biased locking may not work well
and how it may affect predictability), and contact your
Java support for further tuning help, questions, to report a
performance bug, etc.

all the best.
-- ramki

>
> Cheers
> Matt
>
> Matt Khan
> --------------------------------------------------
___________________________________________________

Posted on the Hotspot-gc-dev mailing list. Go to http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-dev to subscribe.

#15

21-04-2010 04:01 PM

Hotspot-gc-dev member admin is online now

User

#16

21-04-2010 07:55 PM

Hotspot-gc-dev member admin is online now

User

#17

21-04-2010 11:12 PM

Hotspot-gc-dev member admin is online now

User

#18

21-04-2010 11:36 PM

Hotspot-gc-dev member admin is online now

User

#19

21-04-2010 11:56 PM

Hotspot-gc-dev member admin is online now

User

#20

22-04-2010 12:19 AM

Hotspot-gc-dev member admin is online now

User

Page 1 of 1

NewsArc Lists | Culture Pages | Computing Archive | Media-Pages

Link to this page on your blog or website by copying the HTML code below and pasting it into your site:

Next Thread »