Benchmarks: surface profiler per-sample latency via custom XCTMetric#831
Conversation
The five sampling-scenario profiler benchmarks need a Thread.sleep inside the measure block to give the sampler real time to fire, so wall-clock time is dominated by the sleep rather than profiler overhead. Replace the wall-clock metric on those tests with a custom XCTMetric that carries profile.metrics.avgNs (per-sample capture latency in seconds), and teach parse_benchmarks.py to prefer kscrash.* custom metrics over wall clock and to honor per-test threshold overrides. Other tests in the suite are unaffected. Off-simulator runs assert at least one sample was captured per iteration so a sampler regression fails loud instead of rendering as Excellent.
There was a problem hiding this comment.
Pull request overview
This PR improves the accuracy and usefulness of the sampling-profiler benchmark suite by reporting profiler per-sample capture latency as a custom XCTest metric (instead of relying on wall-clock time dominated by Thread.sleep), and updates the CI parser/config to consume that metric with appropriate thresholds.
Changes:
- Add a closure-backed custom
XCTMetric(ProfilerSampleMetric) to emit per-iteration numeric values into xcresult. - Update five sampling-profiler benchmarks to record
profile.metrics.avgNs(converted to seconds) via the custom metric and assert non-empty sampling on device. - Update the benchmark parser to prefer
kscrash.*custom metrics over wall-clock time, and allow per-test threshold overrides inbenchmark-tests.json.
Reviewed changes
Copilot reviewed 4 out of 4 changed files in this pull request and generated 1 comment.
| File | Description |
|---|---|
| Tests/KSCrashBenchmarks/ProfilerSampleMetric.swift | Adds a custom XCTMetric implementation for emitting per-iteration profiler metrics into xcresult. |
| Tests/KSCrashBenchmarks/KSProfilerBenchmarks.swift | Switches five sampling benchmarks to measure per-sample latency via the new custom metric and adds a device-only “must capture at least one sample” check. |
| .github/scripts/parse_benchmarks.py | Prefers kscrash.* metrics over wall-clock and supports per-test threshold overrides. |
| .github/data/benchmark-tests.json | Adds per-test thresholds for the five sampling scenarios to reflect microsecond-scale per-sample latency. |
… gate Address Copilot review: dedupe the per-iteration metric setup and sample-count assertion across the five sampling-scenario tests by extracting a measurePerSampleLatency helper that takes a body returning ProfileMetrics?. Also tighten the assertion gate from !targetEnvironment(simulator) to (os(iOS) || os(tvOS)) && !targetEnvironment(simulator) && !targetEnvironment(macCatalyst). The previous gate let the assertion fire on the macOS host where swift test runs the benchmarks under sanitizers; the slowed-down dispatch source can't honor 5-10 ms intervals on a non-device, so 0-sample iterations are normal there. The assertion now runs only on real iOS/tvOS device, which is what we actually want to monitor.
PerSampleCaptureLatency and PerSampleCaptureLatencyDeepStack used to compute per-sample latency stats and dump them via print(), so they took up rows in benchmark-tests.json without ever populating any data in the PR comment table. Reuse the measurePerSampleLatency helper so they emit the same kscrash.profiler.persample_avg custom metric as the five sampling-scenario tests, and add per-test threshold overrides suited to per-sample microsecond scale (deeper stack gets a looser band because comprehensive unwind takes longer per sample).
KSCrash's SwiftPM platforms include watchOS 5, where XCTMetric and the XCTPerformanceMeasurement* APIs are unavailable. Wrap the file contents in the same guard already used by KSProfilerBenchmarks.swift so watchOS builds of the benchmarks target compile.
🔍 KSCrash Performance BenchmarksCrash capture performance metrics - lower times are better Host: Apple M1 (Virtual), 7GB RAM, macOS 15.7.4, Xcode 16.4 Target: iPhone 17 Pro (iPhone) | iOS 26.3 | Device 📖 How to interpret results
p-value (in comparison table): Probability the difference is due to chance. Values < 0.05 indicate statistically significant changes.
|
| Operation | Base | Base σ | PR | PR σ | Change | p-value |
|---|---|---|---|---|---|---|
| Swap installation (cold) | 2.02 ms | ±0.0% | 744.1 μs | ±0.0% | ✅ -63.1% | <0.0001 |
| Ops under contention | 1.11 ms | ±3.5% | 1.19 ms | ±4.8% | +7.8% | <0.0001 |
| Check readable (64B) | 1.13 ms | ±3.0% | 1.18 ms | ±3.5% | +5.1% | 0.0006 |
| Get queue name | 3.36 ms | ±3.4% | 3.27 ms | ±1.3% | -2.5% | 0.0332 |
| Find max readable | 503.2 μs | ±45.8% | 344.8 μs | ±10.8% | ✅ -31.5% | 0.0336 |
C++ Exception Handling (KSCxaThrowSwapper)
| Operation | Time | Std Dev | Status | Notes |
|---|---|---|---|---|
| Swap installation (warm) | 754.9 μs | ±87.4% | ✅ Good | Hook __cxa_throw across all dylibs |
| Swap installation (cold) | 744.1 μs | ±0.0% | ✅ Good | First-time installation, cold caches |
| Swap reset | 812.5 μs | ±97.1% | ✅ Good | Restore original bindings |
| Throw (no swap) | 27.0 μs | ±121.4% | ✅ Excellent | Baseline native performance |
| Throw (with swap) | 51.7 μs | ±106.0% | ✅ Excellent | With decorator overhead |
| Throw/catch | 28.1 μs | ±130.3% | ✅ Excellent | Basic exception cycle |
| runtime_error | 71.1 μs | ±239.5% | ✅ Excellent | Standard exception type |
| string exception | 30.2 μs | ±134.8% | ✅ Excellent | String exception type |
| int exception | 28.4 μs | ±131.0% | ✅ Excellent | Primitive exception type |
| Shallow stack (10) | 30.6 μs | ±116.3% | ✅ Excellent | C++ unwinding cost |
| Deep stack (50) | 33.7 μs | ±117.2% | ✅ Excellent | C++ unwinding cost |
| Very deep stack (100) | 33.3 μs | ±115.7% | ✅ Excellent | C++ unwinding cost |
Stack Capture (KSBacktrace)
| Operation | Time | Std Dev | Status | Notes |
|---|---|---|---|---|
| Same thread capture | 11.6 μs | ±117.4% | ✅ Excellent | Fast path, no suspension |
| Cross-thread capture | 114.8 μs | ±49.7% | ✅ Good | Requires thread suspension |
| Typical depth (50 frames) | 8.7 μs | ±89.4% | ✅ Excellent | Common crash scenario |
| Symbolicate (1 address) | 440.4 μs | ±311.2% | ✅ Good | Single frame lookup |
| Symbolicate (20 frames) | 560.3 μs | ±296.8% | ✅ Good | Full stack resolution |
| Capture + symbolicate | 928.5 μs | ±285.6% | ✅ Good | Complete crash flow |
Dynamic Linker (KSDynamicLinker)
| Operation | Time | Std Dev | Status | Notes |
|---|---|---|---|---|
| Image lookup (single) | 441.4 μs | ±311.4% | ✅ Excellent | Single address resolution |
| Image lookup (multiple) | 460.3 μs | ±311.1% | ✅ Excellent | Stack trace addresses |
| Image lookup (different) | 1.63 ms | ±314.8% | ✅ Good | Cross-image lookups |
| Binary image info (single) | 53.1 μs | ±64.9% | ✅ Excellent | Extract image metadata |
| Binary image info (50) | 63.5 μs | ±144.5% | ✅ Excellent | Multiple images |
| Binary image info (all) | 1.60 ms | ±152.7% | ✅ Good | All loaded images |
| Typical crash symbolication | 559.9 μs | ±302.7% | ✅ Excellent | Capture + symbolicate |
| Full crash report | 1.30 ms | ±138.6% | ✅ Good | Complete crash flow |
| Repeated lookup (cache hit) | 19.3 μs | ±74.1% | ✅ Excellent | 1000x same address, warm cache |
| Repeated lookup (cache miss) | 1.16 ms | ±105.0% | ✅ Good | 1000x same address, cold start |
| Sequential nearby (cache hit) | 18.9 μs | ±106.5% | ✅ Excellent | 100 addresses, warm cache |
| Exact function (cache hit) | 18.6 μs | ±62.7% | ✅ Excellent | Function entry, warm cache |
| Exact function (cache miss) | 1.14 ms | ±98.6% | ✅ Good | Function entry, cold start |
| Non-exact lookup (cache hit) | 22.2 μs | ±107.0% | ✅ Excellent | Mid-function, warm cache |
| Non-exact lookup (cache miss) | 1.26 ms | ±100.6% | ✅ Good | Mid-function, cold start |
Safe Memory Operations (KSMemory)
| Operation | Time | Std Dev | Per-Call | Status |
|---|---|---|---|---|
| Check readable (64B) | 1.18 ms | ±3.5% | 1.2 μs | ✅ Good |
| Check readable (4KB) | 1.52 ms | ±3.3% | 1.5 μs | ✅ Good |
| Check readable (64KB) | 1.49 ms | ±4.2% | 14.9 μs | |
| Safe copy (64B) | 1.16 ms | ±3.7% | 1.2 μs | ✅ Good |
| Safe copy (4KB) | 1.49 ms | ±2.6% | 1.5 μs | ✅ Good |
| Safe copy (32KB) | 566.4 μs | ±7.2% | 5.7 μs | ✅ Good |
| Copy max possible (4KB) | 275.1 μs | ±13.5% | 2.8 μs | ✅ Good |
| Find max readable | 344.8 μs | ±10.8% | 3.4 μs | ✅ Good |
| Typical crash dump (8KB) | 22.8 μs | ±149.7% | 22.8 μs |
JSON Encoding (KSJSONCodec)
| Operation | Time | Std Dev | Status | Notes |
|---|---|---|---|---|
| Encode integers (100) | 33.9 μs | ±136.4% | ✅ Excellent | Numeric fields |
| Encode floats (100) | 38.8 μs | ±117.9% | ✅ Excellent | Floating point |
| Encode booleans (100) | 32.6 μs | ±139.8% | ✅ Excellent | Boolean fields |
| Encode short strings (100) | 32.9 μs | ±103.9% | ✅ Excellent | ~13 chars each |
| Encode long strings (50) | 58.3 μs | ±78.2% | ✅ Excellent | ~520 chars each |
| Encode escaped strings (100) | 40.7 μs | ±108.4% | ✅ Excellent | Special chars |
| Encode nested objects (20) | 31.8 μs | ±149.6% | ✅ Excellent | Thread-like structure |
| Encode arrays (50 items) | 23.0 μs | ±192.8% | ✅ Excellent | Backtrace addresses |
| Encode hex data (10x256B) | 48.3 μs | ±98.5% | ✅ Excellent | Memory dumps |
| Full crash report | 105.1 μs | ±35.1% | ✅ Excellent | 10 threads, 30 frames each |
Thread Operations (KSThread)
| Operation | Time | Std Dev | Per-Call | Status |
|---|---|---|---|---|
| Get current thread | 5.76 ms | ±7.6% | <1 μs | ✅ Good |
| Get thread name | 28.1 μs | ±62.2% | <1 μs | ✅ Excellent |
| Get thread state | 2.19 ms | ±2.2% | 2.2 μs | ✅ Good |
| State to string | 60.3 μs | ±37.2% | <1 μs | ✅ Excellent |
| Get queue name | 3.27 ms | ±1.3% | 3.3 μs | ✅ Good |
| Gather all thread info | 589.8 μs | ±7.1% | 5.9 μs | |
| Ops under contention | 1.19 ms | ±4.8% | 1.2 μs | ✅ Good |
| Cache freeze/unfreeze | 25.8 μs | ±76.2% | <1 μs | ✅ Excellent |
| Cache thread name lookup | 13.5 μs | ±152.3% | <1 μs | ✅ Excellent |
| Cache queue name lookup | 8.0 μs | ±162.8% | <1 μs | ✅ Excellent |
| Cache get all threads | 10.0 μs | ±96.8% | <1 μs | ✅ Excellent |
| Cache crash scenario | 19.5 μs | ±172.2% | 19.5 μs | ❌ Review |
Key-Value Store (KSKeyValueStore)
| Operation | Time | Std Dev | Status | Notes |
|---|---|---|---|---|
| 100 string writes | 1.28 ms | ±29.3% | ✅ Good | Fresh store, unique keys |
| 100 mixed-type writes | 1.93 ms | ±136.2% | ✅ Good | String, int64, double, bool, date |
| Iterate 100 records | 31.7 μs | ±37.1% | ✅ Excellent | Resolved last-write-wins |
| 100 overwrites (1 key) | 1.27 ms | ±34.3% | ✅ Good | Append-only log growth |
| Compaction trigger | 1.95 ms | ±132.8% | ✅ Good | Small capacity, repeated overwrites |
| Multiple growths | 1.79 ms | ±26.1% | ✅ Good | 512B initial, 100 unique keys |
| Create + destroy lifecycle | 1.91 ms | ±130.6% | ✅ Good | mmap + munmap |
| Read-only open + iterate | 106.7 μs | ±35.2% | ✅ Excellent | Heap-based read path |
Crash Report Writing (KSCrashReport)
| Operation | Time | Std Dev | Status | Notes |
|---|---|---|---|---|
| Write standard report | 8.50 ms | ±68.9% | ✅ Good | Full report with binary images |
| Write report (no images) | 1.72 ms | ±126.2% | ✅ Excellent | Report without binary images |
| Write 5 reports | 25.85 ms | ±50.2% | Sequential report writing |
Sampling Profiler (KSCrashProfiler)
| Operation | Time | Status | Notes |
|---|---|---|---|
| Profiler initialization | 283.5 μs | ✅ Excellent | Create profiler instance |
| Begin/end cycle | 40.0 μs | ✅ Excellent | Start and stop profiling |
| High frequency (5ms) | 696.1 μs | ✅ Good | Per-sample avg latency, 5ms interval |
| Default frequency (10ms) | 1.27 ms | Per-sample avg latency, 10ms interval | |
| Cross-thread profiling | 103.1 μs | ✅ Excellent | Per-sample avg latency, profiling another thread |
| Sample retrieval | 40.89 ms | ❌ Review | Per-sample avg latency over 200ms profile |
| Concurrent profiles | 589.8 μs | ✅ Good | Per-sample avg latency, 3 simultaneous sessions |
| Storage size calc (1000x) | 27.6 μs | ✅ Excellent | Calculate memory footprint |
| Shallow stack (16 frames) | 2.93 ms | ✅ Good | 100 capture cycles, 16-frame stack |
| Medium stack (64 frames) | 6.76 ms | ✅ Good | 100 capture cycles, 64-frame stack |
| Deep stack (128 frames) | 9.20 ms | ✅ Good | 100 capture cycles, 128-frame stack |
| Very deep stack (256 frames) | 14.00 ms | 100 capture cycles, 256-frame stack | |
| Per-sample latency (64 frames) | 257.6 μs | ✅ Excellent | Per-sample avg latency, ~1000 samples / 1s @ 1ms |
| Per-sample latency (256 frames) | 701.5 μs | ✅ Excellent | Per-sample avg latency, deep stack (slower unwind) |
89 benchmarks | Generated 2026-05-02 22:42:29 UTC
…sholds Two issues surfaced by reviewing the on-device benchmark output: 1. testBenchmarkHighFrequencySampling and testBenchmarkSampleRetrieval profiled pthread_self() with Profiler<Sample64>. Under XCTest the test thread holds 60+ stack frames, exceeding the 64-address Sample64 buffer. The profiler discards truncated samples (Sample.swift:108 sets addressCount to 0 when isTruncated), so every captured sample was thrown away, yielding count=0 and avgNs=0, which the parser formatted as "<1 us, Excellent". Switch both tests to Sample128 so captures fit. 2. The on-device-only assertion (XCTAssertGreaterThan(metrics.count, 0)) masked the bug above on macOS swift test runs. Drop the platform guard so a regression that yields zero samples fails loud everywhere; the prior comment about dispatch-timing unreliability was wrong, the real failure mode is sample truncation. 3. Thresholds in benchmark-tests.json were calibrated for the Sample64 bug's fake "<1 us" reading. Loosened against actual device numbers from the BrowserStack iPhone 17 Pro run so the per-sample latency tests (which measure stack-walk cost, not interval) classify reasonably: per-sample latency tests get ms-scale thresholds matching the 6-7 ms capture cost on slower iOS hardware.
…831) * Benchmarks: surface profiler per-sample latency via custom XCTMetric The five sampling-scenario profiler benchmarks need a Thread.sleep inside the measure block to give the sampler real time to fire, so wall-clock time is dominated by the sleep rather than profiler overhead. Replace the wall-clock metric on those tests with a custom XCTMetric that carries profile.metrics.avgNs (per-sample capture latency in seconds), and teach parse_benchmarks.py to prefer kscrash.* custom metrics over wall clock and to honor per-test threshold overrides. Other tests in the suite are unaffected. Off-simulator runs assert at least one sample was captured per iteration so a sampler regression fails loud instead of rendering as Excellent. * Benchmarks: extract measurePerSampleLatency helper, tighten assertion gate Address Copilot review: dedupe the per-iteration metric setup and sample-count assertion across the five sampling-scenario tests by extracting a measurePerSampleLatency helper that takes a body returning ProfileMetrics?. Also tighten the assertion gate from !targetEnvironment(simulator) to (os(iOS) || os(tvOS)) && !targetEnvironment(simulator) && !targetEnvironment(macCatalyst). The previous gate let the assertion fire on the macOS host where swift test runs the benchmarks under sanitizers; the slowed-down dispatch source can't honor 5-10 ms intervals on a non-device, so 0-sample iterations are normal there. The assertion now runs only on real iOS/tvOS device, which is what we actually want to monitor. * Benchmarks: migrate PerSampleCaptureLatency tests to custom XCTMetric PerSampleCaptureLatency and PerSampleCaptureLatencyDeepStack used to compute per-sample latency stats and dump them via print(), so they took up rows in benchmark-tests.json without ever populating any data in the PR comment table. Reuse the measurePerSampleLatency helper so they emit the same kscrash.profiler.persample_avg custom metric as the five sampling-scenario tests, and add per-test threshold overrides suited to per-sample microsecond scale (deeper stack gets a looser band because comprehensive unwind takes longer per sample). * Benchmarks: gate ProfilerSampleMetric on !os(watchOS) KSCrash's SwiftPM platforms include watchOS 5, where XCTMetric and the XCTPerformanceMeasurement* APIs are unavailable. Wrap the file contents in the same guard already used by KSProfilerBenchmarks.swift so watchOS builds of the benchmarks target compile. * Benchmarks: fix Sample64 stack truncation, tune device-realistic thresholds Two issues surfaced by reviewing the on-device benchmark output: 1. testBenchmarkHighFrequencySampling and testBenchmarkSampleRetrieval profiled pthread_self() with Profiler<Sample64>. Under XCTest the test thread holds 60+ stack frames, exceeding the 64-address Sample64 buffer. The profiler discards truncated samples (Sample.swift:108 sets addressCount to 0 when isTruncated), so every captured sample was thrown away, yielding count=0 and avgNs=0, which the parser formatted as "<1 us, Excellent". Switch both tests to Sample128 so captures fit. 2. The on-device-only assertion (XCTAssertGreaterThan(metrics.count, 0)) masked the bug above on macOS swift test runs. Drop the platform guard so a regression that yields zero samples fails loud everywhere; the prior comment about dispatch-timing unreliability was wrong, the real failure mode is sample truncation. 3. Thresholds in benchmark-tests.json were calibrated for the Sample64 bug's fake "<1 us" reading. Loosened against actual device numbers from the BrowserStack iPhone 17 Pro run so the per-sample latency tests (which measure stack-walk cost, not interval) classify reasonably: per-sample latency tests get ms-scale thresholds matching the 6-7 ms capture cost on slower iOS hardware.
Problem
Five sampling-profiler benchmarks bake
Thread.sleepinto theirmeasure {}block to give the sampler real time to fire. Wall clock is therefore dominated by the sleep, not by profiler overhead. The screenshot example: "100ms of 10ms interval sampling" reports 102.48 ms with aReviewstatus when the real overhead is ~2.48 ms.Fix
Emit a custom
XCTMetric(kscrash.profiler.persample_avg) carryingprofile.metrics.avgNs, the per-sample capture latency in seconds. XCTest records it into the xcresult under our identifier exactly like a built-in metric. The five affected tests now usemeasure(metrics: [profilerMetric])and stashavgNsfrom each iteration's profile.Parser
parse_benchmarks.pyprefers anykscrash.*custom metric over wall clock when both are present, and now honors per-testthresholdsoverrides inbenchmark-tests.jsonso the affected rows can use a per-sample-latency scale (excellent <100µs, good <250µs, ok <500µs) without disturbing the rest of the suite.Safety net
Off-simulator runs assert at least one sample was captured per iteration. A sampler regression that stops capturing now fails the test loudly instead of rendering as Excellent (
avgNsreturns 0 for empty sample lists).Verified end to end
Probed the round-trip: custom metric -> xcresult ->
xcresulttool get test-results metrics-> parser -> markdown report. Identifiers and per-iteration measurement arrays survive intact.