1

I have such setup

  • Java 11 Corretto inside Docker running on EC2
  • Java options: -Xms1200m -Xmx1200m -XX:+UseG1GC -Xlog:gc*

In log I see that usually GC takes ~100-200ms, but for some timeslots, I see some weird behavior:

[2074.114s][info][gc,phases ] GC(39) Other: 4082.5ms

[2074.114s][info][gc,phases ] GC(39) Pre Evacuate Collection Set: 0.0ms

[2074.114s][info][gc,phases ] GC(39) Evacuate Collection Set: 161.7ms

[2074.114s][info][gc,phases ] GC(39) Post Evacuate Collection Set: 0.6ms

!!!!!!!!!!!!!![2074.114s][info][gc,phases ] GC(39) Other: 4082.5ms !!!!!!!!!!!!!!!!!!!!

[2074.114s][info][gc,heap ] GC(39) Eden regions: 253->0(574)

[2074.114s][info][gc,heap ] GC(39) Survivor regions: 49->27(38)

[2074.114s][info][gc,heap ] GC(39) Old regions: 186->229

[2074.114s][info][gc,heap ] GC(39) Humongous regions: 0->0

[2074.114s][info][gc,metaspace ] GC(39) Metaspace: 121063K->121063K(1159168K)

[2074.114s][info][gc ] GC(39) Pause Young (Normal) (G1 Evacuation Pause) 488M->256M(1200M) 4244.945ms

[2074.114s][info][gc,cpu ] GC(39) User=0.20s Sys=0.03s Real=4.25s

What does this "other" step mean?

Aleksandr Filichkin
  • 660
  • 2
  • 8
  • 22
  • it seems that this is supposed to be very small, so `G1` [does not even bother logging what was done there](https://hg.openjdk.java.net/jdk/jdk15/file/0dabbdfd97e6/src/hotspot/share/gc/g1/g1GCPhaseTimes.cpp#l533). It just logs this as "totalTime - allImportantPhases" – Eugene Dec 03 '20 at 20:40
  • there are only two ways out as far as I see : 1) build your own VM and add more logs (not that complicated as it might seem) 2) ask on the gc mailing list (though from the source code I don't see how they can help you more)... may be this was already encountered and they have a hint – Eugene Dec 03 '20 at 21:12

1 Answers1

2

This is most likely due to time spent writing the log out to disk which is considered an "other" task. A simple solution is to write the log out to ramdisk (/tmp on most distros).

Java with Jiva
  • 166
  • 6