Handling of Time traveled backwards warnings ?

[bric3]

I have some logs that came from a Kubernetes JVM app and I noticed these warnings happen a lot.

Thread: vert.x-worker-thread-ZZ, abort GC log parsing. Time traveled backwards from @XXXXX to @YYYYY

That somehow seems expected when different GC threads work in parallel. But the log is odd. And there's not even an API to aggregate on this.

Reference method GCLogParser.advanceClock to look at.

Warning log snippet

Sep 19, 2022 11:27:50 AM com.microsoft.gctoolkit.parser.GCLogParser advanceClock
WARNING: Thread: vert.x-worker-thread-13, abort GC log parsing. Time traveled backwards from @49945.088 to @49945.087
Sep 19, 2022 11:27:50 AM com.microsoft.gctoolkit.parser.GCLogParser advanceClock
WARNING: Thread: vert.x-worker-thread-15, abort GC log parsing. Time traveled backwards from @49945.088 to @49945.087
Sep 19, 2022 11:27:50 AM com.microsoft.gctoolkit.parser.GCLogParser advanceClock
WARNING: Thread: vert.x-worker-thread-4, abort GC log parsing. Time traveled backwards from @49945.088 to @49945.087
Sep 19, 2022 11:27:50 AM com.microsoft.gctoolkit.parser.GCLogParser advanceClock
WARNING: Thread: vert.x-worker-thread-10, abort GC log parsing. Time traveled backwards from @49945.545 to @49945.544
Sep 19, 2022 11:27:50 AM com.microsoft.gctoolkit.parser.GCLogParser advanceClock
WARNING: Thread: vert.x-worker-thread-9, abort GC log parsing. Time traveled backwards from @49945.545 to @49945.544
Sep 19, 2022 11:27:50 AM com.microsoft.gctoolkit.parser.GCLogParser advanceClock
WARNING: Thread: vert.x-worker-thread-4, abort GC log parsing. Time traveled backwards from @49945.545 to @49945.544
Sep 19, 2022 11:27:50 AM com.microsoft.gctoolkit.parser.GCLogParser advanceClock
WARNING: Thread: vert.x-worker-thread-10, abort GC log parsing. Time traveled backwards from @49947.438 to @49947.437
Sep 19, 2022 11:27:50 AM com.microsoft.gctoolkit.parser.GCLogParser advanceClock
WARNING: Thread: vert.x-worker-thread-1, abort GC log parsing. Time traveled backwards from @49947.438 to @49947.437
Sep 19, 2022 11:27:50 AM com.microsoft.gctoolkit.parser.GCLogParser advanceClock
WARNING: Thread: vert.x-worker-thread-14, abort GC log parsing. Time traveled backwards from @49947.438 to @49947.437

Indeed the logs timestamp are not ordered.

GC logs snippet

[49947.437s][info ][safepoint        ] Application time: 1.0001079 seconds
[49947.437s][info ][safepoint        ] Entering safepoint region: Cleanup
[49947.437s][info ][safepoint,cleanup] deflating idle monitors, 0.0000003 secs
[49947.438s][info ][safepoint,cleanup] compilation policy safepoint handler, 0.0000007 secs
[49947.438s][info ][safepoint,cleanup] purging class loader data graph, 0.0000002 secs
[49947.438s][info ][safepoint,cleanup] resizing system dictionaries, 0.0000009 secs
[49947.437s][info ][safepoint,cleanup] updating inline caches, 0.0000087 secs
[49947.438s][info ][safepoint,cleanup] safepoint cleanup tasks, 0.0004885 secs
[49947.438s][info ][safepoint        ] Leaving safepoint region
[49947.438s][info ][safepoint        ] Total time for which application threads were stopped: 0.0009248 seconds, Stopping threads took: 0.0003109 seconds
[49947.725s][info ][safepoint        ] Application time: 0.2873619 seconds
[49947.725s][info ][safepoint        ] Entering safepoint region: FindDeadlocks
[49947.726s][info ][safepoint,cleanup] resizing system dictionaries, 0.0000010 secs
[49947.726s][info ][safepoint,cleanup] deflating idle monitors, 0.0000003 secs
[49947.726s][info ][safepoint,cleanup] updating inline caches, 0.0000013 secs
[49947.726s][info ][safepoint,cleanup] compilation policy safepoint handler, 0.0000006 secs
[49947.726s][info ][safepoint,cleanup] purging class loader data graph, 0.0000002 secs
[49947.726s][info ][safepoint,cleanup] safepoint cleanup tasks, 0.0005193 secs
[49947.726s][info ][safepoint        ] Leaving safepoint region
[49947.726s][info ][safepoint        ] Total time for which application threads were stopped: 0.0010917 seconds, Stopping threads took: 0.0003096 seconds
[49947.726s][info ][safepoint        ] Application time: 0.0000752 seconds
[49947.727s][info ][safepoint        ] Entering safepoint region: FindDeadlocks
[49947.727s][info ][safepoint,cleanup] deflating idle monitors, 0.0000003 secs
[49947.727s][info ][safepoint,cleanup] updating inline caches, 0.0000009 secs
[49947.727s][info ][safepoint,cleanup] resizing system dictionaries, 0.0000008 secs
[49947.727s][info ][safepoint,cleanup] compilation policy safepoint handler, 0.0000006 secs
[49947.727s][info ][safepoint,cleanup] purging class loader data graph, 0.0000002 secs
[49947.727s][info ][safepoint,cleanup] safepoint cleanup tasks, 0.0005068 secs
[49947.727s][info ][safepoint        ] Leaving safepoint region
[49947.727s][info ][safepoint        ] Total time for which application threads were stopped: 0.0007893 seconds, Stopping threads took: 0.0001465 seconds

---

Note: edited for hopefully more clarity

[dsgrieve]

Issue #220 addresses the safepoint parsing issue.

@kcpeppe - What say you about the time travel issue?

[bric3]

What about a synthetic event ? So at least it's possible to build something out of it?

[kcpeppe]

The consideration is that GCToolKit should publish events in time order. This makes it easy for the aggregators to process the data. There are a couple of reasons for time traveling backward. It could be that NTP has rolled the clocks back but this is surprisingly a very rare event. The most common reason is that there is some "after-market" corruption. For example, we have logs being stored in a DB and the query doesn't properly reconstruct things. For logs that have been partitioned, sometimes the reconstruction isn't right. I've even seen cases where two processes were writing to the same log file (also rare but...). In all cases, knowing that the clock has traveled backward is useful. Sending a synthetic event maybe a better way of transmitting this information.

[bric3]

These logs come from a production system in GKE (so kubernetes), I don't remember if the containers ran on the actual machine or on a virtual host. But this backward time travel happen quite a lot.

Unfortunately, I don't have anymore access to the platform since I changed employer since these logs were captured, so I cannot dig for more detail there.

[kcpeppe]

My apologies, I've seemingly missed the log snippet and this is odd so nothing I've said makes sense in this case. Unlike in pre-UL where corruption is the norm, UL has mostly been very clean. In this particular case, the rollback is inconsequential as the timestamp will not be recorded. However, the clock tracks every single timestamp (as you've discovered) and in some cases, I can imagine that the timestamp would be used. 1ms isn't going to make any difference in 99.9% of the calculations. I perform a back-to-back event calculation where it might but...

I'll take input on this but my first inclination is to loosen the constraint to a more meaningful time gap. I'd have to see more instances of this to guess at what a more meaningful time gap might be but 100ms might be on the lower end of that bound? Certainly, 10ms would have eliminated this confusion.

[bric3]

For reference here's the gclogs.zip I've been playing with.

I don't exactly remember the command line I did use to generate those logs as I had tackle various issues back then, something like this

-Xlog:gc*=debug,gc+ergo*=trace,gc+age*=trace,safepoint*:file=/gclogs/%t-gc.log:uptime,tags,level:filecount=10,filesize=20M

Also it was an OpenJDK 11 running, not sure about the exact update.

(At least I can approximate when those logs were created as I wrote this blog post around the same time https://blog.arkey.fr/2020/07/28/embracing-jvm-unified-logging-jep-158-jep-271/#_migrating_the_gc_log_configuration_jep_271)