In OpenJDK 11 Windows OS Need solution for print timestamps in GC logs using JVM arguments

userxp9m 0
Viewed 55

Below is the JVM argument used.

JVMARGS=-Xms2048m -Xmx2048m -XX:MaxMetaspaceSize=128m -XX:+UseParallelGC -XX:+UseParallelOldGC -XX:ParallelGCThreads=2 -XX:+PrintGCDetails -XX:+PrintGCCause -Xloggc:C:\temp.txt

Generated log file

[0.092s][info][gc] Using Parallel [0.092s][info][gc,heap,coops] Heap address: 0x0000000080000000, size: 2048 MB, Compressed Oops mode: 32-bit [2.542s][info][gc,start     ] GC(0) Pause Young (Allocation Failure) [2.558s][info][gc,heap      ] GC(0) PSYoungGen: 524800K->7709K(611840K).

The time stamp in the generated log is not in readable format.

Tried below JVM arguments.

JVMARGS=-Xms2048m -Xmx2048m -XX:MaxMetaspaceSize=128m -XX:+UseParallelGC -XX:+UseParallelOldGC -XX:ParallelGCThreads=2 -XX:+PrintGCDetails -XX:+PrintGCCause -Xloggc:C:\temp.txt

We are expecting the timestamp in the readable format as follows.

[2022-08-18T05:35:53.167-0500][0.006s] Minimum heap 2147483648  Initial heap 2147483648  Maximum heap 147483648
[2022-08-18T05:35:53.173-0500][0.012s] Using Parallel
[2022-08-18T05:35:53.173-0500][0.012s] Heap address: 0x0000000080000000, size: 2048 MB, Compressed Oops mode: 32-bit
[2022-08-18T05:35:54.700-0500][1.539s] GC(0) Heap before GC invocations=1 (full 0): PSYoungGen      total 11840K, used 524800K [0x00000000d5580000, 0x0000000100000000, 0x0000000100000000)
[2022-08-18T05:35:54.700-0500][1.539s] GC(0)   eden space 524800K, 100% used [0x00000000d5580000,0x00000000f5600000,0x00000000f5600000)

Please help us to retrieve the timestamp in readable format using openJDK 11 in windows OS.

jvm-arguments garbage-collection jvm java-11 java
1 Answers

-Xlog:gc*:log.txt:time,uptime will resolve your problem. time provide timestamp and uptime will provide GC operation uptime.

Testing with below arguments

-Xms2048m -Xmx2048m -XX:MaxMetaspaceSize=128m -XX:+UseParallelGC -XX:+UseParallelOldGC -XX:ParallelGCThreads=2 -Xlog:gc*:log.txt:time,uptime

OS: Windows 11

Java: openjdk-11.0.4+11

Result

[2022-09-11T13:14:24.808+0300][0.023s] Using Parallel
[2022-09-11T13:14:24.809+0300][0.024s] Heap address: 0x0000000080000000, size: 2048 MB, Compressed Oops mode: 32-bit
[2022-09-11T13:14:25.326+0300][0.541s] GC(0) Pause Young (Allocation Failure)
[2022-09-11T13:14:25.644+0300][0.859s] GC(0) PSYoungGen: 524800K->87024K(611840K)
[2022-09-11T13:14:25.644+0300][0.859s] GC(0) ParOldGen: 0K->409320K(1398272K)
[2022-09-11T13:14:25.644+0300][0.859s] GC(0) Metaspace: 6712K->6712K(131072K)
[2022-09-11T13:14:25.644+0300][0.859s] GC(0) Pause Young (Allocation Failure) 512M->484M(1963M) 318.035ms
[2022-09-11T13:14:25.644+0300][0.859s] GC(0) User=0.58s Sys=0.08s Real=0.32s
[2022-09-11T13:14:25.721+0300][0.936s] Heap
[2022-09-11T13:14:25.721+0300][0.936s]  PSYoungGen      total 611840K, used 304322K [0x00000000d5580000, 0x0000000100000000, 0x0000000100000000)
Turac0
Related