search

chewiebug / GCViewer

Fork of tagtraum industries' GCViewer. Tagtraum stopped development in 2008, I aim to improve support for Sun's / Oracle's java 1.6+ garbage collector logs (including G1 collector)
https://github.com/chewiebug/GCViewer/wiki
Other
4.46k stars 978 forks source link

Support for ShenandoahGC on jdk11 #210

Open jborgers opened 6 years ago

jborgers commented 6 years ago

Hi,

I get parse errors for ShenandoahGC on jdk11:

NFO [DataReaderFacade]: GCViewer version 1.36-SNAPSHOT (2018-10-23T20:08:13+0000) INFO [DataReaderFactory]: File format: Oracle / OpenJDK unified jvm logging INFO [DataReaderUnifiedJvmLogging]: Reading Oracle / OpenJDK unified jvm logging format... WARNING [DataReaderUnifiedJvmLogging]: Failed to parse line number 1 (no match; line="[0.001s][info][gc] Consider -XX:+ClassUnloadingWithConcurrentMark if large pause times are observed on class-unloading sensitive workloads") INFO [DataReaderUnifiedJvmLogging]: Using Shenandoah WARNING [DataReaderUnifiedJvmLogging]: Failed to parse line number 3 (no match; line="[0,778s][info][gc] Trigger: Learning 1 of 5. Free (714M) is below initial threshold (716M)") WARNING [DataReaderUnifiedJvmLogging]: Failed to parse gc event (com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'Concurrent reset') on line number 4 (line="[0,779s][info][gc] GC(0) Concurrent reset 241M->241M(1024M) 0,627ms") WARNING [DataReaderUnifiedJvmLogging]: Expected memory and pause in the end of line number 8 (line="[0,826s][info][gc] GC(0) Pause Final Mark (process weakrefs) 0,339ms") WARNING [DataReaderUnifiedJvmLogging]: Failed to parse gc event (com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'Concurrent cleanup') on line number 9 (line="[0,826s][info][gc] GC(0) Concurrent cleanup 250M->179M(1024M) 0,078ms") [..] Pause metrics could be correct, however, memory metrics don't have meaningful values. I attached the gc log file.

Thanks! Jeroen

Would be helpful to fix

jborgers commented 6 years ago

[0.001s][info][gc] Consider -XX:+ClassUnloadingWithConcurrentMark if large pause times are observed on class-unloading sensitive workloads [0.011s][info][gc] Using Shenandoah [0,778s][info][gc] Trigger: Learning 1 of 5. Free (714M) is below initial threshold (716M) [0,779s][info][gc] GC(0) Concurrent reset 241M->241M(1024M) 0,627ms [0,783s][info][gc] GC(0) Pause Init Mark (process refs) 1,864ms [0,825s][info][gc] GC(0) Concurrent marking (process weakrefs) 241M->249M(1024M) 41,586ms [0,825s][info][gc] GC(0) Concurrent precleaning 249M->249M(1024M) 0,004ms [0,826s][info][gc] GC(0) Pause Final Mark (process weakrefs) 0,339ms [0,826s][info][gc] GC(0) Concurrent cleanup 250M->179M(1024M) 0,078ms [0,853s][info][gc] GC(0) Concurrent evacuation 179M->217M(1024M) 26,494ms [0,853s][info][gc] GC(0) Pause Init Update Refs 0,037ms [0,919s][info][gc] GC(0) Concurrent update references 217M->233M(1024M) 65,949ms [0,920s][info][gc] GC(0) Pause Final Update Refs 0,182ms [0,921s][info][gc] GC(0) Concurrent cleanup 233M->138M(1024M) 0,069ms [1,309s][info][gc] Trigger: Learning 2 of 5. Free (716M) is below initial threshold (716M) [1,310s][info][gc] GC(1) Concurrent reset 252M->252M(1024M) 0,579ms [1,311s][info][gc] GC(1) Pause Init Mark 0,291ms [1,384s][info][gc] GC(1) Concurrent marking 252M->271M(1024M) 72,940ms [1,384s][info][gc] GC(1) Pause Final Mark 0,297ms [1,384s][info][gc] GC(1) Concurrent cleanup 271M->234M(1024M) 0,063ms [1,401s][info][gc] GC(1) Concurrent evacuation 234M->259M(1024M) 16,903ms [1,402s][info][gc] GC(1) Pause Init Update Refs 0,039ms [1,467s][info][gc] GC(1) Concurrent update references 259M->275M(1024M) 65,039ms [1,467s][info][gc] GC(1) Pause Final Update Refs 0,168ms [1,468s][info][gc] GC(1) Concurrent cleanup 275M->212M(1024M) 0,076ms [1,595s][info][gc] Trigger: Learning 3 of 5. Free (712M) is below initial threshold (716M) [1,595s][info][gc] GC(2) Concurrent reset 259M->259M(1024M) 0,593ms [1,596s][info][gc] GC(2) Pause Init Mark 0,169ms [1,669s][info][gc] GC(2) Concurrent marking 259M->333M(1024M) 72,606ms [1,704s][info][gc] GC(2) Pause Final Mark 34,412ms [1,704s][info][gc] GC(2) Concurrent cleanup 333M->333M(1024M) 0,043ms [1,729s][info][gc] GC(2) Concurrent evacuation 333M->355M(1024M) 25,223ms [1,729s][info][gc] GC(2) Pause Init Update Refs 0,056ms [1,903s][info][gc] GC(2) Concurrent update references 355M->390M(1024M) 174,123ms [1,904s][info][gc] GC(2) Pause Final Update Refs 0,131ms [1,904s][info][gc] GC(2) Concurrent cleanup 391M->339M(1024M) 0,039ms [1,906s][info][gc] Trigger: Learning 4 of 5. Free (631M) is below initial threshold (716M) [1,906s][info][gc] GC(3) Concurrent reset 339M->339M(1024M) 0,606ms [1,907s][info][gc] GC(3) Pause Init Mark 0,164ms [2,020s][info][gc] GC(3) Concurrent marking 339M->367M(1024M) 112,747ms [2,020s][info][gc] GC(3) Pause Final Mark 0,247ms [2,020s][info][gc] GC(3) Concurrent cleanup 367M->312M(1024M) 0,045ms [2,028s][info][gc] GC(3) Concurrent evacuation 312M->323M(1024M) 8,068ms [2,029s][info][gc] GC(3) Pause Init Update Refs 0,034ms [2,112s][info][gc] GC(3) Concurrent update references 323M->341M(1024M) 82,994ms [2,112s][info][gc] GC(3) Pause Final Update Refs 0,185ms [2,112s][info][gc] GC(3) Concurrent cleanup 341M->312M(1024M) 0,058ms [2,114s][info][gc] Trigger: Learning 5 of 5. Free (659M) is below initial threshold (716M) [2,114s][info][gc] GC(4) Concurrent reset 312M->312M(1024M) 0,593ms [2,115s][info][gc] GC(4) Pause Init Mark 0,163ms [2,230s][info][gc] GC(4) Concurrent marking 312M->338M(1024M) 115,559ms [2,231s][info][gc] GC(4) Pause Final Mark 0,295ms [2,231s][info][gc] GC(4) Concurrent cleanup 338M->338M(1024M) 0,028ms [2,240s][info][gc] GC(4) Concurrent evacuation 338M->353M(1024M) 8,968ms [2,240s][info][gc] GC(4) Pause Init Update Refs 0,035ms [2,345s][info][gc] GC(4) Concurrent update references 353M->374M(1024M) 105,554ms [2,346s][info][gc] GC(4) Pause Final Update Refs 0,240ms [2,346s][info][gc] GC(4) Concurrent cleanup 374M->342M(1024M) 0,163ms [4,509s][info][gc] Trigger: Free (102M) is below minimum threshold (102M) [4,510s][info][gc] GC(5) Concurrent reset 867M->867M(1024M) 0,768ms [4,510s][info][gc] GC(5) Pause Init Mark (process refs) 0,215ms [4,849s][info][gc] GC(5) Concurrent marking (process weakrefs) 867M->893M(1024M) 338,293ms [4,849s][info][gc] GC(5) Concurrent precleaning 893M->893M(1024M) 0,004ms [4,851s][info][gc] GC(5) Pause Final Mark (process weakrefs) 0,432ms [4,851s][info][gc] GC(5) Concurrent cleanup 894M->811M(1024M) 0,058ms [4,898s][info][gc] GC(5) Concurrent evacuation 811M->862M(1024M) 47,124ms [4,899s][info][gc] GC(5) Pause Init Update Refs 0,041ms [5,195s][info][gc] GC(5) Concurrent update references 862M->922M(1024M) 295,151ms [5,195s][info][gc] GC(5) Pause Final Update Refs 0,171ms [5,195s][info][gc] GC(5) Concurrent cleanup 922M->595M(1024M) 0,093ms [6,808s][info][gc] Trigger: Free (102M) is below minimum threshold (102M) [6,809s][info][gc] GC(6) Concurrent reset 867M->867M(1024M) 1,544ms [6,810s][info][gc] GC(6) Pause Init Mark 0,260ms [7,203s][info][gc] GC(6) Concurrent marking 867M->894M(1024M) 392,755ms [7,203s][info][gc] GC(6) Pause Final Mark 0,379ms [7,203s][info][gc] GC(6) Concurrent cleanup 894M->893M(1024M) 0,029ms [7,252s][info][gc] GC(6) Concurrent evacuation 893M->946M(1024M) 49,223ms [7,258s][info][gc] GC(6) Pause Init Update Refs 0,042ms [7,556s][info][gc] GC(6) Concurrent update references 946M->989M(1024M) 298,416ms [7,557s][info][gc] GC(6) Pause Final Update Refs 0,147ms [7,558s][info][gc] GC(6) Concurrent cleanup 989M->614M(1024M) 0,156ms [8,879s][info][gc] Trigger: Average GC time (437,12 ms) is above the time for allocation rate (153,05 MB/s) to deplete free headroom (66M) [8,881s][info][gc] GC(7) Concurrent reset 851M->851M(1024M) 1,543ms [8,881s][info][gc] GC(7) Pause Init Mark 0,417ms [9,287s][info][gc] GC(7) Concurrent marking 852M->879M(1024M) 405,492ms [9,288s][info][gc] GC(7) Pause Final Mark 0,465ms [9,288s][info][gc] GC(7) Concurrent cleanup 879M->879M(1024M) 0,029ms [9,333s][info][gc] GC(7) Concurrent evacuation 879M->930M(1024M) 45,309ms [9,333s][info][gc] GC(7) Pause Init Update Refs 0,033ms [9,685s][info][gc] GC(7) Concurrent update references 930M->982M(1024M) 351,446ms [9,685s][info][gc] GC(7) Pause Final Update Refs 0,124ms [9,685s][info][gc] GC(7) Concurrent cleanup 982M->625M(1024M) 0,091ms [10,564s][info][gc] Trigger: Average GC time (536,54 ms) is above the time for allocation rate (171,78 MB/s) to deplete free headroom (91M) [10,566s][info][gc] GC(8) Concurrent reset 826M->826M(1024M) 1,630ms [10,568s][info][gc] GC(8) Pause Init Mark 0,301ms [11,004s][info][gc] GC(8) Concurrent marking 827M->858M(1024M) 435,432ms [11,004s][info][gc] GC(8) Pause Final Mark 0,389ms [11,004s][info][gc] GC(8) Concurrent cleanup 858M->857M(1024M) 0,056ms [11,037s][info][gc] GC(8) Concurrent evacuation 857M->905M(1024M) 32,155ms [11,037s][info][gc] GC(8) Pause Init Update Refs 0,037ms [11,361s][info][gc] GC(8) Concurrent update references 905M->962M(1024M) 323,648ms [11,361s][info][gc] GC(8) Pause Final Update Refs 0,146ms [11,361s][info][gc] GC(8) Concurrent cleanup 962M->627M(1024M) 0,104ms [12,160s][info][gc] Trigger: Average GC time (654,69 ms) is above the time for allocation rate (171,07 MB/s) to deplete free headroom (111M) [12,163s][info][gc] GC(9) Concurrent reset 806M->807M(1024M) 1,676ms [12,163s][info][gc] GC(9) Pause Init Mark 0,197ms [12,582s][info][gc] GC(9) Concurrent marking 807M->842M(1024M) 419,067ms [12,583s][info][gc] GC(9) Pause Final Mark 0,388ms [12,583s][info][gc] GC(9) Concurrent cleanup 842M->841M(1024M) 0,050ms [12,616s][info][gc] GC(9) Concurrent evacuation 841M->891M(1024M) 32,503ms [12,616s][info][gc] GC(9) Pause Init Update Refs 0,036ms [12,937s][info][gc] GC(9) Concurrent update references 891M->950M(1024M) 320,640ms [12,937s][info][gc] GC(9) Pause Final Update Refs 0,155ms [12,937s][info][gc] GC(9) Concurrent cleanup 950M->628M(1024M) 0,111ms [13,662s][info][gc] Trigger: Average GC time (763,44 ms) is above the time for allocation rate (173,22 MB/s) to deplete free headroom (131M) [13,664s][info][gc] GC(10) Concurrent reset 787M->787M(1024M) 1,731ms [13,669s][info][gc] GC(10) Pause Init Mark (process refs) 0,281ms [14,089s][info][gc] GC(10) Concurrent marking (process weakrefs) 787M->825M(1024M) 420,178ms [14,089s][info][gc] GC(10) Concurrent precleaning 825M->825M(1024M) 0,020ms [14,090s][info][gc] GC(10) Pause Final Mark (process weakrefs) 0,401ms [14,090s][info][gc] GC(10) Concurrent cleanup 825M->825M(1024M) 0,029ms [14,122s][info][gc] GC(10) Concurrent evacuation 825M->874M(1024M) 32,258ms [14,122s][info][gc] GC(10) Pause Init Update Refs 0,034ms [14,460s][info][gc] GC(10) Concurrent update references 875M->939M(1024M) 336,276ms [14,460s][info][gc] GC(10) Pause Final Update Refs 0,183ms [14,460s][info][gc] GC(10) Concurrent cleanup 939M->628M(1024M) 0,092ms [15,143s][info][gc] Trigger: Average GC time (785,85 ms) is above the time for allocation rate (176,18 MB/s) to deplete free headroom (138M) [15,145s][info][gc] GC(11) Concurrent reset 780M->780M(1024M) 1,693ms [15,146s][info][gc] GC(11) Pause Init Mark 0,184ms [15,594s][info][gc] GC(11) Concurrent marking 780M->820M(1024M) 447,955ms [15,597s][info][gc] GC(11) Pause Final Mark 2,700ms [15,597s][info][gc] GC(11) Concurrent cleanup 821M->821M(1024M) 0,069ms [15,632s][info][gc] GC(11) Concurrent evacuation 821M->870M(1024M) 35,490ms [15,633s][info][gc] GC(11) Pause Init Update Refs 0,036ms [15,974s][info][gc] GC(11) Concurrent update references 870M->930M(1024M) 340,998ms [15,976s][info][gc] GC(11) Pause Final Update Refs 0,296ms [15,976s][info][gc] GC(11) Concurrent cleanup 931M->623M(1024M) 0,092ms [16,739s][info][gc] Trigger: Average GC time (802,23 ms) is above the time for allocation rate (168,28 MB/s) to deplete free headroom (134M) [16,741s][info][gc] GC(12) Concurrent reset 783M->783M(1024M) 1,220ms [16,741s][info][gc] GC(12) Pause Init Mark 0,158ms [17,186s][info][gc] GC(12) Concurrent marking 783M->822M(1024M) 444,520ms [17,187s][info][gc] GC(12) Pause Final Mark 0,942ms [17,187s][info][gc] GC(12) Concurrent cleanup 822M->823M(1024M) 0,043ms [17,221s][info][gc] GC(12) Concurrent evacuation 823M->872M(1024M) 33,622ms [17,221s][info][gc] GC(12) Pause Init Update Refs 0,035ms [17,560s][info][gc] GC(12) Concurrent update references 872M->933M(1024M) 338,302ms [17,560s][info][gc] GC(12) Pause Final Update Refs 0,191ms [17,560s][info][gc] GC(12) Concurrent cleanup 933M->627M(1024M) 0,114ms [18,242s][info][gc] Trigger: Average GC time (805,22 ms) is above the time for allocation rate (172,66 MB/s) to deplete free headroom (138M) [18,244s][info][gc] GC(13) Concurrent reset 779M->779M(1024M) 1,619ms [18,244s][info][gc] GC(13) Pause Init Mark 0,195ms [18,695s][info][gc] GC(13) Concurrent marking 779M->819M(1024M) 450,717ms [18,696s][info][gc] GC(13) Pause Final Mark 0,377ms [18,696s][info][gc] GC(13) Concurrent cleanup 819M->819M(1024M) 0,057ms [18,726s][info][gc] GC(13) Concurrent evacuation 819M->867M(1024M) 29,921ms [18,728s][info][gc] GC(13) Pause Final Evac 0,005ms [18,728s][info][gc] GC(13) Concurrent cleanup 868M->868M(1024M) 0,163ms [18,831s][info][gc] Cancelling GC: Stopping VM