Measure JVM pauses

[henrikno]

Is your feature request related to a problem?

Sometimes we see spans that should take milliseconds take multiple seconds and it's difficult to know if it was just a slow operation, or the JVM was not responding. This is often caused by GC (which we could correlate, but it's not particularly easy), but it's not the only reason for pauses. It'd be great to track the pause time with would catch the StopTheWorld GC time and other hiccups.

Describe the solution you'd like

I'd like to have a metric that shows when the JVM is not responsive, for how long (was it 100ms, or 10 seconds) and how often.

There's some some existing implementations that resolve around the same idea of sleeping and measuring how much longer than you're supposed to sleep you actually slept (e.g. sleep for 10ms, but wake up 3 seconds later you know something's up)
https://github.com/giltene/jHiccup/blob/master/src/main/java/org/jhiccup/HiccupMeter.java
https://github.com/apache/zookeeper/blob/c74658d398cdc1d207aa296cb6e20de00faec03e/zookeeper-server/src/main/java/org/apache/zookeeper/server/util/JvmPauseMonitor.java
https://github.com/apache/hadoop/blob/trunk/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/util/JvmPauseMonitor.java

Describe alternatives you've considered

I considered using -XX:+PrintGCApplicationStoppedTime, but would need to parse the log, and it's quite verbose, while I'd like just a few metrics that's easy to graph.

Additional context

[jackshirazi]

I think this is doable without too much effort. We already get all the GC pauses. A simple way would be for every Span/Transaction get added to a list and on each GC measurement, run the list and add the pause to the Span/Transaction while it is live. Then they have a the amount of time paused during their life (and subtract all the children pauses to get the exclusive pause - depends on what we want to show, which I guess depends on the use case).

However that simple way leads to an unbounded collection. Though would only be as big as the peak number of concurrently live Span/Transactions. Even so, we could do a different bounded version. Have a ring buffer which stores GC pauses and timestamps. Then on deactivation, the Span/Transaction reads the ring buffer and sums the pauses between the start time and end time of the Span/Transaction. If the earliest pause in the ringbuffer is after the start time of the Span/Transaction, thenit doesn't read the pauses, but stores a not read (or -1) value, since the partial pause is less useful than knowing that either the lifetime of the Span/Transaction is too long, or that there are so many pauses in that lifetime.

[eyalkoren]

Another idea specific for GC pauses- since java.lang.management.GarbageCollectorMXBean#getCollectionTime() returns an ever-increasing meter, subtracting its value on transaction end from that of transaction start would provide an accurate and relevant measurement without adding complicated data structures.
I am not sure how this interface is implemented in different JVMs though. I am assuming it only returns a timer value that is updated at the end of each GC, meaning negligible overhead for high amount of queries, but it's only a guess and needs to be investigated a bit.

[jackshirazi]

You are absolutely right, I was way overthinking it! And even if that call is not consistent, we can easily maintain our own cumulative pause counter