1

I've read a few descriptions of different times printed in G1GC logs but couldn't really prove/understand when I produced them locally. For example, following log was produced on my PC with Java 11. I wanted to know, what's the difference between 0.500ms in the first line vs 0.01s in the second? Was the application paused (because of STW) for 0.500ms or for 10ms (0.01s)? I tried tools like GCeasy, it shows max pause time of 10ms, and in cases where Real = 0.00, GCeasy shows min pause of 0ms. I wonder, what kind of pause is 0.500ms representing then?

[9.090s][info][gc ] GC(25) Pause Young (Normal) (G1 Evacuation Pause) 77M->2M(128M) 0.500ms

[9.090s][info][gc,cpu ] GC(25) User=0.00s Sys=0.00s Real=0.01s

Edit: GC Pause time difference in gc.logs vs in JMC

0.687ms pause in gc.log enter image description here

Where as 1.331 second according to JMC enter image description here

Community
  • 1
  • 1
Abidi
  • 7,846
  • 14
  • 43
  • 65
  • @eugene Are you sure, 10ms is the total time. Because, my logs show many cases where pause time is there (non zero) but Real remains 0? – Abidi Jan 21 '20 at 09:04
  • 1
    I will delete the comment since I rushed it in and it is incorrect. – Eugene Jan 21 '20 at 21:39

1 Answers1

1

I am not sure if I should post this as an answer, because this is my understanding of this log, but it would be too big for a comment it seems.

The total time of the STW event was 0.500ms if you look with the eyes of G1GC and was neither 0.500ms nor 10ms if you take Shenandoah for example. When you use G1GC, STW event is treated as 0.500ms, using Shenandoah, will result in 0.500ms + delta; where this delta will be the cumulative time it took to bring all java threads to a safepoint (also called TTSP - time to safe point) + whatever clean-up was needed for that safepoint. May be a picture will make this easier:

   |------|------------------------|---------| 
   | TTPS |   G1 Evacuation Pause  | CleanUp |
   |------|------------------------|---------|

G1GC treats as the STW Event the G1 Evacuation Pause region only. Shenandoah for example, treats the entire thing as the STW event (all 3 regions). Who is right? I will leave this up to you to decide.

You can enable the safepoint granularity for G1GC via -Xlog:safepoint*, for example.

The tools that you are using have their own "opinion" oh how to treat each time produced by the logs, I guess; but it is absolutely not 10 ms. Why? As you have seen already (as you say in comments) there are times when you will get something like this in logs:

[9.090s][info][gc ] GC(25) Pause Young (Normal) (G1 Evacuation Pause) 77M->2M(128M) 0.500ms

[9.090s][info][gc,cpu ] GC(25) User=0.00s Sys=0.00s Real=**0.00s**

Notice the Real=0.00s. Does this mean there was no pause? Of course not, it just means there was no cpu time spent.

Eugene
  • 117,005
  • 15
  • 201
  • 306
  • if you see my Edit, different pause times are shown on gc.log vs JMC. How come, simply showing pause time for a collection is that different on different tools? – Abidi Jan 21 '20 at 23:31
  • @Abidi I can't tell what number is in JMC, I would have to read the documentation. But anyway, this sounds like a different question you need to ask. – Eugene Jan 22 '20 at 11:56
  • 1
    @Abidi well, I only had time now to read the JMC documentation and that value is: _the accumulated duration of the collector running time. The time is the sum of the wall-clock time of all GC events_. Did you happen to read and understand that? – Eugene Jan 25 '20 at 18:47
  • Thanks Eugene. I didn't quite understand your answer, sorry about my poor understanding. But finally I was able to figure it out and I "think" it's same as you said. The total GC time is 0.500ms. What I dont' understand is, if and how it's linked with User, Sys and Real times. I'm ignoring this for now. – Abidi Jan 26 '20 at 21:22
  • @Abidi there's nothing to be sorry for, I am learning these things too. – Eugene Jan 27 '20 at 14:39