diff --git a/src/trace_writer.ml b/src/trace_writer.ml index cb90cba03..7da19d0b5 100644 --- a/src/trace_writer.ml +++ b/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 diff --git a/test/test.ml b/test/test.ml index 5bd30ca0d..8fdf9404e 100644 --- a/test/test.ml +++ b/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 |}] +;;