Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

Jump to bottom

Parsing issue with Rescan (parallel)' Line 594 #132

Closed
cbondeson opened this issue May 11, 2015 · 5 comments
Closed

Parsing issue with Rescan (parallel)' Line 594 #132

cbondeson opened this issue May 11, 2015 · 5 comments
Assignees
@chewiebug
Labels
bug
Milestone
1.35

Comments

@cbondeson
Copy link

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
Copy link
Owner

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
Copy link
Owner

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 chewiebug added the bug label May 14, 2015
@chewiebug chewiebug added this to the 1.35 milestone May 14, 2015
@chewiebug chewiebug self-assigned this May 14, 2015
@chewiebug
Copy link
Owner

see mailing list for the colours mentioned.

@cbondeson
Copy link
Author

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
Copy link
Owner

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@chewiebug chewiebug

Labels
bug
Projects
None yet
Milestone
1.35
Development

No branches or pull requests
2 participants
@chewiebug @cbondeson