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)

Last update: Jan 4, 2023

Related tags

Overview

GCViewer 1.36

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 ?

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), ms, sum of pauses ms. [memory ][Sat Oct 27 20:01:49 2012][23355] - start time of collection (seconds since jvm start). [memory ][Sat Oct 27 20:01:49 2012][23355] - OC (old collection) or YC (young collection). [memory ][Sat Oct 27 20:01:49 2012][23355] - end time of collection (seconds since jvm start). [memory ][Sat Oct 27 20:01:49 2012][23355] - memory used by objects before collection (KB). [memory ][Sat Oct 27 20:01:49 2012][23355] - memory used by objects after collection (KB). [memory ][Sat Oct 27 20:01:49 2012][23355] - size of heap after collection (KB). [memory ][Sat Oct 27 20:01:49 2012][23355] - total time of collection (milliseconds). [memory ][Sat Oct 27 20:01:49 2012][23355] - total sum of pauses during collection (milliseconds). [memory ][Sat Oct 27 20:01:49 2012][23355] Run with -Xverbose:gcpause to see individual phases. [gcpause][Sat Oct 27 20:04:38 2012][23355] [YC#1] [---] 468.690 ms (168.027000-168.495000) YC [gcpause][Sat Oct 27 20:04:38 2012][23355] [YC#1] [con] 0.004 ms (168.027000-168.027000) YC:PreGC [gcpause][Sat Oct 27 20:04:38 2012][23355] [YC#1] [pau] 468.590 ms (168.027000-168.495000) YC:Main [gcpause][Sat Oct 27 20:04:38 2012][23355] [YC#1] [con] 0.010 ms (168.495000-168.495000) YC:PostGC [memory ][Sat Oct 27 20:04:38 2012][23355] [YC#1] 168.027-168.495: YC 4263587KB->1265249KB (25165824KB), 0.469 s, sum of pauses 468.590 ms, longest pause 468.590 ms. [gcpause][Sat Oct 27 20:04:38 2012][23355] Thread "[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'" id=29 idx=0x60 tid=23444 was in TLA-fetch 468.827 ms from 168.027 s (1 GCs). [gcpause][Sat Oct 27 20:06:20 2012][23355] [YC#2] [---] 645.670 ms (270.685000-271.330000) YC [gcpause][Sat Oct 27 20:06:20 2012][23355] [YC#2] [con] 0.003 ms (270.685000-270.685000) YC:PreGC [gcpause][Sat Oct 27 20:06:20 2012][23355] [YC#2] [pau] 645.545 ms (270.685000-271.330000) YC:Main [gcpause][Sat Oct 27 20:06:20 2012][23355] [YC#2] [con] 0.030 ms (271.330000-271.330000) YC:PostGC [memory ][Sat Oct 27 20:06:20 2012][23355] [YC#2] 270.685-271.330: YC 4435053KB->1543400KB (25165824KB), 0.646 s, sum of pauses 645.545 ms, longest pause 645.545 ms. [gcpause][Sat Oct 27 20:06:20 2012][23355] Thread "[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'" id=29 idx=0x60 tid=23444 was in TLA-fetch 646.349 ms from 270.684 s (1 GCs). [gcpause][Sat Oct 27 20:08:25 2012][23355] [YC#3] [---] 612.496 ms (394.948000-395.561000) YC [gcpause][Sat Oct 27 20:08:25 2012][23355] [YC#3] [con] 0.003 ms (394.948000-394.948000) YC:PreGC [gcpause][Sat Oct 27 20:08:25 2012][23355] [YC#3] [pau] 612.295 ms (394.949000-395.561000) YC:Main [gcpause][Sat Oct 27 20:08:25 2012][23355] [YC#3] [con] 0.068 ms (395.561000-395.561000) YC:PostGC [memory ][Sat Oct 27 20:08:25 2012][23355] [YC#3] 394.948-395.561: YC 4696729KB->1891349KB (25165824KB), 0.612 s, sum of pauses 612.295 ms, longest pause 612.295 ms. [gcpause][Sat Oct 27 20:08:25 2012][23355] Thread "[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'" id=29 idx=0x60 tid=23444 was in TLA-fetch 612.736 ms from 394.948 s (1 GCs). [gcpause][Sat Oct 27 20:09:19 2012][23355] [YC#4] [---] 333.239 ms (449.237000-449.570000) YC [gcpause][Sat Oct 27 20:09:19 2012][23355] [YC#4] [con] 0.003 ms (449.237000-449.237000) YC:PreGC [gcpause][Sat Oct 27 20:09:19 2012][23355] [YC#4] [pau] 333.123 ms (449.237000-449.570000) YC:Main [gcpause][Sat Oct 27 20:09:19 2012][23355] [YC#4] [con] 0.038 ms (449.570000-449.570000) YC:PostGC

Regards, Ramesh
feature request

opened by rdev1991 38
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
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

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

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

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)

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 "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

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

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?)

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

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

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?

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