From 1b840800d61ea47890eced4c24dc137b417e7972 Mon Sep 17 00:00:00 2001 From: Ivona Stojanovic Date: Mon, 26 Oct 2026 22:10:42 +0000 Subject: [PATCH] Fix Gecko marker end times during binary replay Binary replay can deliver sample batches from different threads out of timestamp order. GeckoCollector used the final timestamp from the most recent batch, which could close open markers before they started. Keep the latest timestamp seen across all batches and calculate the sample interval when serializing the profile. --- Lib/profiling/sampling/gecko_collector.py | 12 +++---- .../test_sampling_profiler/test_collectors.py | 32 +++++++++++++++++++ ...-10-26-21-14-17.gh-issue-160735.IIUifI.rst | 2 ++ 3 files changed, 39 insertions(+), 7 deletions(-) create mode 100644 Misc/NEWS.d/next/Library/2026-10-26-21-14-17.gh-issue-160735.IIUifI.rst diff --git a/Lib/profiling/sampling/gecko_collector.py b/Lib/profiling/sampling/gecko_collector.py index 2de8cce387e7f26..e3754b76a4b6bf5 100644 --- a/Lib/profiling/sampling/gecko_collector.py +++ b/Lib/profiling/sampling/gecko_collector.py @@ -245,10 +245,9 @@ def collect(self, stack_frames, timestamps_us=None): first_time = times[0] - # Update interval calculation - if self.sample_count > 0 and self.last_sample_time > 0: - self.interval = (times[-1] - self.last_sample_time) / self.sample_count - self.last_sample_time = times[-1] + # Binary replay can deliver batches from different threads out of + # order, so keep the latest time seen rather than the last one. + self.last_sample_time = max(self.last_sample_time, times[-1]) # Process async tasks if stack_frames and hasattr(stack_frames[0], "awaited_by"): @@ -732,9 +731,6 @@ def _finalize_markers(self): def export(self, filename): """Export the profile to a Gecko JSON file.""" - if self.sample_count > 0 and self.last_sample_time > 0: - self.interval = self.last_sample_time / self.sample_count - # Spinner for progress indication spinner = itertools.cycle(['⠋', '⠙', '⠹', '⠸', '⠼', '⠴', '⠦', '⠧', '⠇', '⠏']) stop_spinner = threading.Event() @@ -864,6 +860,8 @@ def _profile_tail(self): def _prepare_for_serialization(self): if self.exported: raise RuntimeError("GeckoCollector has already been exported") + if self.sample_count > 0 and self.last_sample_time > 0: + self.interval = self.last_sample_time / self.sample_count self._finalize_markers() for thread_data in self.threads.values(): thread_data["_spill"].prepare_read() diff --git a/Lib/test/test_profiling/test_sampling_profiler/test_collectors.py b/Lib/test/test_profiling/test_sampling_profiler/test_collectors.py index d4ba2df5044559f..e0e7fcea8ef8fb0 100644 --- a/Lib/test/test_profiling/test_sampling_profiler/test_collectors.py +++ b/Lib/test/test_profiling/test_sampling_profiler/test_collectors.py @@ -1072,6 +1072,38 @@ def test_gecko_collector_markers(self): f"Marker {i} should have valid category", ) + def test_gecko_collector_replay_out_of_order_batches(self): + """Open markers are closed at the latest replayed sample.""" + collector = GeckoCollector(1000) + # Binary replay can send thread 2's last batch after thread 1's later + # samples + batches = [ + (1, [1000], THREAD_STATUS_ON_CPU), + (2, [1500], 0), + (1, [2000], THREAD_STATUS_ON_CPU), + (1, [3000, 4000], 0), + (2, [2500], 0), + ] + for tid, timestamps, status in batches: + frames = [MockFrameInfo(f"t{tid}.py", 10, f"func{tid}")] + collector.collect( + [MockInterpreterInfo(0, [MockThreadInfo(tid, frames, status=status)])], + timestamps_us=timestamps, + ) + + profile_data = collector._build_profile() + + end_times = [] + for thread_data in profile_data["threads"]: + markers = thread_data["markers"] + for start_time, end_time in zip(markers["startTime"], + markers["endTime"]): + self.assertLessEqual(start_time, end_time) + end_times.append(end_time) + self.assertEqual(max(end_times), 3.0) + # Six samples up to 3.0 ms + self.assertEqual(profile_data["meta"]["interval"], 0.5) + def test_pstats_collector_export(self): collector = PstatsCollector( sample_interval_usec=1000000 diff --git a/Misc/NEWS.d/next/Library/2026-10-26-21-14-17.gh-issue-160735.IIUifI.rst b/Misc/NEWS.d/next/Library/2026-10-26-21-14-17.gh-issue-160735.IIUifI.rst new file mode 100644 index 000000000000000..cf64610a9e62590 --- /dev/null +++ b/Misc/NEWS.d/next/Library/2026-10-26-21-14-17.gh-issue-160735.IIUifI.rst @@ -0,0 +1,2 @@ +Fix Tachyon's Gecko export closing open markers too early when replaying a +binary profile whose thread samples arrive out of time order.