Uploaded image for project: 'Jira Data Center'
  1. Jira Data Center
  2. JRASERVER-71420

Java 11 GC logging configuration is not parseable in GCViewer

XMLWordPrintable

      Issue Summary

      The currently shipped GC logging configuration file (see "set-gc-params.sh" & "set-gc-params.bat" files ) does not allow the GC logs to be parsed in GCViewer correctly. GCViewer throws "Failed to recognize file format" error.

      This is the current configuration :

          GC_JVM_PARAMETERS="-Xlog:gc*:file=$LOGBASEABS/logs/atlassian-jira-gc-%t.log:time,uptime:filecount=5,filesize=20M ${GC_JVM_PARAMETERS}"

      It is missing "tags" and "level"

      I have raised a ticket to GCViewer to get some insight on this here:

      Steps to Reproduce

      1. Use JAVA 11 ( AdoptOpenJDK ) with Jira. You can use the JAVA_HOME="path-to/adoptopenjdk-11.jdk/Contents/Home" to configure this on the setenv.sh file.
      2. Try to open the GC logs in GCViewer

      Expected Results

      GC logs will parse correctly in GCViewer

      Actual Results

      This error will be thrown :

      INFO [DataReaderFacade]: GCViewer version 1.37-SNAPSHOT (2019-12-16T20:29:43+0000)
SEVERE [DataReaderFactory]: Failed to recognize file format.
content:
[2020-08-10T19:43:00.036-0800][207.616s] GC(122)   Post Evacuate Collection Set: 1.9ms
[2020-08-10T19:43:00.036-0800][207.616s] GC(122)   Other: 0.3ms
[2020-08-10T19:43:00.036-0800][207.616s] GC(122) Eden regions: 209->0(203)
[2020-08-10T19:43:00.036-0800][207.616s] GC(122) Survivor regions: 21->15(29)
[2020-08-10T19:43:00.036-0800][207.616s] GC(122) Old regions: 371->384
[2020-08-10T19:43:00.036-0800][207.616s] GC(122) Humongous regions: 2->2
[2020-08-10T19:43:00.036-0800][207.616s] GC(122) Metaspace: 237617K->237617K(1271808K)
[2020-08-10T19:43:00.036-0800][207.616s] GC(122) Pause Young (Normal) (GCLocker Initiated GC) 601M->399M(703M) 45.411ms
[2020-08-10T19:43:00.036-0800][207.616s] GC(122) User=0.10s Sys=0.00s Real=0.04s
[2020-08-10T19:43:00.884-0800][208.464s] GC(123) Pause Young (Concurrent Start) (GCLocker Initiated GC)
[2020-08-10T19:43:00.884-0800][208.465s] GC(123) Using 4 workers of 4 for evacuation
[2020-08-10T19:43:00.934-0800][208.514s] GC(123)   Pre Evacuate Collection Set: 0.5ms
[2020-08-10T19:43:00.934-0800][208.514s] GC(123)   Evacuate Collection Set: 39.1ms
[2020-08-10T19:43:00.934-0800][208.514s] GC(123)   Post Evacuate Collection Set: 9.7ms
[2020-08-10T19:43:00.934-0800][208.514s] GC(123)   Other: 0.5ms
[2020-08-10T19:43:00.934-0800][208.514s] GC(123) Eden regions: 204->0(196)
[2020-08-10T19:43:00.934-0800][208.514s] GC(123) Survivor regions: 15->23(28)
[2020-08-10T19:43:00.934-0800][208.514s] GC(123) Old regions: 384->384
[2020-08-10T19:43:00.934-0800][208.514s] GC(123) Humongous regions: 2->2
[2020-08-10T19:43:00.934-0800][208.514s] GC(123) Metaspace: 246711K->246711K(1280000K)
[2020-08-10T19:43:00.934-0800][208.514s] GC(123) Pause Young (Concurrent Start) (GCLocker Initiated GC) 603M->408M(703M) 49.910ms
[2020-08-10T19:43:00.934-0800][208.514s] GC(123) User=0.13s Sys=0.00s Real=0.05s
[2020-08-10T19:43:00.934-0800][208.514s] GC(124) Concurrent Cycle
[2020-08-10T19:43:00.934-0800][208.514s] GC(124) Concurrent Clear Claimed Marks
[2020-08-10T19:43:00.934-0800][208.515s] GC(124) Concurrent Clear Claimed Marks 0.403ms
[2020-08-10T19:43:00.935-0800][208.515s] GC(124) Concurrent Scan Root Regions
[2020-08-10T19:43:00.982-0800][208.563s] GC(124) Concurrent Scan Root Regions 47.671ms
[2020-08-10T19:43:00.982-0800][208.563s] GC(124) Concurrent Mark (208.563s)
[2020-08-10T19:43:00.982-0800][208.563s] GC(124) Concurrent Mark From Roots
[2020-08-10T19:43:00.982-0800][208.563s] GC(124) Using 1 workers of 1 for marking
[2020-08-10T19:43:01.952-0800][209.532s] GC(125) Pause Young (Normal) (G1 Evacuation Pause)
[2020-08-10T19:43:01.952-0800][209.533s] GC(125) Using 4 workers of 4 for evacuation
[2020-08-10T19:43:01.991-0800][209.572s] GC(125)   Pre Evacuate Collection Set: 0.0ms
[2020-08-10T19:43:01.991-0800][209.572s] GC(125)   Evacuate Collection Set: 37.6ms
[2020-08-10T19:43:01.991-0800][209.572s] GC(125)   Post Evacuate Collection Set: 1.3ms
[2020-08-10T19:43:01.991-0800][209.572s] GC(125)   Other: 0.3ms
[2020-08-10T19:43:01.991-0800][209.572s] GC(125) Eden regions: 196->0(186)
[2020-08-10T19:43:01.991-0800][209.572s] GC(125) Survivor regions: 23->20(28)
[2020-08-10T19:43:01.991-0800][209.572s] GC(125) Old regions: 384->396
[2020-08-10T19:43:01.992-0800][209.572s] GC(125) Humongous regions: 2->2
[2020-08-10T19:43:01.992-0800][209.572s] GC(125) Metaspace: 256819K->256819K(1290240K)
[2020-08-10T19:43:01.992-0800][209.572s] GC(125) Pause Young (Normal) (G1 Evacuation Pause) 604M->418M(703M) 39.392ms
[2020-08-10T19:43:01.992-0800][209.572s] GC(125) User=0.13s Sys=0.00s Real=0.04s

WARNING [DataReaderFacade]: Failed to read file.
java.io.IOException: Failed to recognize file format. Failed to recognize file format.
WARNING [AbstractGCModelLoaderImpl]: Failed to create GCModel from /Users/adrianstephen/jira/atlassian-jira-software-8.11.0-standalone/logs/atlassian-jira-gc-2020-08-10_19-39-32.log
java.util.concurrent.ExecutionException: com.tagtraum.perf.gcviewer.imp.DataReaderException
...
Caused by: java.io.IOException: Failed to recognize file format.

      Workaround

      Reply from https://github.com/chewiebug/GCViewer/issues/245

      GCViewer relies for performance and complexity reasons on the presence of the "tags" and "level" information in the java unified logs generated by JDK 11 VMs (https://openjdk.java.net/jeps/158). Your logs are missing both (this part of the configuration:
      -Xlog:gc*:file=/<path-to-file>:time,uptime:...).

      The readme gives examples of configurations, which GCViewer at this time is able to process:

      -Xlog:gc:file="path-to-file" (uses defaults)
      -Xlog:gc=info:file="path-to-file":tags,uptime,level (minimum configuration needed)
      -Xlog:gc*=trace:file="path-to-file":tags,time,uptime,level (maximum configuration supported, additional tags ok, but ignored; additional decorations will break parsing)
      If you just add "tags" and "level" to your configuration, GCViewer should be able to parse your log files.

      Best regards,
      Jörg

      JIRA Specific workaround for Linux

      1. Stop Jira
      2. Edit the JIRA_INSTALL/bin/set-gc-params.sh file
      3. Modify this line : 
         GC_JVM_PARAMETERS="-Xlog:gc*:file=$LOGBASEABS/logs/atlassian-jira-gc-%t.log:time,uptime:filecount=5,filesize=20M ${GC_JVM_PARAMETERS}"

        to

         GC_JVM_PARAMETERS="-Xlog:gc*:file=$LOGBASEABS/logs/atlassian-jira-gc-%t.log:tags,time,uptime,level:filecount=5,filesize=20M ${GC_JVM_PARAMETERS}"

        Adding tags & level

      4. Start Jira

      JIRA Specific workaround for Windows

      1. Stop Jira
      2. Edit the JIRA_INSTALL/bin/set-gc-params.bat file
      3. Modify this line : 
         set GC_JVM_PARAMETERS=-Xlog:gc*:file=\"%atlassian_logsdir%\atlassian-jira-gc-%%t.log\":time,uptime:filecount=5,filesize=20M %GC_JVM_PARAMETERS%

        to

         set GC_JVM_PARAMETERS=-Xlog:gc*:file=\"%atlassian_logsdir%\atlassian-jira-gc-%%t.log\":tags,time,uptime,level:filecount=5,filesize=20M %GC_JVM_PARAMETERS%

        Adding tags & level

      1. Start Jira

      JIRA Specific workaround for Windows when Jira is being run as a service

      • Stop service
      • Edit the JIRA_INSTALL/bin/set-gc-params-service.bat file
      • Modify this line : 
        set GC_JVM_PARAMETERS=%JVM_GC_ARGS%;-Xlog:gc*:file=.\logs\atlassian-jira-gc-%%t.log:time,uptime:filecount=5,filesize=20M

        to

        set GC_JVM_PARAMETERS=%JVM_GC_ARGS%;-Xlog:gc*:file=.\logs\atlassian-jira-gc-%%t.log:tags,time,uptime,level:filecount=5,filesize=20M

        Adding tags & level

      • Reinstall service
      • Start service

        1. image-2020-08-10-19-43-25-865.png
          509 kB
          Adrian Stephen
        2. image-2020-11-09-17-51-55-174.png
          181 kB
          Alex [Atlassian,PSE]

              agniadzik Artur Gniadzik
              astephen@atlassian.com Adrian Stephen
              Votes:
              0 Vote for this issue
              Watchers:
              11 Start watching this issue

                Created:
                Updated:
                Resolved: