CODEWITHSUNDEEP
javagarbage-collectiong1gc
Roshan
Roshan

Reputation: 290

Understanding cause of G1 garbage collector's long pause in one specific GC-phase

I am trying to G1 type garbage collector in a server-side JVM and while, in general, the gc-pauses are quite short, once in a while they shoot up and then we have issues.

I am giving below the break-up of one of such long pauses, which is overall taking 27.79 seconds, of which 23.923 seconds are going for the phase indicated by "Other" in "[Other: 23923.6 ms]".

If someone can throw some light on how I can understand further the cause of this particular GC cycle-phase or how I can improve the GC situation, which seems to be making majority of the time, I'll appreciate it very much.

[GC pause (G1 Evacuation Pause) (young)
Desired survivor size 524288 bytes, new threshold 0 (max 0)
, 25.0957244 secs]
     [Parallel Time: 1087.3 ms, GC Workers: 4]
   [GC Worker Start (ms): Min: 5050906.2, Avg: 5050906.4, Max: 5050906.5, Diff: 0.2]
   [Ext Root Scanning (ms): Min: 1.0, Avg: 190.7, Max: 415.2, Diff: 414.2, Sum: 762.8]
   [Update RS (ms): Min: 308.9, Avg: 565.0, Max: 650.3, Diff: 341.4, Sum: 2259.8]
      [Processed Buffers: Min: 56, Avg: 69.2, Max: 82, Diff: 26, Sum: 277]
   [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
   [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
   [Object Copy (ms): Min: 0.8, Avg: 310.7, Max: 414.8, Diff: 414.0, Sum: 1242.9]
   [Termination (ms): Min: 0.0, Avg: 15.6, Max: 20.8, Diff: 20.8, Sum: 62.4]
      [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
   [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
   [GC Worker Total (ms): Min: 1066.9, Avg: 1082.0, Max: 1087.2, Diff: 20.3, Sum: 4328.2]
   [GC Worker End (ms): Min: 5051973.4, Avg: 5051988.4, Max: 5051993.4, Diff: 20.0]
[Code Root Fixup: 0.2 ms]
[Code Root Purge: 0.0 ms]
[String Dedup Fixup: 2.0 ms, GC Workers: 4]
   [Queue Fixup (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
   [Table Fixup (ms): Min: 0.1, Avg: 0.9, Max: 1.9, Diff: 1.8, Sum: 3.7]
[Clear CT: 82.6 ms]
[Other: 23923.6 ms]
   [Choose CSet: 0.0 ms]
   [Ref Proc: 415.2 ms]
   [Ref Enq: 0.0 ms]
   [Redirty Cards: 0.1 ms]
   [Humongous Register: 0.1 ms]
   [Humongous Reclaim: 0.1 ms]
   [Free CSet: 0.2 ms]
[Eden: 119.0M(119.0M)->0.0B(133.0M) Survivors: 0.0B->0.0B Heap: 572.3M(2391.0M)->456.2M(2666.0M)]
[Times: user=0.00 sys=1.29, real=27.79 secs]

Upvotes: 1

Views: 1735

Answers (1)

the8472
the8472

Reputation: 43042

[Times: user=0.00 sys=1.29, real=27.79 secs]

It spends practically no CPU cycles at all on garbage collection and all the time in the kernel and even more wall time, suggesting the process is blocked in the kernel doing things. The primary suspect is your system swapping.

Other potential causes:

  • the system being CPU-starved by some other process
  • IO being blocked by an idle harddrive having to spin up
  • quotas being exceeded - especially in containerized or VM environments
  • THP compactation - although this is unlikely as it normally manifests through higher kernel load

You can also try increasing GC log verbosity with -XX:G1LogLevel=fine/finer/finest and see if that points at anything particular, but the symptoms point at an system-level problem and nothing VM-specific.

Upvotes: 1

Related Questions