Keep per-thread trace timestamps monotonic

src/trace_writer.ml

@@ -506,6 +506,11 @@ let event_time t (event : Event.t) (thread_info : _ Thread_info.t) =
       thread_info.last_event_time
     | Some time ->
       let time = map_time t time in
+      (* perf can occasionally emit events for a thread with timestamps older than an
+         event we have already processed. Keep the writer's per-thread logical time
+         monotonic so pending-event flushing and callstack reconstruction never operate
+         over a negative time interval. *)
+      let time = Mapped_time.max time thread_info.last_event_time in
       thread_info.last_event_time <- time;
       time
   in

test/test.ml

@@ -196,6 +196,24 @@ let dump_using_file ?range_symbols events =
   return ()
 ;;
 
+let write_using_file events =
+  let%bind events = get_events_pipe ~events () in
+  let close_result = return (Ok ()) in
+  let buf = Iobuf.create ~len:500_000 in
+  let destination = Tracing_zero.Destinations.iobuf_destination buf in
+  let writer = Tracing_zero.Writer.Expert.create ~destination () in
+  write_trace_from_events
+    ~debug_info:None
+    ~trace_scope:Userspace
+    ~events_writer:None
+    ~writer:(Some writer)
+    ~hits:[]
+    ~events:[ events ]
+    ~close_result
+    ~collection_mode:(Intel_processor_trace { extra_events = [] })
+    ()
+;;
+
 let%expect_test "random perfs" =
   let open Trace_helpers in
   let%bind.With _dirname = Expect_test_helpers_async.within_temp_dir in
@@ -850,3 +868,16 @@ let%expect_test "get debug information from ELF" =
   [%expect {| |}];
   return ()
 ;;
+
+let%expect_test "trace writer handles per-thread timestamps that move backwards" =
+  let open Trace_helpers in
+  start_recording ();
+  add Call 200 "outer";
+  add Call 300 "inner";
+  add Return 150 "inner";
+  let events = events () in
+  let%map result = write_using_file events in
+  Or_error.ok_exn result;
+  print_endline "ok";
+  [%expect {| ok |}]
+;;