cu_profiler_core/parser/
mod.rs

1//! Solana log parsing: lexer, compute-budget heuristics, CPI tree, and scope
2//! markers, plus a [`analyze`] facade that turns raw logs into a structured
3//! [`ParseAnalysis`] the profiler can consume.
4
5pub mod compute_budget;
6pub mod cpi_tree;
7pub mod scope_markers;
8pub mod solana_logs;
9
10pub use cpi_tree::{CallNode, NodeStatus};
11pub use scope_markers::{AttributionMethod, MarkerKind, ScopeResult};
12pub use solana_logs::{LexResult, LogEvent};
13
14use crate::program_registry::ProgramRegistry;
15
16/// Structured result of analysing a single transaction's logs.
17#[derive(Debug, Clone)]
18pub struct ParseAnalysis {
19    /// Reconstructed call tree (root included).
20    pub call_tree: CallNode,
21    /// Total CU consumed across top-level (depth-1) invocations.
22    pub total_cu: u64,
23    /// Number of CPIs (depth >= 2).
24    pub cpi_count: u32,
25    /// CPI nesting depth (max depth beyond the entrypoint).
26    pub cpi_depth: u32,
27    /// Estimated requested compute limit, if derivable.
28    pub requested_limit: Option<u64>,
29    /// Requested but unused CU, if derivable.
30    pub over_requested: Option<u64>,
31    /// Percentage of total CU not attributed to a CPI child (0..=100).
32    pub unattributed_pct: f64,
33    /// Scope attribution results.
34    pub scopes: Vec<ScopeResult>,
35    /// Number of scope markers detected.
36    pub scope_marker_count: usize,
37    /// Whether the transaction simulated without a `failed` line.
38    pub simulation_success: bool,
39    /// Number of `Program log:` / `Program data:` lines emitted (log volume).
40    pub log_line_count: usize,
41    /// Whether a validation scope began *after* a CPI was issued — a hint that
42    /// cheap checks run too late. Only set when scope markers are present.
43    pub validation_after_cpi: bool,
44    /// Parser warnings collected along the way.
45    pub warnings: Vec<String>,
46    /// Whether the logs parsed cleanly (no warnings).
47    pub logs_complete: bool,
48}
49
50/// Analyse a log stream into a [`ParseAnalysis`].
51#[must_use]
52pub fn analyze(logs: &[String], registry: &ProgramRegistry) -> ParseAnalysis {
53    let lexed = solana_logs::lex(logs);
54    let events: Vec<LogEvent> = lexed.events().cloned().collect();
55    let mut warnings = lexed.warnings.clone();
56
57    let call_tree = cpi_tree::build(&events, registry);
58    let total_cu = sum_units_at(&call_tree, 1);
59    let cpi_attributed = sum_units_below(&call_tree, 2);
60    let cpi_count = call_tree.cpi_count();
61    let cpi_depth = call_tree.max_depth().saturating_sub(1);
62
63    let requested_limit = compute_budget::estimated_requested_limit(&events);
64    let over_requested = requested_limit.and_then(|lim| lim.checked_sub(total_cu));
65
66    let unattributed = total_cu.saturating_sub(cpi_attributed);
67    let unattributed_pct = if total_cu == 0 {
68        0.0
69    } else {
70        (unattributed as f64 / total_cu as f64) * 100.0
71    };
72
73    let (scopes, scope_marker_count, scope_warnings) = collect_scopes(&events, total_cu);
74    warnings.extend(scope_warnings);
75
76    let simulation_success = !events.iter().any(|e| matches!(e, LogEvent::Failed { .. }));
77
78    let log_line_count = events
79        .iter()
80        .filter(|e| matches!(e, LogEvent::Log { .. }))
81        .count();
82    let validation_after_cpi = detect_validation_after_cpi(&events);
83
84    let logs_complete = warnings.is_empty();
85
86    ParseAnalysis {
87        call_tree,
88        total_cu,
89        cpi_count,
90        cpi_depth,
91        requested_limit,
92        over_requested,
93        unattributed_pct,
94        scopes,
95        scope_marker_count,
96        simulation_success,
97        log_line_count,
98        validation_after_cpi,
99        warnings,
100        logs_complete,
101    }
102}
103
104/// True if a scope whose name mentions validation opens after the first CPI
105/// invoke (depth >= 2). Evidence-based and marker-gated: with no scope markers
106/// it can never fire, so it makes no unsupported claim.
107fn detect_validation_after_cpi(events: &[LogEvent]) -> bool {
108    let mut cpi_seen = false;
109    for e in events {
110        match e {
111            LogEvent::Invoke { depth, .. } if *depth >= 2 => cpi_seen = true,
112            LogEvent::ScopeBegin { name, .. } if cpi_seen => {
113                let lower = name.to_ascii_lowercase();
114                if lower.contains("valid") || lower.contains("check") {
115                    return true;
116                }
117            }
118            _ => {}
119        }
120    }
121    false
122}
123
124fn sum_units_at(node: &CallNode, depth: u32) -> u64 {
125    let here = if node.depth == depth {
126        node.units_consumed.unwrap_or(0)
127    } else {
128        0
129    };
130    here + node
131        .children
132        .iter()
133        .map(|c| sum_units_at(c, depth))
134        .sum::<u64>()
135}
136
137fn sum_units_below(node: &CallNode, min_depth: u32) -> u64 {
138    let here = if node.depth >= min_depth {
139        node.units_consumed.unwrap_or(0)
140    } else {
141        0
142    };
143    here + node
144        .children
145        .iter()
146        .map(|c| sum_units_below(c, min_depth))
147        .sum::<u64>()
148}
149
150fn collect_scopes(events: &[LogEvent], total_cu: u64) -> (Vec<ScopeResult>, usize, Vec<String>) {
151    use scope_markers::{AttributionMethod, Marker, MarkerKind};
152
153    let mut markers: Vec<Marker> = Vec::new();
154    for e in events {
155        match e {
156            LogEvent::ScopeBegin { name, cu } => markers.push(Marker {
157                kind: MarkerKind::Begin,
158                name: name.clone(),
159                cu: *cu,
160            }),
161            LogEvent::ScopeEnd { name, cu } => markers.push(Marker {
162                kind: MarkerKind::End,
163                name: name.clone(),
164                cu: *cu,
165            }),
166            LogEvent::ScopePoint { name, cu } => markers.push(Marker {
167                kind: MarkerKind::Point,
168                name: name.clone(),
169                cu: *cu,
170            }),
171            _ => {}
172        }
173    }
174    let mut warnings = scope_markers::balance_warnings(&markers);
175
176    // One ScopeResult per BEGIN, with parent inferred from nesting. When a BEGIN
177    // and its matching END both carry a `cu=` snapshot, the scope's CU is the
178    // (inclusive) delta — a reliable `LogDelta` estimate; otherwise it stays an
179    // unquantified `Estimated` scope (no fake precision).
180    let mut stack: Vec<(usize, Option<u64>)> = Vec::new();
181    let mut scopes: Vec<ScopeResult> = Vec::new();
182    for m in &markers {
183        match m.kind {
184            MarkerKind::Begin => {
185                let parent = stack.last().map(|&(i, _)| scopes[i].name.clone());
186                stack.push((scopes.len(), m.cu));
187                scopes.push(ScopeResult {
188                    name: m.name.clone(),
189                    parent,
190                    units_estimated: None,
191                    percentage_of_total: None,
192                    attribution_method: AttributionMethod::Estimated,
193                    warnings: Vec::new(),
194                });
195            }
196            MarkerKind::End => {
197                let matches_top = stack.last().is_some_and(|&(i, _)| scopes[i].name == m.name);
198                if matches_top {
199                    if let Some((idx, begin_cu)) = stack.pop() {
200                        if let (Some(begin), Some(end)) = (begin_cu, m.cu) {
201                            let units = begin.saturating_sub(end);
202                            scopes[idx].units_estimated = Some(units);
203                            scopes[idx].attribution_method = AttributionMethod::LogDelta;
204                            // A snapshot delta larger than the measured program
205                            // total is contradictory (only possible with broken
206                            // logs): withhold the percentage rather than emit a
207                            // nonsensical >100%, and flag the inconsistency.
208                            if total_cu > 0 && units <= total_cu {
209                                scopes[idx].percentage_of_total =
210                                    Some((units as f64 / total_cu as f64) * 100.0);
211                            } else if units > total_cu {
212                                let warning = format!(
213                                    "scope `{}` CU delta ({units}) exceeds the measured total ({total_cu}); percentage withheld",
214                                    scopes[idx].name
215                                );
216                                scopes[idx].warnings.push(warning.clone());
217                                warnings.push(warning);
218                            }
219                        }
220                    }
221                }
222            }
223            MarkerKind::Point => {}
224        }
225    }
226
227    (scopes, markers.len(), warnings)
228}
229
230#[cfg(test)]
231mod tests {
232    use super::*;
233
234    fn lines(raw: &[&str]) -> Vec<String> {
235        raw.iter().map(|s| (*s).to_string()).collect()
236    }
237
238    #[test]
239    fn computes_totals_and_unattributed() {
240        let logs = lines(&[
241            "Program User111 invoke [1]",
242            "Program TokenkegQfeZyiNwAJbNbGKPFXCWuBvf9Ss623VQ5DA invoke [2]",
243            "Program TokenkegQfeZyiNwAJbNbGKPFXCWuBvf9Ss623VQ5DA consumed 3000 of 197000 compute units",
244            "Program TokenkegQfeZyiNwAJbNbGKPFXCWuBvf9Ss623VQ5DA success",
245            "Program User111 consumed 12000 of 200000 compute units",
246            "Program User111 success",
247        ]);
248        let a = analyze(&logs, &ProgramRegistry::with_builtins());
249        assert_eq!(a.total_cu, 12_000);
250        assert_eq!(a.cpi_count, 1);
251        assert_eq!(a.cpi_depth, 1);
252        assert_eq!(a.requested_limit, Some(200_000));
253        assert_eq!(a.over_requested, Some(188_000));
254        // 12000 total - 3000 in CPI = 9000 unattributed = 75%.
255        assert!((a.unattributed_pct - 75.0).abs() < 0.01);
256        assert!(a.simulation_success);
257    }
258
259    #[test]
260    fn scopes_inferred_with_nesting() {
261        let logs = lines(&[
262            "Program User111 invoke [1]",
263            "Program log: CU_PROFILER_BEGIN name=outer",
264            "Program log: CU_PROFILER_BEGIN name=inner",
265            "Program log: CU_PROFILER_END name=inner",
266            "Program log: CU_PROFILER_END name=outer",
267            "Program User111 consumed 5000 of 200000 compute units",
268            "Program User111 success",
269        ]);
270        let a = analyze(&logs, &ProgramRegistry::with_builtins());
271        assert_eq!(a.scope_marker_count, 4);
272        assert_eq!(a.scopes.len(), 2);
273        assert_eq!(a.scopes[1].parent.as_deref(), Some("outer"));
274        assert!(a.warnings.is_empty());
275    }
276
277    #[test]
278    fn estimates_scope_cu_from_compute_snapshots() {
279        let logs = lines(&[
280            "Program User111 invoke [1]",
281            "Program log: CU_PROFILER_BEGIN name=swap::validate cu=200000",
282            "Program log: CU_PROFILER_END name=swap::validate cu=188000",
283            "Program User111 consumed 24000 of 200000 compute units",
284            "Program User111 success",
285        ]);
286        let a = analyze(&logs, &ProgramRegistry::with_builtins());
287        let scope = &a.scopes[0];
288        assert_eq!(scope.name, "swap::validate");
289        // 200000 remaining at begin − 188000 at end = 12000 CU in the scope.
290        assert_eq!(scope.units_estimated, Some(12_000));
291        assert_eq!(scope.attribution_method, AttributionMethod::LogDelta);
292        // 12000 / 24000 total = 50%.
293        assert!((scope.percentage_of_total.unwrap() - 50.0).abs() < 0.01);
294    }
295
296    #[test]
297    fn contradictory_snapshot_withholds_percentage_and_warns() {
298        // Snapshot delta (12000) exceeds the program's measured total (5000):
299        // inconsistent logs. The percentage must be withheld, not >100%.
300        let logs = lines(&[
301            "Program User111 invoke [1]",
302            "Program log: CU_PROFILER_BEGIN name=swap::math cu=200000",
303            "Program log: CU_PROFILER_END name=swap::math cu=188000",
304            "Program User111 consumed 5000 of 200000 compute units",
305            "Program User111 success",
306        ]);
307        let a = analyze(&logs, &ProgramRegistry::with_builtins());
308        assert_eq!(a.scopes[0].units_estimated, Some(12_000));
309        assert_eq!(a.scopes[0].percentage_of_total, None);
310        assert!(
311            a.warnings
312                .iter()
313                .any(|w| w.contains("exceeds the measured total"))
314        );
315    }
316
317    #[test]
318    fn scope_without_snapshots_stays_unquantified() {
319        let logs = lines(&[
320            "Program User111 invoke [1]",
321            "Program log: CU_PROFILER_BEGIN name=swap::validate",
322            "Program log: CU_PROFILER_END name=swap::validate",
323            "Program User111 consumed 24000 of 200000 compute units",
324            "Program User111 success",
325        ]);
326        let a = analyze(&logs, &ProgramRegistry::with_builtins());
327        assert_eq!(a.scopes[0].units_estimated, None);
328        assert_eq!(a.scopes[0].attribution_method, AttributionMethod::Estimated);
329    }
330
331    #[test]
332    fn detects_log_volume_and_late_validation() {
333        let logs = lines(&[
334            "Program User111 invoke [1]",
335            "Program TokenkegQfeZyiNwAJbNbGKPFXCWuBvf9Ss623VQ5DA invoke [2]",
336            "Program TokenkegQfeZyiNwAJbNbGKPFXCWuBvf9Ss623VQ5DA success",
337            // Validation marker opens *after* the CPI above.
338            "Program log: CU_PROFILER_BEGIN name=swap::validate_accounts",
339            "Program log: CU_PROFILER_END name=swap::validate_accounts",
340            "Program log: emitting event one",
341            "Program log: emitting event two",
342            "Program User111 consumed 9000 of 200000 compute units",
343            "Program User111 success",
344        ]);
345        let a = analyze(&logs, &ProgramRegistry::with_builtins());
346        assert!(a.validation_after_cpi);
347        assert_eq!(a.log_line_count, 2); // the two non-marker `Program log:` lines
348    }
349
350    #[test]
351    fn validation_before_cpi_is_not_flagged() {
352        let logs = lines(&[
353            "Program User111 invoke [1]",
354            "Program log: CU_PROFILER_BEGIN name=swap::validate_accounts",
355            "Program log: CU_PROFILER_END name=swap::validate_accounts",
356            "Program TokenkegQfeZyiNwAJbNbGKPFXCWuBvf9Ss623VQ5DA invoke [2]",
357            "Program TokenkegQfeZyiNwAJbNbGKPFXCWuBvf9Ss623VQ5DA success",
358            "Program User111 consumed 9000 of 200000 compute units",
359            "Program User111 success",
360        ]);
361        let a = analyze(&logs, &ProgramRegistry::with_builtins());
362        assert!(!a.validation_after_cpi);
363    }
364
365    #[test]
366    fn failure_path_flips_simulation_success() {
367        let logs = lines(&[
368            "Program User111 invoke [1]",
369            "Program User111 consumed 8000 of 200000 compute units",
370            "Program User111 failed: custom program error: 0x1",
371        ]);
372        let a = analyze(&logs, &ProgramRegistry::with_builtins());
373        assert!(!a.simulation_success);
374        assert_eq!(a.total_cu, 8000);
375    }
376}
cu_profiler_core/parser/mod.rs

cu_profiler_core/parser/
mod.rs
