|
| 1 | +# Tracing and profiling |
| 2 | + |
| 3 | +This page is a practical guide for Sapling developers who need to understand why a command is slow, where a call came from, or which tracing target to turn on next. |
| 4 | + |
| 5 | +## Tracing |
| 6 | + |
| 7 | +Sapling uses Rust's [`tracing`](https://crates.io/crates/tracing) ecosystem for native tracing. Python code is not uniformly converted to `tracing`, but some Python execution paths interact with the same tracing and profiling plumbing. |
| 8 | + |
| 9 | +### Rust tracing |
| 10 | + |
| 11 | +Set `SL_LOG` to enable human-readable tracing output: |
| 12 | + |
| 13 | +```sl-shell-example |
| 14 | +$ SL_LOG=debug sl status |
| 15 | +$ SL_LOG=commands::run=trace sl log -r . |
| 16 | +$ SL_LOG=info,dag=debug,commands::run=trace sl log -r . |
| 17 | +``` |
| 18 | + |
| 19 | +`SL_LOG` uses [`tracing_subscriber::filter::EnvFilter`](https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/struct.EnvFilter.html#example-syntax) syntax. The useful subset is: |
| 20 | + |
| 21 | +- `debug`: enable a level globally. |
| 22 | +- `commands::run=trace`: enable a level for a specific target. |
| 23 | +- `info,dag=debug`: combine directives with commas. |
| 24 | + |
| 25 | +Tracing targets usually look like Rust module paths. The best way to find a target is often to start broad (`SL_LOG=debug`), identify the noisy or useful targets in the output, then narrow the filter. |
| 26 | + |
| 27 | +### Python debugging log |
| 28 | + |
| 29 | +For Python-heavy command paths, the most useful first step is usually Sapling's global debug output: |
| 30 | + |
| 31 | +```sl-shell-example |
| 32 | +$ sl --debug --verbose log -r . |
| 33 | +``` |
| 34 | + |
| 35 | +`--debug` and `--verbose` are command-line flags understood by Sapling's Python command layer and extensions. They are usually more useful than `SL_LOG` for Python-only behavior. `SL_LOG` can still affect mixed Python/native paths, for example when Python calls into Rust bindings or code that emits native tracing events. |
| 36 | + |
| 37 | +### Backtraces at tracing points |
| 38 | + |
| 39 | +`SL_BTLOG` prints a native backtrace when a matching tracing event or span enter/exit happens: |
| 40 | + |
| 41 | +```sl-shell-example |
| 42 | +$ SL_BTLOG=dag::lifecycle::create=debug sl log -r . |
| 43 | +``` |
| 44 | + |
| 45 | +`SL_BTLOG` uses the same `EnvFilter` syntax as `SL_LOG`, but the output is much larger: every matching event or span transition prints a backtrace. Use it for questions like "who constructed this object?" or "which caller reached this tracing point?", and keep the filter narrow. |
| 46 | + |
| 47 | +### Mixed Rust/Python backtraces |
| 48 | + |
| 49 | +On supported build combinations, Sapling can resolve Python frames inside native backtraces. This makes profiler output and tracing backtraces more useful for mixed Rust/Python command paths: instead of seeing only a Rust binding or CPython evaluation frame, the stack can include Python function names and sources such as `static:sapling.commands:3874`. |
| 50 | + |
| 51 | +Support depends on the OS, CPU architecture, and CPython version. In practice, this is expected to work on common OS/architecture combinations with Python 3.10 or 3.12. |
| 52 | + |
| 53 | +If Python frame resolution is not available in the current build, native frames still work, but Python-heavy sections may show up as less informative CPython or binding frames. |
| 54 | + |
| 55 | +## Profiling |
| 56 | + |
| 57 | +Tracing answers "what happened here?". Profiling answers "where did the time go?". Sapling has a native sampling profiler and several Python profilers. |
| 58 | + |
| 59 | +### Native sampling profiler |
| 60 | + |
| 61 | +Pass `--profile` to enable the native sampling profiler: |
| 62 | + |
| 63 | +```sl-shell-example |
| 64 | +$ sl log -r . --profile |
| 65 | +``` |
| 66 | + |
| 67 | +The profiler samples native stacks and, on supported builds, Python frames. It prints an ASCII summary to stderr unless `profiling.output` is configured. |
| 68 | + |
| 69 | +A shortened output looks like this: |
| 70 | + |
| 71 | +```text |
| 72 | +Profiling summary: |
| 73 | +Start Dur | Name Source |
| 74 | + 1 +21 | _start |
| 75 | + 1 +21 | main |
| 76 | + 1 +21 | commands::run::run_command |
| 77 | + 2 +20 \ run static:sapling:46 |
| 78 | + 4 +18 | dispatch static:sapling.dispatch:309 |
| 79 | + 19 +3 \ log static:sapling.commands:3874 |
| 80 | + 19 +2 | getlogrevs static:sapling.cmdutil:3202 |
| 81 | + 21 +1 \ show static:sapling.cmdutil:2043 |
| 82 | +Duration 1 unit = Sampling interval = 10ms. |
| 83 | +``` |
| 84 | + |
| 85 | +The defaults are good for a first pass. Useful knobs from `sl help config.profiling`: |
| 86 | + |
| 87 | +```sl-shell-example |
| 88 | +$ sl log -r . --profile --config profiling.interval=1ms |
| 89 | +$ sl log -r . --profile --config profiling.output=/tmp/sl-profile.txt |
| 90 | +``` |
| 91 | + |
| 92 | +Use a shorter interval for short commands or when the default 10ms interval does not collect enough samples. Sampling profilers are approximate; treat one sample as a clue, and repeated samples as evidence. |
| 93 | + |
| 94 | +### Python profilers |
| 95 | + |
| 96 | +Enable a Python-only profiler with: |
| 97 | + |
| 98 | +```sl-shell-example |
| 99 | +$ sl log -r . \ |
| 100 | + --config profiling.enabled-python=true \ |
| 101 | + --config profiling.type=stat |
| 102 | +``` |
| 103 | + |
| 104 | +Available Python profiler types: |
| 105 | + |
| 106 | +- `stat`: statistical profiler. Best for commands that run long enough to gather meaningful samples. It can show hot paths, methods, lines, or JSON depending on `profiling.statformat`. |
| 107 | +- `ls`: Python's built-in instrumenting profiler. Works broadly, but line reporting is tied to function start lines, which can make large functions hard to diagnose. |
| 108 | +- `traceprof`: tracing profiler. Tracks function calls and is especially useful for tree-shaped reports of small functions called many times. |
| 109 | + |
| 110 | +Examples: |
| 111 | + |
| 112 | +```sl-shell-example |
| 113 | +$ sl log -r . --config profiling.enabled-python=true --config profiling.type=ls |
| 114 | +$ sl log -r . --config profiling.enabled-python=true --config profiling.type=stat |
| 115 | +$ sl log -r . --config profiling.enabled-python=true --config profiling.type=traceprof |
| 116 | +``` |
| 117 | + |
| 118 | +Check `sl help config.profiling` for output formats, limits, and filtering options. |
| 119 | + |
| 120 | +### Reading profiler output |
| 121 | + |
| 122 | +Sapling's native profiler summarizes sampled stacks as an ASCII tree. The tree is optimized for hot paths, so it is intentionally not the same as a fully expanded tree. |
| 123 | + |
| 124 | +An ordinary tree might render every level with extra indentation: |
| 125 | + |
| 126 | +```text |
| 127 | +main |
| 128 | + run_command |
| 129 | + run |
| 130 | + dispatch |
| 131 | + log |
| 132 | + getlogrevs |
| 133 | + show |
| 134 | +``` |
| 135 | + |
| 136 | +The profiler output is more compact: |
| 137 | + |
| 138 | +```text |
| 139 | +Start Dur | Name |
| 140 | + 1 +21 | main |
| 141 | + 1 +21 | commands::run::run_command |
| 142 | + 2 +20 | run |
| 143 | + 4 +18 | dispatch |
| 144 | + 19 +3 | log |
| 145 | + 19 +2 \ getlogrevs |
| 146 | + 21 +1 \ show |
| 147 | +``` |
| 148 | + |
| 149 | +Read it as: |
| 150 | + |
| 151 | +- `Start` is the first observed time unit for that span in the rendered tree. |
| 152 | +- `Dur` is the span duration in sampling units, not necessarily milliseconds. The footer says how large one unit is. |
| 153 | +- `Name` is the function or frame name. `Source` usually shows a Rust symbol, Python source, or generated/static module source. |
| 154 | +- `|` continues a straight path through nodes with a single rendered child. This avoids excessive indentation when the profile is mostly one long hot path. |
| 155 | +- `\` starts each rendered child when a node has multiple rendered children. If one of those children then has a single rendered child, the tree switches back to `|` at the deeper indentation level. |
| 156 | + |
| 157 | +The important move is to follow large `Dur` values downward until the time stops concentrating in one child. That split is usually where the next investigation should start. |
0 commit comments