Skip to content

Commit 1b84080

Browse files
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.
1 parent 3acc941 commit 1b84080

3 files changed

Lines changed: 39 additions & 7 deletions

File tree

‎Lib/profiling/sampling/gecko_collector.py‎

Lines changed: 5 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -245,10 +245,9 @@ def collect(self, stack_frames, timestamps_us=None):
245245

246246
first_time = times[0]
247247

248-
# Update interval calculation
249-
if self.sample_count > 0 and self.last_sample_time > 0:
250-
self.interval = (times[-1] - self.last_sample_time) / self.sample_count
251-
self.last_sample_time = times[-1]
248+
# Binary replay can deliver batches from different threads out of
249+
# order, so keep the latest time seen rather than the last one.
250+
self.last_sample_time = max(self.last_sample_time, times[-1])
252251

253252
# Process async tasks
254253
if stack_frames and hasattr(stack_frames[0], "awaited_by"):
@@ -732,9 +731,6 @@ def _finalize_markers(self):
732731

733732
def export(self, filename):
734733
"""Export the profile to a Gecko JSON file."""
735-
if self.sample_count > 0 and self.last_sample_time > 0:
736-
self.interval = self.last_sample_time / self.sample_count
737-
738734
# Spinner for progress indication
739735
spinner = itertools.cycle(['⠋', '⠙', '⠹', '⠸', '⠼', '⠴', '⠦', '⠧', '⠇', '⠏'])
740736
stop_spinner = threading.Event()
@@ -864,6 +860,8 @@ def _profile_tail(self):
864860
def _prepare_for_serialization(self):
865861
if self.exported:
866862
raise RuntimeError("GeckoCollector has already been exported")
863+
if self.sample_count > 0 and self.last_sample_time > 0:
864+
self.interval = self.last_sample_time / self.sample_count
867865
self._finalize_markers()
868866
for thread_data in self.threads.values():
869867
thread_data["_spill"].prepare_read()

‎Lib/test/test_profiling/test_sampling_profiler/test_collectors.py‎

Lines changed: 32 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1072,6 +1072,38 @@ def test_gecko_collector_markers(self):
10721072
f"Marker {i} should have valid category",
10731073
)
10741074

1075+
def test_gecko_collector_replay_out_of_order_batches(self):
1076+
"""Open markers are closed at the latest replayed sample."""
1077+
collector = GeckoCollector(1000)
1078+
# Binary replay can send thread 2's last batch after thread 1's later
1079+
# samples
1080+
batches = [
1081+
(1, [1000], THREAD_STATUS_ON_CPU),
1082+
(2, [1500], 0),
1083+
(1, [2000], THREAD_STATUS_ON_CPU),
1084+
(1, [3000, 4000], 0),
1085+
(2, [2500], 0),
1086+
]
1087+
for tid, timestamps, status in batches:
1088+
frames = [MockFrameInfo(f"t{tid}.py", 10, f"func{tid}")]
1089+
collector.collect(
1090+
[MockInterpreterInfo(0, [MockThreadInfo(tid, frames, status=status)])],
1091+
timestamps_us=timestamps,
1092+
)
1093+
1094+
profile_data = collector._build_profile()
1095+
1096+
end_times = []
1097+
for thread_data in profile_data["threads"]:
1098+
markers = thread_data["markers"]
1099+
for start_time, end_time in zip(markers["startTime"],
1100+
markers["endTime"]):
1101+
self.assertLessEqual(start_time, end_time)
1102+
end_times.append(end_time)
1103+
self.assertEqual(max(end_times), 3.0)
1104+
# Six samples up to 3.0 ms
1105+
self.assertEqual(profile_data["meta"]["interval"], 0.5)
1106+
10751107
def test_pstats_collector_export(self):
10761108
collector = PstatsCollector(
10771109
sample_interval_usec=1000000
Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,2 @@
1+
Fix Tachyon's Gecko export closing open markers too early when replaying a
2+
binary profile whose thread samples arrive out of time order.

0 commit comments

Comments
 (0)