1 Reply Latest reply: Oct 31, 2011 4:59 PM by jschellSomeoneStoleMyAlias RSS

    How generate class histogram before/after GC (JVM 1.6.0.17 only JRE instal)

    896899
      Hi - looking for suggestions on how can generate a class histogram before a stop-the-world GC when
      using a Solaris 10 Sparc platform with java version 1.6.0.17 with only the JRE installed.

      I know about -XX:+HeapDumpBeforeFullGC/-XX:+HeapDumpAfterFullGC, but that only available in 1.6.0.18.
      Also, this box only has the JRE installed, so can not use: jmap -histo 'pid' ...

      When using -XX:+PrintClassHistogram, we do get the histogram AFTER the GC ...(unfortunately, not what I
      want)...

      I have a very large application running on a SPARC platform (Solaris10) with 16Gig RAM I'm trying to
      debug/reduce-stop-world-GC times. Current, we observer stop-the-world GCs in 60+ second ranges,
      we need to reduced these times....

      The issue is that, "occasionally" there are a hugh number of objects being rapidly created and they
      live a very short period of time, a large amount of the RAM is cleaned up (below, jstat in one case
      shows 5Gigs is cleaned up) in the stop-the-world GC (so don't believe it is a object/memory leak) -
      apps is going a bit nuts, trying to figure out why- or - try to determine if there are JVM parameters
      could use to reduce the amount of time it takes when these stop-the-world GC occur...
      Any suggestions welcomed...

      jstat output is below ...(with comments...)...

      Not sure which objects are being created/then die - thinking if can get a before GC and
      after GC histograms, should be able to tell which objects these are then can track down the "problem".

      JVM options used currently (related to memory/GC...)...

      -Xms10469m
      -Xmx10469m
      -XX:PermSize=1500m
      -XX:NewSize=2617m
      -XX:MaxNewSize=2617m
      -XX:MaxPermSize=1500m
      -XX:ThreadStackSize=512
      -XX:+PrintClassHistogram
      -XX:+DisableExplicitGC
      -XX:+UseConcMarkSweepGC
      -XX:CMSInitiatingOccupancyFraction=65
      -XX:+UseParNewGC
      -XX:+UseCMSCompactAtFullCollection
      -XX:+CMSClassUnloadingEnabled
      -XX:CMSInitiatingPermOccupancyFraction=95"

      To reduce stop-the-world GC times, am considering the following:
      -XX:+UseCMSInitiatingOccupancyOnly and reducing -XX:CMSInitiatingOccupancyFraction=65 from 65 to somthing lower,
      but don't know the side effect, anyone have any comments/experiences they can provide related to
      using -XX:+UseCMSInitiatingOccupancyOnly ?


      jstat logs below from 1 occurrence, comments added ...

      the size of each survivor space (S0C && S1C),
      the utilization of each survivor space (S0U && S1U),
      the capacity of eden (EC), the utilization of eden (EU),
      the capacity of the old generation (OC), the utilization of the old generation (OU),
      the permanent generation capacity (PC), the permanent generation utilization (PU),
      the total number of young generation garbage collection events (YGC),
      the total amount of time spent collecting objects in the new generation (YGCT),
      the total number of old generation garbage collection events that have occurred (FGC),
      the total amount of time spent collecting objects in the old generation (FGCT),
      and the total time spent performing garbage collection.


      (over next ~90 seconds, add ~ 3Gig of new objects..., on the 66 second GC, it cleans up ~5 Gigs)...


      Timeframe between logs 3 seconds...

      Timestamp S0C S1C S0U S1U EC EU OC OU PC PU YGC YGCT FGC FGCT GCT
      35089.6 267968.0 267968.0 151058.4 0.0 2143872.0 1217499.3 8043520.0 5023371.5 1536000.0 578511.2 464 873.411 48 318.400 1191.811
      EDEN space: 1217499.3

      35092.6 267968.0 267968.0 151058.4 0.0 2143872.0 1855673.3 8043520.0 5023371.5 1536000.0 578511.2 464 873.411 48 318.400 1191.811

      EDEN space: 1855673.3
      674K in 3 seconds ...

      35095.6 267968.0 267968.0 151058.4 267968.0 2143872.0 2143678.4 8043520.0 5156424.8 1536000.0 578511.2 465 873.411 48 318.400 1191.811
      35098.6 267968.0 267968.0 151058.4 267968.0 2143872.0 2143678.4 8043520.0 5738204.2 1536000.0 578511.2 465 873.411 48 318.400 1191.811

      Eden space was full, time for new generation (YGCT) increases ..., then eden space down to 360.2

      35101.6 267968.0 267968.0 0.0 267968.0 2143872.0 360.2 8043520.0 5729279.8 1536000.0 578511.2 465 880.024 49 318.400 1198.424

      Eden space goes up by ~527K in next 3 seconds ...

      35104.6 267968.0 267968.0 0.0 267968.0 2143872.0 527419.4 8043520.0 5729279.8 1536000.0 578511.2 465 880.024 49 319.780 1199.805
      35107.7 267968.0 267968.0 0.0 267968.0 2143872.0 1135553.7 8043520.0 5729279.8 1536000.0 578511.2 465 880.024 49 319.780 1199.805
      35110.7 267968.0 267968.0 0.0 267968.0 2143872.0 1709236.4 8043520.0 5729279.8 1536000.0 578511.2 465 880.024 49 319.780 1199.805


      35113.6 267968.0 267968.0 222094.2 267968.0 2143872.0 2143872.0 8043520.0 5738910.5 1536000.0 578511.2 466 880.024 49 319.780 1199.805
      Eden space full again ...
      35116.7 267968.0 267968.0 267968.0 267968.0 2143872.0 2143872.0 8043520.0 6126805.2 1536000.0 578511.2 466 880.024 49 319.780 1199.805
      35119.7 267968.0 267968.0 267968.0 267968.0 2143872.0 2143872.0 8043520.0 6539662.6 1536000.0 578511.2 466 880.024 49 319.780 1199.805

      new generation (YGCT) increases ..., then eden space down 120001.3, i

      35122.7 267968.0 267968.0 267968.0 0.0 2143872.0 120001.3 8043520.0 6531558.2 1536000.0 578511.2 466 889.008 49 319.780 1208.789
      35125.7 267968.0 267968.0 267968.0 0.0 2143872.0 671136.1 8043520.0 6531558.2 1536000.0 578511.2 466 889.008 49 319.780 1208.789
      35128.7 267968.0 267968.0 267968.0 0.0 2143872.0 1082680.2 8043520.0 6531558.2 1536000.0 578511.2 466 889.008 49 319.780 1208.789
      35131.7 267968.0 267968.0 267968.0 0.0 2143872.0 1520016.2 8043520.0 6531558.2 1536000.0 578511.2 466 889.008 49 319.780 1208.789
      35134.7 267968.0 267968.0 267968.0 0.0 2143872.0 1950854.2 8043520.0 6531558.2 1536000.0 578511.2 466 889.008 49 319.780 1208.789
      Eden full again ...

      35137.8 267968.0 267968.0 267968.0 267968.0 2143872.0 2143872.0 8043520.0 6622408.9 1536000.0 578512.6 467 889.008 49 319.780 1208.789
      35140.7 267968.0 267968.0 267968.0 267968.0 2143872.0 2143872.0 8043520.0 6938114.5 1536000.0 578512.6 467 889.008 49 319.780 1208.789

      new generation (YGCT) increases ..., then eden space down ti 367846.8

      35143.8 267968.0 267968.0 0.0 267968.0 2143872.0 367846.8 8043520.0 6936775.4 1536000.0 578512.9 467 894.001 49 319.780 1213.781
      35146.8 267968.0 267968.0 0.0 267968.0 2143872.0 775767.3 8043520.0 6936775.4 1536000.0 578512.9 467 894.001 49 319.780 1213.781
      35149.8 267968.0 267968.0 0.0 267968.0 2143872.0 1172577.1 8043520.0 6936775.4 1536000.0 578512.9 467 894.001 49 319.780 1213.781
      35152.8 267968.0 267968.0 0.0 267968.0 2143872.0 1615883.8 8043520.0 6936775.4 1536000.0 578512.9 467 894.001 49 319.780 1213.781
      35155.9 267968.0 267968.0 0.0 267968.0 2143872.0 2064291.6 8043520.0 6936775.4 1536000.0 578513.2 467 894.001 49 319.780 1213.781
      35158.9 267968.0 267968.0 267968.0 267968.0 2143872.0 2143872.0 8043520.0 7190054.7 1536000.0 578513.2 468 894.001 49 319.780 1213.781
      Eden full again, YGCT increases ...

      35161.9 267968.0 267968.0 267968.0 0.0 2143872.0 240639.6 8043520.0 7255807.0 1536000.0 578513.2 468 898.009 49 319.780 1217.789
      35164.9 267968.0 267968.0 267968.0 0.0 2143872.0 692600.4 8043520.0 7255807.0 1536000.0 578513.2 468 898.009 49 319.780 1217.789
      35167.9 267968.0 267968.0 267968.0 0.0 2143872.0 1190958.0 8043520.0 7255807.0 1536000.0 578513.2 468 898.009 49 319.780 1217.789
      35170.9 267968.0 267968.0 267968.0 0.0 2143872.0 1658177.8 8043520.0 7255807.0 1536000.0 578513.2 468 898.009 49 319.780 1217.789
      35173.9 267968.0 267968.0 267968.0 0.0 2143872.0 2135519.5 8043520.0 7255807.0 1536000.0 578513.2 468 898.009 49 319.780 1217.789
      35176.9 267968.0 267968.0 267968.0 267968.0 2143872.0 2143872.0 8043520.0 7559906.5 1536000.0 578513.2 469 898.009 49 319.780 1217.789
      35179.9 267968.0 267968.0 267968.0 267968.0 2143872.0 2143872.0 8043520.0 7786576.4 1536000.0 578513.2 469 898.009 49 319.780 1217.789

      Now old generation is now full ... 8043520-7786576 = 256944
      Not enough room ...stop-the-world-GC required...

      A full GC below...things freeze...

      Timestamp S0C S1C S0U S1U EC EU OC OU PC PU YGC YGCT FGC FGCT GCT
      35183.0 267968.0 267968.0 0.0 267968.0 2143872.0 412261.4 8043520.0 7783431.4 1536000.0 578606.8 469 904.504 49 319.780 1224.284
      35186.0 267968.0 267968.0 0.0 267968.0 2143872.0 823677.8 8043520.0 7783431.4 1536000.0 578606.8 469 904.504 49 319.780 1224.284
      35189.0 267968.0 267968.0 0.0 267968.0 2143872.0 1281240.7 8043520.0 7783431.4 1536000.0 578616.5 469 904.504 49 319.780 1224.284
      35192.0 267968.0 267968.0 0.0 267968.0 2143872.0 1724725.6 8043520.0 7783431.4 1536000.0 578619.1 469 904.504 49 319.780 1224.284
      35195.0 267968.0 267968.0 0.0 267968.0 2143872.0 2143872.0 8043520.0 7783431.4 1536000.0 578619.1 469 904.504 50 319.780 1224.284
      35198.0 267968.0 267968.0 0.0 267968.0 2143872.0 2143872.0 8043520.0 7783431.4 1536000.0 578619.1 469 904.504 50 319.780 1224.284
      35201.0 267968.0 267968.0 0.0 267968.0 2143872.0 2143872.0 8043520.0 7783431.4 1536000.0 578619.1 469 904.504 50 319.780 1224.284
      35204.0 267968.0 267968.0 0.0 267968.0 2143872.0 2143872.0 8043520.0 7783431.4 1536000.0 578619.1 469 904.504 50 319.780 1224.284
      35207.0 267968.0 267968.0 0.0 267968.0 2143872.0 2143872.0 8043520.0 7783431.4 1536000.0 578619.1 469 904.504 50 319.780 1224.284
      35210.0 267968.0 267968.0 0.0 267968.0 2143872.0 2143872.0 8043520.0 7783431.4 1536000.0 578619.1 469 904.504 50 319.780 1224.284
      35213.1 267968.0 267968.0 0.0 267968.0 2143872.0 2143872.0 8043520.0 7783431.4 1536000.0 578619.1 469 904.504 50 319.780 1224.284
      35216.0 267968.0 267968.0 0.0 267968.0 2143872.0 2143872.0 8043520.0 7783431.4 1536000.0 578619.1 469 904.504 50 319.780 1224.284
      35219.1 267968.0 267968.0 0.0 267968.0 2143872.0 2143872.0 8043520.0 7783431.4 1536000.0 578619.1 469 904.504 50 319.780 1224.284
      35222.1 267968.0 267968.0 0.0 267968.0 2143872.0 2143872.0 8043520.0 7783431.4 1536000.0 578619.1 469 904.504 50 319.780 1224.284
      35225.1 267968.0 267968.0 0.0 267968.0 2143872.0 2143872.0 8043520.0 7783431.4 1536000.0 578619.1 469 904.504 50 319.780 1224.284
      35228.1 267968.0 267968.0 0.0 267968.0 2143872.0 2143872.0 8043520.0 7783431.4 1536000.0 578619.1 469 904.504 50 319.780 1224.284
      35231.1 267968.0 267968.0 0.0 267968.0 2143872.0 2143872.0 8043520.0 7783431.4 1536000.0 578619.1 469 904.504 50 319.780 1224.284
      35234.1 267968.0 267968.0 0.0 267968.0 2143872.0 2143872.0 8043520.0 7783431.4 1536000.0 578619.1 469 904.504 50 319.780 1224.284
      35237.1 267968.0 267968.0 0.0 267968.0 2143872.0 2143872.0 8043520.0 7783431.4 1536000.0 578619.1 469 904.504 50 319.780 1224.284
      35240.1 267968.0 267968.0 0.0 267968.0 2143872.0 2143872.0 8043520.0 7783431.4 1536000.0 578619.1 469 904.504 50 319.780 1224.284
      35243.1 267968.0 267968.0 0.0 267968.0 2143872.0 2143872.0 8043520.0 7783431.4 1536000.0 578619.1 469 904.504 50 319.780 1224.284
      35246.2 267968.0 267968.0 0.0 267968.0 2143872.0 2143872.0 8043520.0 7783431.4 1536000.0 578619.1 469 904.504 50 319.780 1224.284
      35249.2 267968.0 267968.0 0.0 267968.0 2143872.0 2143872.0 8043520.0 7783431.4 1536000.0 578619.1 469 904.504 50 319.780 1224.284
      35252.2 267968.0 267968.0 0.0 267968.0 2143872.0 2143872.0 8043520.0 7783431.4 1536000.0 578619.1 469 904.504 50 319.780 1224.284
      35255.2 267968.0 267968.0 0.0 267968.0 2143872.0 2143872.0 8043520.0 7783431.4 1536000.0 578579.7 469 904.504 50 319.780 1224.284
      35258.2 267968.0 267968.0 0.0 267968.0 2143872.0 2143872.0 8043520.0 7783431.4 1536000.0 578579.7 469 904.504 50 319.780 1224.284

      .... time difference is 66 seconds ...


      The output above contains
      the size of each survivor space (S0C && S1C),
      the utilization of each survivor space (S0U && S1U),
      the capacity of eden (EC), the utilization of eden (EU),
      the capacity of the old generation (OC), the utilization of the old generation (OU),
      the permanent generation capacity (PC), the permanent generation utilization (PU),
      the total number of young generation garbage collection events (YGC),
      the total amount of time spent collecting objects in the new generation (YGCT),
      the total number of old generation garbage collection events that have occurred (FGC),
      the total amount of time spent collecting objects in the old generation (FGCT),
      and the total time spent performing garbage collection.

      old generation changed from 7783431.4 to 2712370.7 (limit is 8043520.0)
      old generation reduced by 7783431.4 - 2712370.7 = 5071060.7 (5 Gigs)...

      Timestamp S0C S1C S0U S1U EC EU OC OU PC PU YGC YGCT FGC FGCT GCT
      35261.2 267968.0 267968.0 0.0 0.0 2143872.0 90238.8 8043520.0 2712370.7 1536000.0 578581.4 469 904.504 50 385.785 1290.289

      35264.2 267968.0 267968.0 0.0 0.0 2143872.0 538408.1 8043520.0 2712370.7 1536000.0 578588.9 469 904.504 50 385.785 1290.289
      35267.3 267968.0 267968.0 0.0 0.0 2143872.0 866885.7 8043520.0 2712370.7 1536000.0 578588.9 469 904.504 50 385.785 1290.289
      35270.6 267968.0 267968.0 0.0 0.0 2143872.0 1130407.5 8043520.0 2712370.7 1536000.0 578588.9 469 904.504 50 385.785 1290.289
      35274.0 267968.0 267968.0 0.0 0.0 2143872.0 1390679.5 8043520.0 2712370.7 1536000.0 578588.9 469 904.504 50 385.785 1290.289
      35277.1 267968.0 267968.0 0.0 0.0 2143872.0 1566244.4 8043520.0 2712370.7 1536000.0 578589.0 469 904.504 50 385.785 1290.289
      35280.2 267968.0 267968.0 0.0 0.0 2143872.0 1787384.6 8043520.0 2712370.7 1536000.0 578589.0 469 904.504 50 385.785 1290.289
      35283.3 267968.0 267968.0 0.0 0.0 2143872.0 1975767.7 8043520.0 2712370.7 1536000.0 578589.0 469 904.504 50

      and 24 seconds later....eden starting to fill up again...

      Cheers