Speedscope output fails (event ordering?)

[viraptor]

When trying to process a capture using:

rbspy report -i /tmp/rbspy.trace.raw3 -o /tmp/rbspy.trace.ss -f speedscope

I get:

Something went wrong while rbspy was sampling the process. Here's what we know:
- second time provided was later than self

This is from rbspy 0.18.0 and ruby 3.2.2 captured using:

./rbspy-x86_64-musl record --raw-file /tmp/rbspy.trace.raw --silent -s -- bundle exec puma ...

I'm happy to copy some of that trace if have some specific things I should check?

[viraptor]

Not sure if related, but if I extract the time from the raw capture and compare plain to sorted:

gunzip < /tmp/rbspy.trace.raw3 | tail -n +3 | jq -r -c '(.time.secs_since_epoch|tostring) + "." + (.time.nanos_since_epoch|tostring)' > /tmp/timestamps
sort -V /tmp/timestamps > /tmp/timestamps2
diff -u /tmp/timestamps{,2}

I get some differences:

--- /tmp/timestamps     2024-01-04 12:29:39
+++ /tmp/timestamps2    2024-01-04 12:30:10
@@ -4156,8 +4156,8 @@
 1704330545.646488903
 1704330545.656765177
 1704330545.659977080
-1704330545.666087593
 1704330545.663377493
+1704330545.666087593
 1704330545.749912008
 1704330545.752892418
 1704330545.753367638
@@ -4166,34 +4166,34 @@
 1704330545.846077224
 1704330545.848417319
 1704330545.849479333
-1704330545.854436937
 1704330545.851719190
+1704330545.854436937
 1704330545.858306998
 1704330545.947996549
-1704330545.953209778
 1704330545.948760704
-1704330545.958598964
+1704330545.953209778
 1704330545.957577071
+1704330545.958598964
 1704330546.51287364
...

[viraptor]

Yeah, I think that was the issue. A hack to fix a trace if anyone needs a workaround:

gunzip < /tmp/rbspy.trace.raw3 | tail -n +3 | jq -s -c 'sort_by([.time.secs_since_epoch, .time.nanos_since_epoch]) | .[]' > /tmp/rbspy.trace.raw3.suffix
gunzip < /tmp/rbspy.trace.raw3 | head -n2 > /tmp/rbspy.trace.raw3.prefix
cat /tmp/rbspy.trace.raw3.{pre,suf}fix | gzip > /tmp/rbspy.trace.raw3

rbspy report -i /tmp/rbspy.trace.raw3 -o /tmp/rbspy.trace.ss -f speedscope
# works

[acj]

Hmm, my guess is that we need a fix similar to #371. Or maybe it can be fixed upstream in the recorder, e.g. if we keep track of the most recent timestamp and warn (but not record) when there's an ordering issue.

[viraptor]

A slightly complicated, but cheap solution could be to keep a rolling buffer of 10 or so entries that's always sorted. Then flush the remaining of the buffer at the end?