Skip to content

Benchmarks: surface profiler per-sample latency via custom XCTMetric#831

Merged
naftaly merged 5 commits into
release/2.6.0from
ac/profiler-xctmetric
May 2, 2026
Merged

Benchmarks: surface profiler per-sample latency via custom XCTMetric#831
naftaly merged 5 commits into
release/2.6.0from
ac/profiler-xctmetric

Conversation

@naftaly

@naftaly naftaly commented May 2, 2026

Copy link
Copy Markdown
Collaborator

Problem

Five sampling-profiler benchmarks bake Thread.sleep into their measure {} 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 a Review status when the real overhead is ~2.48 ms.

Fix

Emit a custom XCTMetric (kscrash.profiler.persample_avg) carrying profile.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 use measure(metrics: [profilerMetric]) and stash avgNs from each iteration's profile.

Parser

parse_benchmarks.py prefers any kscrash.* custom metric over wall clock when both are present, and now honors per-test thresholds overrides in benchmark-tests.json so 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 (avgNs returns 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.

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.

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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 in benchmark-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.

Comment thread Tests/KSCrashBenchmarks/KSProfilerBenchmarks.swift
naftaly added 2 commits May 2, 2026 16:23
… 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).

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

Copilot reviewed 4 out of 4 changed files in this pull request and generated 1 comment.

Comment thread Tests/KSCrashBenchmarks/ProfilerSampleMetric.swift Outdated
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.
@github-actions

github-actions Bot commented May 2, 2026

Copy link
Copy Markdown
Contributor

🔍 KSCrash Performance Benchmarks

Crash 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
Std Dev Interpretation
< 5% Stable, reliable measurement
5-15% Some variability, typical for most benchmarks
> 15% High variability, interpret with caution

p-value (in comparison table): Probability the difference is due to chance. Values < 0.05 indicate statistically significant changes.

📊 Changes from Base Branch

Only showing statistically significant changes (p < 0.05, threshold > 15%)

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 ⚠️ OK
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 ⚠️ OK

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 ⚠️ OK
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% ⚠️ OK 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 ⚠️ OK 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 ⚠️ OK 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.
@naftaly
naftaly merged commit 8c8f715 into release/2.6.0 May 2, 2026
21 checks passed
@naftaly
naftaly deleted the ac/profiler-xctmetric branch May 2, 2026 21:44
naftaly added a commit that referenced this pull request May 10, 2026
…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.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants