Skip to content
This repository has been archived by the owner on May 26, 2023. It is now read-only.

gc log data not recognised #3

Open
dbwrangler opened this issue Sep 27, 2017 · 4 comments
Open

gc log data not recognised #3

dbwrangler opened this issue Sep 27, 2017 · 4 comments

Comments

@dbwrangler
Copy link

Hi

Trying out your viewer for the first time and get an error. I've successfully parsed this gc log with other viewers, it has 14k lines. Error:

gc alg: parallel=False, g1gc=True, cms=False
line 0: warning: Skipping data file with no valid points

set term png size 1024,768; set output "default-stw-mixed.png"; set xdata time; set ylabel "Secs"; set timefmt "%Y-%m-%d:%H:%M:%S"; plot "mixed-pause.dat" using 1:2 title "mixed"
^
line 0: x range is invalid

line 0: warning: Skipping data file with no valid points
line 0: warning: Skipping data file with no valid points
line 0: warning: Skipping data file with no valid points

set term png size 1024,768; set output "default-mixed-duration.png"; set xdata time; set timefmt "%Y-%m-%d:%H:%M:%S"; plot "mixed_duration.dat" using 1:2 title "mixed-gc-duration(ms)"
^
line 0: x range is invalid

line 0: warning: Skipping data file with no valid points

set term png size 1024,768; set output "default-mixed-duration-count.png"; set xdata time; set timefmt "%Y-%m-%d:%H:%M:%S"; plot "mixed_duration.dat" using 1:3 title "mixed-gc-count"
^
line 0: x range is invalid

I have installed pip requirements and brew installed as suggested.

Any pointers?

thanks
@marlier
Copy link

marlier commented Sep 27, 2017

Can you provide the command line that you're running, and possibly a snippet of the log?

@dbwrangler
Copy link
Author

sure...

python gc_log_visualizer.py gc-2017-09-26_10-38-14.log

{Heap before GC invocations=0 (full 0):
garbage-first heap total 33554432K, used 147456K [0x0000000140000000, 0x0000000141004000, 0x0000000940000000)
region size 16384K, 10 young (163840K), 0 survivors (0K)
Metaspace used 20820K, capacity 21148K, committed 21248K, reserved 22528K
2017-09-26T10:38:25.055+0200: 10.151: [GC pause (Metadata GC Threshold) (young) (initial-mark)
Desired survivor size 645922816 bytes, new threshold 15 (max 15)
, 0.0289907 secs]
[Parallel Time: 21.1 ms, GC Workers: 16]
[GC Worker Start (ms): Min: 10151.7, Avg: 10154.1, Max: 10158.9, Diff: 7.2]
[Ext Root Scanning (ms): Min: 0.1, Avg: 5.7, Max: 11.9, Diff: 11.8, Sum: 90.8]
[Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Code Root Scanning (ms): Min: 0.0, Avg: 3.0, Max: 12.6, Diff: 12.6, Sum: 48.5]
[Object Copy (ms): Min: 0.0, Avg: 7.6, Max: 11.6, Diff: 11.6, Sum: 121.8]
[Termination (ms): Min: 0.0, Avg: 1.2, Max: 1.6, Diff: 1.6, Sum: 18.7]
[Termination Attempts: Min: 1, Avg: 229.4, Max: 376, Diff: 375, Sum: 3671]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.6]
[GC Worker Total (ms): Min: 12.7, Avg: 17.5, Max: 19.9, Diff: 7.2, Sum: 280.5]
[GC Worker End (ms): Min: 10171.6, Avg: 10171.6, Max: 10171.6, Diff: 0.0]
[Code Root Fixup: 0.3 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 7.4 ms]
ps-MacBook-Pro:gc_log_visualizer p$ head -100 gc-2017-09-26_10-38-14.log
Java HotSpot(TM) 64-Bit Server VM (25.141-b15) for windows-amd64 JRE (1.8.0_141-b15), built on Jul 12 2017 04:25:12 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 100652852k(97232056k free), swap 100650992k(96851484k free)
CommandLine flags: -XX:+AlwaysPreTouch -XX:CompileCommandFile=C:\APPS\apache-cassandra-3.11.0-bin\conf\hotspot_compiler -XX:ConcGCThreads=16 -XX:G1MaxNewSizePercent=80 -XX:G1NewSizePercent=30 -XX:G1RSetUpdatingPauseTimePercent=5 -XX:G1ReservePercent=20 -XX:GCLogFileSize=10485760 -XX:+HeapDumpOnOutOfMemoryError -XX:InitialHeapSize=34359738368 -XX:InitiatingHeapOccupancyPercent=0 -XX:+ManagementServer -XX:MaxHeapSize=34359738368 -XX:NumberOfGCLogFiles=10 -XX:ParallelGCThreads=16 -XX:+ParallelRefProcEnabled -XX:+PerfDisableSharedMem -XX:+PrintGC -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+PrintPromotionFailure -XX:+PrintTenuringDistribution -XX:-ReduceInitialCardMarks -XX:+ResizeTLAB -XX:StringTableSize=1000003 -XX:ThreadPriorityPolicy=42 -XX:ThreadStackSize=256 -XX:+UnlockExperimentalVMOptions -XX:-UseBiasedLocking -XX:-UseCompressedOops -XX:+UseG1GC -XX:+UseGCLogFileRotation -XX:-UseLargePagesIndividualAllocation -XX:-UseNUMA -XX:+UseTLAB -XX:+UseThreadPriorities
2017-09-26T10:38:23.005+0200: 8.087: Total time for which application threads were stopped: 0.0001054 seconds, Stopping threads took: 0.0000171 seconds
2017-09-26T10:38:23.130+0200: 8.199: Total time for which application threads were stopped: 0.0001306 seconds, Stopping threads took: 0.0000230 seconds
2017-09-26T10:38:23.660+0200: 8.732: Total time for which application threads were stopped: 0.0002544 seconds, Stopping threads took: 0.0000273 seconds
2017-09-26T10:38:23.785+0200: 8.858: Total time for which application threads were stopped: 0.0002377 seconds, Stopping threads took: 0.0000226 seconds
2017-09-26T10:38:23.801+0200: 8.868: Total time for which application threads were stopped: 0.0001037 seconds, Stopping threads took: 0.0000145 seconds
2017-09-26T10:38:23.816+0200: 8.890: Total time for which application threads were stopped: 0.0001374 seconds, Stopping threads took: 0.0000141 seconds
2017-09-26T10:38:24.019+0200: 9.091: Total time for which application threads were stopped: 0.0002834 seconds, Stopping threads took: 0.0000452 seconds
2017-09-26T10:38:24.035+0200: 9.103: Total time for which application threads were stopped: 0.0001481 seconds, Stopping threads took: 0.0000158 seconds
2017-09-26T10:38:24.628+0200: 9.701: Total time for which application threads were stopped: 0.0004895 seconds, Stopping threads took: 0.0001485 seconds
2017-09-26T10:38:24.674+0200: 9.750: Total time for which application threads were stopped: 0.0003009 seconds, Stopping threads took: 0.0000623 seconds
2017-09-26T10:38:24.674+0200: 9.753: Total time for which application threads were stopped: 0.0001297 seconds, Stopping threads took: 0.0000137 seconds
2017-09-26T10:38:24.711+0200: 9.807: Total time for which application threads were stopped: 0.0002514 seconds, Stopping threads took: 0.0000213 seconds
2017-09-26T10:38:24.728+0200: 9.824: Total time for which application threads were stopped: 0.0004345 seconds, Stopping threads took: 0.0002326 seconds
{Heap before GC invocations=0 (full 0):
garbage-first heap total 33554432K, used 147456K [0x0000000140000000, 0x0000000141004000, 0x0000000940000000)
region size 16384K, 10 young (163840K), 0 survivors (0K)
Metaspace used 20820K, capacity 21148K, committed 21248K, reserved 22528K
2017-09-26T10:38:25.055+0200: 10.151: [GC pause (Metadata GC Threshold) (young) (initial-mark)
Desired survivor size 645922816 bytes, new threshold 15 (max 15)
, 0.0289907 secs]
[Parallel Time: 21.1 ms, GC Workers: 16]
[GC Worker Start (ms): Min: 10151.7, Avg: 10154.1, Max: 10158.9, Diff: 7.2]
[Ext Root Scanning (ms): Min: 0.1, Avg: 5.7, Max: 11.9, Diff: 11.8, Sum: 90.8]
[Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Code Root Scanning (ms): Min: 0.0, Avg: 3.0, Max: 12.6, Diff: 12.6, Sum: 48.5]
[Object Copy (ms): Min: 0.0, Avg: 7.6, Max: 11.6, Diff: 11.6, Sum: 121.8]
[Termination (ms): Min: 0.0, Avg: 1.2, Max: 1.6, Diff: 1.6, Sum: 18.7]
[Termination Attempts: Min: 1, Avg: 229.4, Max: 376, Diff: 375, Sum: 3671]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.6]
[GC Worker Total (ms): Min: 12.7, Avg: 17.5, Max: 19.9, Diff: 7.2, Sum: 280.5]
[GC Worker End (ms): Min: 10171.6, Avg: 10171.6, Max: 10171.6, Diff: 0.0]
[Code Root Fixup: 0.3 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 7.4 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 6.3 ms]
[Ref Enq: 0.4 ms]
[Redirty Cards: 0.2 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.1 ms]
[Eden: 160.0M(9824.0M)->0.0B(9792.0M) Survivors: 0.0B->32.0M Heap: 160.0M(32.0G)->16.5M(32.0G)]
Heap after GC invocations=1 (full 0):
garbage-first heap total 33554432K, used 16865K [0x0000000140000000, 0x0000000141004000, 0x0000000940000000)
region size 16384K, 2 young (32768K), 2 survivors (32768K)
Metaspace used 20820K, capacity 21148K, committed 21248K, reserved 22528K
}
[Times: user=0.19 sys=0.00, real=0.03 secs]
2017-09-26T10:38:25.085+0200: 10.181: [GC concurrent-root-region-scan-start]
2017-09-26T10:38:25.085+0200: 10.181: Total time for which application threads were stopped: 0.0296970 seconds, Stopping threads took: 0.0000538 seconds
2017-09-26T10:38:25.094+0200: 10.190: [GC concurrent-root-region-scan-end, 0.0091381 secs]
2017-09-26T10:38:25.094+0200: 10.190: [GC concurrent-mark-start]
2017-09-26T10:38:25.095+0200: 10.191: [GC concurrent-mark-end, 0.0011907 secs]
2017-09-26T10:38:25.095+0200: 10.191: [GC remark 2017-09-26T10:38:25.095+0200: 10.191: [Finalize Marking, 0.0005783 secs] 2017-09-26T10:38:25.096+0200: 10.192: [GC ref-proc, 0.0052066 secs] 2017-09-26T10:38:25.101+0200: 10.197: [Unloading, 0.0091120 secs], 0.0156080 secs]
[Times: user=0.25 sys=0.00, real=0.02 secs]
2017-09-26T10:38:25.111+0200: 10.207: Total time for which application threads were stopped: 0.0157313 seconds, Stopping threads took: 0.0000265 seconds
2017-09-26T10:38:25.111+0200: 10.207: [GC cleanup 32M->32M(32G), 0.0024800 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]
2017-09-26T10:38:25.114+0200: 10.210: Total time for which application threads were stopped: 0.0026242 seconds, Stopping threads took: 0.0000256 seconds
2017-09-26T10:38:25.508+0200: 10.604: Total time for which application threads were stopped: 0.0003730 seconds, Stopping threads took: 0.0000243 seconds
2017-09-26T10:38:26.508+0200: 11.604: Total time for which application threads were stopped: 0.0001588 seconds, Stopping threads took: 0.0000320 seconds
2017-09-26T10:38:27.411+0200: 12.507: Total time for which application threads were stopped: 0.0006700 seconds, Stopping threads took: 0.0000376 seconds
2017-09-26T10:38:28.411+0200: 13.507: Total time for which application threads were stopped: 0.0002198 seconds, Stopping threads took: 0.0000930 seconds
2017-09-26T10:38:29.412+0200: 14.507: Total time for which application threads were stopped: 0.0001524 seconds, Stopping threads took: 0.0000282 seconds
2017-09-26T10:38:30.004+0200: 15.099: Total time for which application threads were stopped: 0.0002701 seconds, Stopping threads took: 0.0000303 seconds
2017-09-26T10:38:30.242+0200: 15.337: Total time for which application threads were stopped: 0.0006649 seconds, Stopping threads took: 0.0000265 seconds
2017-09-26T10:38:30.267+0200: 15.362: Total time for which application threads were stopped: 0.0006009 seconds, Stopping threads took: 0.0000282 seconds
2017-09-26T10:38:30.520+0200: 15.615: Total time for which application threads were stopped: 0.0006649 seconds, Stopping threads took: 0.0000324 seconds
2017-09-26T10:38:31.520+0200: 16.615: Total time for which application threads were stopped: 0.0003453 seconds, Stopping threads took: 0.0000461 seconds
2017-09-26T10:38:32.520+0200: 17.615: Total time for which application threads were stopped: 0.0003828 seconds, Stopping threads took: 0.0000452 seconds
2017-09-26T10:38:36.520+0200: 21.615: Total time for which application threads were stopped: 0.0003265 seconds, Stopping threads took: 0.0000487 seconds
2017-09-26T10:38:38.520+0200: 23.615: Total time for which application threads were stopped: 0.0002578 seconds, Stopping threads took: 0.0000363 seconds
{Heap before GC invocations=2 (full 0):
garbage-first heap total 33554432K, used 1204705K [0x0000000140000000, 0x0000000141004000, 0x0000000940000000)
region size 16384K, 74 young (1212416K), 2 survivors (32768K)
Metaspace used 34545K, capacity 35837K, committed 35840K, reserved 36864K
2017-09-26T10:38:39.000+0200: 24.094: [GC pause (Metadata GC Threshold) (young) (initial-mark)
Desired survivor size 645922816 bytes, new threshold 15 (max 15)

  • age 1: 8752048 bytes, 8752048 total
    , 0.0547303 secs]
    [Parallel Time: 45.0 ms, GC Workers: 16]
    [GC Worker Start (ms): Min: 24094.8, Avg: 24095.1, Max: 24095.3, Diff: 0.5]
    [Ext Root Scanning (ms): Min: 6.6, Avg: 7.8, Max: 9.0, Diff: 2.3, Sum: 124.5]
    [Update RS (ms): Min: 0.0, Avg: 1.4, Max: 2.7, Diff: 2.7, Sum: 22.3]
    [Processed Buffers: Min: 0, Avg: 1.3, Max: 2, Diff: 2, Sum: 21]
    [Scan RS (ms): Min: 0.0, Avg: 8.6, Max: 19.3, Diff: 19.3, Sum: 137.6]
    [Code Root Scanning (ms): Min: 0.0, Avg: 3.7, Max: 23.4, Diff: 23.4, Sum: 59.4]
    [Object Copy (ms): Min: 11.7, Avg: 22.7, Max: 28.3, Diff: 16.5, Sum: 363.2]
    [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
    [Termination Attempts: Min: 1, Avg: 2.9, Max: 6, Diff: 5, Sum: 46]
    [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.8]
    [GC Worker Total (ms): Min: 44.0, Avg: 44.2, Max: 44.5, Diff: 0.5, Sum: 707.9]
    [GC Worker End (ms): Min: 24139.3, Avg: 24139.3, Max: 24139.4, Diff: 0.1]
    [Code Root Fixup: 1.7 ms]
    ps-MacBook-Pro:gc_log_visualizer p$
    ps-MacBook-Pro:gc_log_visualizer p$
    ps-MacBook-Pro:gc_log_visualizer p$
    ps-MacBook-Pro:gc_log_visualizer p$
    ps-MacBook-Pro:gc_log_visualizer p$
    ps-MacBook-Pro:gc_log_visualizer p$
    ps-MacBook-Pro:gc_log_visualizer p$
    ps-MacBook-Pro:gc_log_visualizer p$
    ps-MacBook-Pro:gc_log_visualizer p$
    ps-MacBook-Pro:gc_log_visualizer p$ head -100 gc-2017-09-26_10-38-14.log
    Java HotSpot(TM) 64-Bit Server VM (25.141-b15) for windows-amd64 JRE (1.8.0_141-b15), built on Jul 12 2017 04:25:12 by "java_re" with MS VC++ 10.0 (VS2010)
    Memory: 4k page, physical 100652852k(97232056k free), swap 100650992k(96851484k free)
    CommandLine flags: -XX:+AlwaysPreTouch -XX:CompileCommandFile=C:\APPS\apache-cassandra-3.11.0-bin\conf\hotspot_compiler -XX:ConcGCThreads=16 -XX:G1MaxNewSizePercent=80 -XX:G1NewSizePercent=30 -XX:G1RSetUpdatingPauseTimePercent=5 -XX:G1ReservePercent=20 -XX:GCLogFileSize=10485760 -XX:+HeapDumpOnOutOfMemoryError -XX:InitialHeapSize=34359738368 -XX:InitiatingHeapOccupancyPercent=0 -XX:+ManagementServer -XX:MaxHeapSize=34359738368 -XX:NumberOfGCLogFiles=10 -XX:ParallelGCThreads=16 -XX:+ParallelRefProcEnabled -XX:+PerfDisableSharedMem -XX:+PrintGC -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+PrintPromotionFailure -XX:+PrintTenuringDistribution -XX:-ReduceInitialCardMarks -XX:+ResizeTLAB -XX:StringTableSize=1000003 -XX:ThreadPriorityPolicy=42 -XX:ThreadStackSize=256 -XX:+UnlockExperimentalVMOptions -XX:-UseBiasedLocking -XX:-UseCompressedOops -XX:+UseG1GC -XX:+UseGCLogFileRotation -XX:-UseLargePagesIndividualAllocation -XX:-UseNUMA -XX:+UseTLAB -XX:+UseThreadPriorities
    2017-09-26T10:38:23.005+0200: 8.087: Total time for which application threads were stopped: 0.0001054 seconds, Stopping threads took: 0.0000171 seconds
    2017-09-26T10:38:23.130+0200: 8.199: Total time for which application threads were stopped: 0.0001306 seconds, Stopping threads took: 0.0000230 seconds
    2017-09-26T10:38:23.660+0200: 8.732: Total time for which application threads were stopped: 0.0002544 seconds, Stopping threads took: 0.0000273 seconds
    2017-09-26T10:38:23.785+0200: 8.858: Total time for which application threads were stopped: 0.0002377 seconds, Stopping threads took: 0.0000226 seconds
    2017-09-26T10:38:23.801+0200: 8.868: Total time for which application threads were stopped: 0.0001037 seconds, Stopping threads took: 0.0000145 seconds
    2017-09-26T10:38:23.816+0200: 8.890: Total time for which application threads were stopped: 0.0001374 seconds, Stopping threads took: 0.0000141 seconds
    2017-09-26T10:38:24.019+0200: 9.091: Total time for which application threads were stopped: 0.0002834 seconds, Stopping threads took: 0.0000452 seconds
    2017-09-26T10:38:24.035+0200: 9.103: Total time for which application threads were stopped: 0.0001481 seconds, Stopping threads took: 0.0000158 seconds
    2017-09-26T10:38:24.628+0200: 9.701: Total time for which application threads were stopped: 0.0004895 seconds, Stopping threads took: 0.0001485 seconds
    2017-09-26T10:38:24.674+0200: 9.750: Total time for which application threads were stopped: 0.0003009 seconds, Stopping threads took: 0.0000623 seconds
    2017-09-26T10:38:24.674+0200: 9.753: Total time for which application threads were stopped: 0.0001297 seconds, Stopping threads took: 0.0000137 seconds
    2017-09-26T10:38:24.711+0200: 9.807: Total time for which application threads were stopped: 0.0002514 seconds, Stopping threads took: 0.0000213 seconds
    2017-09-26T10:38:24.728+0200: 9.824: Total time for which application threads were stopped: 0.0004345 seconds, Stopping threads took: 0.0002326 seconds
    {Heap before GC invocations=0 (full 0):
    garbage-first heap total 33554432K, used 147456K [0x0000000140000000, 0x0000000141004000, 0x0000000940000000)
    region size 16384K, 10 young (163840K), 0 survivors (0K)
    Metaspace used 20820K, capacity 21148K, committed 21248K, reserved 22528K
    2017-09-26T10:38:25.055+0200: 10.151: [GC pause (Metadata GC Threshold) (young) (initial-mark)
    Desired survivor size 645922816 bytes, new threshold 15 (max 15)
    , 0.0289907 secs]
    [Parallel Time: 21.1 ms, GC Workers: 16]
    [GC Worker Start (ms): Min: 10151.7, Avg: 10154.1, Max: 10158.9, Diff: 7.2]
    [Ext Root Scanning (ms): Min: 0.1, Avg: 5.7, Max: 11.9, Diff: 11.8, Sum: 90.8]
    [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
    [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
    [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
    [Code Root Scanning (ms): Min: 0.0, Avg: 3.0, Max: 12.6, Diff: 12.6, Sum: 48.5]
    [Object Copy (ms): Min: 0.0, Avg: 7.6, Max: 11.6, Diff: 11.6, Sum: 121.8]
    [Termination (ms): Min: 0.0, Avg: 1.2, Max: 1.6, Diff: 1.6, Sum: 18.7]
    [Termination Attempts: Min: 1, Avg: 229.4, Max: 376, Diff: 375, Sum: 3671]
    [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.6]
    [GC Worker Total (ms): Min: 12.7, Avg: 17.5, Max: 19.9, Diff: 7.2, Sum: 280.5]
    [GC Worker End (ms): Min: 10171.6, Avg: 10171.6, Max: 10171.6, Diff: 0.0]
    [Code Root Fixup: 0.3 ms]
    [Code Root Purge: 0.0 ms]
    [Clear CT: 0.1 ms]
    [Other: 7.4 ms]
    [Choose CSet: 0.0 ms]
    [Ref Proc: 6.3 ms]
    [Ref Enq: 0.4 ms]
    [Redirty Cards: 0.2 ms]
    [Humongous Register: 0.0 ms]
    [Humongous Reclaim: 0.0 ms]
    [Free CSet: 0.1 ms]
    [Eden: 160.0M(9824.0M)->0.0B(9792.0M) Survivors: 0.0B->32.0M Heap: 160.0M(32.0G)->16.5M(32.0G)]
    Heap after GC invocations=1 (full 0):
    garbage-first heap total 33554432K, used 16865K [0x0000000140000000, 0x0000000141004000, 0x0000000940000000)
    region size 16384K, 2 young (32768K), 2 survivors (32768K)
    Metaspace used 20820K, capacity 21148K, committed 21248K, reserved 22528K
    }
    [Times: user=0.19 sys=0.00, real=0.03 secs]
    2017-09-26T10:38:25.085+0200: 10.181: [GC concurrent-root-region-scan-start]
    2017-09-26T10:38:25.085+0200: 10.181: Total time for which application threads were stopped: 0.0296970 seconds, Stopping threads took: 0.0000538 seconds
    2017-09-26T10:38:25.094+0200: 10.190: [GC concurrent-root-region-scan-end, 0.0091381 secs]
    2017-09-26T10:38:25.094+0200: 10.190: [GC concurrent-mark-start]
    2017-09-26T10:38:25.095+0200: 10.191: [GC concurrent-mark-end, 0.0011907 secs]
    2017-09-26T10:38:25.095+0200: 10.191: [GC remark 2017-09-26T10:38:25.095+0200: 10.191: [Finalize Marking, 0.0005783 secs] 2017-09-26T10:38:25.096+0200: 10.192: [GC ref-proc, 0.0052066 secs] 2017-09-26T10:38:25.101+0200: 10.197: [Unloading, 0.0091120 secs], 0.0156080 secs]
    [Times: user=0.25 sys=0.00, real=0.02 secs]
    2017-09-26T10:38:25.111+0200: 10.207: Total time for which application threads were stopped: 0.0157313 seconds, Stopping threads took: 0.0000265 seconds
    2017-09-26T10:38:25.111+0200: 10.207: [GC cleanup 32M->32M(32G), 0.0024800 secs]
    [Times: user=0.00 sys=0.00, real=0.00 secs]
    2017-09-26T10:38:25.114+0200: 10.210: Total time for which application threads were stopped: 0.0026242 seconds, Stopping threads took: 0.0000256 seconds
    2017-09-26T10:38:25.508+0200: 10.604: Total time for which application threads were stopped: 0.0003730 seconds, Stopping threads took: 0.0000243 seconds
    2017-09-26T10:38:26.508+0200: 11.604: Total time for which application threads were stopped: 0.0001588 seconds, Stopping threads took: 0.0000320 seconds
    2017-09-26T10:38:27.411+0200: 12.507: Total time for which application threads were stopped: 0.0006700 seconds, Stopping threads took: 0.0000376 seconds
    2017-09-26T10:38:28.411+0200: 13.507: Total time for which application threads were stopped: 0.0002198 seconds, Stopping threads took: 0.0000930 seconds
    2017-09-26T10:38:29.412+0200: 14.507: Total time for which application threads were stopped: 0.0001524 seconds, Stopping threads took: 0.0000282 seconds
    2017-09-26T10:38:30.004+0200: 15.099: Total time for which application threads were stopped: 0.0002701 seconds, Stopping threads took: 0.0000303 seconds
    2017-09-26T10:38:30.242+0200: 15.337: Total time for which application threads were stopped: 0.0006649 seconds, Stopping threads took: 0.0000265 seconds
    2017-09-26T10:38:30.267+0200: 15.362: Total time for which application threads were stopped: 0.0006009 seconds, Stopping threads took: 0.0000282 seconds
    2017-09-26T10:38:30.520+0200: 15.615: Total time for which application threads were stopped: 0.0006649 seconds, Stopping threads took: 0.0000324 seconds
    2017-09-26T10:38:31.520+0200: 16.615: Total time for which application threads were stopped: 0.0003453 seconds, Stopping threads took: 0.0000461 seconds
    2017-09-26T10:38:32.520+0200: 17.615: Total time for which application threads were stopped: 0.0003828 seconds, Stopping threads took: 0.0000452 seconds
    2017-09-26T10:38:36.520+0200: 21.615: Total time for which application threads were stopped: 0.0003265 seconds, Stopping threads took: 0.0000487 seconds
    2017-09-26T10:38:38.520+0200: 23.615: Total time for which application threads were stopped: 0.0002578 seconds, Stopping threads took: 0.0000363 seconds
    {Heap before GC invocations=2 (full 0):
    garbage-first heap total 33554432K, used 1204705K [0x0000000140000000, 0x0000000141004000, 0x0000000940000000)
    region size 16384K, 74 young (1212416K), 2 survivors (32768K)
    Metaspace used 34545K, capacity 35837K, committed 35840K, reserved 36864K
    2017-09-26T10:38:39.000+0200: 24.094: [GC pause (Metadata GC Threshold) (young) (initial-mark)
    Desired survivor size 645922816 bytes, new threshold 15 (max 15)
  • age 1: 8752048 bytes, 8752048 total
    , 0.0547303 secs]
    [Parallel Time: 45.0 ms, GC Workers: 16]
    [GC Worker Start (ms): Min: 24094.8, Avg: 24095.1, Max: 24095.3, Diff: 0.5]
    [Ext Root Scanning (ms): Min: 6.6, Avg: 7.8, Max: 9.0, Diff: 2.3, Sum: 124.5]
    [Update RS (ms): Min: 0.0, Avg: 1.4, Max: 2.7, Diff: 2.7, Sum: 22.3]
    [Processed Buffers: Min: 0, Avg: 1.3, Max: 2, Diff: 2, Sum: 21]
    [Scan RS (ms): Min: 0.0, Avg: 8.6, Max: 19.3, Diff: 19.3, Sum: 137.6]
    [Code Root Scanning (ms): Min: 0.0, Avg: 3.7, Max: 23.4, Diff: 23.4, Sum: 59.4]
    [Object Copy (ms): Min: 11.7, Avg: 22.7, Max: 28.3, Diff: 16.5, Sum: 363.2]
    [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
    [Termination Attempts: Min: 1, Avg: 2.9, Max: 6, Diff: 5, Sum: 46]
    [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.8]
    [GC Worker Total (ms): Min: 44.0, Avg: 44.2, Max: 44.5, Diff: 0.5, Sum: 707.9]
    [GC Worker End (ms): Min: 24139.3, Avg: 24139.3, Max: 24139.4, Diff: 0.1]
    [Code Root Fixup: 1.7 ms]

@eabbott
Copy link

eabbott commented Sep 28, 2017

Judging by the names of the charts that aren't rendering (default-stw-mixed.png, default-mixed-duration.png, default-mixed-duration-count.png), I'd say there were no mixed gc events. Those three graphs would not have been made correctly. The rest of the graphs should have been made correctly, do you see them in the directory?

@dbwrangler
Copy link
Author

Correct , I just noticed an hour ago that actually a bunch of graphs had been created. Now I'm having problems with regionsize_vs_objectsize.sh, but I'll keep troubleshooting - think data is nothing like expected. Also I don't have -XX:+PrintAdaptiveSizePolicy currently set, so have added and will check again (not sure how important this is).

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@eabbott @marlier @dbwrangler