// Use sftrace, which is based on LLVM Xray instrumentation, to trace all Rust function calls. This can be used for performance analysis and troubleshooting.
| name | sftrace |
| description | Use sftrace, which is based on LLVM Xray instrumentation, to trace all Rust function calls. This can be used for performance analysis and troubleshooting. |
Use sftrace (LLVM XRay) to trace rspack-resolver's Rust function calls and convert them to perfetto protobuf format for performance analysis and troubleshooting.
Default workflow: run from the project root and store all trace artifacts in a sftrace-<timestamp> directory.
git clone https://github.com/quininer/sftrace
cd sftrace
cargo build --release
mkdir "$(./target/release/sftrace record --print-solib-install-dir)"
cp ./target/release/libsftrace.so "$(./target/release/sftrace record --print-solib-install-dir)/"
XRay instrumentation must be enabled via RUSTFLAGS. There are two targets: the Node.js binding and the Rust benchmark binary.
RUSTFLAGS="-Zinstrument-xray=always" pnpm build:binding:profiling
The .node binding file will be output to the project root (e.g. resolver.darwin-arm64.node).
RUSTFLAGS="-Zinstrument-xray=always" cargo +nightly bench --profile profiling --no-run
The benchmark binary will be output under target/profiling/deps/. Find it with:
BENCH_BIN="$(ls -t target/profiling/deps/resolver-* | grep -v '\.d$' | head -1)"
sftrace filter works on function symbols from an object file (.node binding or benchmark binary).
# For Node.js binding
TARGET="$(ls resolver.*.node | head -1)"
# For benchmark binary
TARGET="$(ls -t target/profiling/deps/resolver-* | grep -v '\.d$' | head -1)"
# Regex mode
sftrace filter -p "$TARGET" -r 'resolve|normalize|cache' -o sftrace.filter
# List mode (one regex per line)
# sftrace filter -p "$TARGET" --list symbols.list -o sftrace.filter
TRACE_DIR="sftrace-$(date +%Y%m%d-%H%M%S)"
mkdir -p "$TRACE_DIR"
sftrace record -o "$TRACE_DIR/sf.log" -- pnpm test
BENCH_BIN="$(ls -t target/profiling/deps/resolver-* | grep -v '\.d$' | head -1)"
# Full trace
sftrace record -o "$TRACE_DIR/sf.log" -- "$BENCH_BIN" --bench
# Filtered trace (requires sftrace.filter from step 3)
sftrace record -f sftrace.filter -o "$TRACE_DIR/sf.filtered.log" -- "$BENCH_BIN" --bench
--bench tells criterion to run in benchmark mode. You can append -- <filter> to run only specific benchmarks (e.g. -- "resolve_node_modules").
Convert sftrace log to polars dataframe.
TRACE_DIR="sftrace-YYYYMMDD-HHMMSS" # replace with your run directory
sftrace convert --type pola "$TRACE_DIR/sf.log" -o "$TRACE_DIR/sf.pola"
This will generate two files, whose schema format is as follows:
This records all events from sftrace log.
| name | type | description |
|---|---|---|
| frame_id | uint64 | a unique id for each frame. a function's entry and exit have same frame id |
| parent | uint64 | point to previous frame id. zero means non-existent |
| tid | uint32 | thread id |
| func_id | uint64 | function unique id |
| time | nanoseconds | time elapsed since program started |
| kind | uint32 | event type, 1 is entry, 2 is exit, 3 is tail call |
This records the function symbol name and file path of func_id.
| name | type | description |
|---|---|---|
| func_id | uint64 | function unique id |
| name | string | function symbol name (demangled) |
| path | string | the file path and line number of function |
You can use python-polars to perform data analysis on sf.pola.
import polars as pl
sf = pl.scan_parquet("./sf.pola")
symtab = pl.scan_parquet("./sf.pola.symtab")
# Query the functions that appear most frequently
(
sf
.filter(pl.col("kind").eq(1))
.group_by("func_id")
.agg(pl.len().alias("func_count"))
.top_k(10, by="func_count")
.join(symtab, on="func_id")
.collect()
)
# Query the leaf frame of longest execution time
(
sf
.filter(~pl.col("frame_id").is_in(pl.col("parent").implode()))
.group_by("frame_id")
.agg([
pl.col("func_id").first(),
pl.col("time").filter(pl.col("kind").eq(1)).first().alias("entry_time"),
pl.col("time").filter(pl.col("kind").is_in([2, 3])).last().alias("exit_time"),
])
.filter(pl.col("exit_time").is_not_null())
.with_columns(pl.col("exit_time").sub("entry_time").alias("duration"))
.top_k(10, by="duration")
.join(symtab, on="func_id")
.collect()
)
Convert sftrace log to perfetto protobuf format.
TRACE_DIR="sftrace-YYYYMMDD-HHMMSS" # replace with your run directory
sftrace convert "$TRACE_DIR/sf.log" -o "$TRACE_DIR/sf.pb.gz"
Visualization using viztracer
vizviewer --use_external_processor "$TRACE_DIR/sf.pb.gz"
Use this only for visualization.
sftrace filter matches function symbols by regex/list. It is not a first-class crate-path/module-path filter.