Grokbase › Groups › OpenJDK › hotspot-gc-dev › May 2010
FAQ
Hi all,

In build 1.6.0_17-b04-248-9M3125 I've been running into log entries that
look like this.

41.597: [GC 41.597: [ParNew (promotion failed)
Desired survivor size 1343488 bytes, new threshold 4 (max 4)
- age 1: 744120 bytes, 744120 total
- age 2: 529152 bytes, 1273272 total
- age 3: 32392 bytes, 1305664 total
: 17486K->17249K(18624K), 0.0021027 secs]41.599: [CMS41.600:
[CMS-concurrent-abortable-preclean: 0.028/0.632 secs] [Times: user=1.00
sys=0.04, real=0.63 secs]
(concurrent mode failure): 63809K->8087K(64768K), 0.0860671 secs]
81202K->8087K(83392K), [CMS Perm : 10707K->10707K(21248K)], 0.0883203 secs]
[Times: user=0.09 sys=0.00, real=0.09 secs]

Looks like ParNew is mixed with the invocation of the CMS instead of that
record being on a new line. The format is consistent but not so nice to
parse ;-)

Regards,
Kirk
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-dev/attachments/20100526/8f1663a7/attachment.html

Search Discussions

  • Jon Masamitsu at May 26, 2010 at 1:34 pm ⇧
    I think you're seeing a mix of the ParNew collection experiencing a
    promotion failure and resulting in a full collection - this part

    41.599: [CMS

    and at the same time a CMS concurrent phase starting

    41.600: [CMS-concurrent-abortable-preclean:

    Yah, we hate it too. We're not doing any piecemeal fixing
    of the logging since we're trying to overhaul the whole thing.


    On 5/26/10 12:58 PM, Kirk Pepperdine wrote:
    Hi all,

    In build 1.6.0_17-b04-248-9M3125 I've been running into log entries
    that look like this.

    41.597: [GC 41.597: [ParNew (promotion failed)
    Desired survivor size 1343488 bytes, new threshold 4 (max 4)
    - age 1: 744120 bytes, 744120 total
    - age 2: 529152 bytes, 1273272 total
    - age 3: 32392 bytes, 1305664 total
    : 17486K->17249K(18624K), 0.0021027 secs]41.599: [CMS41.600:
    [CMS-concurrent-abortable-preclean: 0.028/0.632 secs] [Times:
    user=1.00 sys=0.04, real=0.63 secs]
    (concurrent mode failure): 63809K->8087K(64768K), 0.0860671 secs]
    81202K->8087K(83392K), [CMS Perm : 10707K->10707K(21248K)], 0.0883203
    secs] [Times: user=0.09 sys=0.00, real=0.09 secs]

    Looks like ParNew is mixed with the invocation of the CMS instead of
    that record being on a new line. The format is consistent but not so
    nice to parse ;-)

    Regards,
    Kirk
  • Y. Srinivas Ramakrishna at May 26, 2010 at 1:41 pm ⇧

    Jon Masamitsu wrote:
    I think you're seeing a mix of the ParNew collection experiencing a
    promotion failure and resulting in a full collection - this part

    41.599: [CMS

    and at the same time a CMS concurrent phase starting

    41.600: [CMS-concurrent-abortable-preclean:
    That's the concurrent phase _ending_. It turns out that because
    of historical reasons, we have to _end_ an ongoing concurrent
    phase before the foreground collection can take over and
    do a full gc as done here. So, yes, each concurrent mode failure
    will likely have such a report of the "interrupted" concurrent
    phase reporting its end before the foreground compacting
    collection occures.
    Yah, we hate it too. We're not doing any piecemeal fixing
    of the logging since we're trying to overhaul the whole thing.
    Right, and as we've remarked on occasion, our approach in the
    interim is to post-process the logs so as to separate out such
    interleaving so that our existing parsers can grok the data.
    Perhaps that approach can work for Kirk too in the interim...

    -- ramki
    On 5/26/10 12:58 PM, Kirk Pepperdine wrote:
    Hi all,

    In build 1.6.0_17-b04-248-9M3125 I've been running into log entries
    that look like this.

    41.597: [GC 41.597: [ParNew (promotion failed)
    Desired survivor size 1343488 bytes, new threshold 4 (max 4)
    - age 1: 744120 bytes, 744120 total
    - age 2: 529152 bytes, 1273272 total
    - age 3: 32392 bytes, 1305664 total
    : 17486K->17249K(18624K), 0.0021027 secs]41.599: [CMS41.600:
    [CMS-concurrent-abortable-preclean: 0.028/0.632 secs] [Times:
    user=1.00 sys=0.04, real=0.63 secs]
    (concurrent mode failure): 63809K->8087K(64768K), 0.0860671 secs]
    81202K->8087K(83392K), [CMS Perm : 10707K->10707K(21248K)], 0.0883203
    secs] [Times: user=0.09 sys=0.00, real=0.09 secs]

    Looks like ParNew is mixed with the invocation of the CMS instead of
    that record being on a new line. The format is consistent but not so
    nice to parse ;-)

    Regards,
    Kirk

Related Discussions

Discussion Navigation
viewthread | post
Discussion Overview
grouphotspot-gc-dev @
categoriesopenjdk
postedMay 26, '10 at 12:58p
activeMay 26, '10 at 1:41p
posts3
users3
websiteopenjdk.java.net

3 users in discussion

Kirk Pepperdine: 1 post Jon Masamitsu: 1 post Y. Srinivas Ramakrishna: 1 post

Content

People

Support

Translate

site design / logo © 2023 Grokbase