FAQ
Dear All,

please advise any more tuning for avoiding promotion failed

VM Options:
"C:\Program Files\Java\jdk1.6.0_04\bin\java" -server -verbose:gc
-XX:+PrintGCDetails -Xloggc:gc.log -showversion -Xms4G -Xmx4G
-XX:NewSizeQ2M -XX:PermSizedM -XX:MaxPermSizedM
-XX:+CMSClassUnloadingEnabled -XX:+DisableExplicitGC -XX:+UseConcMarkSweepGC
-XX:+UseParNewGC -XX:SurvivorRatio=6 -XX:CMSInitiatingOccupancyFractionp
-XX:TargetSurvivorRatio� -XX:+HandlePromotionFailure
-Dcom.sun.management.jmxremote.portq91
-Dcom.sun.management.jmxremote.authenticateúlse
-Dcom.sun.management.jmxremote.sslúlse

GC Log:
227734.958: [GC 227734.958: [ParNew: 458751K->65536K(458752K), 0.4883967
secs] 2975829K->2611470K(4128768K), 0.4885529 secs] [Times: user=1.42
sys=0.20, real=0.48 secs]
227781.363: [GC 227781.363: [ParNew (promotion failed):
458752K->458751K(458752K), 1.1739277 secs]
227782.544: [CMS: 2566464K->903491K(3670016K), 14.2218888 secs]
3004686K->903491K(4128768K), 15.4022930 secs] [Times: user.16 sys=0.70,
real.39 secs]
227796.767: [GC [1 CMS-initial-mark: 903491K(3670016K)] 910269K(4128768K),
0.0014926 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
227796.769: [CMS-concurrent-mark-start]
227799.448: [GC 227799.449: [ParNew: 393216K->21851K(458752K), 0.0851390
secs] 1296707K->925343K(4128768K), 0.0853620 secs] [Times: user=0.86
sys=0.00, real=0.09 secs]
227799.536: [CMS-concurrent-mark: 2.670/2.767 secs] [Times: user=9.72
sys=0.03, real=2.77 secs]
227799.536: [CMS-concurrent-preclean-start]
227800.624: [GC 227800.624: [ParNew: 415067K->11565K(458752K), 0.0345770
secs] 1318559K->915056K(4128768K), 0.0347455 secs] [Times: user=0.27
sys=0.06, real=0.05 secs]
227800.684: [CMS-concurrent-preclean: 0.995/1.148 secs] [Times: user=4.38
sys=0.23, real=1.14 secs]
227800.684: [CMS-concurrent-abortable-preclean-start]
227801.270: [CMS-concurrent-abortable-preclean: 0.475/0.587 secs] [Times:
user=2.22 sys=0.09, real=0.59 secs]
227801.273: [GC[YG occupancy: 240407 K (458752 K)]227801.273: [Rescan
(parallel) , 0.0092978 secs]227801.282: [weak refs processing, 0.0002179
secs]227801.283: [class unloading, 0.0082907 secs]227801.291: [scrub symbol
& string tables, 0.0066056 secs] [1 CMS-remark: 903491K(3670016K)]
1143898K(4128768K), 0.0275619 secs] [Times: user=0.03 sys=0.00, real=0.03
secs]
227801.302: [CMS-concurrent-sweep-start]
227803.075: [CMS-concurrent-sweep: 1.773/1.773 secs] [Times: user=4.19
sys=0.03, real=1.77 secs]
227803.075: [CMS-concurrent-reset-start]
227803.103: [CMS-concurrent-reset: 0.028/0.028 secs] [Times: user=0.06
sys=0.00, real=0.03 secs]
227816.785: [GC 227816.786: [ParNew: 404776K->25694K(458752K), 0.2086003
secs] 1188297K->809215K(4128768K), 0.2087517 secs] [Times: user=1.13
sys=0.19, real=0.20 secs]

Regards,
Ken



--
View this message in context: http://www.nabble.com/promotion-failed-tp18528055p18528055.html
Sent from the OpenJDK Hotspot Garbage Collection mailing list archive at Nabble.com.

Search Discussions

  • Jon Masamitsu at Jul 18, 2008 at 8:20 am
    Ken,

    How often do your promotion failures occur?

    Jon

    Ken-- at newsgroupstats.hk wrote On 07/18/08 05:21,:
    Dear All,

    please advise any more tuning for avoiding promotion failed

    VM Options:
    "C:\Program Files\Java\jdk1.6.0_04\bin\java" -server -verbose:gc
    -XX:+PrintGCDetails -Xloggc:gc.log -showversion -Xms4G -Xmx4G
    -XX:NewSizeQ2M -XX:PermSizedM -XX:MaxPermSizedM
    -XX:+CMSClassUnloadingEnabled -XX:+DisableExplicitGC -XX:+UseConcMarkSweepGC
    -XX:+UseParNewGC -XX:SurvivorRatio=6 -XX:CMSInitiatingOccupancyFractionp
    -XX:TargetSurvivorRatio� -XX:+HandlePromotionFailure
    -Dcom.sun.management.jmxremote.portq91
    -Dcom.sun.management.jmxremote.authenticateúlse
    -Dcom.sun.management.jmxremote.sslúlse

    GC Log:
    227734.958: [GC 227734.958: [ParNew: 458751K->65536K(458752K), 0.4883967
    secs] 2975829K->2611470K(4128768K), 0.4885529 secs] [Times: user=1.42
    sys=0.20, real=0.48 secs]
    227781.363: [GC 227781.363: [ParNew (promotion failed):
    458752K->458751K(458752K), 1.1739277 secs]
    227782.544: [CMS: 2566464K->903491K(3670016K), 14.2218888 secs]
    3004686K->903491K(4128768K), 15.4022930 secs] [Times: user.16 sys=0.70,
    real.39 secs]
    227796.767: [GC [1 CMS-initial-mark: 903491K(3670016K)] 910269K(4128768K),
    0.0014926 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
    227796.769: [CMS-concurrent-mark-start]
    227799.448: [GC 227799.449: [ParNew: 393216K->21851K(458752K), 0.0851390
    secs] 1296707K->925343K(4128768K), 0.0853620 secs] [Times: user=0.86
    sys=0.00, real=0.09 secs]
    227799.536: [CMS-concurrent-mark: 2.670/2.767 secs] [Times: user=9.72
    sys=0.03, real=2.77 secs]
    227799.536: [CMS-concurrent-preclean-start]
    227800.624: [GC 227800.624: [ParNew: 415067K->11565K(458752K), 0.0345770
    secs] 1318559K->915056K(4128768K), 0.0347455 secs] [Times: user=0.27
    sys=0.06, real=0.05 secs]
    227800.684: [CMS-concurrent-preclean: 0.995/1.148 secs] [Times: user=4.38
    sys=0.23, real=1.14 secs]
    227800.684: [CMS-concurrent-abortable-preclean-start]
    227801.270: [CMS-concurrent-abortable-preclean: 0.475/0.587 secs] [Times:
    user=2.22 sys=0.09, real=0.59 secs]
    227801.273: [GC[YG occupancy: 240407 K (458752 K)]227801.273: [Rescan
    (parallel) , 0.0092978 secs]227801.282: [weak refs processing, 0.0002179
    secs]227801.283: [class unloading, 0.0082907 secs]227801.291: [scrub symbol
    & string tables, 0.0066056 secs] [1 CMS-remark: 903491K(3670016K)]
    1143898K(4128768K), 0.0275619 secs] [Times: user=0.03 sys=0.00, real=0.03
    secs]
    227801.302: [CMS-concurrent-sweep-start]
    227803.075: [CMS-concurrent-sweep: 1.773/1.773 secs] [Times: user=4.19
    sys=0.03, real=1.77 secs]
    227803.075: [CMS-concurrent-reset-start]
    227803.103: [CMS-concurrent-reset: 0.028/0.028 secs] [Times: user=0.06
    sys=0.00, real=0.03 secs]
    227816.785: [GC 227816.786: [ParNew: 404776K->25694K(458752K), 0.2086003
    secs] 1188297K->809215K(4128768K), 0.2087517 secs] [Times: user=1.13
    sys=0.19, real=0.20 secs]

    Regards,
    Ken



  • Ken-- at Jul 18, 2008 at 9:43 am
    Hi Jon,

    uptime is 346136 (96 hours)

    first Big GC occur at 227781 second (63th hour)

    2nd Big GC occur at 311815 second (86th hour)

    Total count of promotion failed = 2

    Regards,
    Ken



    Jon Masamitsu wrote:
    Ken,

    How often do your promotion failures occur?

    Jon

    Ken-- at newsgroupstats.hk wrote On 07/18/08 05:21,:
    Dear All,

    please advise any more tuning for avoiding promotion failed

    VM Options:
    "C:\Program Files\Java\jdk1.6.0_04\bin\java" -server -verbose:gc
    -XX:+PrintGCDetails -Xloggc:gc.log -showversion -Xms4G -Xmx4G
    -XX:NewSizeQ2M -XX:PermSizedM -XX:MaxPermSizedM
    -XX:+CMSClassUnloadingEnabled -XX:+DisableExplicitGC
    -XX:+UseConcMarkSweepGC
    -XX:+UseParNewGC -XX:SurvivorRatio=6 -XX:CMSInitiatingOccupancyFractionp
    -XX:TargetSurvivorRatio� -XX:+HandlePromotionFailure
    -Dcom.sun.management.jmxremote.portq91
    -Dcom.sun.management.jmxremote.authenticateúlse
    -Dcom.sun.management.jmxremote.sslúlse

    GC Log:
    227734.958: [GC 227734.958: [ParNew: 458751K->65536K(458752K), 0.4883967
    secs] 2975829K->2611470K(4128768K), 0.4885529 secs] [Times: user=1.42
    sys=0.20, real=0.48 secs]
    227781.363: [GC 227781.363: [ParNew (promotion failed):
    458752K->458751K(458752K), 1.1739277 secs]
    227782.544: [CMS: 2566464K->903491K(3670016K), 14.2218888 secs]
    3004686K->903491K(4128768K), 15.4022930 secs] [Times: user.16 sys=0.70,
    real.39 secs]
    227796.767: [GC [1 CMS-initial-mark: 903491K(3670016K)] 910269K(4128768K),
    0.0014926 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
    227796.769: [CMS-concurrent-mark-start]
    227799.448: [GC 227799.449: [ParNew: 393216K->21851K(458752K), 0.0851390
    secs] 1296707K->925343K(4128768K), 0.0853620 secs] [Times: user=0.86
    sys=0.00, real=0.09 secs]
    227799.536: [CMS-concurrent-mark: 2.670/2.767 secs] [Times: user=9.72
    sys=0.03, real=2.77 secs]
    227799.536: [CMS-concurrent-preclean-start]
    227800.624: [GC 227800.624: [ParNew: 415067K->11565K(458752K), 0.0345770
    secs] 1318559K->915056K(4128768K), 0.0347455 secs] [Times: user=0.27
    sys=0.06, real=0.05 secs]
    227800.684: [CMS-concurrent-preclean: 0.995/1.148 secs] [Times: user=4.38
    sys=0.23, real=1.14 secs]
    227800.684: [CMS-concurrent-abortable-preclean-start]
    227801.270: [CMS-concurrent-abortable-preclean: 0.475/0.587 secs] [Times:
    user=2.22 sys=0.09, real=0.59 secs]
    227801.273: [GC[YG occupancy: 240407 K (458752 K)]227801.273: [Rescan
    (parallel) , 0.0092978 secs]227801.282: [weak refs processing, 0.0002179
    secs]227801.283: [class unloading, 0.0082907 secs]227801.291: [scrub
    symbol
    & string tables, 0.0066056 secs] [1 CMS-remark: 903491K(3670016K)]
    1143898K(4128768K), 0.0275619 secs] [Times: user=0.03 sys=0.00, real=0.03
    secs]
    227801.302: [CMS-concurrent-sweep-start]
    227803.075: [CMS-concurrent-sweep: 1.773/1.773 secs] [Times: user=4.19
    sys=0.03, real=1.77 secs]
    227803.075: [CMS-concurrent-reset-start]
    227803.103: [CMS-concurrent-reset: 0.028/0.028 secs] [Times: user=0.06
    sys=0.00, real=0.03 secs]
    227816.785: [GC 227816.786: [ParNew: 404776K->25694K(458752K), 0.2086003
    secs] 1188297K->809215K(4128768K), 0.2087517 secs] [Times: user=1.13
    sys=0.19, real=0.20 secs]

    Regards,
    Ken



    --
    View this message in context: http://www.nabble.com/promotion-failed-tp18528055p18533303.html
    Sent from the OpenJDK Hotspot Garbage Collection mailing list archive at Nabble.com.
  • Jon Masamitsu at Jul 18, 2008 at 2:57 pm
    Ken,

    A promotion failure is often a sign that the CMS
    collection did not start soon enough. In your case
    based on the -XX:CMSInitiatingOccupancyFractionp
    flag, it looks like the CMS collection would have started
    soon and that was a little too late. There is probably a
    fair amount of fragmentation in the CMS generation
    at the point of the promotion failure since it looks like
    there is 100m free in the CMS generation and from
    the log fragment you sent, it looks like the promotion
    rate is very low.

    If most of the data in you application is short lived,
    try increasing the MaxTenuringThreshold to see
    if you can keep more of it in the young gen until it
    dies.

    A smaller CMSInitiatingOccupancyFraction will
    help as will a larger heap, but if fragmentation
    is your real problem, then those will only delay
    the promotion failure.

    If it's fragementation, take a look at

    http://blogs.sun.com/jonthecollector/entry/when_the_sum_of_the

    for some suggestions.

    Jon



    Ken-- at newsgroupstats.hk wrote On 07/18/08 09:43,:
    Hi Jon,

    uptime is 346136 (96 hours)

    first Big GC occur at 227781 second (63th hour)

    2nd Big GC occur at 311815 second (86th hour)

    Total count of promotion failed = 2

    Regards,
    Ken



    Jon Masamitsu wrote:

    Ken,

    How often do your promotion failures occur?

    Jon

    Ken-- at newsgroupstats.hk wrote On 07/18/08 05:21,:


    Dear All,

    please advise any more tuning for avoiding promotion failed

    VM Options:
    "C:\Program Files\Java\jdk1.6.0_04\bin\java" -server -verbose:gc
    -XX:+PrintGCDetails -Xloggc:gc.log -showversion -Xms4G -Xmx4G
    -XX:NewSizeQ2M -XX:PermSizedM -XX:MaxPermSizedM
    -XX:+CMSClassUnloadingEnabled -XX:+DisableExplicitGC
    -XX:+UseConcMarkSweepGC

    -XX:+UseParNewGC -XX:SurvivorRatio=6 -XX:CMSInitiatingOccupancyFractionp
    -XX:TargetSurvivorRatio� -XX:+HandlePromotionFailure
    -Dcom.sun.management.jmxremote.portq91
    -Dcom.sun.management.jmxremote.authenticateúlse
    -Dcom.sun.management.jmxremote.sslúlse

    GC Log:
    227734.958: [GC 227734.958: [ParNew: 458751K->65536K(458752K), 0.4883967
    secs] 2975829K->2611470K(4128768K), 0.4885529 secs] [Times: user=1.42
    sys=0.20, real=0.48 secs]
    227781.363: [GC 227781.363: [ParNew (promotion failed):
    458752K->458751K(458752K), 1.1739277 secs]
    227782.544: [CMS: 2566464K->903491K(3670016K), 14.2218888 secs]
    3004686K->903491K(4128768K), 15.4022930 secs] [Times: user.16 sys=0.70,
    real.39 secs]
    227796.767: [GC [1 CMS-initial-mark: 903491K(3670016K)] 910269K(4128768K),
    0.0014926 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
    227796.769: [CMS-concurrent-mark-start]
    227799.448: [GC 227799.449: [ParNew: 393216K->21851K(458752K), 0.0851390
    secs] 1296707K->925343K(4128768K), 0.0853620 secs] [Times: user=0.86
    sys=0.00, real=0.09 secs]
    227799.536: [CMS-concurrent-mark: 2.670/2.767 secs] [Times: user=9.72
    sys=0.03, real=2.77 secs]
    227799.536: [CMS-concurrent-preclean-start]
    227800.624: [GC 227800.624: [ParNew: 415067K->11565K(458752K), 0.0345770
    secs] 1318559K->915056K(4128768K), 0.0347455 secs] [Times: user=0.27
    sys=0.06, real=0.05 secs]
    227800.684: [CMS-concurrent-preclean: 0.995/1.148 secs] [Times: user=4.38
    sys=0.23, real=1.14 secs]
    227800.684: [CMS-concurrent-abortable-preclean-start]
    227801.270: [CMS-concurrent-abortable-preclean: 0.475/0.587 secs] [Times:
    user=2.22 sys=0.09, real=0.59 secs]
    227801.273: [GC[YG occupancy: 240407 K (458752 K)]227801.273: [Rescan
    (parallel) , 0.0092978 secs]227801.282: [weak refs processing, 0.0002179
    secs]227801.283: [class unloading, 0.0082907 secs]227801.291: [scrub
    symbol

    & string tables, 0.0066056 secs] [1 CMS-remark: 903491K(3670016K)]
    1143898K(4128768K), 0.0275619 secs] [Times: user=0.03 sys=0.00, real=0.03
    secs]
    227801.302: [CMS-concurrent-sweep-start]
    227803.075: [CMS-concurrent-sweep: 1.773/1.773 secs] [Times: user=4.19
    sys=0.03, real=1.77 secs]
    227803.075: [CMS-concurrent-reset-start]
    227803.103: [CMS-concurrent-reset: 0.028/0.028 secs] [Times: user=0.06
    sys=0.00, real=0.03 secs]
    227816.785: [GC 227816.786: [ParNew: 404776K->25694K(458752K), 0.2086003
    secs] 1188297K->809215K(4128768K), 0.2087517 secs] [Times: user=1.13
    sys=0.19, real=0.20 secs]

    Regards,
    Ken





  • Ken-- at Jul 18, 2008 at 5:14 pm
    Thanks for your respnose.

    My application will long live around 500M data in memory, actually that is
    preloading the whole database to memory and will daily reload the whole
    database.

    Now, My plan is:

    1) decrease the new size to 128M, it result decrease in pause time but
    increase the frequency of the pause.
    2) decrease CMSInitiatingOccupancyFraction to 50 see how dose fragmentation
    effect
    3) increase MaxTenuringThreshold

    Thanks,
    Ken



    Jon Masamitsu wrote:
    Ken,

    A promotion failure is often a sign that the CMS
    collection did not start soon enough. In your case
    based on the -XX:CMSInitiatingOccupancyFractionp
    flag, it looks like the CMS collection would have started
    soon and that was a little too late. There is probably a
    fair amount of fragmentation in the CMS generation
    at the point of the promotion failure since it looks like
    there is 100m free in the CMS generation and from
    the log fragment you sent, it looks like the promotion
    rate is very low.

    If most of the data in you application is short lived,
    try increasing the MaxTenuringThreshold to see
    if you can keep more of it in the young gen until it
    dies.

    A smaller CMSInitiatingOccupancyFraction will
    help as will a larger heap, but if fragmentation
    is your real problem, then those will only delay
    the promotion failure.

    If it's fragementation, take a look at

    http://blogs.sun.com/jonthecollector/entry/when_the_sum_of_the

    for some suggestions.

    Jon



    Ken-- at newsgroupstats.hk wrote On 07/18/08 09:43,:
    Hi Jon,

    uptime is 346136 (96 hours)

    first Big GC occur at 227781 second (63th hour)

    2nd Big GC occur at 311815 second (86th hour)

    Total count of promotion failed = 2

    Regards,
    Ken



    Jon Masamitsu wrote:

    Ken,

    How often do your promotion failures occur?

    Jon

    Ken-- at newsgroupstats.hk wrote On 07/18/08 05:21,:


    Dear All,

    please advise any more tuning for avoiding promotion failed

    VM Options:
    "C:\Program Files\Java\jdk1.6.0_04\bin\java" -server -verbose:gc
    -XX:+PrintGCDetails -Xloggc:gc.log -showversion -Xms4G -Xmx4G
    -XX:NewSizeQ2M -XX:PermSizedM -XX:MaxPermSizedM
    -XX:+CMSClassUnloadingEnabled -XX:+DisableExplicitGC
    -XX:+UseConcMarkSweepGC

    -XX:+UseParNewGC -XX:SurvivorRatio=6
    -XX:CMSInitiatingOccupancyFractionp
    -XX:TargetSurvivorRatio� -XX:+HandlePromotionFailure
    -Dcom.sun.management.jmxremote.portq91
    -Dcom.sun.management.jmxremote.authenticateúlse
    -Dcom.sun.management.jmxremote.sslúlse

    GC Log:
    227734.958: [GC 227734.958: [ParNew: 458751K->65536K(458752K), 0.4883967
    secs] 2975829K->2611470K(4128768K), 0.4885529 secs] [Times: user=1.42
    sys=0.20, real=0.48 secs]
    227781.363: [GC 227781.363: [ParNew (promotion failed):
    458752K->458751K(458752K), 1.1739277 secs]
    227782.544: [CMS: 2566464K->903491K(3670016K), 14.2218888 secs]
    3004686K->903491K(4128768K), 15.4022930 secs] [Times: user.16
    sys=0.70,
    real.39 secs]
    227796.767: [GC [1 CMS-initial-mark: 903491K(3670016K)]
    910269K(4128768K),
    0.0014926 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
    227796.769: [CMS-concurrent-mark-start]
    227799.448: [GC 227799.449: [ParNew: 393216K->21851K(458752K), 0.0851390
    secs] 1296707K->925343K(4128768K), 0.0853620 secs] [Times: user=0.86
    sys=0.00, real=0.09 secs]
    227799.536: [CMS-concurrent-mark: 2.670/2.767 secs] [Times: user=9.72
    sys=0.03, real=2.77 secs]
    227799.536: [CMS-concurrent-preclean-start]
    227800.624: [GC 227800.624: [ParNew: 415067K->11565K(458752K), 0.0345770
    secs] 1318559K->915056K(4128768K), 0.0347455 secs] [Times: user=0.27
    sys=0.06, real=0.05 secs]
    227800.684: [CMS-concurrent-preclean: 0.995/1.148 secs] [Times:
    user=4.38
    sys=0.23, real=1.14 secs]
    227800.684: [CMS-concurrent-abortable-preclean-start]
    227801.270: [CMS-concurrent-abortable-preclean: 0.475/0.587 secs]
    [Times:
    user=2.22 sys=0.09, real=0.59 secs]
    227801.273: [GC[YG occupancy: 240407 K (458752 K)]227801.273: [Rescan
    (parallel) , 0.0092978 secs]227801.282: [weak refs processing, 0.0002179
    secs]227801.283: [class unloading, 0.0082907 secs]227801.291: [scrub
    symbol

    & string tables, 0.0066056 secs] [1 CMS-remark: 903491K(3670016K)]
    1143898K(4128768K), 0.0275619 secs] [Times: user=0.03 sys=0.00,
    real=0.03
    secs]
    227801.302: [CMS-concurrent-sweep-start]
    227803.075: [CMS-concurrent-sweep: 1.773/1.773 secs] [Times: user=4.19
    sys=0.03, real=1.77 secs]
    227803.075: [CMS-concurrent-reset-start]
    227803.103: [CMS-concurrent-reset: 0.028/0.028 secs] [Times: user=0.06
    sys=0.00, real=0.03 secs]
    227816.785: [GC 227816.786: [ParNew: 404776K->25694K(458752K), 0.2086003
    secs] 1188297K->809215K(4128768K), 0.2087517 secs] [Times: user=1.13
    sys=0.19, real=0.20 secs]

    Regards,
    Ken





    --
    View this message in context: http://www.nabble.com/promotion-failed-tp18528055p18539751.html
    Sent from the OpenJDK Hotspot Garbage Collection mailing list archive at Nabble.com.

Related Discussions

Discussion Navigation
viewthread | post
Discussion Overview
grouphotspot-gc-dev @
categoriesopenjdk
postedJul 18, '08 at 5:21a
activeJul 18, '08 at 5:14p
posts5
users2
websiteopenjdk.java.net

2 users in discussion

Ken--: 3 posts Jon Masamitsu: 2 posts

People

Translate

site design / logo © 2022 Grokbase