-
Notifications
You must be signed in to change notification settings - Fork 9
docs: add sftrace skill for XRay performance tracing #179
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Changes from all commits
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change | ||||||||
|---|---|---|---|---|---|---|---|---|---|---|
| @@ -0,0 +1,188 @@ | ||||||||||
| --- | ||||||||||
| 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. | ||||||||||
| --- | ||||||||||
|
|
||||||||||
| # Rspack Resolver Sftrace | ||||||||||
|
|
||||||||||
| ## Overview | ||||||||||
|
|
||||||||||
| 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. | ||||||||||
|
|
||||||||||
| ## Workflow | ||||||||||
|
|
||||||||||
| ### 1) Build sftrace tools | ||||||||||
|
|
||||||||||
| ```sh | ||||||||||
| 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)/" | ||||||||||
|
stormslowly marked this conversation as resolved.
|
||||||||||
| ``` | ||||||||||
|
Comment on lines
+19
to
+24
|
||||||||||
|
|
||||||||||
| ### 2) Build with XRay instrumentation | ||||||||||
|
|
||||||||||
| XRay instrumentation must be enabled via RUSTFLAGS. There are two targets: the Node.js binding and the Rust benchmark binary. | ||||||||||
|
|
||||||||||
| #### 2a) Node.js binding | ||||||||||
|
|
||||||||||
| ```sh | ||||||||||
| 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`). | ||||||||||
|
stormslowly marked this conversation as resolved.
|
||||||||||
|
|
||||||||||
| #### 2b) Benchmark binary | ||||||||||
|
|
||||||||||
| ```sh | ||||||||||
| RUSTFLAGS="-Zinstrument-xray=always" cargo +nightly bench --profile profiling --no-run | ||||||||||
| ``` | ||||||||||
|
Comment on lines
+28
to
+42
|
||||||||||
|
|
||||||||||
| The benchmark binary will be output under `target/profiling/deps/`. Find it with: | ||||||||||
|
|
||||||||||
| ```sh | ||||||||||
| BENCH_BIN="$(ls -t target/profiling/deps/resolver-* | grep -v '\.d$' | head -1)" | ||||||||||
| ``` | ||||||||||
|
Comment on lines
+47
to
+48
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. The command to define
Suggested change
|
||||||||||
|
|
||||||||||
| ### 3) Optional: Generate a filter file from symbols | ||||||||||
|
|
||||||||||
| `sftrace filter` works on function symbols from an object file (`.node` binding or benchmark binary). | ||||||||||
|
|
||||||||||
| ```sh | ||||||||||
| # For Node.js binding | ||||||||||
| TARGET="$(ls resolver.*.node | head -1)" | ||||||||||
|
stormslowly marked this conversation as resolved.
|
||||||||||
|
|
||||||||||
| # 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 | ||||||||||
| ``` | ||||||||||
|
|
||||||||||
| ### 4) Record sftrace | ||||||||||
|
|
||||||||||
| ```sh | ||||||||||
| TRACE_DIR="sftrace-$(date +%Y%m%d-%H%M%S)" | ||||||||||
| mkdir -p "$TRACE_DIR" | ||||||||||
| ``` | ||||||||||
|
|
||||||||||
| #### 4a) Trace Node.js binding (e.g. run tests) | ||||||||||
|
|
||||||||||
| ```sh | ||||||||||
| sftrace record -o "$TRACE_DIR/sf.log" -- pnpm test | ||||||||||
| ``` | ||||||||||
|
|
||||||||||
| #### 4b) Trace benchmark binary | ||||||||||
|
|
||||||||||
| ```sh | ||||||||||
| 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 | ||||||||||
|
Comment on lines
+86
to
+87
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more.
These commands execute the compiled benchmark binary directly, but this repo’s bench target is Useful? React with 👍 / 👎.
stormslowly marked this conversation as resolved.
|
||||||||||
|
|
||||||||||
| # 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"`). | ||||||||||
|
|
||||||||||
| ### 5) Optional: Analyze sf.log by [polars](https://docs.pola.rs/) | ||||||||||
|
|
||||||||||
| Convert sftrace log to polars dataframe. | ||||||||||
|
|
||||||||||
| ```sh | ||||||||||
| TRACE_DIR="sftrace-YYYYMMDD-HHMMSS" # replace with your run directory | ||||||||||
|
stormslowly marked this conversation as resolved.
|
||||||||||
| sftrace convert --type pola "$TRACE_DIR/sf.log" -o "$TRACE_DIR/sf.pola" | ||||||||||
| ``` | ||||||||||
|
|
||||||||||
| This will generate two files, whose schema format is as follows: | ||||||||||
|
|
||||||||||
| 1. sf.pola | ||||||||||
|
|
||||||||||
| 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 | | ||||||||||
|
Comment on lines
+110
to
+114
|
||||||||||
| | 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 | | ||||||||||
|
|
||||||||||
| 2. sf.pola.symtab | ||||||||||
|
|
||||||||||
| 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 | | ||||||||||
|
stormslowly marked this conversation as resolved.
|
||||||||||
|
|
||||||||||
| You can use `python-polars` to perform data analysis on `sf.pola`. | ||||||||||
|
|
||||||||||
| ```python | ||||||||||
| 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() | ||||||||||
| ) | ||||||||||
| ``` | ||||||||||
|
|
||||||||||
| ### 6) Optional: Visualization sf.log | ||||||||||
|
|
||||||||||
| Convert sftrace log to perfetto protobuf format. | ||||||||||
|
|
||||||||||
| ```sh | ||||||||||
| 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](https://github.com/gaogaotiantian/viztracer) | ||||||||||
|
|
||||||||||
| ```sh | ||||||||||
| vizviewer --use_external_processor "$TRACE_DIR/sf.pb.gz" | ||||||||||
| ``` | ||||||||||
|
|
||||||||||
| Use this only for visualization. | ||||||||||
|
|
||||||||||
| ## Filtering Notes | ||||||||||
|
|
||||||||||
| - `sftrace filter` matches function symbols by regex/list. It is not a first-class crate-path/module-path filter. | ||||||||||
| - Filtering does not automatically keep all descendants. If a child function symbol does not match your filter, it may disappear from the trace. | ||||||||||
| - Cross-thread relationships (for example via rayon) are not reconstructed as a single uninterrupted call chain. | ||||||||||
| - For complete call stacks, record without filter (or with a broad filter) and narrow down during analysis. | ||||||||||
Uh oh!
There was an error while loading. Please reload this page.