Skip to content
New issue

Have a question about this project? # for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “#”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? # to your account

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

Closed
krishna81m opened this issue Jan 16, 2015 · 15 comments
Closed

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

krishna81m opened this issue Jan 16, 2015 · 15 comments
Assignees
Labels
Milestone

Comments

@krishna81m
Copy link

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)

@chewiebug
Copy link
Owner

I'd be very interested in your go.log.0. It looks like PrintHeapAtGC prints unexpected output.

@krishna81m
Copy link
Author

Unable to attach, so pasting lines as is again:

2015-01-09T23:56:44.894+0000: 8.135: Total time for which application threads were stopped: 0.0000930 seconds
2015-01-09T23:56:44.895+0000: 8.137: Total time for which application threads were stopped: 0.0000910 seconds
2015-01-09T23:56:44.896+0000: 8.137: Total time for which application threads were stopped: 0.0000660 seconds
2015-01-09T23:56:44.896+0000: 8.137: Total time for which application threads were stopped: 0.0000860 seconds
2015-01-09T23:56:44.897+0000: 8.139: Total time for which application threads were stopped: 0.0001390 seconds
2015-01-09T23:56:44.898+0000: 8.140: Total time for which application threads were stopped: 0.0000650 seconds
2015-01-09T23:56:44.900+0000: 8.142: Total time for which application threads were stopped: 0.0004630 seconds
2015-01-09T23:56:44.903+0000: 8.145: Total time for which application threads were stopped: 0.0000580 seconds
2015-01-09T23:56:44.905+0000: 8.146: Total time for which application threads were stopped: 0.0000690 seconds
2015-01-09T23:56:44.906+0000: 8.147: Total time for which application threads were stopped: 0.0000570 seconds
2015-01-09T23:56:44.906+0000: 8.148: Total time for which application threads were stopped: 0.0000640 seconds
2015-01-09T23:56:44.931+0000: 8.173: Total time for which application threads were stopped: 0.0000710 seconds
2015-01-09T23:56:44.951+0000: 8.192: Total time for which application threads were stopped: 0.0001000 seconds
2015-01-09T23:56:44.951+0000: 8.193: Total time for which application threads were stopped: 0.0000940 seconds
2015-01-09T23:56:44.961+0000: 8.203: Total time for which application threads were stopped: 0.0000750 seconds
2015-01-09T23:56:44.974+0000: 8.215: Total time for which application threads were stopped: 0.0000980 seconds
2015-01-09T23:56:44.975+0000: 8.217: Total time for which application threads were stopped: 0.0000550 seconds
2015-01-09T23:56:44.976+0000: 8.218: Total time for which application threads were stopped: 0.0000750 seconds
2015-01-09T23:56:44.986+0000: 8.228: Total time for which application threads were stopped: 0.0001010 seconds
2015-01-09T23:56:45.000+0000: 8.242: Total time for which application threads were stopped: 0.0001000 seconds
2015-01-09T23:56:45.001+0000: 8.243: Total time for which application threads were stopped: 0.0000420 seconds
2015-01-09T23:56:45.011+0000: 8.253: Total time for which application threads were stopped: 0.0000780 seconds
2015-01-09T23:56:45.040+0000: 8.282: Total time for which application threads were stopped: 0.0001270 seconds
2015-01-09T23:56:45.335+0000: 8.577: Total time for which application threads were stopped: 0.0002190 seconds
2015-01-09T23:56:46.336+0000: 9.577: Total time for which application threads were stopped: 0.0002540 seconds
2015-01-09T23:56:46.569+0000: 9.811: Total time for which application threads were stopped: 0.0002750 seconds
2015-01-09T23:56:47.570+0000: 10.811: Total time for which application threads were stopped: 0.0002140 seconds
2015-01-09T23:56:47.972+0000: 11.214: Total time for which application threads were stopped: 0.0002360 seconds
2015-01-09T23:56:48.973+0000: 12.214: Total time for which application threads were stopped: 0.0002760 seconds
2015-01-09T23:56:50.786+0000: 14.028: Total time for which application threads were stopped: 0.0002230 seconds
2015-01-09T23:56:50.818+0000: 14.059: Total time for which application threads were stopped: 0.0000760 seconds
2015-01-09T23:56:50.818+0000: 14.060: Total time for which application threads were stopped: 0.0000620 seconds
2015-01-09T23:56:50.836+0000: 14.077: Total time for which application threads were stopped: 0.0001140 seconds
2015-01-09T23:56:50.844+0000: 14.086: Total time for which application threads were stopped: 0.0000810 seconds
2015-01-09T23:56:50.850+0000: 14.091: Total time for which application threads were stopped: 0.0003140 seconds
2015-01-09T23:56:50.855+0000: 14.097: Total time for which application threads were stopped: 0.0000730 seconds
2015-01-09T23:56:50.868+0000: 14.110: Total time for which application threads were stopped: 0.0000670 seconds
{Heap before GC invocations=0 (full 0):
 par new generation   total 4404032K, used 3914752K [0x000000047ae00000, 0x00000005a58a0000, 0x00000005a58a0000)
  eden space 3914752K, 100% used [0x000000047ae00000, 0x0000000569d00000, 0x0000000569d00000)
  from space 489280K,   0% used [0x0000000569d00000, 0x0000000569d00000, 0x0000000587ad0000)
  to   space 489280K,   0% used [0x0000000587ad0000, 0x0000000587ad0000, 0x00000005a58a0000)
 concurrent mark-sweep generation total 9786752K, used 0K [0x00000005a58a0000, 0x00000007fae00000, 0x00000007fae00000)
 concurrent-mark-sweep perm gen total 21248K, used 19013K [0x00000007fae00000, 0x00000007fc2c0000, 0x0000000800000000)
2015-01-09T23:56:50.872+0000: 14.114: [GCBefore GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 1252704256
Max   Chunk Size: 1252704256
Number of Blocks: 1
Av.  Block  Size: 1252704256
Tree      Height: 1
Before GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 0
Max   Chunk Size: 0
Number of Blocks: 0
Tree      Height: 0
2015-01-09T23:56:50.872+0000: 14.114: [ParNew
Desired survivor size 250511360 bytes, new threshold 10 (max 10)
- age   1:   21552952 bytes,   21552952 total
: 3914752K->21242K(4404032K), 0.0250820 secs] 3914752K->21242K(14190784K)After GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 1252687872
Max   Chunk Size: 1252687872
Number of Blocks: 1
Av.  Block  Size: 1252687872
Tree      Height: 1
After GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 0
Max   Chunk Size: 0
Number of Blocks: 0
Tree      Height: 0
, 0.0252550 secs] [Times: user=0.30 sys=0.00, real=0.02 secs] 
Heap after GC invocations=1 (full 0):
 par new generation   total 4404032K, used 21242K [0x000000047ae00000, 0x00000005a58a0000, 0x00000005a58a0000)
  eden space 3914752K,   0% used [0x000000047ae00000, 0x000000047ae00000, 0x0000000569d00000)
  from space 489280K,   4% used [0x0000000587ad0000, 0x0000000588f8e938, 0x00000005a58a0000)
  to   space 489280K,   0% used [0x0000000569d00000, 0x0000000569d00000, 0x0000000587ad0000)
 concurrent mark-sweep generation total 9786752K, used 0K [0x00000005a58a0000, 0x00000007fae00000, 0x00000007fae00000)
 concurrent-mark-sweep perm gen total 21248K, used 19013K [0x00000007fae00000, 0x00000007fc2c0000, 0x0000000800000000)
}
2015-01-09T23:56:50.897+0000: 14.139: Total time for which application threads were stopped: 0.0255420 seconds
2015-01-09T23:56:50.898+0000: 14.140: Total time for which application threads were stopped: 0.0001050 seconds
2015-01-09T23:56:50.898+0000: 14.140: Total time for which application threads were stopped: 0.0001010 seconds
2015-01-09T23:56:50.898+0000: 14.140: Total time for which application threads were stopped: 0.0000670 seconds
2015-01-09T23:56:50.898+0000: 14.140: Total time for which application threads were stopped: 0.0000840 seconds
2015-01-09T23:56:50.898+0000: 14.140: Total time for which application threads were stopped: 0.0000800 seconds
2015-01-09T23:56:50.899+0000: 14.140: Total time for which application threads were stopped: 0.0000850 seconds
2015-01-09T23:56:50.899+0000: 14.140: Total time for which application threads were stopped: 0.0001000 seconds
2015-01-09T23:56:50.899+0000: 14.140: Total time for which application threads were stopped: 0.0000660 seconds
2015-01-09T23:56:50.899+0000: 14.141: Total time for which application threads were stopped: 0.0000610 seconds
2015-01-09T23:56:50.899+0000: 14.141: Total time for which application threads were stopped: 0.0000600 seconds
2015-01-09T23:56:50.899+0000: 14.141: Total time for which application threads were stopped: 0.0000750 seconds
2015-01-09T23:56:50.899+0000: 14.141: Total time for which application threads were stopped: 0.0000630 seconds
2015-01-09T23:56:50.899+0000: 14.141: Total time for which application threads were stopped: 0.0000630 seconds
2015-01-09T23:56:50.899+0000: 14.141: Total time for which application threads were stopped: 0.0000550 seconds
2015-01-09T23:56:50.899+0000: 14.141: Total time for which application threads were stopped: 0.0000580 seconds
2015-01-09T23:56:50.899+0000: 14.141: Total time for which application threads were stopped: 0.0000540 seconds
2015-01-09T23:56:50.900+0000: 14.141: Total time for which application threads were stopped: 0.0000550 seconds
2015-01-09T23:56:50.900+0000: 14.141: Total time for which application threads were stopped: 0.0000490 seconds
2015-01-09T23:56:50.900+0000: 14.141: Total time for which application threads were stopped: 0.0000520 seconds
2015-01-09T23:56:50.900+0000: 14.142: Total time for which application threads were stopped: 0.0003300 seconds
2015-01-09T23:56:50.900+0000: 14.142: Total time for which application threads were stopped: 0.0000380 seconds
2015-01-09T23:56:50.900+0000: 14.142: Total time for which application threads were stopped: 0.0000560 seconds
2015-01-09T23:56:50.900+0000: 14.142: Total time for which application threads were stopped: 0.0000610 seconds
2015-01-09T23:56:50.900+0000: 14.142: Total time for which application threads were stopped: 0.0000500 seconds
2015-01-09T23:56:50.901+0000: 14.142: Total time for which application threads were stopped: 0.0000690 seconds
2015-01-09T23:56:50.901+0000: 14.142: Total time for which application threads were stopped: 0.0000670 seconds
2015-01-09T23:56:50.901+0000: 14.142: Total time for which application threads were stopped: 0.0000730 seconds
2015-01-09T23:56:50.901+0000: 14.143: Total time for which application threads were stopped: 0.0000580 seconds
2015-01-09T23:56:50.901+0000: 14.143: Total time for which application threads were stopped: 0.0000610 seconds
2015-01-09T23:56:50.901+0000: 14.143: Total time for which application threads were stopped: 0.0000630 seconds
2015-01-09T23:56:50.901+0000: 14.143: Total time for which application threads were stopped: 0.0000620 seconds
2015-01-09T23:56:50.901+0000: 14.143: Total time for which application threads were stopped: 0.0000500 seconds
2015-01-09T23:56:50.901+0000: 14.143: Total time for which application threads were stopped: 0.0000580 seconds
2015-01-09T23:56:50.901+0000: 14.143: Total time for which application threads were stopped: 0.0000610 seconds
2015-01-09T23:56:50.902+0000: 14.143: Total time for which application threads were stopped: 0.0000650 seconds
2015-01-09T23:56:50.902+0000: 14.143: Total time for which application threads were stopped: 0.0000530 seconds
2015-01-09T23:56:50.902+0000: 14.143: Total time for which application threads were stopped: 0.0000470 seconds
2015-01-09T23:56:50.902+0000: 14.144: Total time for which application threads were stopped: 0.0000760 seconds
2015-01-09T23:56:50.902+0000: 14.144: Total time for which application threads were stopped: 0.0000830 seconds
2015-01-09T23:56:50.902+0000: 14.144: Total time for which application threads were stopped: 0.0002230 seconds
2015-01-09T23:56:50.904+0000: 14.145: Total time for which application threads were stopped: 0.0000670 seconds
2015-01-09T23:56:50.904+0000: 14.145: Total time for which application threads were stopped: 0.0000730 seconds
2015-01-09T23:56:50.904+0000: 14.146: Total time for which application threads were stopped: 0.0000550 seconds
2015-01-09T23:56:50.904+0000: 14.146: Total time for which application threads were stopped: 0.0000530 seconds
2015-01-09T23:56:50.904+0000: 14.146: Total time for which application threads were stopped: 0.0000610 seconds
2015-01-09T23:56:50.905+0000: 14.146: Total time for which application threads were stopped: 0.0000640 seconds
2015-01-09T23:56:50.905+0000: 14.147: Total time for which application threads were stopped: 0.0000710 seconds
2015-01-09T23:56:50.905+0000: 14.147: Total time for which application threads were stopped: 0.0000720 seconds
2015-01-09T23:56:50.905+0000: 14.147: Total time for which application threads were stopped: 0.0000480 seconds
2015-01-09T23:56:50.911+0000: 14.153: Total time for which application threads were stopped: 0.0000740 seconds
2015-01-09T23:56:50.918+0000: 14.159: Total time for which application threads were stopped: 0.0000690 seconds
2015-01-09T23:56:50.918+0000: 14.159: Total time for which application threads were stopped: 0.0000590 seconds
2015-01-09T23:56:50.918+0000: 14.160: Total time for which application threads were stopped: 0.0000430 seconds
2015-01-09T23:56:50.918+0000: 14.160: Total time for which application threads were stopped: 0.0000500 seconds
2015-01-09T23:56:50.918+0000: 14.160: Total time for which application threads were stopped: 0.0000330 seconds
2015-01-09T23:56:50.918+0000: 14.160: Total time for which application threads were stopped: 0.0000470 seconds
2015-01-09T23:56:50.918+0000: 14.160: Total time for which application threads were stopped: 0.0000490 seconds
2015-01-09T23:56:50.918+0000: 14.160: Total time for which application threads were stopped: 0.0000490 seconds
2015-01-09T23:56:50.918+0000: 14.160: Total time for which application threads were stopped: 0.0000510 seconds
2015-01-09T23:56:50.919+0000: 14.160: Total time for which application threads were stopped: 0.0000560 seconds
2015-01-09T23:56:50.919+0000: 14.160: Total time for which application threads were stopped: 0.0002060 seconds
2015-01-09T23:56:50.923+0000: 14.164: Total time for which application threads were stopped: 0.0000800 seconds
2015-01-09T23:56:50.923+0000: 14.165: Total time for which application threads were stopped: 0.0000770 seconds
2015-01-09T23:56:50.927+0000: 14.169: Total time for which application threads were stopped: 0.0000900 seconds
2015-01-09T23:56:50.932+0000: 14.174: Total time for which application threads were stopped: 0.0000710 seconds
2015-01-09T23:56:50.937+0000: 14.179: Total time for which application threads were stopped: 0.0000770 seconds
2015-01-09T23:56:50.948+0000: 14.190: Total time for which application threads were stopped: 0.0001050 seconds
2015-01-09T23:56:50.949+0000: 14.191: Total time for which application threads were stopped: 0.0000480 seconds
2015-01-09T23:56:50.955+0000: 14.196: Total time for which application threads were stopped: 0.0000770 seconds
2015-01-09T23:56:50.963+0000: 14.205: Total time for which application threads were stopped: 0.0001330 seconds
2015-01-09T23:56:50.968+0000: 14.209: Total time for which application threads were stopped: 0.0000790 seconds
2015-01-09T23:56:50.975+0000: 14.217: Total time for which application threads were stopped: 0.0000720 seconds
2015-01-09T23:56:50.980+0000: 14.222: Total time for which application threads were stopped: 0.0000550 seconds
2015-01-09T23:56:50.982+0000: 14.224: Total time for which application threads were stopped: 0.0001020 seconds
2015-01-09T23:56:50.990+0000: 14.231: Total time for which application threads were stopped: 0.0000980 seconds
2015-01-09T23:56:50.995+0000: 14.236: Total time for which application threads were stopped: 0.0002400 seconds
2015-01-09T23:56:51.744+0000: 14.986: Total time for which application threads were stopped: 0.0003500 seconds
2015-01-09T23:56:51.800+0000: 15.042: Total time for which application threads were stopped: 0.0002970 seconds
2015-01-09T23:56:52.157+0000: 15.398: Total time for which application threads were stopped: 0.0001770 seconds
2015-01-09T23:56:52.157+0000: 15.398: [GC [1 CMS-initial-mark: 0K(9786752K)] 2518487K(14190784K), 0.0728220 secs] [Times: user=0.07 sys=0.00, real=0.07 secs] 
2015-01-09T23:56:52.230+0000: 15.472: Total time for which application threads were stopped: 0.0731200 seconds
2015-01-09T23:56:52.230+0000: 15.472: [CMS-concurrent-mark-start]
2015-01-09T23:56:52.237+0000: 15.479: [CMS-concurrent-mark: 0.006/0.007 secs] [Times: user=0.04 sys=0.00, real=0.01 secs] 
2015-01-09T23:56:52.237+0000: 15.479: [CMS-concurrent-preclean-start]
2015-01-09T23:56:52.264+0000: 15.506: [CMS-concurrent-preclean: 0.027/0.027 secs] [Times: user=0.05 sys=0.00, real=0.03 secs] 
2015-01-09T23:56:52.264+0000: 15.506: [CMS-concurrent-abortable-preclean-start]
2015-01-09T23:56:53.231+0000: 16.473: Total time for which application threads were stopped: 0.0014990 seconds
2015-01-09T23:56:54.232+0000: 17.474: Total time for which application threads were stopped: 0.0003570 seconds
{Heap before GC invocations=1 (full 1):
 par new generation   total 4404032K, used 3935994K [0x000000047ae00000, 0x00000005a58a0000, 0x00000005a58a0000)
  eden space 3914752K, 100% used [0x000000047ae00000, 0x0000000569d00000, 0x0000000569d00000)
  from space 489280K,   4% used [0x0000000587ad0000, 0x0000000588f8e938, 0x00000005a58a0000)
  to   space 489280K,   0% used [0x0000000569d00000, 0x0000000569d00000, 0x0000000587ad0000)
 concurrent mark-sweep generation total 9786752K, used 0K [0x00000005a58a0000, 0x00000007fae00000, 0x00000007fae00000)
 concurrent-mark-sweep perm gen total 21248K, used 20465K [0x00000007fae00000, 0x00000007fc2c0000, 0x0000000800000000)
2015-01-09T23:56:56.048+0000: 19.290: [GCBefore GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 1252687872
Max   Chunk Size: 1252687872
Number of Blocks: 1
Av.  Block  Size: 1252687872
Tree      Height: 1
Before GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 0
Max   Chunk Size: 0
Number of Blocks: 0
Tree      Height: 0
2015-01-09T23:56:56.048+0000: 19.290: [ParNew2015-01-09T23:56:56.082+0000: 19.323: [CMS-concurrent-abortable-preclean: 2.462/3.817 secs] [Times: user=8.78 sys=3.18, real=3.81 secs] 

Desired survivor size 250511360 bytes, new threshold 10 (max 10)
- age   1:  180656512 bytes,  180656512 total
- age   2:   12061336 bytes,  192717848 total
: 3935994K->193774K(4404032K), 0.0648380 secs] 3935994K->193774K(14190784K)After GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 1252687872
Max   Chunk Size: 1252687872
Number of Blocks: 1
Av.  Block  Size: 1252687872
Tree      Height: 1
After GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 0
Max   Chunk Size: 0
Number of Blocks: 0
Tree      Height: 0
, 0.0653210 secs] [Times: user=1.16 sys=0.01, real=0.07 secs] 
Heap after GC invocations=2 (full 1):
 par new generation   total 4404032K, used 193774K [0x000000047ae00000, 0x00000005a58a0000, 0x00000005a58a0000)
  eden space 3914752K,   0% used [0x000000047ae00000, 0x000000047ae00000, 0x0000000569d00000)
  from space 489280K,  39% used [0x0000000569d00000, 0x0000000575a3ba70, 0x0000000587ad0000)
  to   space 489280K,   0% used [0x0000000587ad0000, 0x0000000587ad0000, 0x00000005a58a0000)
 concurrent mark-sweep generation total 9786752K, used 0K [0x00000005a58a0000, 0x00000007fae00000, 0x00000007fae00000)
 concurrent-mark-sweep perm gen total 21248K, used 20465K [0x00000007fae00000, 0x00000007fc2c0000, 0x0000000800000000)
}
2015-01-09T23:56:56.114+0000: 19.356: Total time for which application threads were stopped: 0.0671230 seconds
2015-01-09T23:56:56.114+0000: 19.356: [GC[YG occupancy: 227366 K (4404032 K)]2015-01-09T23:56:56.114+0000: 19.356: [Rescan (parallel) , 0.0138510 secs]2015-01-09T23:56:56.128+0000: 19.370: [weak refs processing, 0.0000410 secs]2015-01-09T23:56:56.128+0000: 19.370: [class unloading, 0.0018880 secs]2015-01-09T23:56:56.130+0000: 19.372: [scrub symbol table, 0.0025550 secs]2015-01-09T23:56:56.133+0000: 19.374: [scrub string table, 0.0008870 secs] [1 CMS-remark: 0K(9786752K)] 227366K(14190784K), 0.0205520 secs] [Times: user=0.27 sys=0.00, real=0.02 secs] 
2015-01-09T23:56:56.135+0000: 19.377: Total time for which application threads were stopped: 0.0210750 seconds
2015-01-09T23:56:56.135+0000: 19.377: [CMS-concurrent-sweep-start]
CMS: Large Block: 0x00000005a58c0000; Proximity: 0x0000000000000000 -> 0x00000005a58bfac8
CMS: Large block 0x00000005a58c0000
CMS: Large Block: 0x00000007fc2c0000; Proximity: 0x0000000000000000 -> 0x00000007fc28adf8
CMS: Large block 0x0000000000000000
2015-01-09T23:56:56.141+0000: 19.383: [CMS-concurrent-sweep: 0.006/0.006 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
2015-01-09T23:56:56.141+0000: 19.383: Total time for which application threads were stopped: 0.0002570 seconds
2015-01-09T23:56:56.143+0000: 19.385: [CMS-concurrent-reset-start]
2015-01-09T23:56:56.172+0000: 19.413: [CMS-concurrent-reset: 0.029/0.029 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
2015-01-09T23:56:57.142+0000: 20.383: Total time for which application threads were stopped: 0.0001820 seconds
2015-01-09T23:56:58.143+0000: 21.384: Total time for which application threads were stopped: 0.0010800 seconds
{Heap before GC invocations=2 (full 1):
 par new generation   total 4404032K, used 4108526K [0x000000047ae00000, 0x00000005a58a0000, 0x00000005a58a0000)
  eden space 3914752K, 100% used [0x000000047ae00000, 0x0000000569d00000, 0x0000000569d00000)
  from space 489280K,  39% used [0x0000000569d00000, 0x0000000575a3ba70, 0x0000000587ad0000)
  to   space 489280K,   0% used [0x0000000587ad0000, 0x0000000587ad0000, 0x00000005a58a0000)
 concurrent mark-sweep generation total 9786752K, used 0K [0x00000005a58a0000, 0x00000007fae00000, 0x00000007fae00000)
 concurrent-mark-sweep perm gen total 34100K, used 20483K [0x00000007fae00000, 0x00000007fcf4d000, 0x0000000800000000)
2015-01-09T23:57:00.042+0000: 23.284: [GCBefore GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 1252687872
Max   Chunk Size: 1252687872
Number of Blocks: 1
Av.  Block  Size: 1252687872
Tree      Height: 1
Before GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 1645056
Max   Chunk Size: 1645056
Number of Blocks: 1
Av.  Block  Size: 1645056
Tree      Height: 1
2015-01-09T23:57:00.043+0000: 23.284: [ParNew
Desired survivor size 250511360 bytes, new threshold 1 (max 10)
- age   1:  313722536 bytes,  313722536 total
- age   2:  175041520 bytes,  488764056 total
- age   3:   12025392 bytes,  500789448 total
: 4108526K->489280K(4404032K), 2.8108720 secs] 4108526K->856104K(14190784K)After GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 1205727830
Max   Chunk Size: 1205727830
Number of Blocks: 1
Av.  Block  Size: 1205727830
Tree      Height: 1
After GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 1645056
Max   Chunk Size: 1645056
Number of Blocks: 1
Av.  Block  Size: 1645056
Tree      Height: 1
, 2.8113310 secs] [Times: user=16.12 sys=1.16, real=2.82 secs] 
Heap after GC invocations=3 (full 1):
 par new generation   total 4404032K, used 489280K [0x000000047ae00000, 0x00000005a58a0000, 0x00000005a58a0000)
  eden space 3914752K,   0% used [0x000000047ae00000, 0x000000047ae00000, 0x0000000569d00000)
  from space 489280K, 100% used [0x0000000587ad0000, 0x00000005a58a0000, 0x00000005a58a0000)
  to   space 489280K,   0% used [0x0000000569d00000, 0x0000000569d00000, 0x0000000587ad0000)
 concurrent mark-sweep generation total 9786752K, used 366824K [0x00000005a58a0000, 0x00000007fae00000, 0x00000007fae00000)
 concurrent-mark-sweep perm gen total 34100K, used 20483K [0x00000007fae00000, 0x00000007fcf4d000, 0x0000000800000000)
}
2015-01-09T23:57:02.854+0000: 26.096: Total time for which application threads were stopped: 2.8119830 seconds
2015-01-09T23:57:02.880+0000: 26.121: Total time for which application threads were stopped: 0.0002870 seconds
2015-01-09T23:57:02.895+0000: 26.137: Total time for which application threads were stopped: 0.0060630 seconds
2015-01-09T23:57:04.896+0000: 28.138: Total time for which application threads were stopped: 0.0004580 seconds
2015-01-09T23:57:06.898+0000: 30.139: Total time for which application threads were stopped: 0.0012890 seconds
{Heap before GC invocations=3 (full 1):
 par new generation   total 4404032K, used 4404032K [0x000000047ae00000, 0x00000005a58a0000, 0x00000005a58a0000)
  eden space 3914752K, 100% used [0x000000047ae00000, 0x0000000569d00000, 0x0000000569d00000)
  from space 489280K, 100% used [0x0000000587ad0000, 0x00000005a58a0000, 0x00000005a58a0000)
  to   space 489280K,   0% used [0x0000000569d00000, 0x0000000569d00000, 0x0000000587ad0000)
 concurrent mark-sweep generation total 9786752K, used 366824K [0x00000005a58a0000, 0x00000007fae00000, 0x00000007fae00000)
 concurrent-mark-sweep perm gen total 34100K, used 20899K [0x00000007fae00000, 0x00000007fcf4d000, 0x0000000800000000)
2015-01-09T23:57:07.619+0000: 30.860: [GCBefore GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 1205727830
Max   Chunk Size: 1205727830
Number of Blocks: 1
Av.  Block  Size: 1205727830
Tree      Height: 1
Before GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 1645056
Max   Chunk Size: 1645056
Number of Blocks: 1
Av.  Block  Size: 1645056
Tree      Height: 1
2015-01-09T23:57:07.619+0000: 30.861: [ParNew
Desired survivor size 250511360 bytes, new threshold 10 (max 10)
- age   1:  184289592 bytes,  184289592 total
: 4404032K->423626K(4404032K), 0.3447260 secs] 4770856K->1233591K(14190784K)After GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 1148135010
Max   Chunk Size: 1148135010
Number of Blocks: 1
Av.  Block  Size: 1148135010
Tree      Height: 1
After GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 1645056
Max   Chunk Size: 1645056
Number of Blocks: 1
Av.  Block  Size: 1645056
Tree      Height: 1
, 0.3452080 secs] [Times: user=5.21 sys=0.02, real=0.34 secs] 
Heap after GC invocations=4 (full 1):
 par new generation   total 4404032K, used 423626K [0x000000047ae00000, 0x00000005a58a0000, 0x00000005a58a0000)
  eden space 3914752K,   0% used [0x000000047ae00000, 0x000000047ae00000, 0x0000000569d00000)
  from space 489280K,  86% used [0x0000000569d00000, 0x0000000583ab29d0, 0x0000000587ad0000)
  to   space 489280K,   0% used [0x0000000587ad0000, 0x0000000587ad0000, 0x00000005a58a0000)
 concurrent mark-sweep generation total 9786752K, used 809964K [0x00000005a58a0000, 0x00000007fae00000, 0x00000007fae00000)
 concurrent-mark-sweep perm gen total 34100K, used 20899K [0x00000007fae00000, 0x00000007fcf4d000, 0x0000000800000000)
}
2015-01-09T23:57:07.964+0000: 31.206: Total time for which application threads were stopped: 0.3461110 seconds
2015-01-09T23:57:08.966+0000: 32.208: Total time for which application threads were stopped: 0.0014640 seconds
2015-01-09T23:57:09.966+0000: 33.208: Total time for which application threads were stopped: 0.0003690 seconds
2015-01-09T23:57:11.968+0000: 35.210: Total time for which application threads were stopped: 0.0016350 seconds
{Heap before GC invocations=4 (full 1):
 par new generation   total 4404032K, used 4338378K [0x000000047ae00000, 0x00000005a58a0000, 0x00000005a58a0000)
  eden space 3914752K, 100% used [0x000000047ae00000, 0x0000000569d00000, 0x0000000569d00000)
  from space 489280K,  86% used [0x0000000569d00000, 0x0000000583ab29d0, 0x0000000587ad0000)
  to   space 489280K,   0% used [0x0000000587ad0000, 0x0000000587ad0000, 0x00000005a58a0000)
 concurrent mark-sweep generation total 9786752K, used 809964K [0x00000005a58a0000, 0x00000007fae00000, 0x00000007fae00000)
 concurrent-mark-sweep perm gen total 34100K, used 20920K [0x00000007fae00000, 0x00000007fcf4d000, 0x0000000800000000)
2015-01-09T23:57:12.671+0000: 35.913: [GCBefore GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 1148135010
Max   Chunk Size: 1148135010
Number of Blocks: 1
Av.  Block  Size: 1148135010
Tree      Height: 1
Before GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 1645056
Max   Chunk Size: 1645056
Number of Blocks: 1
Av.  Block  Size: 1645056
Tree      Height: 1
2015-01-09T23:57:12.671+0000: 35.913: [ParNew
Desired survivor size 250511360 bytes, new threshold 1 (max 10)
- age   1:  353171168 bytes,  353171168 total
- age   2:  147032624 bytes,  500203792 total
: 4338378K->489280K(4404032K), 0.7500100 secs] 5148343K->1780814K(14190784K)After GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 1086999941
Max   Chunk Size: 1086999941
Number of Blocks: 1
Av.  Block  Size: 1086999941
Tree      Height: 1
After GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 1645056
Max   Chunk Size: 1645056
Number of Blocks: 1
Av.  Block  Size: 1645056
Tree      Height: 1
, 0.7505630 secs] [Times: user=15.17 sys=0.00, real=0.75 secs] 
Heap after GC invocations=5 (full 1):
 par new generation   total 4404032K, used 489280K [0x000000047ae00000, 0x00000005a58a0000, 0x00000005a58a0000)
  eden space 3914752K,   0% used [0x000000047ae00000, 0x000000047ae00000, 0x0000000569d00000)
  from space 489280K, 100% used [0x0000000587ad0000, 0x00000005a58a0000, 0x00000005a58a0000)
  to   space 489280K,   0% used [0x0000000569d00000, 0x0000000569d00000, 0x0000000587ad0000)
 concurrent mark-sweep generation total 9786752K, used 1291534K [0x00000005a58a0000, 0x00000007fae00000, 0x00000007fae00000)
 concurrent-mark-sweep perm gen total 34100K, used 20920K [0x00000007fae00000, 0x00000007fcf4d000, 0x0000000800000000)
}
2015-01-09T23:57:13.422+0000: 36.664: Total time for which application threads were stopped: 0.7513670 seconds
2015-01-09T23:57:13.667+0000: 36.909: Total time for which application threads were stopped: 0.0015250 seconds
{Heap before GC invocations=5 (full 1):
 par new generation   total 4404032K, used 4404032K [0x000000047ae00000, 0x00000005a58a0000, 0x00000005a58a0000)
  eden space 3914752K, 100% used [0x000000047ae00000, 0x0000000569d00000, 0x0000000569d00000)
  from space 489280K, 100% used [0x0000000587ad0000, 0x00000005a58a0000, 0x00000005a58a0000)
  to   space 489280K,   0% used [0x0000000569d00000, 0x0000000569d00000, 0x0000000587ad0000)
 concurrent mark-sweep generation total 9786752K, used 1291534K [0x00000005a58a0000, 0x00000007fae00000, 0x00000007fae00000)
 concurrent-mark-sweep perm gen total 34100K, used 20933K [0x00000007fae00000, 0x00000007fcf4d000, 0x0000000800000000)
2015-01-09T23:57:16.341+0000: 39.583: [GCBefore GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 1086999941
Max   Chunk Size: 1086999941
Number of Blocks: 1
Av.  Block  Size: 1086999941
Tree      Height: 1
Before GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 1645056
Max   Chunk Size: 1645056
Number of Blocks: 1
Av.  Block  Size: 1645056
Tree      Height: 1
2015-01-09T23:57:16.341+0000: 39.583: [ParNew
Desired survivor size 250511360 bytes, new threshold 10 (max 10)
- age   1:  132443984 bytes,  132443984 total
: 4404032K->422270K(4404032K), 0.2780820 secs] 5695566K->2186197K(14190784K)After GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 1025829756
Max   Chunk Size: 1025829756
Number of Blocks: 1
Av.  Block  Size: 1025829756
Tree      Height: 1
After GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 1645056
Max   Chunk Size: 1645056
Number of Blocks: 1
Av.  Block  Size: 1645056
Tree      Height: 1
, 0.2787060 secs] [Times: user=4.36 sys=0.05, real=0.28 secs] 
Heap after GC invocations=6 (full 1):
 par new generation   total 4404032K, used 422270K [0x000000047ae00000, 0x00000005a58a0000, 0x00000005a58a0000)
  eden space 3914752K,   0% used [0x000000047ae00000, 0x000000047ae00000, 0x0000000569d00000)
  from space 489280K,  86% used [0x0000000569d00000, 0x000000058395f8f0, 0x0000000587ad0000)
  to   space 489280K,   0% used [0x0000000587ad0000, 0x0000000587ad0000, 0x00000005a58a0000)
 concurrent mark-sweep generation total 9786752K, used 1763927K [0x00000005a58a0000, 0x00000007fae00000, 0x00000007fae00000)
 concurrent-mark-sweep perm gen total 34100K, used 20933K [0x00000007fae00000, 0x00000007fcf4d000, 0x0000000800000000)
}

@chewiebug
Copy link
Owner

I have pushed a fix to the repository and built the latest SNAPSHOT release. Does it work now?

@krishna81m
Copy link
Author

Checking.
On Jan 16, 2015 2:36 PM, "chewiebug" notifications@github.com wrote:

I have pushed a fix to the repository and built the latest SNAPSHOT
release. Does it work now?


Reply to this email directly or view it on GitHub
#127 (comment).

@krishna81m
Copy link
Author

Awesome works now and able to see them, wonder if there is a way to get event details when I click a data point or "at least the exact time when the event happened on top" instead of hours elapsed so I can back track the spikes in my logs.

@krishna81m
Copy link
Author

Also awesome would be to adjust the time scale as few outliers (> few seconds) can completely mess up the plot.

@krishna81m
Copy link
Author

Our GC configuration is pretty simple and uses fixed values instead of variable ranges, not sure when variable ranges to let JVM decide the sizes would make more sense? Anyways, in our write/read intensive cassandra with some caching, we noticed our (all the way below) 14 GB heap, new ratio=2, tenuringThreshold=10 and survivor ratio=8 or about 250 MB is working fine because most read data generated garbage remains in survivor stays for a long time to reach 250 MB at >80% of the time, but is this a good idea to keep such read related data and cache in survivor spaces as very little amount 40 MB alone is filled up in survivor space? In this case there is no point in increasing survivor space as we don’t fill up but what about increasing tenured ratio to > 15, is it ok to live with 20-40ms par new GCs every half a min or reduce this size and tenuring ratio as most of the time only about 1-10 MB is surviving and flushed to old gen.
Desired survivor size 250511360 bytes, new threshold 10 (max 10)
– age 1: 21011760 bytes, 21011760 total
– age 2: 4261448 bytes, 25273208 total
– age 3: 2583752 bytes, 27856960 total
– age 4: 1939944 bytes, 29796904 total
– age 5: 1933296 bytes, 31730200 total
– age 6: 1876272 bytes, 33606472 total
– age 7: 1900928 bytes, 35507400 total
– age 8: 1756536 bytes, 37263936 total
– age 9: 2162784 bytes, 39426720 total
– age 10: 1401480 bytes, 40828200 total

gc-major-cms-normal-zoomed

-XX:+UseThreadPriorities
-XX:ThreadPriorityPolicy=42
-Xms14G -Xmx14G
-XX:+HeapDumpOnOutOfMemoryError
-XX:NewRatio=2 -XX:MaxTenuringThreshold=10 -XX:+DisableExplicitGC -Xss250k
-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

@krishna81m
Copy link
Author

Wanted to use GCViewer to understand this one outlier, however, I still don't understand why the GC times are more than 4 seconds here although two CMS seem to happen and complete without any problem and the heap really did not hit the full limit?
strange-gc-major-cms-more-than-4s-zoomed

@chewiebug
Copy link
Owner

Thanks - I am happy to know, there are poeple out there, who have a
benefit in using GCViewer!

There is already a feature request for showing exact details, when
hovering on a point (#114) and another requesting adjustment of the time
scale (#5 - partial log file analysis). They still wait for some
implementer do work on it.

Concerning your tuning question: I'd need to have the part of your log,
which contains that outlier to maybe get an idea, why it is there (you
could send it to gcviewer-info@googlegroups.com - please compress, there
is a size limit).

Do you happen to know hotspot-gc-use@openjdk.java.net? That's the
mailing list to go to with your tuning question. There are quite a few
gc tuning experts around.

Best regards,
Jörg

@krishna81m
Copy link
Author

Just sent, thanks.

@chewiebug chewiebug added the bug label Jan 21, 2015
@chewiebug chewiebug added this to the 1.34.1 milestone Jan 21, 2015
@chewiebug chewiebug self-assigned this Jan 21, 2015
@chewiebug
Copy link
Owner

I close this issue, since the GCViewer related part is fixed.

@krishna81m
Copy link
Author

Thanks, curious why are the full GCs showing up as 0 although there are CMS GCs and ParNew GCs which are both stop the world.

@ecki
Copy link
Contributor

ecki commented Jan 29, 2015

The FullGC counter is for real FullGCs, not for "any GC which has a pause phase". In case of CMS you have 3 types of GC, the parallel copy GC in young generation, the mostly concurrent parallel in old generation. And only if a promotion error happens it will do a FullGC. And this is very bad, as it uses the single threaded SerialGC for this. Oldie but goodie: https://blogs.oracle.com/jonthecollector/entry/our_collectors

BTW: the term "Full" used to have different meanings including "stop the world" or "old generation" or "all generations". Its best to not think in these terms.

@krishna81m
Copy link
Author

Makes sense, keep getting confused between Full GCs vs Stop The World mark/remark/par new GCs. Apparently, could not quickly google to find valid Java source that clearly explained "Full GC". I do remember Full GCs happen when sizes expand too. Is this applicable for Young generation expansion too when we specify NewSize and MaxNewSize? Again, could not confirm this anywhere online.

Glad to know that we don't have Full GCs but really long CMS when there is lot of promotion during busy periods. Still trying to figure out an optimal tuning for our long CMS GCs.

@chewiebug
Copy link
Owner

As Bernd explained, it is somewhat up to the reader of a gc log, what he
considers to be a "full gc" and what's just a "gc". You can see in the
event details tab
(https://github.com/chewiebug/GCViewer/wiki/EventDetails) what GCViewer
considers to be a "full gc" (compartment named "Full gc pauses") or just
other stop the world events (compartment named "Gc pauses"). Usually,
full gcs for GCViewer are collections that span more than one generation
(young, tenured, perm), but it might not always be correct - so take
this information with a grain of salt.

The compartment "Concurrent GCs" shows information about concurrent
events in the gc log. They are not stop the world.

In CMS, no full gc events are needed to resize the heap. I observe
however, that young size is only changed with full gc events. Tenured
size can grow with other types of gc events. I am not sure, if resizing
happens, when your configuration includes -Xms14G -Xmx14G.

# for free to join this conversation on GitHub. Already have an account? # to comment
Labels
Projects
None yet
Development

No branches or pull requests

3 participants