Parsing issue with Rescan (parallel)' Line 594

[cbondeson]

I updated my java options to use the newer parallel garbage collection.

INFO [DataReaderFacade]: GCViewer version 1.35-SNAPSHOT (2015-05-03T15:12:31+0200)
INFO [DataReaderFactory]: File format: Sun 1.4.x
INFO [DataReaderSun1_6_0]: Reading Sun / Oracle 1.4.x / 1.5.x / 1.6.x / 1.7.x / 1.8.x format...
INFO [DataReaderSun1_6_0]: Java HotSpot(TM) 64-Bit Server VM (25.45-b02) for windows-amd64 JRE (1.8.0_45-b14), built on Apr 10 2015 10:34:15 by "java_re" with MS VC++ 10.0 (VS2010)
INFO [DataReaderSun1_6_0]: Memory: 4k page, physical 8388152k(7283092k free), swap 16774452k(15642624k free)
INFO [DataReaderSun1_6_0]: CommandLine flags: -XX:+AlwaysPreTouch -XX:+CMSClassUnloadingEnabled -XX:CMSInitiatingOccupancyFraction=70 -XX:+CMSParallelRemarkEnabled -XX:+CMSScavengeBeforeRemark -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=C:\jboss-eap-6.2\standalone\log'date'.hprof -XX:InitialHeapSize=5368709120 -XX:InitialTenuringThreshold=1 -XX:MaxHeapSize=6442450944 -XX:MaxNewSize=1073741824 -XX:MaxTenuringThreshold=1 -XX:NewSize=2111832064 -XX:OldPLABSize=16 -XX:-OmitStackTraceInFastThrow -XX:ParGCCardsPerStrideChunk=4096 -XX:ParallelGCThreads=4 -XX:+ParallelRefProcEnabled -XX:PrintFLSStatistics=2 -XX:+PrintGC -XX:+PrintGCApplicationStoppedTime -XX:-PrintGCCause -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+PrintTenuringDistribution -XX:SurvivorRatio=8 -XX:+UnlockDiagnosticVMOptions -XX:+UseCMSInitiatingOccupancyOnly -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:-UseLargePagesIndividualAllocation -XX:+UseParNewGC
WARNING [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'Rescan (parallel)' Line 594: 13.704: [Rescan (parallel) , 0.0166573 secs]13.721: [weak refs processing, 0.0018643 secs]13.723: [class unloading, 0.0086120 secs]13.732: [scrub symbol table, 0.0140871 secs]13.746: [scrub string table, 0.0013757 secs][1 CMS-remark: 11016K(3180544K)] 36431K(5036672K), 0.2018726 secs] [Times: user=0.58 sys=0.05, real=0.20 secs]
WARNING [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'Rescan (parallel)' Line 6624: 990.129: [Rescan (parallel) , 0.0130737 secs]990.142: [weak refs processing, 0.0233958 secs]990.166: [class unloading, 0.0978213 secs]990.264: [scrub symbol table, 0.0462283 secs]990.310: [scrub string table, 0.0032824 secs][1 CMS-remark: 871496K(3180544K)] 896620K(5036672K), 0.2228297 secs] [Times: user=0.45 sys=0.00, real=0.23 secs]
WARNING [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.ParseException: Error parsing entry (java.lang.StringIndexOutOfBoundsException: String index out of range: 28) Line 18601: 2015-05-11T11:24:36.350
INFO [DataReaderSun1_6_0]: Done reading.

[chewiebug]

Hi,

Could you please send me the log file to gcviewer-info@googlegroups.com?
I have an idea for the reason of the warnings shown, but I need the file
to verify.

Best regards,
Jörg

Am 11.05.2015 um 17:29 schrieb cbondeson:

I updated my java options to use the newer parallel garbage collection.

INFO [DataReaderFacade]: GCViewer version 1.35-SNAPSHOT
(2015-05-03T15:12:31+0200)
INFO [DataReaderFactory]: File format: Sun 1.4.x
INFO [DataReaderSun1_6_0]: Reading Sun / Oracle 1.4.x / 1.5.x / 1.6.x
/ 1.7.x / 1.8.x format...
INFO [DataReaderSun1_6_0]: Java HotSpot(TM) 64-Bit Server VM
(25.45-b02) for windows-amd64 JRE (1.8.0_45-b14), built on Apr 10 2015
10:34:15 by "java_re" with MS VC++ 10.0 (VS2010)
INFO [DataReaderSun1_6_0]: Memory: 4k page, physical 8388152k(7283092k
free), swap 16774452k(15642624k free)
INFO [DataReaderSun1_6_0]: CommandLine flags: -XX:+AlwaysPreTouch
-XX:+CMSClassUnloadingEnabled -XX:CMSInitiatingOccupancyFraction=70
-XX:+CMSParallelRemarkEnabled -XX:+CMSScavengeBeforeRemark
-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=C:\jboss-eap-6.2\standalone\log'date'.hprof
-XX:InitialHeapSize=5368709120 -XX:InitialTenuringThreshold=1
-XX:MaxHeapSize=6442450944 -XX:MaxNewSize=1073741824
-XX:MaxTenuringThreshold=1 -XX:NewSize=2111832064 -XX:OldPLABSize=16
-XX:-OmitStackTraceInFastThrow -XX:ParGCCardsPerStrideChunk=4096
-XX:ParallelGCThreads=4 -XX:+ParallelRefProcEnabled
-XX:PrintFLSStatistics=2 -XX:+PrintGC
-XX:+PrintGCApplicationStoppedTime -XX:-PrintGCCause
-XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps
-XX:+PrintHeapAtGC -XX:+PrintTenuringDistribution -XX:SurvivorRatio=8
-XX:+UnlockDiagnosticVMOptions -XX:+UseCMSInitiatingOccupancyOnly
-XX:+UseCompressedClassPointers -XX:+UseCompressedOops
-XX:+UseConcMarkSweepGC -XX:-UseLargePagesIndividualAl location
-XX:+UseParNewGC
WARNING [DataReaderSun1_6_0]:
com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc
type: 'Rescan (parallel)' Line 594: 13.704: [Rescan (parallel) ,
0.0166573 secs]13.721: [weak refs processing, 0.0018643 secs]13.723:
[class unloading, 0.0086120 secs]13.732: [scrub symbol table,
0.0140871 secs]13.746: [scrub string table, 0.0013757 secs][1
CMS-remark: 11016K(3180544K)] 36431K(5036672K), 0.2018726 secs]
[Times: user=0.58 sys=0.05, real=0.20 secs]
WARNING [DataReaderSun1_6_0]:
com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc
type: 'Rescan (parallel)' Line 6624: 990.129: [Rescan (parallel) ,
0.0130737 secs]990.142: [weak refs processing, 0.0233958 secs]990.166:
[class unloading, 0.0978213 secs]990.264: [scrub symbol table,
0.0462283 secs]990.310: [scrub string table, 0.0032824 secs][1
CMS-remark: 871496K(3180544K)] 896620K(5036672K), 0.2228297 secs]
[Times: user=0.45 sys=0.00, real=0.23 secs]
WARNING [DataReaderSun1_6_0]:
com.tagtraum.perf.gcviewer.imp.ParseException: Error parsing entry
(java.lang.StringIndexOutOfBoundsException: String index out of range:
28) Line 18601: 2015-05-11T11:24:36.350
INFO [DataReaderSun1_6_0]: Done reading.

—
Reply to this email directly or view it on GitHub
#132.

[chewiebug]

Hi Carl,

I have been able to update the parser with a fix for the issue you
opened. The latest 1.35-SNAPSHOT version now parses your sample file
without warnings.

For documentation reasons, here the details of the issue:

The "raw" event consists of a "remark" event (green text) and a
"scavenge before remark" event (blue text):
2015-05-14T22:53:06.052+0200: 1.179: [GC [YG occupancy: 8747 K (47936
K)]2015-05-14T22:53:06.052+0200: 1.179: [GC 1.179: [ParNew:
8747K->8747K(47936K), 0.0000295 secs] 109586K->109586K(154432K),
0.0000754 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
1.179: [Rescan (parallel) , 0.0003007 secs]1.180: [weak refs processing,
0.0000205 secs]1.180: [class unloading, 0.0003380 secs]1.180: [scrub
symbol table, 0.0006800 secs]1.181: [scrub string table, 0.0001462
secs][1 CMS-remark: 100839K(106496K)] 109586K(154432K), 0.0018413 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]

With the combination of your flags, the event is distributed across many
more lines (again: "remark" event -> green text, "scavenge before
remark" -> blue text | the combination of -XX:+ScavengeBeforeRemark
-XX:+PrintHeapAtGC was not supported yet):
2015-05-13T13:28:51.504-0400: 12.356: [GC [YG occupancy: 830688 K
(1310720 K)]{Heap before GC invocations=1 (full 1):
par new generation total 1310720K, used 830688K [0x0000000640000000,
0x00000006a0000000, 0x00000006a0000000)
eden space 1048576K, 76% used [0x0000000640000000,
0x000000067140a1f0, 0x0000000680000000)
from space 262144K, 9% used [0x0000000690000000,
0x000000069172dec0, 0x00000006a0000000)
to space 262144K, 0% used [0x0000000680000000,
0x0000000680000000, 0x0000000690000000)
concurrent mark-sweep generation total 3670016K, used 0K
[0x00000006a0000000, 0x0000000780000000, 0x00000007c0000000)
Metaspace used 38929K, capacity 43528K, committed 43796K,
reserved 1087488K
class space used 4934K, capacity 6361K, committed 6472K, reserved
1048576K
2015-05-13T13:28:51.504-0400: 12.357: [GC Before GC:

Statistics for BinaryTreeDictionary:

Total Free Space: 469745664
Max Chunk Size: 469745664
Number of Blocks: 1
Av. Block Size: 469745664
Tree Height: 1

Statistics for IndexedFreeLists:

Total Free Space: 0
Max Chunk Size: 0
Number of Blocks: 0
free=469745664 frag=0.0000
12.357: [ParNew
Desired survivor size 134217728 bytes, new threshold 1 (max 1)

• age 1: 19742112 bytes, 19742112 total
  : 830688K->25255K(1310720K), 0.1302057 secs]
  830688K->36167K(4980736K)After GC:
  Statistics for BinaryTreeDictionary:

  Total Free Space: 468117326
  Max Chunk Size: 468117326
  Number of Blocks: 1
  Av. Block Size: 468117326
  Tree Height: 1
  Statistics for IndexedFreeLists:

  Total Free Space: 231659
  Max Chunk Size: 254
  Number of Blocks: 3415
  Av. Block Size: 67
  free=468348985 frag=0.0010
  , 0.1306264 secs] [Times: user=0.45 sys=0.02, real=0.12 secs]
  Heap after GC invocations=2 (full 1):
  par new generation total 1310720K, used 25255K [0x0000000640000000,
  0x00000006a0000000, 0x00000006a0000000)
  eden space 1048576K, 0% used [0x0000000640000000,
  0x0000000640000000, 0x0000000680000000)
  from space 262144K, 9% used [0x0000000680000000,
  0x00000006818a9dd0, 0x0000000690000000)
  to space 262144K, 0% used [0x0000000690000000,
  0x0000000690000000, 0x00000006a0000000)
  concurrent mark-sweep generation total 3670016K, used 10911K
  [0x00000006a0000000, 0x0000000780000000, 0x00000007c0000000)
  Metaspace used 38929K, capacity 43528K, committed 43796K,
  reserved 1087488K
  class space used 4934K, capacity 6361K, committed 6472K, reserved
  1048576K
  }
  12.487: [Rescan (parallel) , 0.0173509 secs]12.505: [weak refs
  processing, 0.0018299 secs]12.507: [class unloading, 0.0084064
  secs]12.515: [scrub symbol table, 0.0160760 secs]12.531: [scrub string
  table, 0.0013724 secs][1 CMS-remark: 10911K(3670016K)] 36167K(4980736K),
  0.1787717 secs] [Times: user=0.58 sys=0.02, real=0.17 secs]

Best regards,
Jörg

[chewiebug]

see mailing list for the colours mentioned.

[cbondeson]

Thanks for quick closure. Great product.

From: chewiebug [mailto:notifications@github.com]
Sent: Thursday, May 14, 2015 5:04 PM
To: chewiebug/GCViewer
Cc: Bondeson, Carl
Subject: Re: [GCViewer] Parsing issue with Rescan (parallel)' Line 594 (#132)

Hi Carl,

I have been able to update the parser with a fix for the issue you
opened. The latest 1.35-SNAPSHOT version now parses your sample file
without warnings.

For documentation reasons, here the details of the issue:

The "raw" event consists of a "remark" event (green text) and a
"scavenge before remark" event (blue text):
2015-05-14T22:53:06.052+0200: 1.179: [GC [YG occupancy: 8747 K (47936
K)]2015-05-14T22:53:06.052+0200: 1.179: [GC 1.179: [ParNew:
8747K->8747K(47936K), 0.0000295 secs] 109586K->109586K(154432K),
0.0000754 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
1.179: [Rescan (parallel) , 0.0003007 secs]1.180: [weak refs processing,
0.0000205 secs]1.180: [class unloading, 0.0003380 secs]1.180: [scrub
symbol table, 0.0006800 secs]1.181: [scrub string table, 0.0001462
secs][1 CMS-remark: 100839K(106496K)] 109586K(154432K), 0.0018413 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]

With the combination of your flags, the event is distributed across many
more lines (again: "remark" event -> green text, "scavenge before
remark" -> blue text | the combination of -XX:+ScavengeBeforeRemark
-XX:+PrintHeapAtGC was not supported yet):
2015-05-13T13:28:51.504-0400: 12.356: [GC [YG occupancy: 830688 K
(1310720 K)]{Heap before GC invocations=1 (full 1):
par new generation total 1310720K, used 830688K [0x0000000640000000,
0x00000006a0000000, 0x00000006a0000000)
eden space 1048576K, 76% used [0x0000000640000000,
0x000000067140a1f0, 0x0000000680000000)
from space 262144K, 9% used [0x0000000690000000,
0x000000069172dec0, 0x00000006a0000000)
to space 262144K, 0% used [0x0000000680000000,
0x0000000680000000, 0x0000000690000000)
concurrent mark-sweep generation total 3670016K, used 0K
[0x00000006a0000000, 0x0000000780000000, 0x00000007c0000000)
Metaspace used 38929K, capacity 43528K, committed 43796K,
reserved 1087488K
class space used 4934K, capacity 6361K, committed 6472K, reserved
1048576K
2015-05-13T13:28:51.504-0400: 12.357: [GC Before GC:

Statistics for BinaryTreeDictionary:

Total Free Space: 469745664
Max Chunk Size: 469745664
Number of Blocks: 1
Av. Block Size: 469745664
Tree Height: 1

Statistics for IndexedFreeLists:

Total Free Space: 0
Max Chunk Size: 0
Number of Blocks: 0
free=469745664 frag=0.0000
12.357: [ParNew
Desired survivor size 134217728 bytes, new threshold 1 (max 1)

• age 1: 19742112 bytes, 19742112 total
  : 830688K->25255K(1310720K), 0.1302057 secs]
  830688K->36167K(4980736K)After GC:
  Statistics for BinaryTreeDictionary:

  Total Free Space: 468117326
  Max Chunk Size: 468117326
  Number of Blocks: 1
  Av. Block Size: 468117326
  Tree Height: 1
  Statistics for IndexedFreeLists:

  Total Free Space: 231659
  Max Chunk Size: 254
  Number of Blocks: 3415
  Av. Block Size: 67
  free=468348985 frag=0.0010
  , 0.1306264 secs] [Times: user=0.45 sys=0.02, real=0.12 secs]
  Heap after GC invocations=2 (full 1):
  par new generation total 1310720K, used 25255K [0x0000000640000000,
  0x00000006a0000000, 0x00000006a0000000)
  eden space 1048576K, 0% used [0x0000000640000000,
  0x0000000640000000, 0x0000000680000000)
  from space 262144K, 9% used [0x0000000680000000,
  0x00000006818a9dd0, 0x0000000690000000)
  to space 262144K, 0% used [0x0000000690000000,
  0x0000000690000000, 0x00000006a0000000)
  concurrent mark-sweep generation total 3670016K, used 10911K
  [0x00000006a0000000, 0x0000000780000000, 0x00000007c0000000)
  Metaspace used 38929K, capacity 43528K, committed 43796K,
  reserved 1087488K
  class space used 4934K, capacity 6361K, committed 6472K, reserved
  1048576K
  }
  12.487: [Rescan (parallel) , 0.0173509 secs]12.505: [weak refs
  processing, 0.0018299 secs]12.507: [class unloading, 0.0084064
  secs]12.515: [scrub symbol table, 0.0160760 secs]12.531: [scrub string
  table, 0.0013724 secs][1 CMS-remark: 10911K(3670016K)] 36167K(4980736K),
  0.1787717 secs] [Times: user=0.58 sys=0.02, real=0.17 secs]

Best regards,
Jörg

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/132#issuecomment-102169158.

[chewiebug]

You are welcome! You were lucky, that it was so easy to fix ;-).