PPT 见http://download.csdn.net/download/hsuxu/5620967
- 1. Java™ Garbage CollectionStatistical Analysis 101.Juarez JuniorSystem Architect – Unisys Global Outsourcing
- 2. Agenda. Java Heap Management Simple Garbage Collection Statistics • Generating the Data • Isolating the Data • Graphing the Data • Interpreting the Data • Improving Performance Advanced Garbage Collection Statistics • Generate, Isolate, Graph, Interpret,
Improve Java Command Line Arguments Recap - 3. Java Heap. Young Generation • Eden - Where new objects are created • Survivor spaces - Where garbage collector places objects that are still in use Old Generation • Where tenured objects are placed References • http://java.sun.com/docs/hotspot/gc/ (1.3.1)
• http://java.sun.com/docs/hotspot/gc1.4.2/ - 4. Minor Garbage Collection. Occurs when no room in eden for new object Marks all reachable objects in eden and “from” survivor space Copies those objects to “to” survivor space • Updates references accordingly • If “to” survivor space fills, overflows
to old generation Resets allocation pointer to start of eden H A B C D E I E F G H G I Old Generation Eden From From To To Spaces - 5. Major Garbage Collection. Occurs when insufficient room in old generation to hold to-be- tenured objects during a minor collection • Pessimistic – need sufficient space to hold all object in young generation • Pre-calculated – Minor collection reachable
object algorithm run to determine exactly now many objects will be tenured Mark and Compact • Reachable objects are marked • Marked objects are moved to one end of the old generation J K M M N O L O V W A B C D P Q R X S T U X E F G H I Old Generation Eden
To From Spaces - 6. Agenda. Java Heap Management Simple Garbage Collection Statistics • Generating the Data • Isolating the Data • Graphing the Data • Interpreting the Data • Improving Performance Advanced Garbage Collection Statistics • Generate, Isolate, Graph, Interpret,
Improve Java Command Line Arguments Recap - 7. Generating Simple GC Data. -verbose:gc command line option java ... –verbose:gc ... my.java.app ... Results: ... [GC 1860K->1388K(1984K), 0.0005059 secs] Minor [GC 1900K->1446K(1984K), 0.0006679 secs]collections [GC 1958K->1468K(2112K), 0.0006251 secs]
[Full GC 1468K-> 195K(2112K), 0.0131045 secs] Major and ... Time it took minor collection Total heap size Heap in use after collection Heap in use before collection - 8. Isolating the Simple GC Data.... ...[GC 1860K->1388K(1984K), 0.0005059 secs][GC 1900K->1446K(1984K), 0.0006679 secs] 1860,1388,0.0005059[GC[Full GC 1958K->1468K(2112K), 1468K-> 195K(2112K), 0.0006251 0.0131045 secs] secs] Analyzer 1900,1446,0.0006679...
1958,1468,0.0006251 1468,195,0.0131045 ... import java.util.regex.Matcher; Comma-separated import java.util.regex.Pattern; value (CSV) file ... Pattern p = Pattern.compile ("[(?:Full |)GC (d*)K->(d*)K(d*K), ([d.]*) secs]"); Matcher m = p.matcher(simple_gc_data_output);
while (m.find()) fout.println(m.group(1) + "," + m.group(2) + "," + m.group(3)); - 9. Interpreting the Regular Expression. The ’’ char is an escape character, both in Java and in regular expressions. [(?:Full |)GC (d*)K->(d*)K(d*K), ([d.]*) secs] [(?:Full |)GC - match literal ‘[Full GC ’ or ‘[GC ’ (d*)K-> - capture all digits before the
literal text ‘K->’ (d*)K - capture all digits before the literal text ‘K’ (d*K) - discard the digits and literal text ‘K’ within parenthesis - capture all digits and decimal point after the , ([d.]*) secs] comma and space, and before the literal text ‘secs]’[Full
GC 1468K-> 195K(2112K), 0.0131045 secs] - 10. Graphing the Simple GC Data. Load the CSV file into a spreadsheet Sum the third column - total time spent on GC Create fourth column • Third column * 10000 (or 100000) • Gets times within range of columns 1 and 2 Create a graph containing columns 1,
2 and 4. - 11. Graphing in Excel. Select first column only Create an “XY (Scatter)” graph Wizard step 2, click Series tab and add columns 2 and 4 to the series. • Click Add • Name: Type or select row 1 cell • X Values: leave empty • Y Values: Select cells in column
Suggest creating new sheet for the chart - 12. Graphing in StarOffice. Swap the 3rd and 4th columns (seconds*10000 is now the 3rd column) Select the first 3 columns and create chart • Put chart in new sheet • Select ‘lines’ chart type • Select ‘normal’ variant After chart is created • Turn off labels
on the X axis • Change width of data series lines to 0.02” or higher. - 13. Interpreting Graphed GC Data. Typical GC data graph For many GCs, the heap slowly fills as objects get moved to the old generation • Blue (or magenta) lines with positive slope Then a full GC happens • Drop in blue (or magenta) lines • Yellow dot in
higher position - 14. Interpreting Graphed GC Data.Three Phases Phase 1 Phase 2 Phase 3Phase 1 • Working set equilibrium • Ideal graph • No full GCPhase 2 • Full GC with heap not full - High GC times (yellow dots above blue zig-zag) • App called System.GC()Phase 3 • Incremental
working set equilibrium • Implies various sub-phases each of which adds to working set - 15. Improving Performance, Before. Goal: 1000 business transactions in 12 minutes Heap set to: -Xms1024m –Xmx1024m 18 minute run, 472 seconds (7.8 minutes) in garbage collection Each GC is freeing very little memory
- 16. Improving Performance, After.-Xms1024m –Xmx1024m -XX:NewSize=300m –XX:MaxNewSize=300m12 minute run, 25 seconds in garbage collection • 70 collections instead of 8000 (no major/full collections) • Average collection freed 240MB instead of just 1MB
- 17. Agenda. Java Heap Management Simple Garbage Collection Statistics • Generating the Data • Isolating the Data • Graphing the Data • Interpreting the Data • Improving Performance Advanced Garbage Collection Statistics • Generate, Isolate, Graph, Interpret,
Improve Java Command Line Arguments Recap - 18. More GC Data. PrintGCDetails command line option java ... –XX:+PrintGCDetails ... my.java.app ... Results: Minor [GC [DefNew: 17131K->1606K(18432K), 0.0082055 secs]collection 44904K->29379K(63488K), 0.0083625 secs] [GC [DefNew: 17990K->17990K(18432K),
0.0000839 secs] [Tenured: 27772K->3759K(45056K), 0.0454394 secs]Major and 45763K->3759K(63488K), 0.0459597 secs] minorcollection Time it took Heap size Sizes are for young Heap in use after collection generation, old generation, and total heap Heap in use
before collection - 19. And Even More GC Data. PrintHeapAtGC command line option • java ... –XX:+PrintHeapAtGC ... my.java.app ... Results: {Heap before GC invocations=422: Heap def new generation total 18432K, used 17639K [0x6eb40000, 0x6ff40000, 0x6ff40000) eden space 16384K,
100% used [0x6eb40000, 0x6fb40000, 0x6fb40000) from space 2048K, 61% used [0x6fd40000, 0x6fe79df8, 0x6ff40000) to space 2048K, 0% used [0x6fb40000, 0x6fb40000, 0x6fd40000) tenured generation total 45056K, used 6403K [0x6ff40000, 0x72b40000, 0x72b40000) the
space 45056K, 14% used [0x6ff40000, 0x70580f78, 0x70581000, 0x72b40000) compacting perm gen total 8192K, used 1597K [0x72b40000, 0x73340000, 0x76b40000) the space 8192K, 19% used [0x72b40000, 0x72ccf598, 0x72ccf600, 0x73340000) Heap after GC invocations=423:
Heap def new generation total 18432K, used 1197K [0x6eb40000, 0x6ff40000, 0x6ff40000) eden space 16384K, 0% used [0x6eb40000, 0x6eb40000, 0x6fb40000) from space 2048K, 58% used [0x6fb40000, 0x6fc6b4e8, 0x6fd40000) to space 2048K, 0% used [0x6fd40000, 0x6fd40000,
0x6ff40000) tenured generation total 45056K, used 6416K [0x6ff40000, 0x72b40000, 0x72b40000) the space 45056K, 14% used [0x6ff40000, 0x70584190, 0x70584200, 0x72b40000) compacting perm gen total 8192K, used 1597K [0x72b40000, 0x73340000, 0x76b40000) the space
8192K, 19% used [0x72b40000, 0x72ccf598, 0x72ccf600, 0x73340000) } - 20. PrintHeapAtGC Data.{Heap before GC invocations=422:Heap def new generation total 18432K, used 17639K [0x6eb40000, 0x6ff40000, 0x6ff40000) eden space 16384K, 100% used [0x6eb40000, 0x6fb40000, 0x6fb40000) from space 2048K, 61% used [0x6fd40000, 0x6fe79df8,
0x6ff40000) to space 2048K, 0% used [0x6fb40000, 0x6fb40000, 0x6fd40000) tenured generation total 45056K, used 6403K [0x6ff40000, 0x72b40000, 0x72b40000) the space 45056K, 14% used [0x6ff40000, 0x70580f78, 0x70581000, 0x72b40000) compacting perm gen total
8192K, used 1597K [0x72b40000, 0x73340000, 0x76b40000) the space 8192K, 19% used [0x72b40000, 0x72ccf598, 0x72ccf600, 0x73340000) Heap after GC invocations=423:Heap def new generation total 18432K, used 1197K [0x6eb40000, 0x6ff40000, 0x6ff40000) eden space
16384K, 0% used [0x6eb40000, 0x6eb40000, 0x6fb40000) from space 2048K, 58% used [0x6fb40000, 0x6fc6b4e8, 0x6fd40000) to space 2048K, Data from before GC 0% used [0x6fd40000, 0x6fd40000, 0x6ff40000) tenured generation total 45056K, used 6416K [0x6ff40000, 0x72b40000,
0x72b40000) the space 45056K, 14% used [0x6ff40000, 0x70584190, 0x70584200, 0x72b40000) compacting perm gen total 8192K, used 1597K [0x72b40000, 0x73340000, 0x76b40000) the space 8192K, 19% used [0x72b40000, 0x72ccf598, 0x72ccf600, 0x73340000)} - 21. PrintHeapAtGC Data.{Heap before GC invocations=422:Heap def new generation total 18432K, used 17639K [0x6eb40000, 0x6ff40000, 0x6ff40000) eden space 16384K, 100% used [0x6eb40000, 0x6fb40000, 0x6fb40000) from space 2048K, 61% used [0x6fd40000, 0x6fe79df8,
0x6ff40000) to space 2048K, Data from after GC 0% used [0x6fb40000, 0x6fb40000, 0x6fd40000) tenured generation total 45056K, used 6403K [0x6ff40000, 0x72b40000, 0x72b40000) the space 45056K, 14% used [0x6ff40000, 0x70580f78, 0x70581000, 0x72b40000) compacting
perm gen total 8192K, used 1597K [0x72b40000, 0x73340000, 0x76b40000) the space 8192K, 19% used [0x72b40000, 0x72ccf598, 0x72ccf600, 0x73340000) Heap after GC invocations=423:Heap def new generation total 18432K, used 1197K [0x6eb40000, 0x6ff40000, 0x6ff40000)
eden space 16384K, 0% used [0x6eb40000, 0x6eb40000, 0x6fb40000) from space 2048K, 58% used [0x6fb40000, 0x6fc6b4e8, 0x6fd40000) to space 2048K, 0% used [0x6fd40000, 0x6fd40000, 0x6ff40000) tenured generation total 45056K, used 6416K [0x6ff40000, 0x72b40000,
0x72b40000) the space 45056K, 14% used [0x6ff40000, 0x70584190, 0x70584200, 0x72b40000) compacting perm gen total 8192K, used 1597K [0x72b40000, 0x73340000, 0x76b40000) the space 8192K, 19% used [0x72b40000, 0x72ccf598, 0x72ccf600, 0x73340000)} - 22. PrintHeapAtGC Data.{Heap before GC invocations=422:Heap def new generation total 18432K, used 17639K [0x6eb40000, 0x6ff40000, 0x6ff40000) eden space 16384K, 100% used [0x6eb40000, 0x6fb40000, 0x6fb40000) from space 2048K, 61% used [0x6fd40000, 0x6fe79df8,
0x6ff40000) to space 2048K, 0% used [0x6fb40000, 0x6fb40000, 0x6fd40000) Memory tenured generation total 45056K, used 6403K [0x6ff40000, 0x72b40000, 0x72b40000) addresses: the space 45056K, 14% used [0x6ff40000, 0x70580f78, 0x70581000, 0x72b40000) Memory compacting
perm gen total 8192K, used 1597K [0x72b40000, 0x73340000, 0x76b40000) -addresses start the space 8192K, 19% used [0x72b40000, 0x72ccf598, 0x72ccf600, 0x73340000) Heap after GC invocations=423: - nextHeap - end def new generation eden space 16384K, total 18432K,
used 1197K [0x6eb40000, 0x6ff40000, 0x6ff40000) 0% used [0x6eb40000, 0x6eb40000, 0x6fb40000) from space 2048K, 58% used [0x6fb40000, 0x6fc6b4e8, 0x6fd40000) to space 2048K, 0% used [0x6fd40000, 0x6fd40000, 0x6ff40000) tenured generation total 45056K, used
6416K [0x6ff40000, 0x72b40000, 0x72b40000) the space 45056K, 14% used [0x6ff40000, 0x70584190, 0x70584200, 0x72b40000) compacting perm gen total 8192K, used 1597K [0x72b40000, 0x73340000, 0x76b40000) the space 8192K, 19% used [0x72b40000, 0x72ccf598, 0x72ccf600,
0x73340000)} - 23. PrintHeapAtGC Data.{Heap before GC invocations=422:Heap def new generation total 18432K, used 17639K [0x6eb40000, 0x6ff40000, 0x6ff40000) eden space 16384K, 100% used [0x6eb40000, 0x6fb40000, 0x6fb40000) from space 2048K, 61% used [0x6fd40000, 0x6fe79df8,
0x6ff40000) to space 2048K, 0% used [0x6fb40000, 0x6fb40000, 0x6fd40000) Before GC, eden ‘next’ tenured generation total 45056K, used 6403K [0x6ff40000, 0x72b40000, 0x72b40000) the space 45056K, 14% used [0x6ff40000, 0x70580f78, 0x70581000, 0x72b40000) pointer
is at end compacting perm gen total 8192K, used 1597K [0x72b40000, 0x73340000, 0x76b40000) the space 8192K, 19% used [0x72b40000, 0x72ccf598, 0x72ccf600, 0x73340000) Heap after GC invocations=423:Heap def new generation total 18432K, used 1197K [0x6eb40000,
0x6ff40000, 0x6ff40000) eden space 16384K, 0% used [0x6eb40000, 0x6eb40000, 0x6fb40000) from space 2048K, 58% used [0x6fb40000, 0x6fc6b4e8, 0x6fd40000) to space 2048K, 0% used [0x6fd40000, 0x6fd40000, 0x6ff40000) tenured generation total 45056K, used 6416K
[0x6ff40000, 0x72b40000, 0x72b40000) the space 45056K, 14% used [0x6ff40000, 0x70584190, 0x70584200, 0x72b40000) After GC, eden ‘next’ compacting perm gen total 8192K, used 1597K [0x72b40000, 0x73340000, 0x76b40000)} pointer is at start the space 8192K, 19%
used [0x72b40000, 0x72ccf598, 0x72ccf600, 0x73340000) - 24. PrintHeapAtGC Data.{Heap before GC invocations=422:Heap def new generation For each generation total 18432K, used 17639K [0x6eb40000, 0x6ff40000, 0x6ff40000) eden space 16384K, 100% used [0x6eb40000, 0x6fb40000, 0x6fb40000) from space 2048K, 61% used
[0x6fd40000, 0x6fe79df8, 0x6ff40000) to space 2048K, 0% used [0x6fb40000, 0x6fb40000, 0x6fd40000) tenured generation total 45056K, used 6403K [0x6ff40000, 0x72b40000, 0x72b40000) the space 45056K, 14% used [0x6ff40000, 0x70580f78, 0x70581000, 0x72b40000) compacting
perm gen total 8192K, used 1597K [0x72b40000, 0x73340000, 0x76b40000) the space 8192K, 19% used [0x72b40000, 0x72ccf598, 0x72ccf600, 0x73340000) Heap after GC invocations=423: Memory in useHeap def new generation total 18432K, used 1197K [0x6eb40000, 0x6ff40000,
0x6ff40000) eden space 16384K, 0% used [0x6eb40000, 0x6eb40000, 0x6fb40000) from space 2048K, 58% used [0x6fb40000, 0x6fc6b4e8, 0x6fd40000) to space 2048K, 0% used [0x6fd40000, 0x6fd40000, 0x6ff40000) tenured generation total 45056K, used 6416K [0x6ff40000,
0x72b40000, 0x72b40000) the space 45056K, 14% used [0x6ff40000, 0x70584190, 0x70584200, 0x72b40000) Memory allocated compacting perm gen total 8192K, used 1597K [0x72b40000, 0x73340000, 0x76b40000) the space 8192K, 19% used [0x72b40000, 0x72ccf598, 0x72ccf600,
0x73340000)} - 25. PrintHeapAtGC Data.{Heap before GC invocations=422:Heap For each generational sub-space def new generation total 18432K, used 17639K [0x6eb40000, 0x6ff40000, 0x6ff40000) eden space 16384K, 100% used [0x6eb40000, 0x6fb40000, 0x6fb40000) from space 2048K,
61% used [0x6fd40000, 0x6fe79df8, 0x6ff40000) to space 2048K, 0% used [0x6fb40000, 0x6fb40000, 0x6fd40000) tenured generation total 45056K, used 6403K [0x6ff40000, 0x72b40000, 0x72b40000) the space 45056K, 14% used [0x6ff40000, 0x70580f78, 0x70581000, 0x72b40000)
Percentage of that compacting perm gen total 8192K, used 1597K [0x72b40000, 0x73340000, 0x76b40000) the space 8192K, 19% used [0x72b40000, 0x72ccf598, 0x72ccf600, 0x73340000) Heap after GC invocations=423: memory that is in useHeap def new generation total
18432K, used 1197K [0x6eb40000, 0x6ff40000, 0x6ff40000) eden space 16384K, 0% used [0x6eb40000, 0x6eb40000, 0x6fb40000) from space 2048K, 58% used [0x6fb40000, 0x6fc6b4e8, 0x6fd40000) to space 2048K, 0% used [0x6fd40000, 0x6fd40000, 0x6ff40000) tenured generation
Amount of memory allocated total 45056K, used 6416K [0x6ff40000, 0x72b40000, 0x72b40000) the space 45056K, 14% used [0x6ff40000, 0x70584190, 0x70584200, 0x72b40000) compacting perm gen total 8192K, used 1597K [0x72b40000, 0x73340000, 0x76b40000) the space
8192K, 19% used [0x72b40000, 0x72ccf598, 0x72ccf600, 0x73340000)} - 26. Isolating the Data. Extract data • Need a very complex regular expression • CSV file, spreadsheet, with many columns Interesting data • Memory in use by each generation - Before and after each collection • Percent in use of “from space” New data - NOTE:
“After” data same as next “Before” data worth graphing - 27. Graphing and Analyzing the Data. “From Space” usage is between 10% and 60% Adjust from space size using SurvivorRatio option • -XX:SurvivorRatio=ratio • Eden-size = survivor-size * ratio • Eden-size + 2 * survivor-ratio = young-gen- size Example: •
-XX:NewSize=200M –XX:SurvivorRatio=8 • Eden: 160MB, each Survivor Space: 20MB Aim for 90-95% usage after collection • Typically, with large young generations, use larger ratio (e.g. 32) - 28. Agenda. Java Heap Management Simple Garbage Collection Statistics • Generating the Data • Isolating the Data • Graphing the Data • Interpreting the Data • Improving Performance Advanced Garbage Collection Statistics • Generate, Isolate, Graph, Interpret,
Improve Java Command Line Arguments Recap - 29. Garbage Collection Info Options. -verbose:gc • Heap usage before and after GC • Time spent during GC -XX:+ PrintGCDetails • Generation and heap size before and after GC • Time spent during GC -XX:+ PrintHeapAtGC • Generation sizes before and after GC
• Space sizes and percent in use before and after GC • Memory locations of the heap, its generations, and their spaces - 30. Java Tuning Options. -Xmssizem, -Xmxsizem • Minimum and maximum heap size • Set both sizes to the same value -XX:NewSize=sizem, -XX:MaxNewSize=sizem • Minimum and maximum young generation size • Set both sizes to the same value • Set to about 1/3 or
1/4 the size of the heap. -XX:SurvivorRatio=ratio • Number of times the eden space is larger than the “from” space • Try for maximum of 90-95% usage - 31. Conclusions. The HotSpot™ JVM provides a variety of options for gathering garbage collection statistics. Those statistics are easily extracted using • A simple Java application using • A regular expression The extracted data is easily graphed using
a spreadsheet application. Examining the resulting graph • Tells a lot about what the application is doing • Enables selection of proper heap sizing to improve performance of the application. - 32. Questions?