|
| 1 | +//! Human-readable trace renderer. |
| 2 | +
|
| 3 | +use std::collections::HashMap; |
| 4 | + |
| 5 | +use crate::runtime::execution::trace::{ArgKind, EdgeKind, ExecFrame, Outcome, TraceRun}; |
| 6 | + |
| 7 | +fn frame_micros(frame: &ExecFrame) -> Option<u128> { |
| 8 | + frame |
| 9 | + .end |
| 10 | + .map(|end| end.duration_since(frame.start).as_micros()) |
| 11 | +} |
| 12 | + |
| 13 | +/// Render a trace as plain-text tree output. |
| 14 | +pub fn render_trace(run: &TraceRun) -> String { |
| 15 | + let mut by_id: HashMap<u64, &ExecFrame> = HashMap::new(); |
| 16 | + for frame in &run.frames { |
| 17 | + by_id.insert(frame.frame_id, frame); |
| 18 | + } |
| 19 | + |
| 20 | + let mut output = String::new(); |
| 21 | + if let Some(total_us) = total_duration_us(&run.frames) { |
| 22 | + output.push_str(&format!("Total: {}us\n", total_us)); |
| 23 | + } |
| 24 | + render_frame(run.root, &by_id, "", true, &mut output); |
| 25 | + if let Some(total_us) = total_duration_us(&run.frames) { |
| 26 | + output.push_str(&format!("Summary: total_time={}us\n", total_us)); |
| 27 | + } |
| 28 | + output |
| 29 | +} |
| 30 | + |
| 31 | +fn render_frame( |
| 32 | + id: u64, |
| 33 | + by_id: &HashMap<u64, &ExecFrame>, |
| 34 | + prefix: &str, |
| 35 | + is_last: bool, |
| 36 | + output: &mut String, |
| 37 | +) { |
| 38 | + let frame = by_id[&id]; |
| 39 | + |
| 40 | + let branch = if prefix.is_empty() { |
| 41 | + "" |
| 42 | + } else if is_last { |
| 43 | + "\\- " |
| 44 | + } else { |
| 45 | + "+- " |
| 46 | + }; |
| 47 | + |
| 48 | + let duration = frame_micros(frame) |
| 49 | + .map(|us| format!(" ({}us)", us)) |
| 50 | + .unwrap_or_default(); |
| 51 | + |
| 52 | + output.push_str(&format!( |
| 53 | + "{prefix}{branch}#{frame_id} node={node_id} fn={function}{duration}\n", |
| 54 | + prefix = prefix, |
| 55 | + branch = branch, |
| 56 | + frame_id = frame.frame_id, |
| 57 | + node_id = frame.node_id, |
| 58 | + function = frame.function_name, |
| 59 | + duration = duration |
| 60 | + )); |
| 61 | + |
| 62 | + for arg in &frame.args { |
| 63 | + let continuation = if prefix.is_empty() || is_last { |
| 64 | + " " |
| 65 | + } else { |
| 66 | + "| " |
| 67 | + }; |
| 68 | + |
| 69 | + let kind = match &arg.kind { |
| 70 | + ArgKind::Literal => "lit".to_string(), |
| 71 | + ArgKind::Reference { reference, hit } => { |
| 72 | + let suffix = if *hit { "hit" } else { "miss" }; |
| 73 | + format!("ref({:?}, {})", reference, suffix) |
| 74 | + } |
| 75 | + ArgKind::Thunk { |
| 76 | + node_id, |
| 77 | + eager, |
| 78 | + executed, |
| 79 | + } => { |
| 80 | + let mode = if *eager { "eager" } else { "lazy" }; |
| 81 | + let exec = if *executed { "executed" } else { "deferred" }; |
| 82 | + format!("thunk(node={}, {}, {})", node_id, mode, exec) |
| 83 | + } |
| 84 | + }; |
| 85 | + |
| 86 | + output.push_str(&format!( |
| 87 | + "{prefix}{continuation} arg[{index}] {kind:<24} {preview}\n", |
| 88 | + prefix = prefix, |
| 89 | + continuation = continuation, |
| 90 | + index = arg.index, |
| 91 | + kind = kind, |
| 92 | + preview = arg.preview |
| 93 | + )); |
| 94 | + } |
| 95 | + |
| 96 | + let outcome = match &frame.outcome { |
| 97 | + Some(Outcome::Success { value_preview }) => format!("[SUCCESS] {}", value_preview), |
| 98 | + Some(Outcome::Failure { error_preview }) => format!("[FAILURE] {}", error_preview), |
| 99 | + Some(Outcome::Return { value_preview }) => format!("[RETURN] {}", value_preview), |
| 100 | + Some(Outcome::Respond { value_preview }) => format!("[RESPOND] {}", value_preview), |
| 101 | + Some(Outcome::Stop) => "[STOP]".to_string(), |
| 102 | + None => "...".to_string(), |
| 103 | + }; |
| 104 | + |
| 105 | + let continuation = if prefix.is_empty() || is_last { |
| 106 | + " " |
| 107 | + } else { |
| 108 | + "| " |
| 109 | + }; |
| 110 | + output.push_str(&format!( |
| 111 | + "{prefix}{continuation} => {outcome}\n", |
| 112 | + prefix = prefix, |
| 113 | + continuation = continuation, |
| 114 | + outcome = outcome |
| 115 | + )); |
| 116 | + |
| 117 | + if frame.children.is_empty() { |
| 118 | + return; |
| 119 | + } |
| 120 | + |
| 121 | + let mut runtime_idx = 0usize; |
| 122 | + for (idx, (edge, child_id)) in frame.children.iter().enumerate() { |
| 123 | + let edge_last = idx + 1 == frame.children.len(); |
| 124 | + let edge_branch = if edge_last { "\\- " } else { "+- " }; |
| 125 | + |
| 126 | + let edge_text = match edge { |
| 127 | + EdgeKind::Next => "NEXT".to_string(), |
| 128 | + EdgeKind::EagerCall { arg_index } => format!("eager(arg#{})", arg_index), |
| 129 | + EdgeKind::RuntimeCall { label } => { |
| 130 | + runtime_idx += 1; |
| 131 | + match label { |
| 132 | + Some(label_text) => format!("runtime(call #{}) {}", runtime_idx, label_text), |
| 133 | + None => format!("runtime(call #{})", runtime_idx), |
| 134 | + } |
| 135 | + } |
| 136 | + }; |
| 137 | + |
| 138 | + output.push_str(&format!( |
| 139 | + "{prefix}{edge_branch}{edge_text}\n", |
| 140 | + prefix = prefix, |
| 141 | + edge_branch = edge_branch, |
| 142 | + edge_text = edge_text |
| 143 | + )); |
| 144 | + |
| 145 | + let child_prefix = format!("{}{}", prefix, if edge_last { " " } else { "| " }); |
| 146 | + render_frame(*child_id, by_id, &child_prefix, true, output); |
| 147 | + } |
| 148 | +} |
| 149 | + |
| 150 | +fn total_duration_us(frames: &[ExecFrame]) -> Option<u128> { |
| 151 | + let mut start = None; |
| 152 | + let mut end = None; |
| 153 | + |
| 154 | + for frame in frames { |
| 155 | + start = Some(match start { |
| 156 | + Some(current) if frame.start > current => current, |
| 157 | + Some(_) | None => frame.start, |
| 158 | + }); |
| 159 | + |
| 160 | + if let Some(frame_end) = frame.end { |
| 161 | + end = Some(match end { |
| 162 | + Some(current) if frame_end < current => current, |
| 163 | + Some(_) | None => frame_end, |
| 164 | + }); |
| 165 | + } |
| 166 | + } |
| 167 | + |
| 168 | + match (start, end) { |
| 169 | + (Some(start_time), Some(end_time)) => Some(end_time.duration_since(start_time).as_micros()), |
| 170 | + _ => None, |
| 171 | + } |
| 172 | +} |
0 commit comments