Java™ Garbage CollectionStatistical Analysis

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?