diff --git a/README.md b/README.md index 5a0ae65a..fb29385a 100644 --- a/README.md +++ b/README.md @@ -3,7 +3,7 @@ GCViewer 1.36 [![Build Status](https://app.travis-ci.com/chewiebug/GCViewer.svg?branch=develop)](https://app.travis-ci.com/chewiebug/GCViewer) [![codecov.io](https://codecov.io/github/chewiebug/GCViewer/coverage.svg?branch=develop)](https://codecov.io/github/chewiebug/GCViewer?branch=develop) -[![Download gcviewer](https://img.shields.io/sourceforge/dm/gcviewer.svg)](https://sourceforge.net/projects/gcviewer/files/latest/download) +[![Download gcviewer](https://img.shields.io/sourceforge/dm/gcviewer.svg)](https://sourceforge.net/projects/gcviewer/files) GCViewer is a little tool that visualizes verbose GC output generated by Sun / Oracle, IBM, HP and BEA Java Virtual Machines. It diff --git a/pom.xml b/pom.xml index 568c1727..e8b78d95 100644 --- a/pom.xml +++ b/pom.xml @@ -180,6 +180,10 @@ Pierre Viret https://github.com/pierre-viret + + Cui Weiloong + https://github.com/CuiWeiloong + Yin Xunjun diff --git a/src/main/java/com/tagtraum/perf/gcviewer/exp/impl/SummaryDataWriter.java b/src/main/java/com/tagtraum/perf/gcviewer/exp/impl/SummaryDataWriter.java index 06dcdd6d..aefb295c 100755 --- a/src/main/java/com/tagtraum/perf/gcviewer/exp/impl/SummaryDataWriter.java +++ b/src/main/java/com/tagtraum/perf/gcviewer/exp/impl/SummaryDataWriter.java @@ -6,9 +6,13 @@ import java.io.PrintWriter; import java.text.NumberFormat; import java.util.Date; +import java.util.List; import java.util.Map; +import java.util.Map.Entry; import com.tagtraum.perf.gcviewer.exp.AbstractDataWriter; +import com.tagtraum.perf.gcviewer.math.DoubleData; +import com.tagtraum.perf.gcviewer.math.DoubleDataPercentile; import com.tagtraum.perf.gcviewer.model.GCModel; import com.tagtraum.perf.gcviewer.util.FormattedValue; import com.tagtraum.perf.gcviewer.util.MemoryFormat; @@ -69,7 +73,7 @@ public SummaryDataWriter(OutputStream out, Map configuration) { private void initialiseFormatters() { pauseFormatter = NumberFormat.getInstance(); - pauseFormatter.setMaximumFractionDigits(5); + pauseFormatter.setMaximumFractionDigits(6); totalTimeFormatter = new TimeFormat(); @@ -227,6 +231,74 @@ private void exportPauseSummary(PrintWriter out, GCModel model) { exportValue(out, "fullGCPausePc", percentFormatter.format(model.getFullGCPause().getSum()*100.0/model.getPause().getSum()), "%"); exportValue(out, "gcPause", gcTimeFormatter.format(model.getGCPause().getSum()), "s"); exportValue(out, "gcPausePc", percentFormatter.format(model.getGCPause().getSum()*100.0/model.getPause().getSum()), "%"); + + // Add extra statistical data: sum, count, min, max, average, standardDeviation, median, 75th percentile, 95, 99, 99.5, 99.9 + // All Pause stats + if (pauseDataAvailable) { + exportValue(out, "pauseSum", pauseFormatter.format(model.getPause().getSum()), "s"); + // exportValue(out, "pauseCount", "" + model.getPause().getN(), "-"); + exportValue(out, "pauseMin", pauseFormatter.format(model.getPause().getMin()), "s"); + exportValue(out, "pauseMax", pauseFormatter.format(model.getPause().getMax()), "s"); + exportValue(out, "pauseAverage", pauseFormatter.format(model.getPause().average()), "s"); + exportValue(out, "pauseStandardDeviation", pauseFormatter.format(model.getPause().standardDeviation()), "s"); + exportValue(out, "pauseMedian", pauseFormatter.format(((DoubleDataPercentile)model.getPause()).getPercentile(50)), "s"); + exportValue(out, "pausePercentile75th", pauseFormatter.format(((DoubleDataPercentile)model.getPause()).getPercentile(50)), "s"); + exportValue(out, "pausePercentile95th", pauseFormatter.format(((DoubleDataPercentile)model.getPause()).getPercentile(75)), "s"); + exportValue(out, "pausePercentile99th", pauseFormatter.format(((DoubleDataPercentile)model.getPause()).getPercentile(95)), "s"); + exportValue(out, "pausePercentile99.5th", pauseFormatter.format(((DoubleDataPercentile)model.getPause()).getPercentile(99)), "s"); + exportValue(out, "pausePercentile99.9th", pauseFormatter.format(((DoubleDataPercentile)model.getPause()).getPercentile(99.9)), "s"); + } + // GC Pause stats + if (gcDataAvailable) { + exportValue(out, "gcPauseSum", pauseFormatter.format(model.getGCPause().getSum()), "s"); + // exportValue(out, "gcPauseCount", "" + model.getGCPause().getN(), "-"); + exportValue(out, "gcPauseMin", pauseFormatter.format(model.getGCPause().getMin()), "s"); + exportValue(out, "gcPauseMax", pauseFormatter.format(model.getGCPause().getMax()), "s"); + exportValue(out, "gcPauseAverage", pauseFormatter.format(model.getGCPause().average()), "s"); + exportValue(out, "gcPauseStandardDeviation", pauseFormatter.format(model.getGCPause().standardDeviation()), "s"); + exportValue(out, "gcPauseMedian", pauseFormatter.format(((DoubleDataPercentile)model.getGCPause()).getPercentile(50)), "s"); + exportValue(out, "gcPausePercentile75th", pauseFormatter.format(((DoubleDataPercentile)model.getGCPause()).getPercentile(50)), "s"); + exportValue(out, "gcPausePercentile95th", pauseFormatter.format(((DoubleDataPercentile)model.getGCPause()).getPercentile(75)), "s"); + exportValue(out, "gcPausePercentile99th", pauseFormatter.format(((DoubleDataPercentile)model.getGCPause()).getPercentile(95)), "s"); + exportValue(out, "gcPausePercentile99.5th", pauseFormatter.format(((DoubleDataPercentile)model.getGCPause()).getPercentile(99)), "s"); + exportValue(out, "gcPausePercentile99.9th", pauseFormatter.format(((DoubleDataPercentile)model.getGCPause()).getPercentile(99.9)), "s"); + } + // Full GC Pause stats + if (fullGCDataAvailable) { + exportValue(out, "fullGCPauseSum", pauseFormatter.format(model.getFullGCPause().getSum()), "s"); + // exportValue(out, "fullGCPauseCount", "" + model.getFullGCPause().getN(), "-"); + exportValue(out, "fullGCPauseMin", pauseFormatter.format(model.getFullGCPause().getMin()), "s"); + exportValue(out, "fullGCPauseMax", pauseFormatter.format(model.getFullGCPause().getMax()), "s"); + exportValue(out, "fullGCPauseAverage", pauseFormatter.format(model.getFullGCPause().average()), "s"); + exportValue(out, "fullGCPauseStandardDeviation", pauseFormatter.format(model.getFullGCPause().standardDeviation()), "s"); + exportValue(out, "fullGCPauseMedian", pauseFormatter.format(((DoubleDataPercentile)model.getFullGCPause()).getPercentile(50)), "s"); + exportValue(out, "fullGCPausePercentile75th", pauseFormatter.format(((DoubleDataPercentile)model.getFullGCPause()).getPercentile(50)), "s"); + exportValue(out, "fullGCPausePercentile95th", pauseFormatter.format(((DoubleDataPercentile)model.getFullGCPause()).getPercentile(75)), "s"); + exportValue(out, "fullGCPausePercentile99th", pauseFormatter.format(((DoubleDataPercentile)model.getFullGCPause()).getPercentile(95)), "s"); + exportValue(out, "fullGCPausePercentile99.5th", pauseFormatter.format(((DoubleDataPercentile)model.getFullGCPause()).getPercentile(99)), "s"); + exportValue(out, "fullGCPausePercentile99.9th", pauseFormatter.format(((DoubleDataPercentile)model.getFullGCPause()).getPercentile(99.9)), "s"); + } + // ZGC stats: [gc,phases] + if (model.size() > 1 && model.getGcEventPhases().size() > 0) { + DoubleData gcPhases = new DoubleDataPercentile(); + for (Entry entry : model.getGcEventPhases().entrySet()) { + List phaseList = ((DoubleDataPercentile)entry.getValue()).getDoubleData(); + for (Double d : phaseList) + gcPhases.add(d); + } + exportValue(out, "gcPhaseSum", pauseFormatter.format(gcPhases.getSum()), "s"); + exportValue(out, "gcPhaseCount", "" + gcPhases.getN(), "-"); + exportValue(out, "gcPhaseMin", pauseFormatter.format(gcPhases.getMin()), "s"); + exportValue(out, "gcPhaseMax", pauseFormatter.format(gcPhases.getMax()), "s"); + exportValue(out, "gcPhaseAverage", pauseFormatter.format(gcPhases.average()), "s"); + exportValue(out, "gcPhaseStandardDeviation", pauseFormatter.format(gcPhases.standardDeviation()), "s"); + exportValue(out, "gcPhaseMedian", pauseFormatter.format(((DoubleDataPercentile)gcPhases).getPercentile(50)), "s"); + exportValue(out, "gcPhasePercentile75th", pauseFormatter.format(((DoubleDataPercentile)gcPhases).getPercentile(50)), "s"); + exportValue(out, "gcPhasePercentile95th", pauseFormatter.format(((DoubleDataPercentile)gcPhases).getPercentile(75)), "s"); + exportValue(out, "gcPhasePercentile99th", pauseFormatter.format(((DoubleDataPercentile)gcPhases).getPercentile(95)), "s"); + exportValue(out, "gcPhasePercentile99.5th", pauseFormatter.format(((DoubleDataPercentile)gcPhases).getPercentile(99)), "s"); + exportValue(out, "gcPhasePercentile99.9th", pauseFormatter.format(((DoubleDataPercentile)gcPhases).getPercentile(99.9)), "s"); + } } private boolean isSignificant(final double average, final double standardDeviation) { diff --git a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderIBM_J9_R28.java b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderIBM_J9_R28.java index 489dd487..1b5b53c1 100644 --- a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderIBM_J9_R28.java +++ b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderIBM_J9_R28.java @@ -20,6 +20,7 @@ import javax.xml.stream.events.XMLEvent; import com.tagtraum.perf.gcviewer.model.AbstractGCEvent; +import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.ExtendedType; import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.Type; import com.tagtraum.perf.gcviewer.model.GCEvent; import com.tagtraum.perf.gcviewer.model.GCModel; @@ -92,7 +93,7 @@ public GCModel read() throws IOException { break; case EXCLUSIVE_END: handleExclusiveEnd(startElement, currentGcEvent); - if (currentGcEvent.getExtendedType() == null) { + if (currentGcEvent.getExtendedType() == null || currentGcEvent.getExtendedType() == ExtendedType.UNDEFINED) { if (getLogger().isLoggable(Level.FINE)) getLogger().fine("event at " + in.getLineNumber() + " doesn't contain any information, the parser can handle"); } diff --git a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderSun1_6_0.java b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderSun1_6_0.java index 9c72573b..3b3385af 100644 --- a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderSun1_6_0.java +++ b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderSun1_6_0.java @@ -118,6 +118,7 @@ public class DataReaderSun1_6_0 extends AbstractDataReaderSun { EXCLUDE_STRINGS_LINE_START.add("/proc/meminfo"); // apple vms seem to print this out in the beginning of the logs EXCLUDE_STRINGS_LINE_START.add("Uncommitted"); // -XX:+UseShenandoahGC EXCLUDE_STRINGS_LINE_START.add("Cancelling concurrent GC"); // -XX:+UseShenandoahGC + EXCLUDE_STRINGS_LINE_START.add("Cancelling GC"); // -XX:+UseShenandoahGC EXCLUDE_STRINGS_LINE_START.add("Capacity"); // -XX:+UseShenandoahGC -XX:+PrintGCDetails EXCLUDE_STRINGS_LINE_START.add("Periodic GC triggered"); // -XX:+UseShenandoahGC -XX:+PrintGCDetails EXCLUDE_STRINGS_LINE_START.add("Immediate Garbage"); // -XX:+UseShenandoahGC -XX:+PrintGCDetails @@ -126,7 +127,6 @@ public class DataReaderSun1_6_0 extends AbstractDataReaderSun { EXCLUDE_STRINGS_LINE_START.add("Concurrent marking triggered"); // -XX:+UseShenandoahGC -XX:+PrintGCDetails EXCLUDE_STRINGS_LINE_START.add("Adjusting free threshold"); // -XX:+UseShenandoahGC EXCLUDE_STRINGS_LINE_START.add("Predicted cset threshold"); // -XX:+UseShenandoahGC - EXCLUDE_STRINGS_LINE_START.add("Trigger"); // -XX:+UseShenandoahGC EXCLUDE_STRINGS_LINE_START.add("Free"); // -XX:+UseShenandoahGC EXCLUDE_STRINGS_LINE_START.add("Evacuation Reserve"); // -XX:+UseShenandoahGC EXCLUDE_STRINGS_LINE_START.add("Pacer for "); // -XX:+UseShenandoahGC @@ -135,6 +135,9 @@ public class DataReaderSun1_6_0 extends AbstractDataReaderSun { EXCLUDE_STRINGS_LINE_START.add(" Adaptive CSet Selection"); // -XX:+UseShenandoahGC EXCLUDE_STRINGS_LINE_START.add(" Collectable Garbage"); // -XX:+UseShenandoahGC EXCLUDE_STRINGS_LINE_START.add(" Immediate Garbage"); // -XX:+UseShenandoahGC + EXCLUDE_STRINGS_LINE_START.add(" Good progress for"); // -XX:+UseShenandoahGC + EXCLUDE_STRINGS_LINE_START.add(" Failed to"); // -XX:+UseShenandoahGC + EXCLUDE_STRINGS_LINE_START.add(" Cancelling GC"); // -XX:+UseShenandoahGC EXCLUDE_STRINGS_LINE_CONTAIN.add(LOGFILE_ROLLING_BEGIN); EXCLUDE_STRINGS_LINE_CONTAIN.add(LOGFILE_ROLLING_END); @@ -155,6 +158,8 @@ public class DataReaderSun1_6_0 extends AbstractDataReaderSun { LOG_INFORMATION_STRINGS.add("Reference processing"); // -XX:+UseShenandoahGC LOG_INFORMATION_STRINGS.add("Heuristics ergonomically sets"); // -XX:+UseShenandoahGC LOG_INFORMATION_STRINGS.add("Initialize Shenandoah heap"); // -XX:+UseShenandoahGC + LOG_INFORMATION_STRINGS.add("Shenandoah GC mode"); // -XX:+UseShenandoahGC + LOG_INFORMATION_STRINGS.add("Soft Max Heap Size"); // -XX:+UseShenandoahGC } private static final String EVENT_YG_OCCUPANCY = "YG occupancy"; @@ -253,6 +258,8 @@ public class DataReaderSun1_6_0 extends AbstractDataReaderSun { private static final String SHENANDOAH_DETAILS_FINAL_MARK_SPLIT_START = "Total"; private static final String SHENANDOAH_INTRODUCTION_TO_GC_STATISTICS = "Shenandoah Heap"; + private static final String SHENANDOAH_GC_CYCLE_DETAILS_START = "All times are wall-clock times"; + private static final String SHENANDOAH_GC_CYCLE_START = "Trigger: "; // -XX:+PrintReferenceGC private static final String PRINT_REFERENCE_GC_INDICATOR = "Reference"; @@ -309,9 +316,17 @@ else if (startsWith(line, LOG_INFORMATION_STRINGS, false)) { continue; } else if (line.startsWith(SHENANDOAH_INTRODUCTION_TO_GC_STATISTICS)) { // Assumption: As soon as the shenandoah gc statistics block starts, the vm is shutting down - skipAndLogToEndOfFile(in); + skipAndLogToEndOfFile(in, line); + continue; + } else if (line.startsWith(SHENANDOAH_GC_CYCLE_START)) { + // skip the start string of the first gc cycle + continue; + } else if (line.startsWith(SHENANDOAH_GC_CYCLE_DETAILS_START)) { + // ignore details of each gc cycle + skipGcCycleDetails(in); continue; } + if (line.indexOf(CMS_ABORT_PRECLEAN) >= 0) { // line contains like " CMS: abort preclean due to time " // -> remove the text @@ -485,13 +500,27 @@ else if (beginningOfLine.size() > 0) { } } - private void skipAndLogToEndOfFile(LineNumberReader in) throws IOException { - String line; + private void skipAndLogToEndOfFile(LineNumberReader in, String line) throws IOException { + getLogger().info(line); while ((line = in.readLine()) != null) { getLogger().info(line); } } + private void skipGcCycleDetails(LineNumberReader in) throws IOException { + String line; + while ((line = in.readLine()) != null) { + // parse the events for the next GC cycle + if (line.startsWith(SHENANDOAH_GC_CYCLE_START)) { + break; + } + // the vm is shutting down + if (line.startsWith(SHENANDOAH_INTRODUCTION_TO_GC_STATISTICS)) { + skipAndLogToEndOfFile(in, line); + } + } + } + private boolean isPrintHeapAtGcStarting(String line) { return line.startsWith(HEAP) // jdk 6 and before || line.indexOf(HEAP_SIZING_BEFORE) >= 0 // jdk 7 and after diff --git a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderTools.java b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderTools.java index 883b9d61..e7d2085f 100644 --- a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderTools.java +++ b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderTools.java @@ -69,7 +69,7 @@ public ExtendedType parseType(String typeString) throws UnknownGcTypeException { } /** - * Same as @{link {@link #parseType(String)}}, but returns null instead of exception, if no type could + * Same as {@link #parseType(String)}, but returns null instead of exception, if no type could * be found. * * @param typeName string representation of the gc event diff --git a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java index 1e48f014..47489aa2 100644 --- a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java +++ b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java @@ -60,8 +60,9 @@ public class DataReaderUnifiedJvmLogging extends AbstractDataReader { // Group 6 / tail: Pause Init Mark 1.070ms // Regex: ^(?:\[(?