1use super::summary::{
15 CoreEventKind, OutputEventKind, StressConditionSummary, StressIndexSummary,
16 TestEventKindSummary, TestEventSummary, TestsNotSeenSummary,
17};
18use crate::{
19 errors::{ChromeTraceError, RecordReadError},
20 list::OwnedTestInstanceId,
21 output_spec::RecordingSpec,
22 reporter::events::{
23 CancelReason, ErrorSummary, ExecuteStatus, ExecutionResultDescription, RunFinishedStats,
24 RunStats, StressProgress, TestSlotAssignment,
25 },
26};
27use chrono::{DateTime, FixedOffset};
28use debug_ignore::DebugIgnore;
29use nextest_metadata::RustBinaryId;
30use quick_junit::ReportUuid;
31use semver::Version;
32use serde::Serialize;
33use std::{
34 collections::{BTreeMap, HashMap, HashSet},
35 time::Duration,
36};
37#[derive(Copy, Clone, Debug, PartialEq, Eq)]
39pub enum ChromeTraceMessageFormat {
40 Json,
42
43 JsonPretty,
45}
46
47#[derive(Copy, Clone, Debug, PartialEq, Eq)]
49pub enum ChromeTraceGroupBy {
50 Binary,
53
54 Slot,
58}
59
60impl ChromeTraceGroupBy {
61 fn test_event_name(self, id: &OwnedTestInstanceId) -> String {
67 match self {
68 Self::Binary => id.test_name.as_ref().to_string(),
69 Self::Slot => format!("{} {}", id.binary_id, id.test_name.as_ref()),
70 }
71 }
72
73 fn test_process_display_name(self, binary_id: &RustBinaryId) -> String {
78 match self {
79 Self::Binary => binary_id.to_string(),
80 Self::Slot => "tests".to_string(),
81 }
82 }
83}
84
85pub fn convert_to_chrome_trace<I>(
118 nextest_version: &Version,
119 events: I,
120 group_by: ChromeTraceGroupBy,
121 message_format: ChromeTraceMessageFormat,
122) -> Result<Vec<u8>, ChromeTraceError>
123where
124 I: IntoIterator<Item = Result<TestEventSummary<RecordingSpec>, RecordReadError>>,
125{
126 let mut converter = ChromeTraceConverter::new(nextest_version.clone(), group_by);
127
128 for event_result in events {
129 let event = event_result.map_err(ChromeTraceError::ReadError)?;
130 converter.process_event(event)?;
131 }
132
133 converter.finish(message_format)
134}
135
136#[derive(Debug)]
138enum RunBarState {
139 Closed,
141 Open,
143 Paused,
146}
147
148#[derive(Debug)]
154struct ChromeTraceConverter {
155 slot_assignments: HashMap<OwnedTestInstanceId, TestSlotAssignment>,
158
159 running_scripts: BTreeMap<usize, String>,
163
164 stress_subrun_open: bool,
166
167 run_bar_state: RunBarState,
169
170 group_by: ChromeTraceGroupBy,
172
173 binary_pid_map: HashMap<RustBinaryId, u64>,
175
176 next_pid: u64,
179
180 nextest_version: Version,
182 run_id: Option<ReportUuid>,
183 profile_name: Option<String>,
184 cli_args: Vec<String>,
185 stress_condition: Option<StressConditionSummary>,
186
187 next_flow_id: u64,
189
190 pending_retry_flows: HashMap<OwnedTestInstanceId, u64>,
194
195 running_test_count: usize,
199
200 running_script_count: usize,
206
207 trace_events: DebugIgnore<Vec<ChromeTraceEvent>>,
209
210 emitted_process_names: HashSet<u64>,
212
213 emitted_thread_names: HashSet<(u64, u64)>,
216}
217
218impl ChromeTraceConverter {
219 fn new(nextest_version: Version, group_by: ChromeTraceGroupBy) -> Self {
220 Self {
221 slot_assignments: HashMap::new(),
222 running_scripts: BTreeMap::new(),
223 stress_subrun_open: false,
224 run_bar_state: RunBarState::Closed,
225 group_by,
226 binary_pid_map: HashMap::new(),
227 next_pid: FIRST_BINARY_PID,
228 nextest_version,
229 run_id: None,
230 profile_name: None,
231 cli_args: Vec::new(),
232 stress_condition: None,
233 next_flow_id: 0,
234 pending_retry_flows: HashMap::new(),
235 running_test_count: 0,
236 running_script_count: 0,
237 trace_events: DebugIgnore(Vec::new()),
238 emitted_process_names: HashSet::new(),
239 emitted_thread_names: HashSet::new(),
240 }
241 }
242
243 fn process_event(
244 &mut self,
245 event: TestEventSummary<RecordingSpec>,
246 ) -> Result<(), ChromeTraceError> {
247 let timestamp = event.timestamp;
248 match event.kind {
249 TestEventKindSummary::Core(core) => self.process_core_event(core, timestamp)?,
250 TestEventKindSummary::Output(output) => self.process_output_event(output, timestamp)?,
251 }
252 Ok(())
253 }
254
255 fn process_core_event(
256 &mut self,
257 event: CoreEventKind,
258 timestamp: DateTime<FixedOffset>,
259 ) -> Result<(), ChromeTraceError> {
260 match event {
261 CoreEventKind::RunStarted {
262 run_id,
263 profile_name,
264 cli_args,
265 stress_condition,
266 } => {
267 let process_name = format!("nextest run ({profile_name})");
270 self.ensure_metadata_events(
271 RUN_LIFECYCLE_PID,
272 RUN_LIFECYCLE_TID,
273 &process_name,
274 "run",
275 );
276
277 let begin_args = ChromeTraceArgs::RunBegin(RunBeginArgs {
278 nextest_version: self.nextest_version.to_string(),
279 run_id: run_id.to_string(),
280 profile: profile_name.clone(),
281 cli_args: cli_args.clone(),
282 stress_condition: stress_condition.clone(),
283 });
284
285 self.emit_begin(
287 RUN_LIFECYCLE_PID,
288 RUN_LIFECYCLE_TID,
289 "test run",
290 Category::Run,
291 datetime_to_microseconds(timestamp),
292 Some(begin_args),
293 );
294 self.run_bar_state = RunBarState::Open;
295 self.run_id = Some(run_id);
296 self.profile_name = Some(profile_name);
297 self.cli_args = cli_args;
298 self.stress_condition = stress_condition;
299 }
300 CoreEventKind::RunFinished {
301 run_id: _,
302 start_time: _,
303 elapsed,
304 run_stats,
305 outstanding_not_seen,
306 } => {
307 let ts_us = datetime_to_microseconds(timestamp);
309 match self.run_bar_state {
310 RunBarState::Open => {
311 let args = self.run_finished_args(
313 elapsed,
314 run_stats,
315 outstanding_not_seen.as_ref(),
316 );
317 self.emit_end(
318 RUN_LIFECYCLE_PID,
319 RUN_LIFECYCLE_TID,
320 "test run",
321 Category::Run,
322 ts_us,
323 Some(args),
324 );
325 self.run_bar_state = RunBarState::Closed;
326 }
327 RunBarState::Paused => {
328 self.emit_begin(
332 RUN_LIFECYCLE_PID,
333 RUN_LIFECYCLE_TID,
334 "test run",
335 Category::Run,
336 ts_us,
337 None,
338 );
339 let args = self.run_finished_args(
340 elapsed,
341 run_stats,
342 outstanding_not_seen.as_ref(),
343 );
344 self.emit_end(
345 RUN_LIFECYCLE_PID,
346 RUN_LIFECYCLE_TID,
347 "test run",
348 Category::Run,
349 ts_us,
350 Some(args),
351 );
352 self.run_bar_state = RunBarState::Closed;
353 }
354 RunBarState::Closed => {}
355 }
356 }
357 CoreEventKind::RunBeginCancel {
358 reason,
359 setup_scripts_running,
360 running,
361 } => {
362 self.running_test_count = running;
363 self.running_script_count = setup_scripts_running;
364 let ts_us = datetime_to_microseconds(timestamp);
365 self.emit_counter_event(ts_us);
366
367 self.emit_run_instant_event(
368 timestamp,
369 "cancel",
370 Some(reason),
371 running,
372 setup_scripts_running,
373 );
374 }
375 CoreEventKind::RunPaused {
376 setup_scripts_running,
377 running,
378 } => {
379 self.running_test_count = running;
380 self.running_script_count = setup_scripts_running;
381 let ts_us = datetime_to_microseconds(timestamp);
382 self.emit_counter_event(ts_us);
383
384 self.close_all_open_spans(ts_us);
386
387 self.emit_run_instant_event(
388 timestamp,
389 "paused",
390 None,
391 running,
392 setup_scripts_running,
393 );
394 }
395 CoreEventKind::RunContinued {
396 setup_scripts_running,
397 running,
398 } => {
399 self.running_test_count = running;
400 self.running_script_count = setup_scripts_running;
401 let ts_us = datetime_to_microseconds(timestamp);
402 self.emit_counter_event(ts_us);
403
404 self.emit_run_instant_event(
405 timestamp,
406 "continued",
407 None,
408 running,
409 setup_scripts_running,
410 );
411
412 self.reopen_all_spans(ts_us);
414 }
415 CoreEventKind::TestStarted {
416 test_instance,
417 slot_assignment,
418 stress_index: _,
419 current_stats: _,
420 running,
421 command_line,
422 } => {
423 let pid = self.pid_for_test(&test_instance.binary_id);
424 let tid = slot_assignment.global_slot + TID_OFFSET;
425 let ts_us = datetime_to_microseconds(timestamp);
426
427 let process_name = self
428 .group_by
429 .test_process_display_name(&test_instance.binary_id);
430 self.ensure_metadata_events(
431 pid,
432 tid,
433 &process_name,
434 &format!("slot-{}", slot_assignment.global_slot),
435 );
436
437 let event_name = self.group_by.test_event_name(&test_instance);
438 self.emit_begin(
439 pid,
440 tid,
441 &event_name,
442 Category::Test,
443 ts_us,
444 Some(ChromeTraceArgs::TestBegin(TestBeginArgs {
445 binary_id: test_instance.binary_id.to_string(),
446 command_line,
447 })),
448 );
449
450 self.running_test_count = running;
451 self.emit_counter_event(ts_us);
452
453 self.slot_assignments.insert(test_instance, slot_assignment);
454 }
455 CoreEventKind::TestRetryStarted {
456 test_instance,
457 slot_assignment,
458 stress_index: _,
459 retry_data,
460 running,
461 command_line,
462 } => {
463 let pid = self.pid_for_test(&test_instance.binary_id);
464 let tid = slot_assignment.global_slot + TID_OFFSET;
465 let ts_us = datetime_to_microseconds(timestamp);
466
467 let process_name = self
471 .group_by
472 .test_process_display_name(&test_instance.binary_id);
473 self.ensure_metadata_events(
474 pid,
475 tid,
476 &process_name,
477 &format!("slot-{}", slot_assignment.global_slot),
478 );
479
480 let event_name = self.group_by.test_event_name(&test_instance);
481 self.emit_begin(
482 pid,
483 tid,
484 &event_name,
485 Category::Test,
486 ts_us,
487 Some(ChromeTraceArgs::TestRetryBegin(TestRetryBeginArgs {
488 attempt: retry_data.attempt,
489 total_attempts: retry_data.total_attempts,
490 command_line,
491 })),
492 );
493
494 if let Some(flow_id) = self.pending_retry_flows.remove(&test_instance) {
496 self.emit_flow_finish(pid, tid, ts_us, flow_id);
497 }
498
499 self.running_test_count = running;
500 self.emit_counter_event(ts_us);
501
502 self.slot_assignments.insert(test_instance, slot_assignment);
503 }
504 CoreEventKind::SetupScriptStarted {
505 index,
506 script_id,
507 stress_index: _,
508 total: _,
509 program: _,
510 args: _,
511 no_capture: _,
512 } => {
513 let tid = index as u64 + TID_OFFSET;
514 let name = script_id.to_string();
515 let ts_us = datetime_to_microseconds(timestamp);
516
517 self.ensure_metadata_events(
518 SETUP_SCRIPT_PID,
519 tid,
520 "setup-scripts",
521 &format!("script-{index}"),
522 );
523
524 self.emit_begin(
525 SETUP_SCRIPT_PID,
526 tid,
527 &name,
528 Category::SetupScript,
529 ts_us,
530 None,
531 );
532
533 self.running_script_count += 1;
534 self.emit_counter_event(ts_us);
535
536 self.running_scripts.insert(index, name);
537 }
538 CoreEventKind::TestSlow {
539 stress_index,
540 test_instance,
541 retry_data,
542 elapsed,
543 will_terminate,
544 } => {
545 let pid = self.pid_for_test(&test_instance.binary_id);
546 let tid = self.tid_for_test(&test_instance)?;
547 let ts_us = datetime_to_microseconds(timestamp);
548
549 self.trace_events.push(ChromeTraceEvent {
550 name: "slow".to_string(),
551 cat: Category::Test,
552 ph: Phase::Instant,
553 ts: ts_us,
554 pid,
555 tid,
556 s: Some(InstantScope::Thread),
557 id: None,
558 bp: None,
559 args: Some(ChromeTraceArgs::TestSlow(TestSlowArgs {
560 elapsed_secs: elapsed.as_secs_f64(),
561 will_terminate,
562 attempt: retry_data.attempt,
563 stress_index: stress_index.as_ref().map(StressIndexArgs::new),
564 })),
565 });
566 }
567 CoreEventKind::StressSubRunStarted { progress } => {
568 let ts_us = datetime_to_microseconds(timestamp);
569
570 self.ensure_metadata_events(
571 RUN_LIFECYCLE_PID,
572 STRESS_SUBRUN_TID,
573 &self.run_process_name(),
574 "stress sub-runs",
575 );
576
577 self.emit_begin(
578 RUN_LIFECYCLE_PID,
579 STRESS_SUBRUN_TID,
580 "sub-run",
581 Category::Stress,
582 ts_us,
583 Some(ChromeTraceArgs::StressSubRunBegin(StressSubRunBeginArgs {
584 progress,
585 })),
586 );
587 self.stress_subrun_open = true;
588 }
589 CoreEventKind::StressSubRunFinished {
590 progress,
591 sub_elapsed,
592 sub_stats,
593 } => {
594 if !self.stress_subrun_open {
595 return Err(ChromeTraceError::MissingStressSubRunStart);
596 }
597
598 let ts_us = datetime_to_microseconds(timestamp);
599
600 self.emit_end(
601 RUN_LIFECYCLE_PID,
602 STRESS_SUBRUN_TID,
603 "sub-run",
604 Category::Stress,
605 ts_us,
606 Some(ChromeTraceArgs::StressSubRunEnd(StressSubRunEndArgs {
607 progress,
608 time_taken_ms: duration_to_millis(sub_elapsed),
609 sub_stats,
610 })),
611 );
612 self.stress_subrun_open = false;
613 }
614 CoreEventKind::SetupScriptSlow {
615 stress_index,
616 script_id,
617 program: _,
618 args: _,
619 elapsed,
620 will_terminate,
621 } => {
622 let script_name = script_id.to_string();
623 let tid = self
624 .running_scripts
625 .iter()
626 .find(|(_, name)| **name == script_name)
627 .map(|(&index, _)| index as u64 + TID_OFFSET)
628 .ok_or_else(|| ChromeTraceError::MissingScriptStart {
629 script_id: script_id.clone(),
630 })?;
631 let ts_us = datetime_to_microseconds(timestamp);
632
633 self.trace_events.push(ChromeTraceEvent {
634 name: "slow".to_string(),
635 cat: Category::SetupScript,
636 ph: Phase::Instant,
637 ts: ts_us,
638 pid: SETUP_SCRIPT_PID,
639 tid,
640 s: Some(InstantScope::Thread),
641 id: None,
642 bp: None,
643 args: Some(ChromeTraceArgs::SetupScriptSlow(SetupScriptSlowArgs {
644 script_id: script_id.as_identifier().as_str().to_string(),
645 elapsed_secs: elapsed.as_secs_f64(),
646 will_terminate,
647 stress_index: stress_index.as_ref().map(StressIndexArgs::new),
648 })),
649 });
650 }
651 CoreEventKind::TestSkipped { .. } => {}
653 }
654 Ok(())
655 }
656
657 fn process_output_event(
658 &mut self,
659 event: OutputEventKind<RecordingSpec>,
660 timestamp: DateTime<FixedOffset>,
661 ) -> Result<(), ChromeTraceError> {
662 let end_us = datetime_to_microseconds(timestamp);
668
669 match event {
670 OutputEventKind::TestAttemptFailedWillRetry {
671 stress_index,
672 test_instance,
673 run_status,
674 delay_before_next_attempt,
675 failure_output: _,
676 running,
677 } => {
678 let pid = self.pid_for_test(&test_instance.binary_id);
679 let tid = self.tid_for_test(&test_instance)?;
680
681 let end_args = self.test_end_args(
682 &test_instance,
683 &run_status,
684 stress_index.as_ref(),
685 Some(delay_before_next_attempt),
686 );
687
688 let event_name = self.group_by.test_event_name(&test_instance);
689 self.emit_end(
690 pid,
691 tid,
692 &event_name,
693 Category::Test,
694 end_us,
695 Some(end_args),
696 );
697
698 let flow_id = self.next_flow_id;
700 self.next_flow_id += 1;
701 self.emit_flow_start(pid, tid, end_us, flow_id);
702 self.pending_retry_flows
703 .insert(test_instance.clone(), flow_id);
704
705 self.running_test_count = running;
706 self.emit_counter_event(end_us);
707
708 self.slot_assignments.remove(&test_instance);
710 }
711 OutputEventKind::TestFinished {
712 stress_index,
713 test_instance,
714 run_statuses,
715 success_output: _,
716 failure_output: _,
717 junit_store_success_output: _,
718 junit_store_failure_output: _,
719 current_stats,
720 running,
721 } => {
722 let last = run_statuses.last_status();
725 let pid = self.pid_for_test(&test_instance.binary_id);
726 let tid = self.tid_for_test(&test_instance)?;
727
728 let end_args =
729 self.test_end_args(&test_instance, last, stress_index.as_ref(), None);
730
731 let event_name = self.group_by.test_event_name(&test_instance);
732 self.emit_end(
733 pid,
734 tid,
735 &event_name,
736 Category::Test,
737 end_us,
738 Some(end_args),
739 );
740
741 self.running_test_count = running;
742 self.emit_counter_event(end_us);
743 self.emit_results_counter_event(end_us, ¤t_stats);
744
745 self.slot_assignments.remove(&test_instance);
746 }
747 OutputEventKind::SetupScriptFinished {
748 stress_index,
749 index,
750 total: _,
751 script_id,
752 program: _,
753 args: _,
754 no_capture: _,
755 run_status,
756 } => {
757 if !self.running_scripts.contains_key(&index) {
759 return Err(ChromeTraceError::MissingScriptStart {
760 script_id: script_id.clone(),
761 });
762 }
763
764 let tid = index as u64 + TID_OFFSET;
765 let script_id_str = script_id.as_identifier().as_str().to_string();
766 let script_name = script_id.to_string();
767
768 let end_args = ChromeTraceArgs::SetupScriptEnd(SetupScriptEndArgs {
769 script_id: script_id_str,
770 time_taken_ms: duration_to_millis(run_status.time_taken),
771 result: run_status.result.clone(),
772 is_slow: run_status.is_slow,
773 stress_index: stress_index.as_ref().map(StressIndexArgs::new),
774 error: run_status.error_summary.as_ref().map(ErrorSummaryArgs::new),
775 });
776
777 self.emit_end(
778 SETUP_SCRIPT_PID,
779 tid,
780 &script_name,
781 Category::SetupScript,
782 end_us,
783 Some(end_args),
784 );
785
786 self.running_script_count = self.running_script_count.saturating_sub(1);
787 self.emit_counter_event(end_us);
788
789 self.running_scripts.remove(&index);
790 }
791 }
792 Ok(())
793 }
794
795 fn close_all_open_spans(&mut self, ts_us: f64) {
800 match self.run_bar_state {
801 RunBarState::Open => {
802 self.emit_end(
803 RUN_LIFECYCLE_PID,
804 RUN_LIFECYCLE_TID,
805 "test run",
806 Category::Run,
807 ts_us,
808 None,
809 );
810 self.run_bar_state = RunBarState::Paused;
811 }
812 RunBarState::Paused | RunBarState::Closed => {}
813 }
814
815 if self.stress_subrun_open {
816 self.emit_end(
817 RUN_LIFECYCLE_PID,
818 STRESS_SUBRUN_TID,
819 "sub-run",
820 Category::Stress,
821 ts_us,
822 None,
823 );
824 }
825
826 self.emit_test_and_script_span_events(Phase::End, ts_us);
827 }
828
829 fn reopen_all_spans(&mut self, ts_us: f64) {
832 match self.run_bar_state {
833 RunBarState::Paused => {
834 self.emit_begin(
835 RUN_LIFECYCLE_PID,
836 RUN_LIFECYCLE_TID,
837 "test run",
838 Category::Run,
839 ts_us,
840 None,
841 );
842 self.run_bar_state = RunBarState::Open;
843 }
844 RunBarState::Open | RunBarState::Closed => {}
845 }
846
847 if self.stress_subrun_open {
848 self.emit_begin(
849 RUN_LIFECYCLE_PID,
850 STRESS_SUBRUN_TID,
851 "sub-run",
852 Category::Stress,
853 ts_us,
854 None,
855 );
856 }
857
858 self.emit_test_and_script_span_events(Phase::Begin, ts_us);
859 }
860
861 fn emit_test_and_script_span_events(&mut self, ph: Phase, ts_us: f64) {
871 let mut test_spans: Vec<(u64, u64, String)> = self
873 .slot_assignments
874 .iter()
875 .map(|(id, sa)| {
876 let pid = match self.group_by {
877 ChromeTraceGroupBy::Binary => *self
878 .binary_pid_map
879 .get(&id.binary_id)
880 .expect("binary pid already assigned by TestStarted"),
881 ChromeTraceGroupBy::Slot => ALL_TESTS_PID,
882 };
883 let tid = sa.global_slot + TID_OFFSET;
884 let name = self.group_by.test_event_name(id);
885 (pid, tid, name)
886 })
887 .collect();
888 test_spans.sort_by_key(|&(_, tid, _)| tid);
889 for (pid, tid, name) in &test_spans {
890 self.emit_duration_event(*pid, *tid, name, Category::Test, ph, ts_us, None);
891 }
892
893 let script_spans: Vec<(u64, String)> = self
895 .running_scripts
896 .iter()
897 .map(|(&index, name)| (index as u64 + TID_OFFSET, name.clone()))
898 .collect();
899 for (tid, name) in &script_spans {
900 self.emit_duration_event(
901 SETUP_SCRIPT_PID,
902 *tid,
903 name,
904 Category::SetupScript,
905 ph,
906 ts_us,
907 None,
908 );
909 }
910 }
911
912 fn emit_begin(
915 &mut self,
916 pid: u64,
917 tid: u64,
918 name: &str,
919 cat: Category,
920 ts_us: f64,
921 args: Option<ChromeTraceArgs>,
922 ) {
923 self.emit_duration_event(pid, tid, name, cat, Phase::Begin, ts_us, args);
924 }
925
926 fn emit_end(
927 &mut self,
928 pid: u64,
929 tid: u64,
930 name: &str,
931 cat: Category,
932 ts_us: f64,
933 args: Option<ChromeTraceArgs>,
934 ) {
935 self.emit_duration_event(pid, tid, name, cat, Phase::End, ts_us, args);
936 }
937
938 #[expect(clippy::too_many_arguments)]
940 fn emit_duration_event(
941 &mut self,
942 pid: u64,
943 tid: u64,
944 name: &str,
945 cat: Category,
946 ph: Phase,
947 ts_us: f64,
948 args: Option<ChromeTraceArgs>,
949 ) {
950 self.trace_events.push(ChromeTraceEvent {
951 name: name.to_string(),
952 cat,
953 ph,
954 ts: ts_us,
955 pid,
956 tid,
957 s: None,
958 id: None,
959 bp: None,
960 args,
961 });
962 }
963
964 fn emit_counter_event(&mut self, ts_us: f64) {
966 self.trace_events.push(ChromeTraceEvent {
967 name: "concurrency".to_string(),
968 cat: Category::Run,
969 ph: Phase::Counter,
970 ts: ts_us,
971 pid: RUN_LIFECYCLE_PID,
972 tid: 0,
973 s: None,
974 id: None,
975 bp: None,
976 args: Some(ChromeTraceArgs::Counter(CounterArgs {
977 running_tests: self.running_test_count,
978 running_scripts: self.running_script_count,
979 })),
980 });
981 }
982
983 fn emit_results_counter_event(&mut self, ts_us: f64, stats: &RunStats) {
986 self.trace_events.push(ChromeTraceEvent {
987 name: "test results".to_string(),
988 cat: Category::Run,
989 ph: Phase::Counter,
990 ts: ts_us,
991 pid: RUN_LIFECYCLE_PID,
992 tid: 0,
993 s: None,
994 id: None,
995 bp: None,
996 args: Some(ChromeTraceArgs::ResultsCounter(ResultsCounterArgs {
997 passed: stats.passed,
998 flaky: stats.flaky,
999 failed: stats.failed_count(),
1000 })),
1001 });
1002 }
1003
1004 fn emit_flow_start(&mut self, pid: u64, tid: u64, ts_us: f64, flow_id: u64) {
1006 self.trace_events.push(ChromeTraceEvent {
1007 name: "retry".to_string(),
1008 cat: Category::Test,
1009 ph: Phase::FlowStart,
1010 ts: ts_us,
1011 pid,
1012 tid,
1013 s: None,
1014 id: Some(flow_id),
1015 bp: None,
1016 args: None,
1017 });
1018 }
1019
1020 fn emit_flow_finish(&mut self, pid: u64, tid: u64, ts_us: f64, flow_id: u64) {
1022 self.trace_events.push(ChromeTraceEvent {
1023 name: "retry".to_string(),
1024 cat: Category::Test,
1025 ph: Phase::FlowFinish,
1026 ts: ts_us,
1027 pid,
1028 tid,
1029 s: None,
1030 id: Some(flow_id),
1031 bp: Some(FlowBindingPoint::EnclosingSlice),
1032 args: None,
1033 });
1034 }
1035
1036 fn emit_run_instant_event(
1040 &mut self,
1041 timestamp: DateTime<FixedOffset>,
1042 name: &str,
1043 cancel_reason: Option<CancelReason>,
1044 running: usize,
1045 setup_scripts_running: usize,
1046 ) {
1047 let pid = RUN_LIFECYCLE_PID;
1048 let tid = RUN_LIFECYCLE_TID;
1049 let ts_us = datetime_to_microseconds(timestamp);
1050
1051 self.ensure_metadata_events(pid, tid, &self.run_process_name(), "run");
1055
1056 self.trace_events.push(ChromeTraceEvent {
1057 name: name.to_string(),
1058 cat: Category::Run,
1059 ph: Phase::Instant,
1060 ts: ts_us,
1061 pid,
1062 tid,
1063 s: Some(InstantScope::Process),
1064 id: None,
1065 bp: None,
1066 args: Some(ChromeTraceArgs::RunInstant(RunInstantArgs {
1067 running,
1068 setup_scripts_running,
1069 reason: cancel_reason,
1070 })),
1071 });
1072 }
1073
1074 fn run_process_name(&self) -> String {
1080 match &self.profile_name {
1081 Some(name) => format!("nextest run ({name})"),
1082 None => "nextest run".to_string(),
1083 }
1084 }
1085
1086 fn test_end_args(
1088 &self,
1089 test_instance: &OwnedTestInstanceId,
1090 status: &ExecuteStatus<RecordingSpec>,
1091 stress_index: Option<&StressIndexSummary>,
1092 delay_before_next_attempt: Option<Duration>,
1093 ) -> ChromeTraceArgs {
1094 ChromeTraceArgs::TestEnd(TestEndArgs {
1095 binary_id: test_instance.binary_id.to_string(),
1096 time_taken_ms: duration_to_millis(status.time_taken),
1097 result: status.result.clone(),
1098 attempt: status.retry_data.attempt,
1099 total_attempts: status.retry_data.total_attempts,
1100 is_slow: status.is_slow,
1101 test_group: self
1102 .slot_assignments
1103 .get(test_instance)
1104 .map(|s| s.test_group.to_string()),
1105 stress_index: stress_index.map(StressIndexArgs::new),
1106 delay_before_start_secs: non_zero_duration_secs(status.delay_before_start),
1107 error: status.error_summary.as_ref().map(ErrorSummaryArgs::new),
1108 delay_before_next_attempt_secs: delay_before_next_attempt
1109 .and_then(non_zero_duration_secs),
1110 })
1111 }
1112
1113 fn run_finished_args(
1115 &self,
1116 elapsed: Duration,
1117 run_stats: RunFinishedStats,
1118 outstanding_not_seen: Option<&TestsNotSeenSummary>,
1119 ) -> ChromeTraceArgs {
1120 ChromeTraceArgs::RunEnd(RunEndArgs {
1121 nextest_version: self.nextest_version.to_string(),
1122 time_taken_ms: duration_to_millis(elapsed),
1123 profile: self.profile_name.clone(),
1124 run_stats,
1125 outstanding_not_seen: outstanding_not_seen.map(|ns| OutstandingNotSeenArgs {
1126 total_not_seen: ns.total_not_seen,
1127 }),
1128 })
1129 }
1130
1131 fn pid_for_binary(&mut self, binary_id: &RustBinaryId) -> u64 {
1133 if let Some(&pid) = self.binary_pid_map.get(binary_id) {
1134 pid
1135 } else {
1136 let pid = self.next_pid;
1137 self.next_pid += 1;
1138 self.binary_pid_map.insert(binary_id.clone(), pid);
1139 pid
1140 }
1141 }
1142
1143 fn pid_for_test(&mut self, binary_id: &RustBinaryId) -> u64 {
1148 match self.group_by {
1149 ChromeTraceGroupBy::Binary => self.pid_for_binary(binary_id),
1150 ChromeTraceGroupBy::Slot => ALL_TESTS_PID,
1151 }
1152 }
1153
1154 fn tid_for_test(&self, test_instance: &OwnedTestInstanceId) -> Result<u64, ChromeTraceError> {
1159 match self.slot_assignments.get(test_instance) {
1160 Some(sa) => Ok(sa.global_slot + TID_OFFSET),
1161 None => Err(ChromeTraceError::MissingTestStart {
1162 test_name: test_instance.test_name.clone(),
1163 binary_id: test_instance.binary_id.clone(),
1164 }),
1165 }
1166 }
1167
1168 fn ensure_metadata_events(
1175 &mut self,
1176 pid: u64,
1177 tid: u64,
1178 process_display_name: &str,
1179 thread_display_name: &str,
1180 ) {
1181 if !self.emitted_process_names.contains(&pid) {
1182 self.emit_m_event(
1183 pid,
1184 0,
1185 "process_name",
1186 ChromeTraceArgs::MetadataName(MetadataNameArgs {
1187 name: process_display_name.to_string(),
1188 }),
1189 );
1190 self.emit_m_event(
1191 pid,
1192 0,
1193 "process_sort_index",
1194 ChromeTraceArgs::MetadataSortIndex(MetadataSortIndexArgs { sort_index: pid }),
1195 );
1196 self.emitted_process_names.insert(pid);
1197 }
1198
1199 if !self.emitted_thread_names.contains(&(pid, tid)) {
1200 self.emit_m_event(
1201 pid,
1202 tid,
1203 "thread_name",
1204 ChromeTraceArgs::MetadataName(MetadataNameArgs {
1205 name: thread_display_name.to_string(),
1206 }),
1207 );
1208 self.emit_m_event(
1209 pid,
1210 tid,
1211 "thread_sort_index",
1212 ChromeTraceArgs::MetadataSortIndex(MetadataSortIndexArgs { sort_index: tid }),
1213 );
1214 self.emitted_thread_names.insert((pid, tid));
1215 }
1216 }
1217
1218 fn emit_m_event(&mut self, pid: u64, tid: u64, event_name: &str, args: ChromeTraceArgs) {
1220 self.trace_events.push(ChromeTraceEvent {
1221 name: event_name.to_string(),
1222 cat: Category::Empty,
1223 ph: Phase::Metadata,
1224 ts: 0.0,
1225 pid,
1226 tid,
1227 s: None,
1228 id: None,
1229 bp: None,
1230 args: Some(args),
1231 });
1232 }
1233
1234 fn finish(self, message_format: ChromeTraceMessageFormat) -> Result<Vec<u8>, ChromeTraceError> {
1236 let other_data = ChromeTraceOtherData {
1239 nextest_version: self.nextest_version.to_string(),
1240 run_id: self.run_id.map(|id| id.to_string()),
1241 profile_name: self.profile_name,
1242 cli_args: self.cli_args,
1243 stress_condition: self.stress_condition,
1244 };
1245
1246 let output = ChromeTraceOutput {
1247 trace_events: self.trace_events.0,
1248 display_time_unit: "ms",
1249 other_data,
1250 };
1251
1252 let serialize_fn = match message_format {
1253 ChromeTraceMessageFormat::Json => serde_json::to_vec,
1254 ChromeTraceMessageFormat::JsonPretty => serde_json::to_vec_pretty,
1255 };
1256 serialize_fn(&output).map_err(ChromeTraceError::SerializeError)
1257 }
1258}
1259
1260const RUN_LIFECYCLE_PID: u64 = 0;
1262
1263const SETUP_SCRIPT_PID: u64 = 1;
1265
1266const ALL_TESTS_PID: u64 = 2;
1268
1269const FIRST_BINARY_PID: u64 = 2;
1273
1274const RUN_LIFECYCLE_TID: u64 = 1;
1276
1277const STRESS_SUBRUN_TID: u64 = 2;
1279
1280const TID_OFFSET: u64 = 10_000;
1286
1287#[derive(Copy, Clone, Serialize)]
1289enum Phase {
1290 #[serde(rename = "B")]
1291 Begin,
1292 #[serde(rename = "E")]
1293 End,
1294 #[serde(rename = "M")]
1295 Metadata,
1296 #[serde(rename = "i")]
1297 Instant,
1298 #[serde(rename = "C")]
1299 Counter,
1300 #[serde(rename = "s")]
1301 FlowStart,
1302 #[serde(rename = "f")]
1303 FlowFinish,
1304}
1305
1306#[derive(Copy, Clone, Serialize)]
1308enum Category {
1309 #[serde(rename = "test")]
1310 Test,
1311 #[serde(rename = "setup-script")]
1312 SetupScript,
1313 #[serde(rename = "stress")]
1314 Stress,
1315 #[serde(rename = "run")]
1316 Run,
1317 #[serde(rename = "")]
1318 Empty,
1319}
1320
1321#[derive(Copy, Clone, Serialize)]
1323enum InstantScope {
1324 #[serde(rename = "p")]
1325 Process,
1326 #[serde(rename = "t")]
1327 Thread,
1328}
1329
1330#[derive(Copy, Clone, Serialize)]
1332enum FlowBindingPoint {
1333 #[serde(rename = "e")]
1334 EnclosingSlice,
1335}
1336
1337#[derive(Serialize)]
1339struct ChromeTraceEvent {
1340 name: String,
1342
1343 cat: Category,
1345
1346 ph: Phase,
1348
1349 ts: f64,
1351
1352 pid: u64,
1354
1355 tid: u64,
1357
1358 #[serde(skip_serializing_if = "Option::is_none")]
1360 s: Option<InstantScope>,
1361
1362 #[serde(skip_serializing_if = "Option::is_none")]
1364 id: Option<u64>,
1365
1366 #[serde(skip_serializing_if = "Option::is_none")]
1368 bp: Option<FlowBindingPoint>,
1369
1370 #[serde(skip_serializing_if = "Option::is_none")]
1372 args: Option<ChromeTraceArgs>,
1373}
1374
1375#[derive(Serialize)]
1389#[serde(untagged)]
1390enum ChromeTraceArgs {
1391 RunBegin(RunBeginArgs),
1392 RunEnd(RunEndArgs),
1393 RunInstant(RunInstantArgs),
1394 TestBegin(TestBeginArgs),
1395 TestRetryBegin(TestRetryBeginArgs),
1396 TestEnd(TestEndArgs),
1397 TestSlow(TestSlowArgs),
1398 SetupScriptEnd(SetupScriptEndArgs),
1399 SetupScriptSlow(SetupScriptSlowArgs),
1400 StressSubRunBegin(StressSubRunBeginArgs),
1401 StressSubRunEnd(StressSubRunEndArgs),
1402 Counter(CounterArgs),
1403 ResultsCounter(ResultsCounterArgs),
1404 MetadataName(MetadataNameArgs),
1405 MetadataSortIndex(MetadataSortIndexArgs),
1406}
1407
1408#[derive(Serialize)]
1413struct StressIndexArgs {
1414 current: u32,
1415 total: Option<u32>,
1416}
1417
1418impl StressIndexArgs {
1419 fn new(si: &StressIndexSummary) -> Self {
1420 Self {
1421 current: si.current,
1422 total: si.total.map(|t| t.get()),
1423 }
1424 }
1425}
1426
1427#[derive(Serialize)]
1429struct ErrorSummaryArgs {
1430 short_message: String,
1431 description: String,
1432}
1433
1434impl ErrorSummaryArgs {
1435 fn new(summary: &ErrorSummary) -> Self {
1436 Self {
1437 short_message: summary.short_message.clone(),
1438 description: summary.description.clone(),
1439 }
1440 }
1441}
1442
1443#[derive(Serialize)]
1445struct OutstandingNotSeenArgs {
1446 total_not_seen: usize,
1447}
1448
1449#[derive(Serialize)]
1453struct RunBeginArgs {
1454 nextest_version: String,
1455 run_id: String,
1456 profile: String,
1457 cli_args: Vec<String>,
1458 #[serde(skip_serializing_if = "Option::is_none")]
1459 stress_condition: Option<StressConditionSummary>,
1460}
1461
1462#[derive(Serialize)]
1464struct RunEndArgs {
1465 nextest_version: String,
1466 time_taken_ms: f64,
1467 #[serde(skip_serializing_if = "Option::is_none")]
1468 profile: Option<String>,
1469 run_stats: RunFinishedStats,
1470 #[serde(skip_serializing_if = "Option::is_none")]
1471 outstanding_not_seen: Option<OutstandingNotSeenArgs>,
1472}
1473
1474#[derive(Serialize)]
1476struct RunInstantArgs {
1477 running: usize,
1478 setup_scripts_running: usize,
1479 #[serde(skip_serializing_if = "Option::is_none")]
1480 reason: Option<CancelReason>,
1481}
1482
1483#[derive(Serialize)]
1487struct TestBeginArgs {
1488 binary_id: String,
1489 #[serde(skip_serializing_if = "Vec::is_empty")]
1490 command_line: Vec<String>,
1491}
1492
1493#[derive(Serialize)]
1495struct TestRetryBeginArgs {
1496 attempt: u32,
1497 total_attempts: u32,
1498 #[serde(skip_serializing_if = "Vec::is_empty")]
1499 command_line: Vec<String>,
1500}
1501
1502#[derive(Serialize)]
1504struct TestEndArgs {
1505 binary_id: String,
1506 time_taken_ms: f64,
1507 result: ExecutionResultDescription,
1508 attempt: u32,
1509 total_attempts: u32,
1510 is_slow: bool,
1511 #[serde(skip_serializing_if = "Option::is_none")]
1512 test_group: Option<String>,
1513 #[serde(skip_serializing_if = "Option::is_none")]
1514 stress_index: Option<StressIndexArgs>,
1515 #[serde(skip_serializing_if = "Option::is_none")]
1516 delay_before_start_secs: Option<f64>,
1517 #[serde(skip_serializing_if = "Option::is_none")]
1518 error: Option<ErrorSummaryArgs>,
1519 #[serde(skip_serializing_if = "Option::is_none")]
1520 delay_before_next_attempt_secs: Option<f64>,
1521}
1522
1523#[derive(Serialize)]
1525struct TestSlowArgs {
1526 elapsed_secs: f64,
1527 will_terminate: bool,
1528 attempt: u32,
1529 #[serde(skip_serializing_if = "Option::is_none")]
1530 stress_index: Option<StressIndexArgs>,
1531}
1532
1533#[derive(Serialize)]
1537struct SetupScriptEndArgs {
1538 script_id: String,
1539 time_taken_ms: f64,
1540 result: ExecutionResultDescription,
1541 is_slow: bool,
1542 #[serde(skip_serializing_if = "Option::is_none")]
1543 stress_index: Option<StressIndexArgs>,
1544 #[serde(skip_serializing_if = "Option::is_none")]
1545 error: Option<ErrorSummaryArgs>,
1546}
1547
1548#[derive(Serialize)]
1550struct SetupScriptSlowArgs {
1551 script_id: String,
1552 elapsed_secs: f64,
1553 will_terminate: bool,
1554 #[serde(skip_serializing_if = "Option::is_none")]
1555 stress_index: Option<StressIndexArgs>,
1556}
1557
1558#[derive(Serialize)]
1562struct StressSubRunBeginArgs {
1563 progress: StressProgress,
1564}
1565
1566#[derive(Serialize)]
1568struct StressSubRunEndArgs {
1569 progress: StressProgress,
1570 time_taken_ms: f64,
1571 sub_stats: RunStats,
1572}
1573
1574#[derive(Serialize)]
1578struct CounterArgs {
1579 running_tests: usize,
1580 running_scripts: usize,
1581}
1582
1583#[derive(Serialize)]
1586struct ResultsCounterArgs {
1587 passed: usize,
1589 flaky: usize,
1591 failed: usize,
1593}
1594
1595#[derive(Serialize)]
1599struct MetadataNameArgs {
1600 name: String,
1601}
1602
1603#[derive(Serialize)]
1607struct MetadataSortIndexArgs {
1608 sort_index: u64,
1609}
1610
1611#[derive(Serialize)]
1613#[serde(rename_all = "camelCase")] struct ChromeTraceOutput {
1615 trace_events: Vec<ChromeTraceEvent>,
1616 display_time_unit: &'static str,
1617 other_data: ChromeTraceOtherData,
1621}
1622
1623#[derive(Serialize)]
1625struct ChromeTraceOtherData {
1626 nextest_version: String,
1627 #[serde(skip_serializing_if = "Option::is_none")]
1628 run_id: Option<String>,
1629 #[serde(skip_serializing_if = "Option::is_none")]
1630 profile_name: Option<String>,
1631 #[serde(skip_serializing_if = "Vec::is_empty")]
1632 cli_args: Vec<String>,
1633 #[serde(skip_serializing_if = "Option::is_none")]
1634 stress_condition: Option<StressConditionSummary>,
1635}
1636
1637fn datetime_to_microseconds(dt: DateTime<FixedOffset>) -> f64 {
1639 dt.timestamp_micros() as f64
1643}
1644
1645fn duration_to_millis(d: Duration) -> f64 {
1647 d.as_secs_f64() * 1000.0
1648}
1649
1650fn non_zero_duration_secs(d: Duration) -> Option<f64> {
1652 if d.is_zero() {
1653 None
1654 } else {
1655 Some(d.as_secs_f64())
1656 }
1657}
1658
1659#[cfg(test)]
1660mod tests {
1661 use super::*;
1662 use crate::{
1663 config::{
1664 elements::{FlakyResult, TestGroup},
1665 scripts::ScriptId,
1666 },
1667 list::OwnedTestInstanceId,
1668 output_spec::RecordingSpec,
1669 record::summary::{
1670 CoreEventKind, OutputEventKind, TestEventKindSummary, TestEventSummary,
1671 ZipStoreOutputDescription,
1672 },
1673 reporter::{
1674 TestOutputDisplay,
1675 events::{
1676 ChildExecutionOutputDescription, ExecuteStatus, ExecutionResultDescription,
1677 ExecutionStatuses, FailureDescription, RetryData, RunFinishedStats, RunStats,
1678 SetupScriptExecuteStatus, TestSlotAssignment,
1679 },
1680 },
1681 runner::StressCount,
1682 };
1683 use chrono::{FixedOffset, TimeZone};
1684 use nextest_metadata::{RustBinaryId, TestCaseName};
1685 use std::{
1686 collections::{BTreeSet, HashMap},
1687 num::NonZero,
1688 time::Duration,
1689 };
1690
1691 fn assert_be_balanced(trace_events: &[serde_json::Value]) {
1695 let mut b_counts: HashMap<(u64, u64, &str), usize> = HashMap::new();
1696 let mut e_counts: HashMap<(u64, u64, &str), usize> = HashMap::new();
1697
1698 for event in trace_events {
1699 let ph = event["ph"].as_str().unwrap_or("");
1700 let cat = event["cat"].as_str().unwrap_or("");
1701 let pid = event["pid"].as_u64().unwrap_or(0);
1702 let tid = event["tid"].as_u64().unwrap_or(0);
1703 match ph {
1704 "B" => *b_counts.entry((pid, tid, cat)).or_default() += 1,
1705 "E" => *e_counts.entry((pid, tid, cat)).or_default() += 1,
1706 _ => {}
1707 }
1708 }
1709
1710 let all_keys: BTreeSet<_> = b_counts.keys().chain(e_counts.keys()).copied().collect();
1712
1713 for key in all_keys {
1714 let b = b_counts.get(&key).copied().unwrap_or(0);
1715 let e = e_counts.get(&key).copied().unwrap_or(0);
1716 assert_eq!(
1717 b, e,
1718 "B/E mismatch for (pid={}, tid={}, cat={:?}): {} B events vs {} E events",
1719 key.0, key.1, key.2, b, e,
1720 );
1721 }
1722 }
1723
1724 fn test_version() -> Version {
1725 Version::new(0, 9, 9999)
1726 }
1727
1728 fn ts(secs: i64) -> DateTime<FixedOffset> {
1731 FixedOffset::east_opt(0)
1732 .unwrap()
1733 .timestamp_opt(secs, 0)
1734 .unwrap()
1735 }
1736
1737 fn test_id(binary: &str, test: &str) -> OwnedTestInstanceId {
1738 OwnedTestInstanceId {
1739 binary_id: RustBinaryId::new(binary),
1740 test_name: TestCaseName::new(test),
1741 }
1742 }
1743
1744 fn slot(global: u64) -> TestSlotAssignment {
1745 TestSlotAssignment {
1746 global_slot: global,
1747 group_slot: None,
1748 test_group: TestGroup::Global,
1749 }
1750 }
1751
1752 fn core_event(
1753 timestamp: DateTime<FixedOffset>,
1754 kind: CoreEventKind,
1755 ) -> TestEventSummary<RecordingSpec> {
1756 TestEventSummary {
1757 timestamp,
1758 elapsed: Duration::ZERO,
1759 kind: TestEventKindSummary::Core(kind),
1760 }
1761 }
1762
1763 fn output_event(
1764 timestamp: DateTime<FixedOffset>,
1765 kind: OutputEventKind<RecordingSpec>,
1766 ) -> TestEventSummary<RecordingSpec> {
1767 TestEventSummary {
1768 timestamp,
1769 elapsed: Duration::ZERO,
1770 kind: TestEventKindSummary::Output(kind),
1771 }
1772 }
1773
1774 fn empty_output() -> ChildExecutionOutputDescription<RecordingSpec> {
1775 ChildExecutionOutputDescription::Output {
1776 result: Some(ExecutionResultDescription::Pass),
1777 output: ZipStoreOutputDescription::Split {
1778 stdout: None,
1779 stderr: None,
1780 },
1781 errors: None,
1782 }
1783 }
1784
1785 fn passing_status(
1786 start_time: DateTime<FixedOffset>,
1787 time_taken: Duration,
1788 attempt: u32,
1789 total_attempts: u32,
1790 ) -> ExecuteStatus<RecordingSpec> {
1791 ExecuteStatus {
1792 retry_data: RetryData {
1793 attempt,
1794 total_attempts,
1795 },
1796 output: empty_output(),
1797 result: ExecutionResultDescription::Pass,
1798 start_time,
1799 time_taken,
1800 is_slow: false,
1801 delay_before_start: Duration::ZERO,
1802 error_summary: None,
1803 output_error_slice: None,
1804 }
1805 }
1806
1807 fn failing_status(
1808 start_time: DateTime<FixedOffset>,
1809 time_taken: Duration,
1810 attempt: u32,
1811 total_attempts: u32,
1812 ) -> ExecuteStatus<RecordingSpec> {
1813 ExecuteStatus {
1814 retry_data: RetryData {
1815 attempt,
1816 total_attempts,
1817 },
1818 output: empty_output(),
1819 result: ExecutionResultDescription::Fail {
1820 failure: FailureDescription::ExitCode { code: 1 },
1821 leaked: false,
1822 },
1823 start_time,
1824 time_taken,
1825 is_slow: false,
1826 delay_before_start: Duration::ZERO,
1827 error_summary: None,
1828 output_error_slice: None,
1829 }
1830 }
1831
1832 fn convert_and_parse(
1835 events: Vec<Result<TestEventSummary<RecordingSpec>, RecordReadError>>,
1836 group_by: ChromeTraceGroupBy,
1837 ) -> (serde_json::Value, Vec<serde_json::Value>) {
1838 let json_bytes = convert_to_chrome_trace(
1839 &test_version(),
1840 events,
1841 group_by,
1842 ChromeTraceMessageFormat::JsonPretty,
1843 )
1844 .expect("conversion succeeded");
1845 let parsed: serde_json::Value = serde_json::from_slice(&json_bytes).expect("valid JSON");
1846 let trace_events = parsed["traceEvents"]
1847 .as_array()
1848 .expect("traceEvents is an array")
1849 .clone();
1850 assert_be_balanced(&trace_events);
1851 (parsed, trace_events)
1852 }
1853
1854 fn run_started(timestamp: DateTime<FixedOffset>) -> TestEventSummary<RecordingSpec> {
1855 core_event(
1856 timestamp,
1857 CoreEventKind::RunStarted {
1858 run_id: quick_junit::ReportUuid::nil(),
1859 profile_name: "default".to_string(),
1860 cli_args: vec![],
1861 stress_condition: None,
1862 },
1863 )
1864 }
1865
1866 fn run_finished(
1867 timestamp: DateTime<FixedOffset>,
1868 start_time: DateTime<FixedOffset>,
1869 elapsed: Duration,
1870 ) -> TestEventSummary<RecordingSpec> {
1871 core_event(
1872 timestamp,
1873 CoreEventKind::RunFinished {
1874 run_id: quick_junit::ReportUuid::nil(),
1875 start_time,
1876 elapsed,
1877 run_stats: RunFinishedStats::Single(RunStats::default()),
1878 outstanding_not_seen: None,
1879 },
1880 )
1881 }
1882
1883 fn test_started(
1884 timestamp: DateTime<FixedOffset>,
1885 binary: &str,
1886 test: &str,
1887 global_slot: u64,
1888 running: usize,
1889 ) -> TestEventSummary<RecordingSpec> {
1890 core_event(
1891 timestamp,
1892 CoreEventKind::TestStarted {
1893 stress_index: None,
1894 test_instance: test_id(binary, test),
1895 slot_assignment: slot(global_slot),
1896 current_stats: RunStats::default(),
1897 running,
1898 command_line: vec![],
1899 },
1900 )
1901 }
1902
1903 fn test_finished_pass(
1904 timestamp: DateTime<FixedOffset>,
1905 binary: &str,
1906 test: &str,
1907 start_time: DateTime<FixedOffset>,
1908 time_taken: Duration,
1909 running: usize,
1910 ) -> TestEventSummary<RecordingSpec> {
1911 output_event(
1912 timestamp,
1913 OutputEventKind::TestFinished {
1914 stress_index: None,
1915 test_instance: test_id(binary, test),
1916 success_output: TestOutputDisplay::Never,
1917 failure_output: TestOutputDisplay::Never,
1918 junit_store_success_output: false,
1919 junit_store_failure_output: false,
1920 run_statuses: ExecutionStatuses::new(
1921 vec![passing_status(start_time, time_taken, 1, 1)],
1922 FlakyResult::Pass,
1923 ),
1924 current_stats: RunStats::default(),
1925 running,
1926 },
1927 )
1928 }
1929
1930 #[test]
1931 fn basic_test_run() {
1932 let events = vec![
1933 Ok(run_started(ts(1000))),
1934 Ok(test_started(
1935 ts(1000),
1936 "my-crate::bin/my-test",
1937 "tests::basic",
1938 0,
1939 1,
1940 )),
1941 Ok(test_finished_pass(
1942 ts(1001),
1943 "my-crate::bin/my-test",
1944 "tests::basic",
1945 ts(1000),
1946 Duration::from_millis(500),
1947 0,
1948 )),
1949 Ok(run_finished(ts(1002), ts(1000), Duration::from_secs(2))),
1950 ];
1951
1952 let (parsed, trace_events) = convert_and_parse(events, ChromeTraceGroupBy::Binary);
1953
1954 assert_eq!(
1961 trace_events.len(),
1962 15,
1963 "expected 15 trace events, got: {trace_events:#?}"
1964 );
1965
1966 let test_begins: Vec<_> = trace_events
1968 .iter()
1969 .filter(|e| e["ph"] == "B" && e["cat"] == "test")
1970 .collect();
1971 let test_ends: Vec<_> = trace_events
1972 .iter()
1973 .filter(|e| e["ph"] == "E" && e["cat"] == "test")
1974 .collect();
1975 assert_eq!(test_begins.len(), 1);
1976 assert_eq!(test_ends.len(), 1);
1977
1978 let test_b = test_begins[0];
1979 assert_eq!(test_b["name"], "tests::basic");
1980 assert_eq!(test_b["pid"], 2); assert_eq!(test_b["tid"], TID_OFFSET); let b_ts = test_b["ts"].as_f64().unwrap();
1985 assert!(
1986 (b_ts - 1_000_000_000.0).abs() < 1.0,
1987 "expected ~1e9 us, got {b_ts}"
1988 );
1989
1990 let test_e = test_ends[0];
1992 let e_ts = test_e["ts"].as_f64().unwrap();
1993 assert!(
1994 (e_ts - 1_001_000_000.0).abs() < 1.0,
1995 "expected ~1001000000 us, got {e_ts}"
1996 );
1997
1998 assert_eq!(test_e["args"]["attempt"], 1);
2000
2001 let run_begins: Vec<_> = trace_events
2003 .iter()
2004 .filter(|e| e["ph"] == "B" && e["cat"] == "run")
2005 .collect();
2006 let run_ends: Vec<_> = trace_events
2007 .iter()
2008 .filter(|e| e["ph"] == "E" && e["cat"] == "run")
2009 .collect();
2010 assert_eq!(run_begins.len(), 1);
2011 assert_eq!(run_ends.len(), 1);
2012 assert_eq!(run_ends[0]["args"]["profile"], "default");
2013
2014 assert_eq!(parsed["displayTimeUnit"], "ms");
2015
2016 let other_data = &parsed["otherData"];
2018 assert_eq!(other_data["profile_name"], "default");
2019 assert!(!other_data["run_id"].is_null(), "runId should be present");
2020 assert!(
2021 !other_data["nextest_version"].is_null(),
2022 "nextest version should be present"
2023 );
2024
2025 let proc_sort: Vec<_> = trace_events
2027 .iter()
2028 .filter(|e| e["name"] == "process_sort_index")
2029 .collect();
2030 assert!(
2031 proc_sort.len() >= 2,
2032 "should have sort indexes for run lifecycle and test binary"
2033 );
2034
2035 let run_sort = proc_sort
2037 .iter()
2038 .find(|e| e["pid"] == 0)
2039 .expect("run lifecycle sort index");
2040 assert_eq!(run_sort["args"]["sort_index"], 0);
2041
2042 let binary_sort = proc_sort
2044 .iter()
2045 .find(|e| e["pid"] == 2)
2046 .expect("binary sort index");
2047 assert_eq!(binary_sort["args"]["sort_index"], 2);
2048
2049 let thread_sort: Vec<_> = trace_events
2051 .iter()
2052 .filter(|e| e["name"] == "thread_sort_index")
2053 .collect();
2054 assert!(!thread_sort.is_empty(), "should have thread sort indexes");
2055 }
2056
2057 #[test]
2058 fn setup_script() {
2059 let script_id = ScriptId::new("db-setup".into()).expect("valid script ID");
2060
2061 let events = vec![
2062 Ok(core_event(
2063 ts(1000),
2064 CoreEventKind::SetupScriptStarted {
2065 stress_index: None,
2066 index: 0,
2067 total: 1,
2068 script_id: script_id.clone(),
2069 program: "/bin/setup".to_string(),
2070 args: vec![],
2071 no_capture: false,
2072 },
2073 )),
2074 Ok(core_event(
2076 ts(1005),
2077 CoreEventKind::SetupScriptSlow {
2078 stress_index: None,
2079 script_id: script_id.clone(),
2080 program: "/bin/setup".to_string(),
2081 args: vec![],
2082 elapsed: Duration::from_secs(5),
2083 will_terminate: true,
2084 },
2085 )),
2086 Ok(output_event(
2087 ts(1010),
2088 OutputEventKind::SetupScriptFinished {
2089 stress_index: None,
2090 index: 0,
2091 total: 1,
2092 script_id: script_id.clone(),
2093 program: "/bin/setup".to_string(),
2094 args: vec![],
2095 no_capture: false,
2096 run_status: SetupScriptExecuteStatus {
2097 output: empty_output(),
2098 result: ExecutionResultDescription::Pass,
2099 start_time: ts(1000),
2100 time_taken: Duration::from_secs(10),
2101 is_slow: true,
2102 env_map: None,
2103 error_summary: None,
2104 },
2105 },
2106 )),
2107 ];
2108
2109 let (_parsed, trace_events) = convert_and_parse(events, ChromeTraceGroupBy::Binary);
2110
2111 let b_events: Vec<_> = trace_events
2112 .iter()
2113 .filter(|e| e["ph"] == "B" && e["cat"] == "setup-script")
2114 .collect();
2115 let e_events: Vec<_> = trace_events
2116 .iter()
2117 .filter(|e| e["ph"] == "E" && e["cat"] == "setup-script")
2118 .collect();
2119 assert_eq!(b_events.len(), 1);
2120 assert_eq!(e_events.len(), 1);
2121
2122 assert_eq!(b_events[0]["name"], "db-setup");
2123 assert_eq!(b_events[0]["pid"], 1); assert_eq!(b_events[0]["tid"], TID_OFFSET); assert_eq!(e_events[0]["args"]["script_id"], "db-setup");
2128
2129 let slow_events: Vec<_> = trace_events
2131 .iter()
2132 .filter(|e| e["ph"] == "i" && e["name"] == "slow")
2133 .collect();
2134 assert_eq!(slow_events.len(), 1, "expected 1 slow instant event");
2135
2136 let slow = slow_events[0];
2137 assert_eq!(slow["cat"], "setup-script");
2138 assert_eq!(slow["s"], "t", "should be thread-scoped");
2139 assert_eq!(slow["args"]["will_terminate"], true);
2140 assert_eq!(slow["args"]["elapsed_secs"], 5.0);
2141 assert_eq!(slow["args"]["script_id"], "db-setup");
2142 assert_eq!(slow["pid"], SETUP_SCRIPT_PID);
2143 }
2144
2145 #[test]
2146 fn empty_run_produces_only_run_lifecycle() {
2147 let events = vec![
2148 Ok(run_started(ts(1000))),
2149 Ok(run_finished(ts(1000), ts(1000), Duration::ZERO)),
2150 ];
2151
2152 let (_parsed, trace_events) = convert_and_parse(events, ChromeTraceGroupBy::Binary);
2153
2154 assert_eq!(
2158 trace_events.len(),
2159 6,
2160 "empty run should produce only run lifecycle events, got: {trace_events:#?}"
2161 );
2162
2163 let b_events: Vec<_> = trace_events
2164 .iter()
2165 .filter(|e| e["ph"] == "B" && e["cat"] == "run")
2166 .collect();
2167 let e_events: Vec<_> = trace_events
2168 .iter()
2169 .filter(|e| e["ph"] == "E" && e["cat"] == "run")
2170 .collect();
2171 assert_eq!(b_events.len(), 1);
2172 assert_eq!(e_events.len(), 1);
2173 assert_eq!(b_events[0]["name"], "test run");
2174 }
2175
2176 #[test]
2179 fn pause_resume_splits_events() {
2180 let events = vec![
2181 Ok(core_event(
2183 ts(1000),
2184 CoreEventKind::RunStarted {
2185 run_id: quick_junit::ReportUuid::nil(),
2186 profile_name: "ci".to_string(),
2187 cli_args: vec!["--run-ignored".to_string()],
2188 stress_condition: None,
2189 },
2190 )),
2191 Ok(test_started(ts(1000), "crate::bin/test", "test_a", 0, 1)),
2192 Ok(core_event(
2194 ts(1001),
2195 CoreEventKind::RunPaused {
2196 setup_scripts_running: 0,
2197 running: 1,
2198 },
2199 )),
2200 Ok(core_event(
2202 ts(1005),
2203 CoreEventKind::RunContinued {
2204 setup_scripts_running: 0,
2205 running: 1,
2206 },
2207 )),
2208 Ok(test_finished_pass(
2209 ts(1010),
2210 "crate::bin/test",
2211 "test_a",
2212 ts(1000),
2213 Duration::from_secs(10),
2214 0,
2215 )),
2216 Ok(core_event(
2217 ts(1011),
2218 CoreEventKind::RunBeginCancel {
2219 setup_scripts_running: 0,
2220 running: 0,
2221 reason: CancelReason::TestFailure,
2222 },
2223 )),
2224 Ok(run_finished(ts(1012), ts(1000), Duration::from_secs(12))),
2225 ];
2226
2227 let (parsed, trace_events) = convert_and_parse(events, ChromeTraceGroupBy::Binary);
2228
2229 let test_b: Vec<_> = trace_events
2232 .iter()
2233 .filter(|e| e["ph"] == "B" && e["cat"] == "test")
2234 .collect();
2235 let test_e: Vec<_> = trace_events
2236 .iter()
2237 .filter(|e| e["ph"] == "E" && e["cat"] == "test")
2238 .collect();
2239 assert_eq!(test_b.len(), 2, "expected 2 test B events (start + resume)");
2240 assert_eq!(test_e.len(), 2, "expected 2 test E events (pause + finish)");
2241
2242 let b1_ts = test_b[0]["ts"].as_f64().unwrap();
2244 let e1_ts = test_e[0]["ts"].as_f64().unwrap();
2245 assert!(
2246 (b1_ts - 1_000_000_000.0).abs() < 1.0,
2247 "first B should be at T=1000"
2248 );
2249 assert!(
2250 (e1_ts - 1_001_000_000.0).abs() < 1.0,
2251 "first E should be at T=1001 (pause)"
2252 );
2253
2254 let b2_ts = test_b[1]["ts"].as_f64().unwrap();
2256 let e2_ts = test_e[1]["ts"].as_f64().unwrap();
2257 assert!(
2258 (b2_ts - 1_005_000_000.0).abs() < 1.0,
2259 "second B should be at T=1005 (resume)"
2260 );
2261 assert!(
2262 (e2_ts - 1_010_000_000.0).abs() < 1.0,
2263 "second E should be at T=1010 (finish)"
2264 );
2265
2266 let run_b: Vec<_> = trace_events
2268 .iter()
2269 .filter(|e| e["ph"] == "B" && e["cat"] == "run")
2270 .collect();
2271 let run_e: Vec<_> = trace_events
2272 .iter()
2273 .filter(|e| e["ph"] == "E" && e["cat"] == "run")
2274 .collect();
2275 assert_eq!(run_b.len(), 2, "expected 2 run B events (start + resume)");
2276 assert_eq!(run_e.len(), 2, "expected 2 run E events (pause + finish)");
2277
2278 let instant_events: Vec<_> = trace_events.iter().filter(|e| e["ph"] == "i").collect();
2280 assert_eq!(instant_events.len(), 3);
2281 let names: Vec<&str> = instant_events
2282 .iter()
2283 .map(|e| e["name"].as_str().unwrap())
2284 .collect();
2285 assert_eq!(names, vec!["paused", "continued", "cancel"]);
2286
2287 assert_eq!(instant_events[2]["args"]["reason"], "test-failure");
2289
2290 let process_meta: Vec<_> = trace_events
2292 .iter()
2293 .filter(|e| e["name"] == "process_name" && e["pid"] == 0)
2294 .collect();
2295 assert_eq!(process_meta.len(), 1);
2296 assert_eq!(process_meta[0]["args"]["name"], "nextest run (ci)");
2297
2298 assert!(parsed["metadata"].is_null(), "metadata should not exist");
2301 let other_data = &parsed["otherData"];
2302 assert!(!other_data.is_null(), "otherData should exist");
2303 let version = other_data["nextest_version"].as_str().unwrap();
2304 assert!(!version.is_empty(), "nextest version should be non-empty");
2305 assert_eq!(other_data["profile_name"], "ci");
2306 assert_eq!(other_data["cli_args"][0], "--run-ignored");
2307 }
2308
2309 #[test]
2312 fn pause_resume_with_setup_scripts() {
2313 let script_id = ScriptId::new("db-setup".into()).expect("valid script ID");
2314
2315 let events = vec![
2316 Ok(run_started(ts(1000))),
2317 Ok(core_event(
2318 ts(1000),
2319 CoreEventKind::SetupScriptStarted {
2320 stress_index: None,
2321 index: 0,
2322 total: 1,
2323 script_id: script_id.clone(),
2324 program: "/bin/setup".to_string(),
2325 args: vec![],
2326 no_capture: false,
2327 },
2328 )),
2329 Ok(core_event(
2331 ts(1002),
2332 CoreEventKind::RunPaused {
2333 setup_scripts_running: 1,
2334 running: 0,
2335 },
2336 )),
2337 Ok(core_event(
2339 ts(1005),
2340 CoreEventKind::RunContinued {
2341 setup_scripts_running: 1,
2342 running: 0,
2343 },
2344 )),
2345 Ok(output_event(
2347 ts(1010),
2348 OutputEventKind::SetupScriptFinished {
2349 stress_index: None,
2350 index: 0,
2351 total: 1,
2352 script_id: script_id.clone(),
2353 program: "/bin/setup".to_string(),
2354 args: vec![],
2355 no_capture: false,
2356 run_status: SetupScriptExecuteStatus {
2357 output: empty_output(),
2358 result: ExecutionResultDescription::Pass,
2359 start_time: ts(1000),
2360 time_taken: Duration::from_secs(10),
2361 is_slow: false,
2362 env_map: None,
2363 error_summary: None,
2364 },
2365 },
2366 )),
2367 Ok(run_finished(ts(1012), ts(1000), Duration::from_secs(12))),
2368 ];
2369
2370 let (_parsed, trace_events) = convert_and_parse(events, ChromeTraceGroupBy::Binary);
2371
2372 let script_b: Vec<_> = trace_events
2375 .iter()
2376 .filter(|e| e["ph"] == "B" && e["cat"] == "setup-script")
2377 .collect();
2378 let script_e: Vec<_> = trace_events
2379 .iter()
2380 .filter(|e| e["ph"] == "E" && e["cat"] == "setup-script")
2381 .collect();
2382 assert_eq!(
2383 script_b.len(),
2384 2,
2385 "expected 2 setup-script B events (start + resume)"
2386 );
2387 assert_eq!(
2388 script_e.len(),
2389 2,
2390 "expected 2 setup-script E events (pause + finish)"
2391 );
2392
2393 let b1_ts = script_b[0]["ts"].as_f64().unwrap();
2395 let e1_ts = script_e[0]["ts"].as_f64().unwrap();
2396 assert!(
2397 (b1_ts - 1_000_000_000.0).abs() < 1.0,
2398 "first B should be at T=1000"
2399 );
2400 assert!(
2401 (e1_ts - 1_002_000_000.0).abs() < 1.0,
2402 "first E should be at T=1002 (pause)"
2403 );
2404
2405 let b2_ts = script_b[1]["ts"].as_f64().unwrap();
2407 assert!(
2408 (b2_ts - 1_005_000_000.0).abs() < 1.0,
2409 "second B should be at T=1005 (resume)"
2410 );
2411
2412 for e in script_b.iter().chain(script_e.iter()) {
2414 assert_eq!(
2415 e["pid"], 1,
2416 "setup script events should use SETUP_SCRIPT_PID"
2417 );
2418 }
2419
2420 let run_b: Vec<_> = trace_events
2422 .iter()
2423 .filter(|e| e["ph"] == "B" && e["cat"] == "run")
2424 .collect();
2425 let run_e: Vec<_> = trace_events
2426 .iter()
2427 .filter(|e| e["ph"] == "E" && e["cat"] == "run")
2428 .collect();
2429 assert_eq!(run_b.len(), 2, "expected 2 run B events (start + resume)");
2430 assert_eq!(run_e.len(), 2, "expected 2 run E events (pause + finish)");
2431 }
2432
2433 #[test]
2437 fn run_bar_uses_event_timestamp() {
2438 let events = vec![
2439 Ok(run_started(ts(1000))),
2440 Ok(test_started(ts(1000), "crate::bin/test", "slow_test", 0, 1)),
2441 Ok(test_finished_pass(
2442 ts(1010),
2443 "crate::bin/test",
2444 "slow_test",
2445 ts(1000),
2446 Duration::from_secs(10),
2447 0,
2448 )),
2449 Ok(run_finished(ts(1012), ts(1000), Duration::from_secs(8))),
2453 ];
2454
2455 let (_parsed, trace_events) = convert_and_parse(events, ChromeTraceGroupBy::Binary);
2456
2457 let run_b = trace_events
2459 .iter()
2460 .find(|e| e["ph"] == "B" && e["cat"] == "run")
2461 .expect("run B event");
2462 let run_e = trace_events
2463 .iter()
2464 .find(|e| e["ph"] == "E" && e["cat"] == "run")
2465 .expect("run E event");
2466
2467 let run_b_ts = run_b["ts"].as_f64().unwrap();
2468 let run_e_ts = run_e["ts"].as_f64().unwrap();
2469
2470 assert!(
2472 (run_b_ts - 1_000_000_000.0).abs() < 1.0,
2473 "run B should be at ts(1000)"
2474 );
2475 assert!(
2476 (run_e_ts - 1_012_000_000.0).abs() < 1.0,
2477 "run E should be at ts(1012), not ts(1008)"
2478 );
2479
2480 let test_e = trace_events
2482 .iter()
2483 .find(|e| e["ph"] == "E" && e["cat"] == "test")
2484 .expect("test E event");
2485 let test_e_ts = test_e["ts"].as_f64().unwrap();
2486 assert!(
2487 test_e_ts <= run_e_ts,
2488 "test E ({test_e_ts}) should not exceed run E ({run_e_ts})"
2489 );
2490 }
2491
2492 #[test]
2495 fn run_finished_while_paused() {
2496 let events = vec![
2497 Ok(run_started(ts(1000))),
2498 Ok(test_started(ts(1000), "crate::bin/test", "test_a", 0, 1)),
2499 Ok(core_event(
2501 ts(1002),
2502 CoreEventKind::RunPaused {
2503 setup_scripts_running: 0,
2504 running: 1,
2505 },
2506 )),
2507 Ok(run_finished(ts(1005), ts(1000), Duration::from_secs(5))),
2510 ];
2511
2512 let (_parsed, trace_events) = convert_and_parse(events, ChromeTraceGroupBy::Binary);
2513
2514 let run_b: Vec<_> = trace_events
2517 .iter()
2518 .filter(|e| e["ph"] == "B" && e["cat"] == "run")
2519 .collect();
2520 let run_e: Vec<_> = trace_events
2521 .iter()
2522 .filter(|e| e["ph"] == "E" && e["cat"] == "run")
2523 .collect();
2524
2525 assert_eq!(run_b.len(), 2, "expected 2 run B events, got {run_b:#?}");
2528 assert_eq!(run_e.len(), 2, "expected 2 run E events, got {run_e:#?}");
2529
2530 let last_e = run_e.last().unwrap();
2532 assert!(
2533 !last_e["args"]["run_stats"].is_null(),
2534 "final E should have run_stats"
2535 );
2536
2537 for (b, e) in run_b.iter().zip(run_e.iter()) {
2540 let b_ts = b["ts"].as_f64().unwrap();
2541 let e_ts = e["ts"].as_f64().unwrap();
2542 assert!(
2543 b_ts <= e_ts,
2544 "B timestamp ({b_ts}) should not exceed E timestamp ({e_ts})"
2545 );
2546 }
2547 }
2548
2549 #[test]
2552 fn retry_flow_events() {
2553 let events = vec![
2554 Ok(test_started(
2555 ts(1000),
2556 "crate::bin/test",
2557 "flaky_test",
2558 0,
2559 1,
2560 )),
2561 Ok(output_event(
2562 ts(1001),
2563 OutputEventKind::TestAttemptFailedWillRetry {
2564 stress_index: None,
2565 test_instance: test_id("crate::bin/test", "flaky_test"),
2566 run_status: failing_status(ts(1000), Duration::from_millis(200), 1, 3),
2567 delay_before_next_attempt: Duration::ZERO,
2568 failure_output: TestOutputDisplay::Never,
2569 running: 1,
2570 },
2571 )),
2572 Ok(core_event(
2573 ts(1001),
2574 CoreEventKind::TestRetryStarted {
2575 stress_index: None,
2576 test_instance: test_id("crate::bin/test", "flaky_test"),
2577 slot_assignment: slot(0),
2578 retry_data: RetryData {
2579 attempt: 2,
2580 total_attempts: 3,
2581 },
2582 running: 1,
2583 command_line: vec![],
2584 },
2585 )),
2586 Ok(output_event(
2587 ts(1002),
2588 OutputEventKind::TestFinished {
2589 stress_index: None,
2590 test_instance: test_id("crate::bin/test", "flaky_test"),
2591 success_output: TestOutputDisplay::Never,
2592 failure_output: TestOutputDisplay::Never,
2593 junit_store_success_output: false,
2594 junit_store_failure_output: false,
2595 run_statuses: ExecutionStatuses::new(
2596 vec![
2597 failing_status(ts(1000), Duration::from_millis(200), 1, 3),
2598 passing_status(ts(1001), Duration::from_millis(300), 2, 3),
2599 ],
2600 FlakyResult::Pass,
2601 ),
2602 current_stats: RunStats::default(),
2603 running: 0,
2604 },
2605 )),
2606 ];
2607
2608 let (_parsed, trace_events) = convert_and_parse(events, ChromeTraceGroupBy::Binary);
2609
2610 let flow_starts: Vec<_> = trace_events
2612 .iter()
2613 .filter(|e| e["ph"] == "s" && e["name"] == "retry")
2614 .collect();
2615 assert_eq!(flow_starts.len(), 1, "expected 1 flow start event");
2616
2617 let flow_finishes: Vec<_> = trace_events
2619 .iter()
2620 .filter(|e| e["ph"] == "f" && e["name"] == "retry")
2621 .collect();
2622 assert_eq!(flow_finishes.len(), 1, "expected 1 flow finish event");
2623
2624 let start_id = flow_starts[0]["id"].as_u64().unwrap();
2626 let finish_id = flow_finishes[0]["id"].as_u64().unwrap();
2627 assert_eq!(start_id, finish_id, "flow start and finish should share ID");
2628
2629 assert_eq!(flow_finishes[0]["bp"], "e");
2631
2632 assert_eq!(flow_starts[0]["pid"], flow_finishes[0]["pid"]);
2634 assert_eq!(flow_starts[0]["tid"], flow_finishes[0]["tid"]);
2635
2636 let b_events: Vec<_> = trace_events
2638 .iter()
2639 .filter(|e| e["ph"] == "B" && e["cat"] == "test")
2640 .collect();
2641 let e_events: Vec<_> = trace_events
2642 .iter()
2643 .filter(|e| e["ph"] == "E" && e["cat"] == "test")
2644 .collect();
2645 assert_eq!(b_events.len(), 2);
2646 assert_eq!(e_events.len(), 2);
2647
2648 assert_eq!(e_events[0]["args"]["attempt"], 1);
2650 assert_eq!(e_events[1]["args"]["attempt"], 2);
2652
2653 for e in b_events.iter().chain(e_events.iter()) {
2655 assert_eq!(e["tid"], TID_OFFSET); }
2657 }
2658
2659 #[test]
2661 fn retry_across_pause_boundary() {
2662 let events = vec![
2663 Ok(run_started(ts(1000))),
2664 Ok(test_started(ts(1000), "crate::bin/test", "flaky", 0, 1)),
2665 Ok(output_event(
2667 ts(1001),
2668 OutputEventKind::TestAttemptFailedWillRetry {
2669 stress_index: None,
2670 test_instance: test_id("crate::bin/test", "flaky"),
2671 run_status: failing_status(ts(1000), Duration::from_millis(200), 1, 2),
2672 delay_before_next_attempt: Duration::from_secs(1),
2673 failure_output: TestOutputDisplay::Never,
2674 running: 1,
2675 },
2676 )),
2677 Ok(core_event(
2679 ts(1002),
2680 CoreEventKind::RunPaused {
2681 setup_scripts_running: 0,
2682 running: 1,
2683 },
2684 )),
2685 Ok(core_event(
2687 ts(1005),
2688 CoreEventKind::RunContinued {
2689 setup_scripts_running: 0,
2690 running: 1,
2691 },
2692 )),
2693 Ok(core_event(
2695 ts(1005),
2696 CoreEventKind::TestRetryStarted {
2697 stress_index: None,
2698 test_instance: test_id("crate::bin/test", "flaky"),
2699 slot_assignment: slot(0),
2700 retry_data: RetryData {
2701 attempt: 2,
2702 total_attempts: 2,
2703 },
2704 running: 1,
2705 command_line: vec![],
2706 },
2707 )),
2708 Ok(output_event(
2709 ts(1006),
2710 OutputEventKind::TestFinished {
2711 stress_index: None,
2712 test_instance: test_id("crate::bin/test", "flaky"),
2713 success_output: TestOutputDisplay::Never,
2714 failure_output: TestOutputDisplay::Never,
2715 junit_store_success_output: false,
2716 junit_store_failure_output: false,
2717 run_statuses: ExecutionStatuses::new(
2718 vec![
2719 failing_status(ts(1000), Duration::from_millis(200), 1, 2),
2720 passing_status(ts(1005), Duration::from_millis(300), 2, 2),
2721 ],
2722 FlakyResult::Pass,
2723 ),
2724 current_stats: RunStats::default(),
2725 running: 0,
2726 },
2727 )),
2728 Ok(run_finished(ts(1007), ts(1000), Duration::from_secs(7))),
2729 ];
2730
2731 let (_parsed, trace_events) = convert_and_parse(events, ChromeTraceGroupBy::Binary);
2732
2733 let flow_starts: Vec<_> = trace_events.iter().filter(|e| e["ph"] == "s").collect();
2735 let flow_finishes: Vec<_> = trace_events.iter().filter(|e| e["ph"] == "f").collect();
2736 assert_eq!(flow_starts.len(), 1);
2737 assert_eq!(flow_finishes.len(), 1);
2738 assert_eq!(
2739 flow_starts[0]["id"].as_u64(),
2740 flow_finishes[0]["id"].as_u64(),
2741 "flow events should be paired"
2742 );
2743
2744 let test_b: Vec<_> = trace_events
2752 .iter()
2753 .filter(|e| e["ph"] == "B" && e["cat"] == "test")
2754 .collect();
2755 let test_e: Vec<_> = trace_events
2756 .iter()
2757 .filter(|e| e["ph"] == "E" && e["cat"] == "test")
2758 .collect();
2759 assert_eq!(test_b.len(), 2, "2 B events: initial + retry");
2760 assert_eq!(test_e.len(), 2, "2 E events: attempt failed + finished");
2761 }
2762
2763 #[test]
2765 fn test_slow_instant_event() {
2766 let events = vec![
2767 Ok(test_started(ts(1000), "crate::bin/test", "slow_test", 0, 1)),
2768 Ok(core_event(
2769 ts(1005),
2770 CoreEventKind::TestSlow {
2771 stress_index: None,
2772 test_instance: test_id("crate::bin/test", "slow_test"),
2773 retry_data: RetryData {
2774 attempt: 1,
2775 total_attempts: 1,
2776 },
2777 elapsed: Duration::from_secs(5),
2778 will_terminate: false,
2779 },
2780 )),
2781 Ok(test_finished_pass(
2782 ts(1010),
2783 "crate::bin/test",
2784 "slow_test",
2785 ts(1000),
2786 Duration::from_secs(10),
2787 0,
2788 )),
2789 ];
2790
2791 let (_parsed, trace_events) = convert_and_parse(events, ChromeTraceGroupBy::Binary);
2792
2793 let slow_events: Vec<_> = trace_events
2795 .iter()
2796 .filter(|e| e["ph"] == "i" && e["name"] == "slow")
2797 .collect();
2798 assert_eq!(slow_events.len(), 1, "expected 1 slow instant event");
2799
2800 let slow = slow_events[0];
2801 assert_eq!(slow["cat"], "test");
2802 assert_eq!(slow["s"], "t", "should be thread-scoped");
2803 assert_eq!(slow["args"]["will_terminate"], false);
2804 assert_eq!(slow["args"]["elapsed_secs"], 5.0);
2805 assert_eq!(slow["args"]["attempt"], 1);
2806
2807 let test_b = trace_events
2809 .iter()
2810 .find(|e| e["ph"] == "B" && e["cat"] == "test")
2811 .expect("test B event");
2812 assert_eq!(slow["pid"], test_b["pid"]);
2813 assert_eq!(slow["tid"], test_b["tid"]);
2814 }
2815
2816 #[test]
2817 fn snapshot_basic_trace() {
2818 let events = vec![
2820 Ok(test_started(
2821 ts(1000),
2822 "my-crate::bin/my-test",
2823 "tests::it_works",
2824 0,
2825 1,
2826 )),
2827 Ok(test_finished_pass(
2831 ts(1002),
2832 "my-crate::bin/my-test",
2833 "tests::it_works",
2834 ts(1000),
2835 Duration::from_millis(500),
2836 0,
2837 )),
2838 ];
2839
2840 let result = convert_to_chrome_trace(
2841 &test_version(),
2842 events,
2843 ChromeTraceGroupBy::Binary,
2844 ChromeTraceMessageFormat::JsonPretty,
2845 );
2846 let json_bytes = result.expect("conversion succeeded");
2847 let json_str = String::from_utf8(json_bytes).expect("valid UTF-8");
2848
2849 insta::assert_snapshot!("basic_chrome_trace", json_str);
2850 }
2851
2852 #[test]
2853 fn snapshot_pause_resume_trace() {
2854 let events = vec![
2855 Ok(run_started(ts(1000))),
2856 Ok(test_started(
2857 ts(1000),
2858 "my-crate::bin/my-test",
2859 "tests::slow",
2860 0,
2861 1,
2862 )),
2863 Ok(core_event(
2865 ts(1002),
2866 CoreEventKind::RunPaused {
2867 setup_scripts_running: 0,
2868 running: 1,
2869 },
2870 )),
2871 Ok(core_event(
2873 ts(1008),
2874 CoreEventKind::RunContinued {
2875 setup_scripts_running: 0,
2876 running: 1,
2877 },
2878 )),
2879 Ok(test_finished_pass(
2885 ts(1010),
2886 "my-crate::bin/my-test",
2887 "tests::slow",
2888 ts(1000),
2889 Duration::from_secs(4),
2890 0,
2891 )),
2892 Ok(run_finished(ts(1010), ts(1000), Duration::from_secs(10))),
2893 ];
2894
2895 let result = convert_to_chrome_trace(
2896 &test_version(),
2897 events,
2898 ChromeTraceGroupBy::Binary,
2899 ChromeTraceMessageFormat::JsonPretty,
2900 );
2901 let json_bytes = result.expect("conversion succeeded");
2902 let json_str = String::from_utf8(json_bytes).expect("valid UTF-8");
2903
2904 insta::assert_snapshot!("pause_resume_chrome_trace", json_str);
2905 }
2906
2907 fn stress_progress(completed: u32, total: u32) -> StressProgress {
2909 StressProgress::Count {
2910 total: StressCount::Count {
2911 count: NonZero::new(total).expect("total is non-zero"),
2912 },
2913 elapsed: Duration::from_secs(completed as u64),
2914 completed,
2915 }
2916 }
2917
2918 #[test]
2921 fn stress_subrun_events() {
2922 let events = vec![
2923 Ok(run_started(ts(1000))),
2924 Ok(core_event(
2926 ts(1000),
2927 CoreEventKind::StressSubRunStarted {
2928 progress: stress_progress(0, 3),
2929 },
2930 )),
2931 Ok(test_started(ts(1000), "crate::bin/test", "test_a", 0, 1)),
2932 Ok(test_finished_pass(
2933 ts(1002),
2934 "crate::bin/test",
2935 "test_a",
2936 ts(1000),
2937 Duration::from_secs(2),
2938 0,
2939 )),
2940 Ok(core_event(
2941 ts(1002),
2942 CoreEventKind::StressSubRunFinished {
2943 progress: stress_progress(1, 3),
2944 sub_elapsed: Duration::from_secs(2),
2945 sub_stats: RunStats::default(),
2946 },
2947 )),
2948 Ok(core_event(
2950 ts(1003),
2951 CoreEventKind::StressSubRunStarted {
2952 progress: stress_progress(1, 3),
2953 },
2954 )),
2955 Ok(test_started(ts(1003), "crate::bin/test", "test_a", 0, 1)),
2956 Ok(test_finished_pass(
2957 ts(1005),
2958 "crate::bin/test",
2959 "test_a",
2960 ts(1003),
2961 Duration::from_secs(2),
2962 0,
2963 )),
2964 Ok(core_event(
2965 ts(1005),
2966 CoreEventKind::StressSubRunFinished {
2967 progress: stress_progress(2, 3),
2968 sub_elapsed: Duration::from_secs(2),
2969 sub_stats: RunStats::default(),
2970 },
2971 )),
2972 Ok(run_finished(ts(1006), ts(1000), Duration::from_secs(6))),
2973 ];
2974
2975 let (_parsed, trace_events) = convert_and_parse(events, ChromeTraceGroupBy::Binary);
2976
2977 let subrun_b: Vec<_> = trace_events
2979 .iter()
2980 .filter(|e| e["ph"] == "B" && e["cat"] == "stress")
2981 .collect();
2982 let subrun_e: Vec<_> = trace_events
2983 .iter()
2984 .filter(|e| e["ph"] == "E" && e["cat"] == "stress")
2985 .collect();
2986 assert_eq!(subrun_b.len(), 2, "expected 2 sub-run B events");
2987 assert_eq!(subrun_e.len(), 2, "expected 2 sub-run E events");
2988
2989 for e in subrun_b.iter().chain(subrun_e.iter()) {
2992 assert_eq!(e["pid"], RUN_LIFECYCLE_PID);
2993 assert_eq!(e["tid"], STRESS_SUBRUN_TID);
2994 assert_eq!(e["name"], "sub-run");
2995 }
2996
2997 assert!(
2999 !subrun_b[0]["args"]["progress"].is_null(),
3000 "sub-run B should have progress args"
3001 );
3002
3003 assert!(
3005 !subrun_e[0]["args"]["sub_stats"].is_null(),
3006 "sub-run E should have sub-stats"
3007 );
3008
3009 let thread_meta: Vec<_> = trace_events
3011 .iter()
3012 .filter(|e| {
3013 e["name"] == "thread_name"
3014 && e["pid"] == RUN_LIFECYCLE_PID
3015 && e["tid"] == STRESS_SUBRUN_TID
3016 })
3017 .collect();
3018 assert_eq!(
3019 thread_meta.len(),
3020 1,
3021 "stress sub-run thread_name metadata should be emitted once"
3022 );
3023 assert_eq!(thread_meta[0]["args"]["name"], "stress sub-runs");
3024 }
3025
3026 #[test]
3029 fn pause_resume_with_stress_subrun() {
3030 let events = vec![
3031 Ok(run_started(ts(1000))),
3032 Ok(core_event(
3033 ts(1000),
3034 CoreEventKind::StressSubRunStarted {
3035 progress: stress_progress(0, 2),
3036 },
3037 )),
3038 Ok(test_started(ts(1000), "crate::bin/test", "test_a", 0, 1)),
3039 Ok(core_event(
3041 ts(1002),
3042 CoreEventKind::RunPaused {
3043 setup_scripts_running: 0,
3044 running: 1,
3045 },
3046 )),
3047 Ok(core_event(
3049 ts(1005),
3050 CoreEventKind::RunContinued {
3051 setup_scripts_running: 0,
3052 running: 1,
3053 },
3054 )),
3055 Ok(test_finished_pass(
3057 ts(1008),
3058 "crate::bin/test",
3059 "test_a",
3060 ts(1000),
3061 Duration::from_secs(5),
3062 0,
3063 )),
3064 Ok(core_event(
3065 ts(1008),
3066 CoreEventKind::StressSubRunFinished {
3067 progress: stress_progress(1, 2),
3068 sub_elapsed: Duration::from_secs(5),
3069 sub_stats: RunStats::default(),
3070 },
3071 )),
3072 Ok(run_finished(ts(1009), ts(1000), Duration::from_secs(9))),
3073 ];
3074
3075 let (_parsed, trace_events) = convert_and_parse(events, ChromeTraceGroupBy::Binary);
3076
3077 let subrun_b: Vec<_> = trace_events
3080 .iter()
3081 .filter(|e| e["ph"] == "B" && e["cat"] == "stress")
3082 .collect();
3083 let subrun_e: Vec<_> = trace_events
3084 .iter()
3085 .filter(|e| e["ph"] == "E" && e["cat"] == "stress")
3086 .collect();
3087 assert_eq!(
3088 subrun_b.len(),
3089 2,
3090 "expected 2 sub-run B events (start + resume)"
3091 );
3092 assert_eq!(
3093 subrun_e.len(),
3094 2,
3095 "expected 2 sub-run E events (pause + finish)"
3096 );
3097
3098 let b1_ts = subrun_b[0]["ts"].as_f64().unwrap();
3100 let e1_ts = subrun_e[0]["ts"].as_f64().unwrap();
3101 assert!(
3102 (b1_ts - 1_000_000_000.0).abs() < 1.0,
3103 "first sub-run B should be at T=1000"
3104 );
3105 assert!(
3106 (e1_ts - 1_002_000_000.0).abs() < 1.0,
3107 "first sub-run E should be at T=1002 (pause)"
3108 );
3109
3110 let b2_ts = subrun_b[1]["ts"].as_f64().unwrap();
3112 let e2_ts = subrun_e[1]["ts"].as_f64().unwrap();
3113 assert!(
3114 (b2_ts - 1_005_000_000.0).abs() < 1.0,
3115 "second sub-run B should be at T=1005 (resume)"
3116 );
3117 assert!(
3118 (e2_ts - 1_008_000_000.0).abs() < 1.0,
3119 "second sub-run E should be at T=1008 (finish)"
3120 );
3121
3122 let test_b: Vec<_> = trace_events
3124 .iter()
3125 .filter(|e| e["ph"] == "B" && e["cat"] == "test")
3126 .collect();
3127 let test_e: Vec<_> = trace_events
3128 .iter()
3129 .filter(|e| e["ph"] == "E" && e["cat"] == "test")
3130 .collect();
3131 assert_eq!(test_b.len(), 2, "expected 2 test B events (start + resume)");
3132 assert_eq!(test_e.len(), 2, "expected 2 test E events (pause + finish)");
3133
3134 let run_b: Vec<_> = trace_events
3136 .iter()
3137 .filter(|e| e["ph"] == "B" && e["cat"] == "run")
3138 .collect();
3139 let run_e: Vec<_> = trace_events
3140 .iter()
3141 .filter(|e| e["ph"] == "E" && e["cat"] == "run")
3142 .collect();
3143 assert_eq!(run_b.len(), 2, "expected 2 run B events (start + resume)");
3144 assert_eq!(run_e.len(), 2, "expected 2 run E events (pause + finish)");
3145 }
3146
3147 #[test]
3150 fn results_counter_events() {
3151 let stats = RunStats {
3154 initial_run_count: 5,
3155 finished_count: 5,
3156 passed: 3,
3157 flaky: 1,
3158 failed: 1,
3159 exec_failed: 1,
3160 ..RunStats::default()
3161 };
3162
3163 let events = vec![
3164 Ok(test_started(ts(1000), "crate::bin/test", "test_a", 0, 1)),
3165 Ok(output_event(
3166 ts(1001),
3167 OutputEventKind::TestFinished {
3168 stress_index: None,
3169 test_instance: test_id("crate::bin/test", "test_a"),
3170 success_output: TestOutputDisplay::Never,
3171 failure_output: TestOutputDisplay::Never,
3172 junit_store_success_output: false,
3173 junit_store_failure_output: false,
3174 run_statuses: ExecutionStatuses::new(
3175 vec![passing_status(ts(1000), Duration::from_millis(500), 1, 1)],
3176 FlakyResult::Pass,
3177 ),
3178 current_stats: stats,
3179 running: 0,
3180 },
3181 )),
3182 ];
3183
3184 let (_parsed, trace_events) = convert_and_parse(events, ChromeTraceGroupBy::Binary);
3185
3186 let results_counters: Vec<_> = trace_events
3188 .iter()
3189 .filter(|e| e["ph"] == "C" && e["name"] == "test results")
3190 .collect();
3191 assert_eq!(
3192 results_counters.len(),
3193 1,
3194 "expected 1 results counter event"
3195 );
3196
3197 let args = &results_counters[0]["args"];
3198 assert_eq!(args["passed"], 3);
3200 assert_eq!(args["flaky"], 1);
3202 assert_eq!(args["failed"], 2, "failed should include exec_failed");
3204 }
3205
3206 #[test]
3210 fn multiple_binaries_grouping_modes() {
3211 let make_events = || {
3212 vec![
3213 Ok(run_started(ts(1000))),
3214 Ok(test_started(
3215 ts(1000),
3216 "crate-a::bin/test-a",
3217 "test_1",
3218 0,
3219 1,
3220 )),
3221 Ok(test_started(
3222 ts(1000),
3223 "crate-b::bin/test-b",
3224 "test_2",
3225 1,
3226 2,
3227 )),
3228 Ok(test_finished_pass(
3229 ts(1001),
3230 "crate-a::bin/test-a",
3231 "test_1",
3232 ts(1000),
3233 Duration::from_millis(100),
3234 1,
3235 )),
3236 Ok(test_finished_pass(
3237 ts(1001),
3238 "crate-b::bin/test-b",
3239 "test_2",
3240 ts(1000),
3241 Duration::from_millis(100),
3242 0,
3243 )),
3244 Ok(run_finished(ts(1002), ts(1000), Duration::from_secs(2))),
3245 ]
3246 };
3247
3248 {
3250 let (_parsed, trace_events) =
3251 convert_and_parse(make_events(), ChromeTraceGroupBy::Binary);
3252
3253 let b_events: Vec<_> = trace_events
3254 .iter()
3255 .filter(|e| e["ph"] == "B" && e["cat"] == "test")
3256 .collect();
3257 assert_eq!(b_events.len(), 2);
3258
3259 assert_eq!(b_events[0]["pid"], FIRST_BINARY_PID);
3262 assert_eq!(b_events[1]["pid"], FIRST_BINARY_PID + 1);
3263 }
3264
3265 {
3267 let (_parsed, trace_events) =
3268 convert_and_parse(make_events(), ChromeTraceGroupBy::Slot);
3269
3270 let test_b: Vec<_> = trace_events
3272 .iter()
3273 .filter(|e| e["ph"] == "B" && e["cat"] == "test")
3274 .collect();
3275 assert_eq!(test_b.len(), 2);
3276 for b in &test_b {
3277 assert_eq!(
3278 b["pid"], ALL_TESTS_PID,
3279 "slot mode: all tests should share ALL_TESTS_PID"
3280 );
3281 }
3282
3283 let names: Vec<&str> = test_b.iter().map(|e| e["name"].as_str().unwrap()).collect();
3285 assert!(
3286 names.contains(&"crate-a::bin/test-a test_1"),
3287 "expected qualified name for test_1, got: {names:?}"
3288 );
3289 assert!(
3290 names.contains(&"crate-b::bin/test-b test_2"),
3291 "expected qualified name for test_2, got: {names:?}"
3292 );
3293
3294 let test_e: Vec<_> = trace_events
3296 .iter()
3297 .filter(|e| e["ph"] == "E" && e["cat"] == "test")
3298 .collect();
3299 for e in &test_e {
3300 assert_eq!(
3301 e["pid"], ALL_TESTS_PID,
3302 "slot mode: all test E events should share ALL_TESTS_PID"
3303 );
3304 let name = e["name"].as_str().unwrap();
3305 assert!(
3306 name.contains("crate-a::bin/test-a") || name.contains("crate-b::bin/test-b"),
3307 "E event name should be qualified: {name}"
3308 );
3309 }
3310
3311 let proc_names: Vec<_> = trace_events
3313 .iter()
3314 .filter(|e| e["name"] == "process_name" && e["pid"] == ALL_TESTS_PID)
3315 .collect();
3316 assert_eq!(proc_names.len(), 1);
3317 assert_eq!(proc_names[0]["args"]["name"], "tests");
3318 }
3319 }
3320
3321 #[test]
3322 fn snapshot_slot_mode_chrome_trace() {
3323 let events = vec![
3324 Ok(run_started(ts(1000))),
3325 Ok(test_started(
3326 ts(1000),
3327 "crate-a::bin/test-a",
3328 "test_alpha",
3329 0,
3330 1,
3331 )),
3332 Ok(test_started(
3333 ts(1000),
3334 "crate-b::bin/test-b",
3335 "test_beta",
3336 1,
3337 2,
3338 )),
3339 Ok(test_finished_pass(
3340 ts(1002),
3341 "crate-a::bin/test-a",
3342 "test_alpha",
3343 ts(1000),
3344 Duration::from_millis(500),
3345 1,
3346 )),
3347 Ok(test_finished_pass(
3348 ts(1003),
3349 "crate-b::bin/test-b",
3350 "test_beta",
3351 ts(1000),
3352 Duration::from_millis(800),
3353 0,
3354 )),
3355 Ok(run_finished(ts(1004), ts(1000), Duration::from_secs(4))),
3356 ];
3357
3358 let result = convert_to_chrome_trace(
3359 &test_version(),
3360 events,
3361 ChromeTraceGroupBy::Slot,
3362 ChromeTraceMessageFormat::JsonPretty,
3363 );
3364 let json_bytes = result.expect("conversion succeeded");
3365 let json_str = String::from_utf8(json_bytes).expect("valid UTF-8");
3366
3367 insta::assert_snapshot!("slot_mode_chrome_trace", json_str);
3368 }
3369}