Fork of tagtraum industries' GCViewer. Tagtraum stopped development in 2008, I aim to improve support for Sun's / Oracle's java 1.6+ garbage collector logs (including G1 collector)

Related tags

Profilers GCViewer
Overview

GCViewer 1.36

Build Status codecov.io

GCViewer is a little tool that visualizes verbose GC output generated by Sun / Oracle, IBM, HP and BEA Java Virtual Machines. It is free software released under GNU LGPL.

You can start GCViewer (gui) by simply double-clicking on gcviewer-1.3x.jar or running java -jar gcviewer-1.3x.jar (it needs a java 1.8 vm to run).

For a cmdline based report summary just type the following to generate a report (including optional chart image file): java -jar gcviewer-1.3x.jar gc.log summary.csv [chart.png] [-t PLAIN|CSV|CSV_TS|SIMPLE|SUMMARY] When logfile rotation (-XX:+UseGCLogFileRotation) is enabled, the logfiles can be read at once: java -jar gcviewer-1.3x.jar gc.log.0;gc.log.1;gc.log.2;gc.log.current summary.csv [chart.png] [-t PLAIN|CSV|CSV_TS|SIMPLE|SUMMARY]

Supported verbose:gc formats are:

  • some support for OpenJDK 9 / 10 unified logging format -Xlog:gc:, the following configurations will work
    • -Xlog:gc:file="path-to-file" (uses defaults)
    • -Xlog:gc=info:file="path-to-file":tags,uptime,level (minimum configuration needed)
    • -Xlog:gc*=trace:file="path-to-file":tags,time,uptime,level (maximum configuration supported, additional tags ok, but ignored; additional decorations will break parsing)
  • Oracle JDK 1.8 -Xloggc: [-XX:+PrintGCDetails] [-XX:+PrintGCDateStamps]
  • Sun / Oracle JDK 1.7 with option -Xloggc: [-XX:+PrintGCDetails] [-XX:+PrintGCDateStamps]
  • Sun / Oracle JDK 1.6 with option -Xloggc: [-XX:+PrintGCDetails] [-XX:+PrintGCDateStamps]
  • Sun JDK 1.4/1.5 with the option -Xloggc: [-XX:+PrintGCDetails]
  • Sun JDK 1.2.2/1.3.1/1.4 with the option -verbose:gc
  • IBM JDK 1.3.1/1.3.0/1.2.2 with the option -verbose:gc
  • IBM iSeries Classic JVM 1.4.2 with option -verbose:gc
  • HP-UX JDK 1.2/1.3/1.4.x with the option -Xverbosegc
  • BEA JRockit 1.4.2/1.5/1.6 with the option -verbose:memory [-Xverbose:gcpause,gcreport] [-Xverbosetimestamp]

Best results for non unified gc logging Oracle JDKs are achieved with: -Xloggc: -XX:+PrintGCDetails -XX:+PrintGCDateStamps. A few other options are supported, but most of the information generated is ignored by GCViewer (the javadoc introduction of https://github.com/chewiebug/GCViewer/blob/master/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderSun1_6_0.java shows the details).

Hendrik Schreiber wrote GCViewer up to 1.29. What you are seeing here is based on his very good work. Links to detailed descriptions of many JVM parameters relevant to garbage collection can be found in the links section of https://github.com/chewiebug/GCViewer/wiki

Results of log analysis

There are two sections, where the results of the log analysis are shown. One is the left side with the chart, the other the data panel on the right side. In the following, the content of these sections is explained.

Chart

GCViewer shows a number of lines etc. in a chart (first tab). These are:

  • Full GC Lines:
    • Black vertical line at every Full GC
  • Inc GC Lines:
    • Cyan vertical line at every Incremental GC
  • GC Times Line:
    • Green line that shows the length of all GCs
  • GC Times Rectangles:
    • black rectangle at every Full GC
    • blue rectangle at every inital mark event
    • orange rectangle at every remark event
    • red rectangle at every vm operation event ("application stopped...")
    • Grey rectangle at every 'normal' GC
    • Light grey rectangle at every Incremental GC
  • Total Heap:
    • Red line that shows heap size
  • Tenured Generation:
    • Magenta area that shows the size of the tenured generation (not available without PrintGCDetails)
  • Young Generation:
    • Orange area that shows the size of the young generation (not available without PrintGCDetails)
  • Used Heap:
    • Blue line that shows used heap size
  • Initial mark level:
    • Yellow line that shows the heap usage at "initial-mark" event (only available when the gc algorithm uses concurrent collections, which is the case for CMS and G1)
  • Concurrent collections
    • Cyan vertical line for every begin (concurrent-mark-start) and pink vertical line for every end (CMS-concurrent-reset / G1: concurrent-cleanup-end) of a concurrent collection cycle

Event details

In the second tab it shows details about the events it parsed: E.g. events like the following

24.187: [GC 24.188: [ParNew: 93184K->5464K(104832K), 0.0442895 secs]
93184K->5464K(1036928K), 0.0447149 secs]
[Times: user=0.39 sys=0.07, real=0.05 secs]

are shown in one line as GC ParNew: , , ...

Events like these

4183.962: [Full GC 4183.962: [CMS: 32957K->40326K(932096K), 2.3313389 secs]
76067K->40326K(1036928K), [CMS Perm : 43837K->43453K(43880K)], 2.3339606 secs]
[Times: user=2.33 sys=0.01, real=2.33 secs]

are shown as Full GC; CMS; CMS Perm ...

So for every line the text is extracted (not always every part of it). This allows a user which is familiar with the text log files to find out more details about the events that occurred.

median, 75th...

These columns show the median, 75th percentile etc.

Gc pauses

This are shows all stop-the-world pauses, that are not full gc pauses.

Full gc pauses

In this area all pauses are shown, which GCViewer considers as "full gc" pauses. The current definition of a "full gc" is: Either the gc algorithm prints "full gc" in its event name, or more than one generation (young, old, permgen / metaspace) were involved during collection.

VM operations overhead (safepoint pauses)

This area is only shown, if the gc log was written with the option -XX:+PrintGCApplicationStoppedTime. To understand the meaning of this metric, it is important to know about safepoints (see e.g. http://blog.ragozin.info/2012/10/safepoints-in-hotspot-jvm.html).

If GCViewer finds gc log lines like the following: 2017-03-29T14:37:12.812+0200: 8.832: [GC (Allocation Failure)
[PSYoungGen: 29146K->3457K(29184K)] 78228K->52539K(116736K), 0.0009340 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs] 2017-03-29T14:37:12.813+0200: 8.833: Total time for which application
threads were stopped: 0.0010682 seconds, Stopping threads took: 0.0000155 seconds

GCViewer will report one event in the "Gc pauses" area and one in this area. The pause duration reported for "Total time..." will be 0.0001342s (0.0010682 (duration of safepoint pause) - 0.0009340 (duration of gc pause)) So GCViewer only calculates the additional overhead needed for the whole safepoint on top of the gc pause.

If the event immediately before the "Total time..." event was not a any kind of gc pause, but another "Total time..." event, then the whole pause for "Total time..." will be recorded for this event. In this case the safepoint was not caused by a gc pause.

Concurrent GCs

This are contains information about concurrent collection cycles, if the gc algorithm used them. The time reported here is spent while the application threads are running. It is possible to read here, how long concurrent gc operations took until they finished.

Parser

In the third tab the output of the parser is shown. If there were warnings during the parsing process or other output, you can check there.

Data Panel

GCViewer provides some metrics to help you interpret the chart. Note that some metrics based on averages are shown along with their standard deviation. If it is obvious that the standard deviation is fairly big in comparison to the average, the values are grayed out, indicating that actual values are much smaller or bigger than the average.

Summary

  • Footprint:
    • Maximal amount of memory allocated
  • Max heap after conc GC:
    • Max used heap after concurrent gc.
  • Max tenured after conc GC:
    • Max used tenured heap after concurrent gc (followed by % of max tenured / % of max total heap).
  • Max heap after full GC:
    • Max used heap after full gc. Indicates max live object size and can help to determine heap size.
  • Freed Memory:
    • Total amount of memory that has been freed
  • Freed Mem/Min:
    • Amount of memory that has been freed per minute
  • Total Time:
    • Time data was collected for (only if timestamp was present in log)
  • Acc Pauses:
    • Sum of all pauses due to GC
  • Throughput:
    • Time percentage the application was NOT busy with GC
  • Full GC Performance:
    • Performance of full collections. Note that all collections that include a collection of the tenured generation or are marked with "Full GC" are considered Full GC.
  • GC Performance:
    • Performance of minor collections. These are collections that are not full according to the definition above.

Memory

  • Total heap (usage / alloc max):
    • Max memory usage / allocation in total heap (the last is the same as "footprint" in Summary)
  • Tenured heap (usage / alloc max):
    • Max memory usage / allocation in tenured space
  • Young heap (usage / alloc max):
    • Max memory usage / allocation in young space
  • Perm heap (usage / alloc max):
    • Max memory usage / allocation in perm space
  • Max tenured after conc GC:
    • see in "summary" section
  • Avg tenured after conc GC:
    • average size of tenured heap after concurrent collection
  • Max heap after conc GC:
    • see in "summary" section
  • Avg heap after conc GC:
    • average size of concurrent heap after concurrent collection
  • Max heap after full GC:
    • see in "summary" section
  • Avg after full GC:
    • The average heap memory consumption after a full collection
  • Avg after GC:
    • The average heap memory consumption after a minor collection
  • Freed Memory:
    • Total amount of memory that has been freed
  • Freed by full GC:
    • Amount of memory that has been freed by full collections
  • Freed by GC:
    • Amount of memory that has been freed by minor collections
  • Avg freed full GC:
    • Average amount of memory that has been freed by full collections
  • Avg freed GC:
    • Average amount of memory that has been freed by minor collections
  • Avg rel inc after FGC:
    • Average relative increase in memory consumption between full collections. This is the average difference between the memory consumption after a full collection to the memory consumption after the next full collection.
  • Avg rel inc after GC:
    • Average relative increase in memory consumption between minor collections. This is the average difference between the memory consumption after a minor collection to the memory consumption after the next minor collection. This can be used as an indicator for the amount of memory that survives minor collections and has to be moved to the survivor spaces or the tenured generation. This value added to "Avg freed GC" gives you an idea about the size of the young generation in case you don't have PrintGCDetails turned on.
  • Slope full GC:
    • Slope of the regression line for the memory consumption after full collections. This can be used as an indicator for the increase in indispensable memory consumption (base footprint) of an application over time.
  • Slope GC:
    • Average of the slope of the regression lines for the memory consumption after minor collections in between full collections. That is, if you have two full collections and many minor collections in between, GCViewer will calculate the slope for the minor collections up to the first full collection, then the slope of the minor collections between the first and the second full collection. Then it will compute a weighted average (each slope wil be weighted with the number of measuring points it was computed with).
  • initiatingOccFraction (avg / max)
    • CMS GC kicks in before tenured generation is filled. InitiatingOccupancyFraction tells you the avg / max usage in % of the tenured generation, when CMS GC started (initial mark). This value can be set manually using -XX:CMSInitiatingOccupancyFraction=.
  • avg promotion
    • Promotion means the size of objects that are promoted from young to tenured generation during a young generation collection. Avg promotion shows the average amount of memory that is promoted from young to tenured with each young collection (only available with PrintGCDetails)
  • total promotion
    • Total promotion shows the total amount of memory that is promoted from young to tenured with all young collections in a file (only available with PrintGCDetails)

Pause

  • Acc Pauses:
    • Sum of all pauses due to any kind of GC
  • Number of Pauses:
    • Count of all pauses due to any kind of GC
  • Avg Pause:
    • Average length of a GC pause of any kind
  • Min / max Pause:
    • Shortest /longest pause of any kind
  • Avg pause interval:
    • avg interval between two pauses of any kind
  • Min / max pause interval:
    • Min / max interval between two pauses of any kind

  • Acc full GC:
    • Sum of all pauses due to full collections
  • Number of full GC pauses:
    • Count of all pauses due to full collections
  • Acc GC:
    • Sum of all full GC pauses
  • Avg full GC:
    • Average length of a full GC pause
  • Min / max full GC pause:
    • Shortest / longest full GC pause
  • Min / max full GC pause interval:
    • Min / max interval between two pauses due to full collections

  • Acc GC:
    • Sum of all pauses due to minor collections
  • Number of GC pauses:
    • Count of all pauses due to minor collections
  • Avg GC:
    • Average length of a minor collection pause
  • Min / max GC pause:
    • Shortest / longest minor GC pause

Notes

This is not a perfect tool. However, GCViewer can help you getting a grip on finding out what's going on in your application with regards to garbage collection.

Here are some known limitations.

IBM JDKs

If you have problems with the IBM format, please check that every line of information is really in one line and not wrapped.

The IBM format actually provides a lot more information than is visualized.

Sun JDK 1.3.1/1.4 with -verbose:gc

Sun JDK 1.3.1/1.4 with -verbose:gc does not provide a timestamp. Therefore values like 'Total Time', 'Throughput', and 'Freed Mem/Min' cannot be calculated.

Sun / Oracle JDK 1.6 / 1.7 / 1.8 (a.k.a. Java 6 / 7 / 8)

CMS and G1 collector sometimes mix concurrent events with stop the world collections in the output. In some cases the parser can recover from such mixed lines, sometimes it can't and will show an error message.

BEA JRockit 1.4.2/1.5/1.6

Concurrently collected garbage may not be reflected correctly in the data panel.

Export formats

CSV Comma Separated Values The CSV format is quite useful for importing the data to a spreadsheet application. However, it does not export all data.

CSV_TS Comma Separated Values CSV format using unix timestamp and one line per gc event.

PLAIN Plain Data Plain text representation of the gc log. If written from Sun / Oracle gc log it is usually compatible with HPjmeter.

SIMPLE Simple GC Log Very simple representation of a gc log in the format . This format is compatible with gchisto (http://java.net/projects/gchisto)

SUMMARY Detailed summary exporting all details about a gc log file (same as shown in data panel).

Internationalization

Provided are a German, an English and a Swedish localStrings.properties file. If someone feels the need to translate these to another language, please do so. I will be more than glad, to include it in a future version of this tool.

Start of log / absolute times

If you happen to know when the application and GC log was started, you can specify this time by right-clicking on the time ruler and entering a start time. Sun / Oracle VMs: If -XX:+PrintGCDateStamps was used, the proposed start time is read from the gc log file.

Bug reports

If you are a developer, you may fork (http://help.github.com/fork-a-repo/) the repository on http://github.com/chewiebug/GCViewer and send me a pull request (http://help.github.com/send-pull-requests/). If you plan a bigger change I'd appreciate a notice in advance.

To file a bug report, please open an issue on http://github.com/chewiebug/GCViewer/issues or send an email to [email protected] with a description of the error, the name of the JVM that produced the GC data and all used flags along with a sample GC log file.

Building GCViewer from Source

Download and install Maven3 from http://maven.apache.org/ Download the src distribution of GCViewer. Execute from the GCViewer base directory (same as pom.xml):

mvn clean install

The executable jar will be placed in the target directory.

Enjoy!

Joerg Wuethrich
http://github.com/chewiebug/GCViewer
[email protected]

Comments
  • Jrockit 1.5 support ?

    Jrockit 1.5 support ?

    Is GCViewer supports JRockit 1.5's GC logs ? Coz i am not able view GC logs generated on one of my application running on JRockit 1.5.

    -Xverboselog:gc.log -verbose:memory -Xverbose:gcpause,gcreport -Xverbosetimestamp

    [memory ][Sat Oct 27 20:01:49 2012][23355] Running with 32 bit heap and compressed references supporting 32GB heap. [memory ][Sat Oct 27 20:01:49 2012][23355] GC mode: Garbage collection optimized for short pausetimes, strategy: Generational Concurrent Mark & Sweep. [memory ][Sat Oct 27 20:01:49 2012][23355] Heap size: 25165824KB, maximal heap size: 25165824KB, nursery size: 4194304KB. [memory ][Sat Oct 27 20:01:49 2012][23355] -: KB->KB (KB),

    Regards, Ramesh

    feature request 
    opened by rdev1991 38
  • Strange parsing issue concerning G1 collector

    Strange parsing issue concerning G1 collector

    Hi,

    First of all, it would be great if gcviewer could ignore the "G1Ergonomics" messages from the -XX:+PrintAdaptiveSizePolicy setting.

    Second, I do have a strange bug while parsing gc log files.

    This one works fine :

    2015-02-13T17:12:01.182+0100: 195,970: Total time for which application threads were stopped: 0,0001000 seconds 2015-02-13T17:12:01.265+0100: 196,053: [GC pause (G1 Evacuation Pause) (young) Desired survivor size 20447232 bytes, new threshold 15 (max 15)

    • age 1: 503304 bytes, 503304 total
    • age 2: 43928 bytes, 547232 total , 0,0331820 secs] [Parallel Time: 22,5 ms, GC Workers: 4] [GC Worker Start (ms): Min: 196053,3, Avg: 196053,3, Max: 196053,4, Diff: 0,1] [Ext Root Scanning (ms): Min: 11,0, Avg: 11,5, Max: 12,1, Diff: 1,1, Sum: 46,1] [Update RS (ms): Min: 0,6, Avg: 1,1, Max: 1,5, Diff: 0,9, Sum: 4,3] [Processed Buffers: Min: 12, Avg: 19,0, Max: 30, Diff: 18, Sum: 76] [Scan RS (ms): Min: 0,9, Avg: 1,0, Max: 1,0, Diff: 0,1, Sum: 3,8] [Code Root Scanning (ms): Min: 0,0, Avg: 0,0, Max: 0,1, Diff: 0,0, Sum: 0,1] [Object Copy (ms): Min: 8,4, Avg: 8,7, Max: 8,9, Diff: 0,5, Sum: 34,9] [Termination (ms): Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0] [GC Worker Other (ms): Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,1] [GC Worker Total (ms): Min: 22,3, Avg: 22,4, Max: 22,4, Diff: 0,1, Sum: 89,4] [GC Worker End (ms): Min: 196075,7, Avg: 196075,7, Max: 196075,7, Diff: 0,0] [Code Root Fixup: 0,0 ms] [Code Root Migration: 0,1 ms] [Clear CT: 0,5 ms] [Other: 10,1 ms] [Choose CSet: 0,0 ms] [Ref Proc: 8,6 ms] [Ref Enq: 0,2 ms] [Free CSet: 1,0 ms] [Eden: 304,0M(304,0M)->0,0B(279,0M) Survivors: 3072,0K->28,0M Heap: 418,0M(512,0M)->139,3M(512,0M)] [Times: user=0,09 sys=0,00, real=0,03 secs] 2015-02-13T17:12:01.299+0100: 196,087: Total time for which application threads were stopped: 0,0338710 seconds

    But, this one doesn't work :

    2015-02-13T17:12:01.196+0100: 195,854: Total time for which application threads were stopped: 0,0000890 seconds 2015-02-13T17:12:01.729+0100: 196,388: [GC pause (G1 Evacuation Pause) (young) Desired survivor size 20447232 bytes, new threshold 15 (max 15)

    • age 1: 6700576 bytes, 6700576 total
    • age 2: 10504568 bytes, 17205144 total
    • age 3: 320040 bytes, 17525184 total
    • age 4: 92336 bytes, 17617520 total , 0,0608680 secs] [Parallel Time: 48,4 ms, GC Workers: 4] [GC Worker Start (ms): Min: 196388,7, Avg: 196390,4, Max: 196394,8, Diff: 6,1] [Ext Root Scanning (ms): Min: 14,1, Avg: 16,5, Max: 20,1, Diff: 6,0, Sum: 66,0] [Update RS (ms): Min: 0,0, Avg: 0,6, Max: 2,2, Diff: 2,2, Sum: 2,2] [Processed Buffers: Min: 0, Avg: 20,8, Max: 83, Diff: 83, Sum: 83] [Scan RS (ms): Min: 0,3, Avg: 1,4, Max: 2,5, Diff: 2,2, Sum: 5,7] [Code Root Scanning (ms): Min: 0,0, Avg: 0,1, Max: 0,1, Diff: 0,1, Sum: 0,2] [Object Copy (ms): Min: 26,6, Avg: 27,4, Max: 28,5, Diff: 1,9, Sum: 109,6] [Termination (ms): Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,1] [GC Worker Other (ms): Min: 0,0, Avg: 0,0, Max: 0,1, Diff: 0,0, Sum: 0,2] [GC Worker Total (ms): Min: 41,6, Avg: 46,0, Max: 47,8, Diff: 6,2, Sum: 183,9] [GC Worker End (ms): Min: 196436,4, Avg: 196436,4, Max: 196436,4, Diff: 0,0] [Code Root Fixup: 0,1 ms] [Code Root Migration: 0,2 ms] [Clear CT: 0,3 ms] [Other: 11,8 ms] [Choose CSet: 0,0 ms] [Ref Proc: 10,5 ms] [Ref Enq: 0,3 ms] [Free CSet: 0,7 ms] [Eden: 281,0M(281,0M)->0,0B(180,0M) Survivors: 26,0M->39,0M Heap: 398,8M(512,0M)->138,5M(512,0M)] [Times: user=0,20 sys=0,00, real=0,06 secs] 2015-02-13T17:12:01.791+0100: 196,450: Total time for which application threads were stopped: 0,0624330 seconds

    I couldn't see any structural difference between these two samples. Here are the error messages:

    AVERTISSEMENT [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.ParseException: Error parsing entry (java.lang.ArrayIndexOutOfBoundsException) Line 245: 2015-02-13T17:12:01.729+0100: 196,388: [GC pause (G1 Evacuation Pause) (young) AVERTISSEMENT [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: '' Line 251: , 0,0608680 secs] AVERTISSEMENT [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'Parallel Time' Line 252: [Parallel Time: 48,4 ms, GC Workers: 4] AVERTISSEMENT [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'GC Worker Start (ms)' Line 253: [GC Worker Start (ms): Min: 196388,7, Avg: 196390,4, Max: 196394,8, Diff: 6,1] AVERTISSEMENT [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'Ext Root Scanning (ms)' Line 254: [Ext Root Scanning (ms): Min: 14,1, Avg: 16,5, Max: 20,1, Diff: 6,0, Sum: 66,0] AVERTISSEMENT [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'Update RS (ms)' Line 255: [Update RS (ms): Min: 0,0, Avg: 0,6, Max: 2,2, Diff: 2,2, Sum: 2,2] AVERTISSEMENT [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'Processed Buffers' Line 256: [Processed Buffers: Min: 0, Avg: 20,8, Max: 83, Diff: 83, Sum: 83] AVERTISSEMENT [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'Scan RS (ms)' Line 257: [Scan RS (ms): Min: 0,3, Avg: 1,4, Max: 2,5, Diff: 2,2, Sum: 5,7] AVERTISSEMENT [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'Code Root Scanning (ms)' Line 258: [Code Root Scanning (ms): Min: 0,0, Avg: 0,1, Max: 0,1, Diff: 0,1, Sum: 0,2] AVERTISSEMENT [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'Object Copy (ms)' Line 259: [Object Copy (ms): Min: 26,6, Avg: 27,4, Max: 28,5, Diff: 1,9, Sum: 109,6] AVERTISSEMENT [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'Termination (ms)' Line 260: [Termination (ms): Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,1] AVERTISSEMENT [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'GC Worker Other (ms)' Line 261: [GC Worker Other (ms): Min: 0,0, Avg: 0,0, Max: 0,1, Diff: 0,0, Sum: 0,2] AVERTISSEMENT [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'GC Worker Total (ms)' Line 262: [GC Worker Total (ms): Min: 41,6, Avg: 46,0, Max: 47,8, Diff: 6,2, Sum: 183,9] AVERTISSEMENT [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'GC Worker End (ms)' Line 263: [GC Worker End (ms): Min: 196436,4, Avg: 196436,4, Max: 196436,4, Diff: 0,0] AVERTISSEMENT [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'Code Root Fixup' Line 264: [Code Root Fixup: 0,1 ms] AVERTISSEMENT [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'Code Root Migration' Line 265: [Code Root Migration: 0,2 ms] AVERTISSEMENT [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'Clear CT' Line 266: [Clear CT: 0,3 ms] AVERTISSEMENT [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'Other' Line 267: [Other: 11,8 ms] AVERTISSEMENT [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'Choose CSet' Line 268: [Choose CSet: 0,0 ms] AVERTISSEMENT [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'Ref Proc' Line 269: [Ref Proc: 10,5 ms] AVERTISSEMENT [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'Ref Enq' Line 270: [Ref Enq: 0,3 ms] AVERTISSEMENT [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'Free CSet' Line 271: [Free CSet: 0,7 ms]

    Any clue ?

    bug 
    opened by YouriAndropov 33
  • Use SwingWorker to read GCModel in a background thread

    Use SwingWorker to read GCModel in a background thread

    In the current 1.33 implementation the Swing event dispatcher thread is blocked during loading the GCModel. It means that you cannot select anything in the menu, you cannot even quit the application.

    I've created a fix in https://github.com/hbswn/GCViewer It's not production ready, but for developers it's nice to play with.

    I added:

    • GCModelLoader extends SwingWorker<GCModel, Object>: loads GCModel and sends progress update events
    • MonitoredBufferedInputStream: a simple (but not complete) way to monitor progress
    • ShutdownHandler: make sure the threads are interrupted, when the application is stopped. (but maybe ExecutorService.shutdown* methods do a better job)
    • A parser Logger per URL: otherwise concurrent logging causes some weird behaviour. (info for other files being logged in the error window)

    Some issues:

    • The progress bar does not look very well but it works
    • The progress code only uses the input file position. It should monitor the entire loading process including parsing
    • DataReaderFacade is now a singleton. I needed a single "DataReader" thread group and ThreadFactory. Maybe a better solution exists.
    • I would prefer to create GCModel before the DataReader is started. Then we can add some properties to monitor the loading process (e.g. file size, date and the current position). GCModel can be passed to the reader and returned, when it's done. Also the parser logger can be created in GCModel and with GCModel's hashCode in its name.
    • If loading a file/URL failed, then the item is not removed from the Window list
    • GCModelLoader should be canceled if ChartPanelView is closed

    Let me know, what you think. (maybe I should create a Google+ account)

    feature request 
    opened by hbswn 29
  • Support GC log file rotation

    Support GC log file rotation

    Java 7 supports Rolling GC logs files with the parameters -XX:+UseGCLogFileRotation -XX:GCLogFileSize=M -XX:NumberOfGCLogFiles= the files will be suffexed with .1 .2 .3 etc....

    GCViewer should be able to read all the files at once and merge them in correct order. Add a checkbox to load all related files or add a popup dialog to ask if you want to load all related log files.

    feature request 
    opened by lifey 23
  • Support to parse PrintGCID

    Support to parse PrintGCID

    Hi,

    Fixed https://github.com/chewiebug/GCViewer/issues/197

    Testcase:

    Command Line:

    -Xloggc:specjbb2015-psgc-`date +%Y%m%d%H%M%S`.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+PrintGCID
    

    GC log:

    2022-07-26T23:30:28.892+0800: 8991.259: #353: [Full GC (System.gc()) [PSYoungGen: 384K->0K(7465472K)] [ParOldGen: 325752K->325474K(1048576K)] 326136K->325474K(8514048K), [Metaspace: 20971K->20971K(1069056K)], 0.4225592 secs] [Times: user=1.49 sys=0.01, real=0.43 secs]
    

    Please review my patch.

    Thanks, Leslie Zhai

    opened by xiangzhai 17
  • Support for ShenandoahGC in non unified jvm logging format

    Support for ShenandoahGC in non unified jvm logging format

    Hi,

    As a GC tuner I'd like GCViewer to support ShenandoahGC, the ultra low pause time collector. See https://wiki.openjdk.java.net/display/shenandoah/Main

    Best, Jeroen

    opened by jborgers 17
  • Add support for -XX:+PrintGCCause (will be on by default in Java 8)

    Add support for -XX:+PrintGCCause (will be on by default in Java 8)

    In java 8, this will be on by default. In the next non-security Java 7 release, it is going to be available via the -XX:+PrintGCCause flag (it's currently available in ea build)

    The AbstractGCEvent.parse method currently barfs when hit with a GC log message that comes out of something with the PrintGCCause information in it:

    the log entries look like:

    "GC pause (G1 Evacuation Pause) (young)"

    This will not be just for G1, this additional detail will be provided for all collectors - it makes the parsing in AbstractGCEvent.parse a bit trickier because it will have to know that

    "GC pause (G1 Evacuation Pause) (young)" "GC pause (G1 Humongous Allocation) (young)"

    both map to:

    "GC pause (young)"

    Looking at the JDK7 / JDK8 sources - the constants are defined in the gcCause.cpp file:

    System.gc() FullGCAlot ScavengeAlot Allocation Profiler JvmtiEnv ForceGarbageCollection GCLocker Initiated GC Heap Inspection Initiated GC Heap Dump Initiated GC No GC Allocation Failure Tenured Generation Full Metadata GC Threshold CMS Generation Full CMS Initial Mark CMS Final Remark Old Generation Expanded On Last Scavenge Old Generation Too Full To Scavenge Ergonomics G1 Evacuation Pause G1 Humongous Allocation Last ditch collection ILLEGAL VALUE - last gc cause - ILLEGAL VALUE unknown GCCause

    Java 7 has

    Permanent Generation Full

    instead of "Metadata GC Threshold"

    I can help with a patch if you have an idea of where this might be easiest to wedge in

    feature request 
    opened by ryangardner 17
  • gcviewer-1.35-SNAPSHOT throws warnings

    gcviewer-1.35-SNAPSHOT throws warnings "Unknown gc type"

    Just gave it a try and ended up getting lot of warnings. java -jar gcviewer-1.35-SNAPSHOT.jar gc.log.0 summary.csv chart.png -t CSV_TS

    gc logs generated as follows: /usr/java/jre1.7.0_51//bin/java -ea -javaagent:/usr/share/dse/cassandra/lib/jamm-0.2.5.jar -XX:+UseThreadPriorities -XX:ThreadPriorityPolicy=42 -Xms14G -Xmx14G -XX:+HeapDumpOnOutOfMemoryError -XX:NewRatio=2 -XX:MaxTenuringThreshold=10 -XX:+DisableExplicitGC -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+CMSParallelRemarkEnabled -XX:SurvivorRatio=8 -XX:CMSInitiatingOccupancyFraction=75 -XX:+UseCMSInitiatingOccupancyOnly -XX:+UseTLAB -XX:+UseCondCardMark -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -XX:+PrintTenuringDistribution -XX:+PrintGCApplicationStoppedTime -XX:+PrintPromotionFailure -XX:PrintFLSStatistics=1 -Xloggc:/var/log/cassandra/gc.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=64M

    WARNING: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'concurrent mark-sweep generation total' Line 309835: concurrent mar k-sweep generation total 9786752K, used 6660868K [0x00000005a58a0000, 0x00000007fae00000, 0x00000007fae00000) Jan 16, 2015 1:41:06 AM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0 read WARNING: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'concurrent-mark-sweep perm gen total' Line 309836: concurrent-mark- sweep perm gen total 83968K, used 51110K [0x00000007fae00000, 0x0000000800000000, 0x0000000800000000) Jan 16, 2015 1:41:06 AM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0 read WARNING: com.tagtraum.perf.gcviewer.imp.ParseException: Error parsing entry (java.lang.ArrayIndexOutOfBoundsException) Line 309837: } Jan 16, 2015 1:41:06 AM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0 read WARNING: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'GCHeap after GC invocations=' Line 309892: 2015-01-10T22:38:37.116+0 000: 81720.358: [GCHeap after GC invocations=4682 (full 16): Jan 16, 2015 1:41:06 AM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0 read WARNING: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'par new generation total' Line 309893: par new generation total 4404032K, used 63139K [0x000000047ae00000, 0x00000005a58a0000, 0x00000005a58a0000) Jan 16, 2015 1:41:06 AM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0 read WARNING: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'eden space' Line 309894: eden space 3914752K, 0% used [0x0000000 47ae00000, 0x000000047ae00000, 0x0000000569d00000) Jan 16, 2015 1:41:06 AM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0 read WARNING: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'from space' Line 309895: from space 489280K, 12% used [0x00000005 69d00000, 0x000000056daa8eb8, 0x0000000587ad0000) Jan 16, 2015 1:41:07 AM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0 read WARNING: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'to space' Line 309896: to space 489280K, 0% used [0x00000005 87ad0000, 0x0000000587ad0000, 0x00000005a58a0000) Jan 16, 2015 1:41:07 AM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0 read WARNING: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'concurrent mark-sweep generation total' Line 309897: concurrent mar k-sweep generation total 9786752K, used 6663249K [0x00000005a58a0000, 0x00000007fae00000, 0x00000007fae00000) Jan 16, 2015 1:41:07 AM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0 read WARNING: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'concurrent-mark-sweep perm gen total' Line 309898: concurrent-mark- sweep perm gen total 83968K, used 51110K [0x00000007fae00000, 0x0000000800000000, 0x0000000800000000)

    bug 
    opened by krishna81m 15
  • UnifiedLogging from Java 11 not completely parsable

    UnifiedLogging from Java 11 not completely parsable

    The information in the unified jvm logging is in Java 11 slightly different than in Java 9 and 10. Therefore parsing the gc logging from Java 11 fails with the following errors.

    WARNUNG [DataReaderUnifiedJvmLogging]: Failed to parse gc event (com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'Pause Young (Normal) (G1 Evacuation Pause)') on line number 4 (line="[1.015s][info][gc,start ] GC(0) Pause Young (Normal) (G1 Evacuation Pause)") WARNUNG [DataReaderUnifiedJvmLogging]: Didn't find parent event for partial event [1.026] GC(0) [Eden regions:: 24576K->0K(153600K), 0.0 secs] (line number 10, line="[1.026s][info][gc,heap ] GC(0) Eden regions: 24->0(150)" WARNUNG [DataReaderUnifiedJvmLogging]: Didn't find parent event for partial event [1.026] GC(0) [Survivor regions:: 0K->3072K(3072K), 0.0 secs] (line number 11, line="[1.026s][info][gc,heap ] GC(0) Survivor regions: 0->3(3)" WARNUNG [DataReaderUnifiedJvmLogging]: Didn't find parent event for partial event [1.027] GC(0) [Old regions:: 0K->4096K(0K), 0.0 secs] (line number 12, line="[1.027s][info][gc,heap ] GC(0) Old regions: 0->4" WARNUNG [DataReaderUnifiedJvmLogging]: Didn't find parent event for partial event [1.027] GC(0) [Humongous regions:: 5120K->5120K(0K), 0.0 secs] (line number 13, line="[1.027s][info][gc,heap ] GC(0) Humongous regions: 5->5" WARNUNG [DataReaderUnifiedJvmLogging]: Didn't find parent event for partial event [1.027] GC(0) [Metaspace:: 16948K->16948K(1064960K), 0.0 secs] (line number 14, line="[1.027s][info][gc,metaspace ] GC(0) Metaspace: 16948K->16948K(1064960K)"

    Java 9/10 GC logging [1.379s][info][gc,start ] GC(0) Pause Young (G1 Evacuation Pause)

    Java 11 GC logging [1.015s][info][gc,start ] GC(0) Pause Young (Normal) (G1 Evacuation Pause)

    There also seems to be different types than Normal. I found the following different warnings in my log file. WARNUNG [DataReaderUnifiedJvmLogging]: Failed to parse gc event (com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'Pause Young (Concurrent Start) (G1 Evacuation Pause)') on line number 401 (line="[25.574s][info][gc ] GC(28) Pause Young (Concurrent Start) (G1 Evacuation Pause) 205M->131M(256M) 4.154ms") WARNUNG [DataReaderUnifiedJvmLogging]: Failed to parse gc event (com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'Pause Young (Prepare Mixed) (G1 Evacuation Pause)') on line number 427 (line="[25.667s][info][gc,start ] GC(30) Pause Young (Prepare Mixed) (G1 Evacuation Pause)")

    GC logging configuration for all Java versions

    -Xlog:gc*:file=gc.log

    Java 11 version

    openjdk version "11" 2018-09-25 OpenJDK Runtime Environment 18.9 (build 11+28) OpenJDK 64-Bit Server VM 18.9 (build 11+28, mixed mode)

    opened by theobisproject 11
  • Add support for ZGC logging

    Add support for ZGC logging

    Added ZGC GC log in unified JVM logging format to GCViewer. Currently parsing all 3 STW pause events as well as all 7 concurrency events. These info are listed in [gc,phases] so we had to include that for parsing in ZGC. Memory info are displayed separately, the pre and post used heap sizes are only displayed every GC cycle, not at every pause. For total heap, we parsed the capacity block in [gc,heap]. Currently we are only parsing the capacity block, but there are information in the [gc,heap] section that could be useful in future improvements.

    I had to add a line in the pom file on javadoc plugin because travis build is failing, it has recently started running JDK 11.0.2 (only that version fails, 11.0.1 works fine) Also did some refactoring around the classes I have touched.

    opened by yanqilee 10
  • 1.31 has problems reading 1.6.0_24_64 output (maybe caused by -XX:-UseAdaptiveSizePolicy -XX:+PrintAdaptiveSizePolicy?)

    1.31 has problems reading 1.6.0_24_64 output (maybe caused by -XX:-UseAdaptiveSizePolicy -XX:+PrintAdaptiveSizePolicy?)

    Hey! Trying to tune an app, logged GC with -XX:+PrintGCDetails -XX:-UseAdaptiveSizePolicy -XX:+PrintAdaptiveSizePolicy -XX:+PrintGCDateStamps -Xloggc:[...].

    GCViewer 1.31 does not show anything, but reports 3 errors and some warnings:

    INFO [DataReaderFactory]: File format: Sun 1.6.x INFO [DataReaderSun1_6_0]: Reading Sun / Oracle 1.4.x / 1.5.x / 1.6.x / 1.7.x format... WARNING [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.ParseException: problem resetting stream (java.io.IOException: Mark invalid) Line 462: 2012-09-26T18:23:54.092+0200: 6591.672: [GCAdaptiveSizePolicy::compute_survivor_space_size_and_thresh: survived: 3994640 promoted: 49152 overflow: false [PSYoungGen: 783920K->3901K(786304K)] 1036641K->256670K(1042304K), 0.0078830 secs] [Times: user=0.04 sys=0.00, real=0.01 secs] WARNING [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.ParseException: Error parsing entry (java.lang.NumberFormatException: For input string: "260017K->111440K(1042304K)") Line 529: 2012-09-26T18:34:25.956+0200: 7223.537: [GC2012-09-26T18:34:25.964+0200: 7223.545: [Full GC [PSYoungGen: 4064K->0K(786304K)] [ParOldGen: 255953K->111440K(256000K)] 260017K->111440K(1042304K) [PSPermGen: 142360K->138587K(262144K)], 1.2956780 secs] [Times: user=4.32 sys=0.02, real=1.30 secs] WARNING [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.ParseException: problem resetting stream (java.io.IOException: Mark invalid) Line 1154: 2012-09-26T20:08:16.521+0200: 12854.102: [GCAdaptiveSizePolicy::compute_survivor_space_size_and_thresh: survived: 3866624 promoted: 49152 overflow: false [PSYoungGen: 784000K->3776K(786304K)] 925980K->145804K(1042304K), 0.0068860 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] WARNING [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.ParseException: problem resetting stream (java.io.IOException: Mark invalid) Line 1614: 2012-09-26T21:17:48.435+0200: 17026.016: [GCAdaptiveSizePolicy::compute_survivor_space_size_and_thresh: survived: 3932160 promoted: 49152 overflow: false [PSYoungGen: 783872K->3840K(786304K)] 948627K->168643K(1042304K), 0.0060840 secs] [Times: user=0.04 sys=0.00, real=0.01 secs] WARNING [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.ParseException: problem resetting stream (java.io.IOException: Mark invalid) Line 2074: 2012-09-26T22:29:15.085+0200: 21312.665: [GCAdaptiveSizePolicy::compute_survivor_space_size_and_thresh: survived: 3801088 promoted: 49152 overflow: false [PSYoungGen: 783808K->3712K(786304K)] 971314K->191266K(1042304K), 0.0073270 secs] [Times: user=0.04 sys=0.00, real=0.01 secs] WARNING [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.ParseException: problem resetting stream (java.io.IOException: Mark invalid) Line 2534: 2012-09-26T23:41:40.907+0200: 25658.488: [GCAdaptiveSizePolicy::compute_survivor_space_size_and_thresh: survived: 3899392 promoted: 49152 overflow: false [PSYoungGen: 783840K->3808K(786304K)] 993664K->213680K(1042304K), 0.0062760 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] WARNING [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.ParseException: problem resetting stream (java.io.IOException: Mark invalid) Line 2993: 2012-09-27T00:55:27.250+0200: 30084.831: [GCAdaptiveSizePolicy::compute_survivor_space_size_and_thresh: survived: 3932160 promoted: 40960 overflow: false [PSYoungGen: 783808K->3840K(786304K)] 1015958K->236030K(1042304K), 0.0067370 secs] [Times: user=0.04 sys=0.00, real=0.01 secs] WARNING [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.ParseException: problem resetting stream (java.io.IOException: Mark invalid) Line 3222: 2012-09-27T01:32:25.304+0200: 32302.885: [GCAdaptiveSizePolicy::compute_survivor_space_size_and_thresh: survived: 3964928 promoted: 40960 overflow: false [PSYoungGen: 783864K->3872K(786304K)] 1026982K->247030K(1042304K), 0.0069120 secs] [Times: user=0.04 sys=0.00, real=0.00 secs] WARNING [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.ParseException: problem resetting stream (java.io.IOException: Mark invalid) Line 3451: 2012-09-27T02:09:51.757+0200: 34549.337: [GCAdaptiveSizePolicy::compute_survivor_space_size_and_thresh: survived: 3932160 promoted: 49152 overflow: false [PSYoungGen: 783872K->3840K(786304K)] 1038197K->258213K(1042304K), 0.0071970 secs] [Times: user=0.04 sys=0.00, real=0.00 secs] WARNING [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.ParseException: Error parsing entry (java.lang.NumberFormatException: For input string: "259765K->114749K(1042304K)") Line 3485: 2012-09-27T02:15:26.242+0200: 34883.822: [GC2012-09-27T02:15:26.249+0200: 34883.829: [Full GC [PSYoungGen: 3808K->0K(786304K)] [ParOldGen: 255957K->114749K(256000K)] 259765K->114749K(1042304K) [PSPermGen: 143531K->139011K(262144K)], 0.5934780 secs] [Times: user=1.82 sys=0.01, real=0.59 secs] WARNING [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.ParseException: problem resetting stream (java.io.IOException: Mark invalid) Line 3681: 2012-09-27T02:44:37.901+0200: 36635.481: [GCAdaptiveSizePolicy::compute_survivor_space_size_and_thresh: survived: 4014096 promoted: 40960 overflow: false [PSYoungGen: 783872K->3920K(786304K)] 907269K->127357K(1042304K), 0.0056990 secs] [Times: user=0.04 sys=0.00, real=0.01 secs] WARNING [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.ParseException: problem resetting stream (java.io.IOException: Mark invalid) Line 4141: 2012-09-27T03:53:37.575+0200: 40775.156: [GCAdaptiveSizePolicy::compute_survivor_space_size_and_thresh: survived: 3929104 promoted: 49152 overflow: false [PSYoungGen: 783904K->3837K(786304K)] 928926K->148907K(1042304K), 0.0057890 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] WARNING [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.ParseException: problem resetting stream (java.io.IOException: Mark invalid) Line 4601: 2012-09-27T05:03:04.944+0200: 44942.525: [GCAdaptiveSizePolicy::compute_survivor_space_size_and_thresh: survived: 3964928 promoted: 49152 overflow: false [PSYoungGen: 783872K->3872K(786304K)] 949992K->170040K(1042304K), 0.0061710 secs] [Times: user=0.04 sys=0.00, real=0.01 secs] WARNING [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.ParseException: problem resetting stream (java.io.IOException: Mark invalid) Line 5061: 2012-09-27T06:13:24.398+0200: 49161.978: [GCAdaptiveSizePolicy::compute_survivor_space_size_and_thresh: survived: 3899392 promoted: 40960 overflow: false [PSYoungGen: 783837K->3808K(786304K)] 971070K->191081K(1042304K), 0.0065200 secs] [Times: user=0.04 sys=0.00, real=0.00 secs] WARNING [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.ParseException: problem resetting stream (java.io.IOException: Mark invalid) Line 5521: 2012-09-27T07:23:58.066+0200: 53395.646: [GCAdaptiveSizePolicy::compute_survivor_space_size_and_thresh: survived: 3997696 promoted: 40960 overflow: false [PSYoungGen: 783872K->3904K(786304K)] 991872K->211944K(1042304K), 0.0070690 secs] [Times: user=0.04 sys=0.00, real=0.00 secs] WARNING [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.ParseException: problem resetting stream (java.io.IOException: Mark invalid) Line 5980: 2012-09-27T08:35:10.220+0200: 57667.801: [GCAdaptiveSizePolicy::compute_survivor_space_size_and_thresh: survived: 4227088 promoted: 49152 overflow: false [PSYoungGen: 784192K->4128K(786304K)] 1012880K->232864K(1042304K), 0.0068950 secs] [Times: user=0.04 sys=0.00, real=0.01 secs] WARNING [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.ParseException: Error parsing entry (java.lang.NumberFormatException: For input string: "1014212K->1040157K(1042304K).") Line 6003: 2012-09-27T08:38:47.257+0200: 57884.837: [GC2012-09-27T08:38:56.052+0200: 57893.633: [GC-- [PSYoungGen: 784160K->784160K(786304K)] 1014212K->1040157K(1042304K), 0.3464400 secs] [Times: user=0.41 sys=0.41, real=0.34 secs] WARNING [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.ParseException: problem resetting stream (java.io.IOException: Mark invalid) Line 6015: 2012-09-27T10:06:38.415+0200: 63155.996: [GCAdaptiveSizePolicy::compute_survivor_space_size_and_thresh: survived: 6389792 promoted: 7036960 overflow: true [PSYoungGen: 786272K->6240K(786304K)] 983913K->210753K(1042304K), 0.0312370 secs]

    INFO [DataReaderSun1_6_0]: Done reading.

    Best regards, Kai

    feature request 
    opened by ka-ba 10
  • The reported freed memory is incorrect

    The reported freed memory is incorrect

    There are some cases, the GC pauses increase the memory heap size, example below:

    [2022-08-23T14:36:33.337+0200][0.157s] GC(2) Pause Young (Normal) (G1 Evacuation Pause) 147M->148M(1028M) 7.903ms --> increased by 1mb

    the GCVIWER in this case will do the following: before= 147 after=148 totalFreedMemory+=before - after ; --> in this case we subtract the totalFreedMemory by (1)

    The solution should avoid adding into the totalFreedMemory when before-after is <0 : before= 147 after=148 diff= before - after totalFreedMemory+= diff >= 0 ? diff : 0

    Please apply a fix to this issue, as the reported totalFreedMemory is incorrect.

    Regards, Alkadri

    opened by Kadri314 0
  • enhance support for zgc and shenandoah

    enhance support for zgc and shenandoah

    The latest GCViewer failed to parse some gc events of ZGC and ShenandoahGC. I fixed some bugs and added some gc event types in this PR.

    1. The event "Metaspace" in gc tag "[gc,metaspace]" don't match the "PATTERN_MEMORY" rules for ZGC and don't have GC number for Shenandoah, ignored in "DataReaderUnifiedJvmLogging.java:handleTagGcMetaspaceTail()" method.
    // ZGC:
    //  [1.182s][info][gc,metaspace] GC(0) Metaspace: 19M used, 19M capacity, 19M committed, 20M reserved
    //  [1.182s][info][gc,metaspace] GC(0) Metaspace: 11M used, 12M committed, 1088M reserved
    // G1:
    //  [5.537s][info][gc,metaspace] GC(0) Metaspace: 118K(320K)->118K(320K) NonClass: 113K(192K)->113K(192K) Class: 4K(128K)->4K(128K
    // Shenandoah:
    // [5.063s][info][gc,metaspace] Metaspace: 13104K(13376K)->13192K(13440K) NonClass: 1345K(11456K)->11431K(11520K) Class: 1758K(1920K)->1761K(1920K)
    
    1. [gc,heap] -> Unknown gc type for ZGC: Excludes all lines that do not contain Capacity.
    [1.182s][info][gc,metaspace] GC(0) Metaspace: 19M used, 19M capacity, 19M committed, 20M reserved
    [1.182s][info][gc,heap     ] GC(0)                Mark Start          Mark End        Relocate Start      Relocate End           High               Low    
    [1.182s][info][gc,heap     ] GC(0)  Capacity:      448M (11%)         452M (11%)         454M (11%)         454M (11%)         454M (11%)         448M (11%)        
    [1.182s][info][gc,heap     ] GC(0)   Reserve:       48M (1%)           48M (1%)           48M (1%)           48M (1%)           48M (1%)           48M (1%)         
    [1.182s][info][gc,heap     ] GC(0)      Free:     3506M (89%)        3502M (89%)        3758M (95%)        3874M (98%)        3874M (98%)        3500M (89%)        
    [1.182s][info][gc,heap     ] GC(0)      Used:      400M (10%)         404M (10%)         148M (4%)           32M (1%)          406M (10%)          32M (1%)         
    [1.182s][info][gc,heap     ] GC(0)      Live:         -                 6M (0%)            6M (0%)            6M (0%)             -                  -              
    [1.182s][info][gc,heap     ] GC(0) Allocated:         -                 4M (0%)           10M (0%)           32M (1%)             -                  -              
    [1.182s][info][gc,heap     ] GC(0)   Garbage:         -               393M (10%)         131M (3%)           13M (0%)             -                  -              
    [1.182s][info][gc,heap     ] GC(0) Reclaimed:         -                  -               262M (7%)          380M (10%)            -                  -              
    
    1. Add new gc events "Concurrent Mark Free,Allocation Stall,Relocation Stall" for ZGC.
    2. Update some gc events that contain wrong GcPattern for ShenandoahGC.
    3. Add percentiles data to output csv file.
    4. Add "[gc,init" to LOG_ONLY_STRINGS.

    Please review this PR.

    Thanks, Weilong Cui

    opened by CuiWeiloong 3
  • Failed to parse gc event

    Failed to parse gc event "Merge Heap Roots" on Adopt OpenJDK 17

    We recently switched from Adopt OpenJDK 11 to 17 using G1.

    Now when parsing the GC-Logs there are many warnings in the GCViewer output:

    Jan 05, 2022 7:48:56 PM com.tagtraum.perf.gcviewer.imp.DataReaderUnifiedJvmLogging parseEvent
    WARNING: Failed to parse gc event (com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: '  Merge Heap Roots:') on line number 80268 (line="[2022-01-05T19:31:03.896+0100][11354.358s][info][gc,phases   ] GC(5340)   Merge Heap Roots: 0.7ms")
    Jan 05, 2022 7:48:56 PM com.tagtraum.perf.gcviewer.imp.DataReaderUnifiedJvmLogging parseGcMemoryTail
    WARNING: Expected only memory in the end of line number 80277 (line="[2022-01-05T19:31:03.896+0100][11354.358s][info][gc,metaspace] GC(5340) Metaspace: 419661K(422592K)->419661K(422592K) NonClass: 376477K(377408K)->376477K(377408K) Class: 43183K(45184K)->43183K(45184K)")
    Jan 05, 2022 7:48:56 PM com.tagtraum.perf.gcviewer.imp.DataReaderUnifiedJvmLogging parseEvent
    WARNING: Failed to parse gc event (com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: '  Merge Heap Roots:') on line number 80283 (line="[2022-01-05T19:31:19.578+0100][11370.040s][info][gc,phases   ] GC(5341)   Merge Heap Roots: 1.1ms")
    Jan 05, 2022 7:48:56 PM com.tagtraum.perf.gcviewer.imp.DataReaderUnifiedJvmLogging parseGcMemoryTail
    WARNING: Expected only memory in the end of line number 80277 (line="[2022-01-05T19:31:03.896+0100][11354.358s][info][gc,metaspace] GC(5340) Metaspace: 419661K(422592K)->419661K(422592K) NonClass: 376477K(377408K)->376477K(377408K) Class: 43183K(45184K)->43183K(45184K)")
    

    We're using the decorators tags,time,uptime,level

    Best regards, Bohne

    opened by Bohne 1
  • What do you think of changing the license to Apache 2.0?

    What do you think of changing the license to Apache 2.0?

    The current license for GCViewer is LGPL which limits how the users can use the software. In practice, many projects can't really use GCViewer as a library because of LGPL restrictions, and the only use is "ad-hoc manual use".

    For instance, Apache Software Foundation forbids depending on LPGL-licensed software (see https://www.apache.org/legal/resolved.html#category-x ) because it Places restrictions on larger works

    There are lots of cases when LGPL dependencies were removed from the ASF projects. Even though LGPL "allows" users to link with unmodified software. The thing is users do not know if they would need to modify the dependency in future, and if they depend on LGPL, and later they decide they need modifications, they are in trouble: you need to deal with licensing, etc, etc. On the other hand, Apache 2.0 license provides users with clear picture on how they can modify the software should they need that.


    Here's a recent example where Apache Airflow team convinced requests library from Python to remove dependency on LGPL-licensed chardet: https://issues.apache.org/jira/browse/LEGAL-572 I believe that is not the only case when the ASF convinced other projects that LGPL is not quite right for the libraries.

    So here's my question: do you really want to limit users on the way they can use GCViewer? Do you expect that there are valid reasons to split "parser" and "UI" into different jars (modules) so people can use the parser from the command line or integrate into other UIs?

    If you expect that you allow people to use GCViewer as a library, then the better license would be Apache 2.0

    opened by vlsi 2
One file java script for visualizing JDK flight recorder execution logs as flamegraphs without any dependencies except Java and a browser.

Flamegraph from JFR logs Simple one file Java script to generate flamegraphs from Java flight recordings without installing Perl and the Brendan Gregg

Billy Sjöberg 17 Oct 2, 2022
Utilities for HDR Histogram logs manipulation

HdrLogProcessing Utilities for HDR Histogram logs manipulation. This repo currently includes utilities for summarizing and unioning of logs. Requires

Nitsan Wakart 29 May 25, 2022
JDK 17 development

Welcome to the JDK! For build instructions please see the online documentation, or either of these files: doc/building.html (html version) doc/buildin

OpenJDK 134 Dec 6, 2022
JDK main-line development

Welcome to the JDK! For build instructions please see the online documentation, or either of these files: doc/building.html (html version) doc/buildin

OpenJDK 14.6k Dec 5, 2022
JVM Explorer is a Java desktop application for browsing loaded class files inside locally running Java Virtual Machines.

JVM Explorer JVM Explorer is a Java desktop application for browsing loaded class files inside locally running Java Virtual Machines. Features Browse

null 109 Nov 30, 2022
A Java agent that rewrites bytecode to instrument allocation sites

The Allocation Instrumenter is a Java agent written using the java.lang.instrument API and ASM. Each allocation in your Java program is instrumented;

Google 437 Nov 30, 2022
Java memory allocation profiler

Aprof - Java Memory Allocation Profiler What is it? The Aprof project is a Java Memory Allocation Profiler with very low performance impact on profile

Devexperts 210 Oct 13, 2022
Sampling CPU and HEAP profiler for Java featuring AsyncGetCallTrace + perf_events

async-profiler This project is a low overhead sampling profiler for Java that does not suffer from Safepoint bias problem. It features HotSpot-specifi

null 5.7k Dec 3, 2022
BTrace - a safe, dynamic tracing tool for the Java platform

btrace A safe, dynamic tracing tool for the Java platform Version 2.1.0 Quick Summary BTrace is a safe, dynamic tracing tool for the Java platform. BT

btrace.io 5.3k Dec 5, 2022
Java Agent for Memory Measurements

Overview Jamm provides MemoryMeter, a Java agent for all Java versions to measure actual object memory use including JVM overhead. Use To use MemoryMe

Jonathan Ellis 620 Nov 10, 2022
Get Method Sampling from Java Flight Recorder Dump and convert to FlameGraph compatible format.

Note: Travis has removed the support for Oracle JDK 8. Therefore the build status is removed temporarily. Converting JFR Method Profiling Samples to F

M. Isuru Tharanga Chrishantha Perera 247 Nov 7, 2022
Tool for creating reports from Java Flight Recorder dumps

jfr-report-tool Tool for creating reports from Java Flight Recorder dumps. Influenced by https://github.com/chrishantha/jfr-flame-graph . Kudos to @ch

Lari Hotari 50 Oct 28, 2022
Log analyser / visualiser for Java HotSpot JIT compiler. Inspect inlining decisions, hot methods, bytecode, and assembly. View results in the JavaFX user interface.

JITWatch Log analyser and visualiser for the HotSpot JIT compiler. Video introduction to JITWatch video Slides from my LJC lightning talk on JITWatch

AdoptOpenJDK 2.8k Dec 1, 2022
Java monitoring for the command-line, profiler included

jvmtop is a lightweight console application to monitor all accessible, running jvms on a machine. In a top-like manner, it displays JVM internal metri

null 1.1k Nov 24, 2022
A java agent to generate method mappings to use with the linux `perf` tool

perf-map-agent A java agent to generate /tmp/perf-<pid>.map files for just-in-time(JIT)-compiled methods for use with the Linux perf tools. Build Make

null 1.5k Dec 3, 2022
PerfJ is a wrapper of linux perf for java programs.

PerfJ PerfJ is a wrapper of linux perf for java programs. As Brendan Gregg's words In order to profile java programs, you need a profiler that can sam

Min Zhou 354 Nov 24, 2022
OOM diagnostics for Java.

Polarbear A tool to help diagnose OutOfMemoryError conditions. Polarbear helps track down the root cause of OutOfMemoryError exceptions in Java. When

Cue 20 May 14, 2019
Inline raw ASM instructions in Java

asm-inline At first I thought: Oh, I can make an optimization transformer for Proguard And then this happened. Example: public class Test { public

null 23 Oct 24, 2022
Some utility classes around java records

record-util Some utility classes around java records On the menu MapTrait Transform any record to a java.util.Map just by implementing the interface M

Rémi Forax 32 Apr 6, 2022