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?