search

mgm3746 / garbagecat

Parses Java garbage collection logging and analyzes collectors, safepoint triggers, JVM version, JVM options, and OS information and reports error/warn/info level analysis and recommendations to support JVM tuning and troubleshooting for OpenJDK derivatives: (e.g. Adoptium, Azul, Microsoft, Oracle, Red Hat, etc.).
https://github.com/mgm3746/garbagecat/wiki
Eclipse Public License 1.0
211 stars 50 forks source link

1000 unidientified loglines - user error #175

Closed wolframhaussig closed 2 years ago

wolframhaussig commented 2 years ago

I am trying to analyze GC logfiles from Elasticsearch which contains its own JDK:

openjdk version "17.0.2" 2022-01-18 OpenJDK Runtime Environment Temurin-17.0.2+8 (build 17.0.2+8) OpenJDK 64-Bit Server VM Temurin-17.0.2+8 (build 17.0.2+8, mixed mode, sharing)

GC configuration:
9-:-Xlog:gc*,gc+age=trace,safepoint:file=/var/log/elasticsearch/gc.log:utctime,pid,tags:filecount=32,filesize=64m

I tried both java -jar garbagecat-4.0.0.jar -v -l gc.log and java -jar garbagecat-4.0.0.jar -v -l gc.log -p but the preprocessing does not seem to make a difference. Every GC log line seems to be unrecognised:

gc.log
=======================================================================
Running garbagecat version: 4.0.0
Latest garbagecat version/tag: v4.0.0
=======================================================================
SUMMARY:
-----------------------------------------------------------------------
# GC Events: 0
=======================================================================
ANALYSIS:
-----------------------------------------------------------------------
warn
-----------------------------------------------------------------------
*Unidentified log line(s). Please submit an issue so we can investigate: https://github.com/mgm3746/garbagecat/issues.
=======================================================================
1000 UNIDENTIFIED LOG LINE(S):
-----------------------------------------------------------------------
[2022-08-03T06:58:37.056+0000][1863][gc] Using G1
[2022-08-03T06:58:37.646+0000][1863][gc,init] Version: 17.0.2+8 (release)
[2022-08-03T06:58:37.646+0000][1863][gc,init] CPUs: 8 total, 8 available
[2022-08-03T06:58:37.647+0000][1863][gc,init] Memory: 32053M
[2022-08-03T06:58:37.647+0000][1863][gc,init] Large Page Support: Disabled
[2022-08-03T06:58:37.647+0000][1863][gc,init] NUMA Support: Disabled
[2022-08-03T06:58:37.647+0000][1863][gc,init] Compressed Oops: Enabled (Zero based)
[2022-08-03T06:58:37.647+0000][1863][gc,init] Heap Region Size: 8M
[2022-08-03T06:58:37.647+0000][1863][gc,init] Heap Min Capacity: 12G
[2022-08-03T06:58:37.647+0000][1863][gc,init] Heap Initial Capacity: 12G
[2022-08-03T06:58:37.647+0000][1863][gc,init] Heap Max Capacity: 12G
[2022-08-03T06:58:37.647+0000][1863][gc,init] Pre-touch: Enabled
[2022-08-03T06:58:37.647+0000][1863][gc,init] Parallel Workers: 8
[2022-08-03T06:58:37.647+0000][1863][gc,init] Concurrent Workers: 2
[2022-08-03T06:58:37.647+0000][1863][gc,init] Concurrent Refinement Workers: 8
[2022-08-03T06:58:37.647+0000][1863][gc,init] Periodic GC: Disabled
[2022-08-03T06:58:37.647+0000][1863][gc,metaspace] CDS archive(s) mapped at: [0x0000000800000000-0x0000000800bd2000-0x0000000800bd2000), size 12394496, SharedBaseAddress: 0x0000000800000000, ArchiveRelocationMode: 0.
[2022-08-03T06:58:37.647+0000][1863][gc,metaspace] Compressed class space mapped at: 0x0000000800c00000-0x0000000840c00000, reserved size: 1073741824
[2022-08-03T06:58:37.647+0000][1863][gc,metaspace] Narrow klass base: 0x0000000800000000, Narrow klass shift: 0, Narrow klass range: 0x100000000
[2022-08-03T06:58:38.019+0000][1863][safepoint   ] Safepoint "ICBufferFull", Time since last: 368885241 ns, Reaching safepoint: 265104 ns, At safepoint: 6352 ns, Total: 271456 ns
[2022-08-03T06:58:38.427+0000][1863][safepoint   ] Safepoint "ICBufferFull", Time since last: 407187526 ns, Reaching safepoint: 793250 ns, At safepoint: 3056 ns, Total: 796306 ns
[2022-08-03T06:58:39.029+0000][1863][safepoint   ] Safepoint "ICBufferFull", Time since last: 601429181 ns, Reaching safepoint: 180828 ns, At safepoint: 32881 ns, Total: 213709 ns
[2022-08-03T06:58:39.721+0000][1863][safepoint   ] Safepoint "ICBufferFull", Time since last: 691675400 ns, Reaching safepoint: 187991 ns, At safepoint: 3186 ns, Total: 191177 ns
[2022-08-03T06:58:40.308+0000][1863][safepoint   ] Safepoint "ICBufferFull", Time since last: 587393347 ns, Reaching safepoint: 193211 ns, At safepoint: 2885 ns, Total: 196096 ns
[2022-08-03T06:58:40.365+0000][1863][safepoint   ] Safepoint "ICBufferFull", Time since last: 56815642 ns, Reaching safepoint: 72846 ns, At safepoint: 1793 ns, Total: 74639 ns
[2022-08-03T06:58:40.366+0000][1863][safepoint   ] Safepoint "ICBufferFull", Time since last: 901322 ns, Reaching safepoint: 30116 ns, At safepoint: 1413 ns, Total: 31529 ns
[2022-08-03T06:58:40.371+0000][1863][safepoint   ] Safepoint "ICBufferFull", Time since last: 4303808 ns, Reaching safepoint: 64421 ns, At safepoint: 2344 ns, Total: 66765 ns
[2022-08-03T06:58:40.371+0000][1863][safepoint   ] Safepoint "ICBufferFull", Time since last: 542973 ns, Reaching safepoint: 64941 ns, At safepoint: 1363 ns, Total: 66304 ns
[2022-08-03T06:58:40.372+0000][1863][safepoint   ] Safepoint "ICBufferFull", Time since last: 862739 ns, Reaching safepoint: 120014 ns, At safepoint: 1132 ns, Total: 121146 ns
[2022-08-03T06:58:40.663+0000][1863][safepoint   ] Safepoint "ICBufferFull", Time since last: 290993304 ns, Reaching safepoint: 176306 ns, At safepoint: 2355 ns, Total: 178661 ns
[2022-08-03T06:58:41.313+0000][1863][gc,start    ] GC(0) Pause Young (Normal) (G1 Evacuation Pause)
[2022-08-03T06:58:41.313+0000][1863][gc,task     ] GC(0) Using 8 workers of 8 for evacuation
[2022-08-03T06:58:41.313+0000][1863][gc,age      ] GC(0) Desired survivor size 41943040 bytes, new threshold 15 (max threshold 15)
[2022-08-03T06:58:41.321+0000][1863][gc,age      ] GC(0) Age table with threshold 15 (max threshold 15)
[2022-08-03T06:58:41.321+0000][1863][gc,age      ] GC(0) - age   1:   16037032 bytes,   16037032 total
[2022-08-03T06:58:41.321+0000][1863][gc,phases   ] GC(0)   Pre Evacuate Collection Set: 0,2ms
[2022-08-03T06:58:41.321+0000][1863][gc,phases   ] GC(0)   Merge Heap Roots: 0,1ms
[2022-08-03T06:58:41.321+0000][1863][gc,phases   ] GC(0)   Evacuate Collection Set: 6,4ms
[2022-08-03T06:58:41.321+0000][1863][gc,phases   ] GC(0)   Post Evacuate Collection Set: 1,0ms
[2022-08-03T06:58:41.321+0000][1863][gc,phases   ] GC(0)   Other: 0,2ms
[2022-08-03T06:58:41.321+0000][1863][gc,heap     ] GC(0) Eden regions: 76->0(74)
[2022-08-03T06:58:41.321+0000][1863][gc,heap     ] GC(0) Survivor regions: 0->2(10)
[2022-08-03T06:58:41.321+0000][1863][gc,heap     ] GC(0) Old regions: 0->0
[2022-08-03T06:58:41.321+0000][1863][gc,heap     ] GC(0) Archive regions: 2->2
[2022-08-03T06:58:41.321+0000][1863][gc,heap     ] GC(0) Humongous regions: 0->0
[2022-08-03T06:58:41.321+0000][1863][gc,metaspace] GC(0) Metaspace: 19460K(19840K)->19460K(19840K) NonClass: 17082K(17280K)->17082K(17280K) Class: 2378K(2560K)->2378K(2560K)
[2022-08-03T06:58:41.321+0000][1863][gc          ] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 615M->23M(12288M) 7,870ms
[2022-08-03T06:58:41.321+0000][1863][gc,cpu      ] GC(0) User=0,04s Sys=0,00s Real=0,01s
[2022-08-03T06:58:41.321+0000][1863][safepoint   ] Safepoint "G1CollectForAllocation", Time since last: 648990739 ns, Reaching safepoint: 1001938 ns, At safepoint: 7951757 ns, Total: 8953695 ns

Can you give me a hint what I am doing wrong?

mgm3746 commented 2 years ago

Hi,

Your logging pattern includes the pid and tags.

The tags are these: [gc,init] [gc,heap ] [gc,phases ] etc.

garbagecat does handle default tags, where they are prepended by the log level. For example, "[info]" before the "[gc]": [0.014s][info][gc] Using G1

But when you explicitly specify "tag", it looks like it removes the leading "[info]".

I will update the code so "[info]" is optional.

Regarding tags, what is the use case for including these in your logging?

I would think logging that every line is wasted space?

I'm not that familiar with Elasticsearch, but doesn't it have the ability to extract gc logging for a specific process without logging pid on each line?

wolframhaussig commented 2 years ago

Thank you for your fast response :-)

We are trying to keep the config changes minimal and this is the default config from Elastic. Elasticsearch does not even read this line, but I feat that that the config is overwritten on version updates so we do not really want to touch this file.

mgm3746 commented 2 years ago

Ok, I will make an update to handle the default Elasticsearch logging pattern.

mgm3746 commented 2 years ago

I added support for the provided logging. You may well run into other issues, if you do, please open a new issue.