3 Replies Latest reply: Aug 29, 2010 9:16 PM by 843829 RSS

    ParNew (promotion failed)  and  long time stopped !

    843829
      I use the latest JDK6u21 and I found a strange problem, the JVM will stop after 1 hours of my server start. after view the gc log, it said ParNew (promotion failed), but the memory is enough.
      before promotion failed, I found the variable contiguous_available decreased to 3682040, but other case it is very big, and I used the "-XX:+UseCMSCompactAtFullCollection -XX:CMSFullGCsBeforeCompaction=2 " for CMS memory fragment...

      anybody could give me a light? I am very appreciate for that!

      *1. The following is my jvm parameter:*
      -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime -XX:+UseMembar -XX:PrintCMSStatistics=3 -XX:+PrintCMSInitiationStatistics -XX:+PrintAdaptiveSizePolicy -XX:+PrintCompilation -XX:+PrintConcurrentLocks -XX:+PrintGCTaskTimeStamps -XX:+PrintSharedSpaces -XX:+PrintTenuringDistribution -XX:+PrintVMQWaitTime -XX:+PrintHeapAtGC -Xms10g -Xmx10g -Xmn1512m -XX:SurvivorRatio=6 -XX:MaxTenuringThreshold=2 -XX:ParallelGCThreads=15 -XX:MaxPermSize=96m -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:MaxGCPauseMillis=150 -XX:CMSAbortablePrecleanWaitMillis=100 -XX:ParallelCMSThreads=8 -XX:CMSInitiatingOccupancyFraction=65 -XX:+UseCMSInitiatingOccupancyOnly -XX:+UseCMSCompactAtFullCollection -XX:CMSFullGCsBeforeCompaction=2 -XX:GCTimeRatio=19 -Dsun.rmi.dgc.client.gcInterval=7200000 -Dsun.rmi.dgc.server.gcInterval=7200000 -XX:+UseFastAccessorMethods -XX:-UseFastEmptyMethods -XX:+UseFastJNIAccessors -Xnoclassgc -XX:+DisableExplicitGC
      by the way, I had change the -Xmn to 512m, but same problem..

      *2. The gc log of ParNew (promotion failed):*
      4393.505: [GC 4393.505: [ParNew
      Desired survivor size 99090432 bytes, new threshold 2 (max 2)
      - age   1:   46429016 bytes,   46429016 total
      - age   2:   34759512 bytes,   81188528 total
      : 1273754K->126139K(1354752K), 0.2438560 secs] 7058007K->5941399K(10292224K), 0.2443570 secs] [Times: user=1.72 sys=0.00, real=0.24 secs]
      }
      Total time for which application threads were stopped: 0.2466460 seconds
      CMSCollector shouldConcurrentCollect: 4393.750
      time_until_cms_gen_full 99.3452089
      free=3197145264
      contiguous_available=3682040
      promotion_rate=2.86619e+07
      cms_allocation_rate=0
      occupancy=0.6506605
      initiatingOccupancy=0.6500000
      initiatingPermOccupancy=0.9200000
      Application time: 0.0001620 seconds
      4393.751: [GC [1 CMS-initial-mark: 5815259K(8937472K)] 5941797K(10292224K), 0.3126700 secs] [Times: user=0.31 sys=0.00, real=0.32 secs]
      Total time for which application threads were stopped: 0.3144440 seconds
      4394.064: [CMS-concurrent-mark-start]
      Application time: 0.6382660 seconds
      ...
      4404.367: [GC 4404.368: [ParNew
      Desired survivor size 99090432 bytes, new threshold 2 (max 2)
      - age   1:   49937360 bytes,   49937360 total
      - age   2:   30650624 bytes,   80587984 total
      : 1254716K->132309K(1354752K), 0.2603790 secs] 7080972K->5991636K(10292224K), 0.2609090 secs] [Times: user=1.74 sys=0.01, real=0.26 secs]
      }
      Total time for which application threads were stopped: 0.2631700 seconds
      Application time: 0.7369730 seconds
      {Heap before GC invocations=3976 (full 37):
      par new generation   total 1354752K, used 1293525K [0x00002aaaae200000, 0x00002aab0ca00000, 0x00002aab0ca00000)
        eden space 1161216K, 100% used [0x00002aaaae200000, 0x00002aaaf5000000, 0x00002aaaf5000000)
        from space 193536K,  68% used [0x00002aaaf5000000, 0x00002aaafd1355e0, 0x00002aab00d00000)
        to   space 193536K,   0% used [0x00002aab00d00000, 0x00002aab00d00000, 0x00002aab0ca00000)
      concurrent mark-sweep generation total 8937472K, used 5719921K [0x00002aab0ca00000, 0x00002aad2e200000, 0x00002aad2e200000)
      concurrent-mark-sweep perm gen total 64956K, used 38890K [0x00002aad2e200000, 0x00002aad3216f000, 0x00002aad34200000)
      *4405.367: [GC 4405.368: [ParNew (promotion failed)*
      Desired survivor size 99090432 bytes, new threshold 2 (max 2)
      - age   1:   44406944 bytes,   44406944 total
      - age   2:   34887616 bytes,   79294560 total
      : 1293525K->1255442K(1354752K), 3.3235350 secs]4408.691: [CMS4430.835: [CMS-concurrent-sweep: 24.401/28.241 secs] (CMS-concurrent-sweep yielded 3 times)
      [Times: user=48.33 sys=1.42, real=28.24 secs]
      *(concurrent mode failure) (concurrent mode failure): 5749663K->2538850K(8937472K), 22.2083950 secs] 7013447K->3794292K(10292224K), [CMS Perm : 38890K->38890K(64956K)], 25.5325540 secs] [Times: user=26.98 sys=0.00, real=25.53 secs]*
      Heap after GC invocations=3977 (full 38):
      par new generation total 1354752K, used 1255442K [0x00002aaaae200000, 0x00002aab0ca00000, 0x00002aab0ca00000)
      eden space 1161216K, 100% used [0x00002aaaae200000, 0x00002aaaf5000000, 0x00002aaaf5000000)
      from space 193536K, 48% used [0x00002aab00d00000, 0x00002aab06904a50, 0x00002aab0ca00000)
      to space 193536K, 68% used [0x00002aaaf5000000, 0x00002aaafd1355e0, 0x00002aab00d00000)
      concurrent mark-sweep generation total 8937472K, used 2538850K [0x00002aab0ca00000, 0x00002aad2e200000, 0x00002aad2e200000)
      concurrent-mark-sweep perm gen total 64956K, used 38890K [0x00002aad2e200000, 0x00002aad3216f000, 0x00002aad34200000)
      }
      Total time for which application threads were stopped: 25.5346940 seconds
      Application time: 1.6390800 seconds
      {Heap before GC invocations=3977 (full 38):
      par new generation   total 1354752K, used 1354751K [0x00002aaaae200000, 0x00002aab0ca00000, 0x00002aab0ca00000)
        eden space 1161216K, 100% used [0x00002aaaae200000, 0x00002aaaf5000000, 0x00002aaaf5000000)
        from space 193536K,  99% used [0x00002aab00d00000, 0x00002aab0c9fff50, 0x00002aab0ca00000)
        to   space 193536K,  68% used [0x00002aaaf5000000, 0x00002aaafd1355e0, 0x00002aab00d00000)
      concurrent mark-sweep generation total 8937472K, used 2538850K [0x00002aab0ca00000, 0x00002aad2e200000, 0x00002aad2e200000)
      concurrent-mark-sweep perm gen total 64956K, used 38891K [0x00002aad2e200000, 0x00002aad3216f000, 0x00002aad34200000)
      4432.541: [Full GC 4432.541: [CMS: 2538850K->2254294K(8937472K), 29.0664770 secs] 3893601K->2254294K(10292224K), [CMS Perm : 38891K->38867K(64956K)], 29.0668970 secs]CMSCollector shouldConcurrentCollect: 4461.608
      time_until_cms_gen_full 203.1005006
      free=6843573736
      contiguous_available=6843442664
      promotion_rate=3.01731e+07
      cms_allocation_rate=0
      occupancy=0.2522295
      initiatingOccupancy=0.6500000
      initiatingPermOccupancy=0.9200000
      }
        • 1. Re: ParNew (promotion failed)  and  long time stopped !
          843829
          could anybody told me what's the "contiguous_available" meaning?
          • 2. Re: ParNew (promotion failed)  and  long time stopped !
            843829
            another abnormal case without "promotion failed" tip, but cost long time of app stopped:

            11958.151: [GC 11958.151: [ParNew
            Desired survivor size 33554432 bytes, new threshold 2 (max 2)
            - age   1:   15735688 bytes,   15735688 total
            - age   2:    9981368 bytes,   25717056 total
            : 436769K->30885K(458752K), 0.1082290 secs] 7131287K->6734723K(10420224K), 0.1088060 secs] [Times: user=0.82 sys=0.02, real=0.11 secs]
            Total time for which application threads were stopped: 0.1130550 seconds
            Application time: 0.1259410 seconds
            Total time for which application threads were stopped: 25.8654900 seconds
            Application time: 0.0003140 seconds
            Total time for which application threads were stopped: 0.0035920 seconds
            Application time: 0.0005900 seconds
            Total time for which application threads were stopped: 0.0018320 seconds
            Application time: 0.0002240 seconds
            Total time for which application threads were stopped: 25.7993410 seconds
            Application time: 0.0002000 seconds
            Total time for which application threads were stopped: 0.0035800 seconds
            Application time: 0.0059850 seconds
            Total time for which application threads were stopped: 0.0031670 seconds
            Application time: 0.0754810 seconds
            12010.152: [GC 12010.152: [ParNew
            Desired survivor size 33554432 bytes, new threshold 2 (max 2)
            - age   1:   21472096 bytes,   21472096 total
            - age   2:    9853168 bytes,   31325264 total
            : 424101K->48164K(458752K), 0.1014030 secs] 7092494K->6726096K(10420224K), 0.1018690 secs] [Times: user=0.88 sys=0.01, real=0.10 secs]
            Total time for which application threads were stopped: 0.1081710 seconds
            Application time: 0.1441860 seconds
            Total time for which application threads were stopped: 0.0064210 seconds
            Application time: 0.0013600 seconds
            Total time for which application threads were stopped: 0.0151980 seconds
            Application time: 0.0033530 seconds
            Total time for which application threads were stopped: 0.0236910 seconds
            Application time: 0.0139520 seconds
            12010.491: [GC 12010.491: [ParNew
            Desired survivor size 33554432 bytes, new threshold 2 (max 2)
            - age   1:   26804960 bytes,   26804960 total
            - age   2:   14022000 bytes,   40826960 total
            : 441380K->56783K(458752K), 0.1109360 secs] 7099837K->6724826K(10420224K), 0.1113860 secs] [Times: user=1.04 sys=0.02, real=0.12 secs]
            Total time for which application threads were stopped: 0.1172810 seconds
            Application time: 0.1822510 seconds
            12010.792: [GC 12010.792: [ParNew
            Desired survivor size 33554432 bytes, new threshold 2 (max 2)
            - age   1:   21406568 bytes,   21406568 total
            - age   2:   19288808 bytes,   40695376 total
            : 449999K->65536K(458752K), 0.1353970 secs] 7089876K->6720230K(10420224K), 0.1358610 secs] [Times: user=1.16 sys=0.01, real=0.14 secs]
            Total time for which application threads were stopped: 0.1424450 seconds
            Application time: 0.1772370 seconds

            this jdk version is java version "1.6.0_20"
            • 3. Re: ParNew (promotion failed)  and  long time stopped !
              843829
              Another more detail gc log about long time pause of ParNew no "Promotion failed" tips:
              [http://forums.sun.com/thread.jspa?messageID=11041712#11041712|http://forums.sun.com/thread.jspa?messageID=11041712#11041712]

              I had try to use -X:+UseMemBar, but it seems not work...

              I use latest jdk6u21 version and RHEL51_64 with IBM x3850 which has 16cores.