Profile conversion with large thread numbers

[vsarunas]

Noticed that symbolification is taking a long time when using larger duration samples:

time curl -s -d '{"timeInterval":"10 ms","numberOfSamples":3000}' http://127.0.0.1:12345/sample > samples.perf
curl -s -d '{"timeInterval":"10 ms","numberOfSamples":3000}'  >   0.02s user 0.20s system 0% cpu 47.922 total

Default request of pprof duration, sampling takes 38.8 seconds and symbolication takes 8.3 seconds:

2025-10-07T09:11:49.423593 [...] ProfileRecorderSampleConversion/Sampler+Conversion.swift:61 : requesting raw samples ["raw-samples-path": /var/folders/zx/1np75sd15ygcssjxtfnq30xc0000gn/T/WYlcor8c/samples.raw, "symbolicated-samples-path": /var/folders/zx/1np75sd15ygcssjxtfnq30xc0000gn/T/WYlcor8c/samples.perf, "symbolizer": ProfileRecorderSampleConversion.CoreSymbolicationSymboliser, "sample-count": 3000, "time-between-samples": 10ms, "peer": [IPv4]127.0.0.1/127.0.0.1:64470]

2025-10-07T09:12:28.238699 [...] ProfileRecorderSampleConversion/Sampler+Conversion.swift:70 : raw samples complete ["raw-samples-path": /var/folders/zx/1np75sd15ygcssjxtfnq30xc0000gn/T/WYlcor8c/samples.raw, "symbolizer": ProfileRecorderSampleConversion.CoreSymbolicationSymboliser, "sample-count": 3000, "peer": [IPv4]127.0.0.1/127.0.0.1:64470, "duration": 38.814310791 seconds, "symbolicated-samples-path": /var/folders/zx/1np75sd15ygcssjxtfnq30xc0000gn/T/WYlcor8c/samples.perf, "time-between-samples": 10ms]

2025-10-07T09:12:36.587133 [...] ProfileRecorderSampleConversion/Sampler+Conversion.swift:97 : samples symbolicated duration ["raw-samples-path": /var/folders/zx/1np75sd15ygcssjxtfnq30xc0000gn/T/WYlcor8c/samples.raw, "symbolizer": ProfileRecorderSampleConversion.CoreSymbolicationSymboliser, "sample-count": 3000, "peer": [IPv4]127.0.0.1/127.0.0.1:64470, "duration": 8.348323542 seconds, "symbolicated-samples-path": /var/folders/zx/1np75sd15ygcssjxtfnq30xc0000gn/T/WYlcor8c/samples.perf, "time-between-samples": 10ms]

Repeated request to sample will take roughly the same amount of time.

Conversion specifically:

$ time ./.build/release/swipr-sample-conv --format pprof < swipr_3000_10ms > sample.pprof
[...]
./.build/release/swipr-sample-conv --format pprof < swipr_3000_10ms >   6.41s user 0.13s system 95% cpu 6.845 total

$ time ./.build/release/swipr-sample-conv < swipr_3000_10ms > /dev/null
[...]
./.build/release/swipr-sample-conv < swipr_3000_10ms > /dev/null  7.64s user 0.13s system 98% cpu 7.865 total

The sample is quite long at 2.7 million lines; mostly caused by 84 threads:

$ wc -l swipr_3000_10ms
 2711686 swipr_3000_10ms

A ~5 second processing time can be reproduced by:

$ ./.build/release/swipr-mini-demo --blocking --no-burn-cpu --sample-count 3000 --ms-between-samples 10 --threads 80 --iterations 80 --output large_sample.swipr

$ wc -l large_sample.swipr
 2022505 large_sample.swipr

$ ./.build/release/swipr-sample-conv --format pprof < large_sample.swipr > large_sample.pprof

I understand the 10ms sampling rate generates excessive samples, and are reducing the parameters to reduce the overhead.

Overhead is mostly from decoding JSON line.

[weissi]

Thanks for this report! Yes, it appears like we should either make the JSON parsing faster (maybe with a very targeted parser) or switch to another format entirely...

[weissi]

Okay, let's first construct a repro case:

# gather samples
.build/release/swipr-mini-demo --tsp true --sample-count 9999 --ms-between-samples 1 --iterations 999  --output /tmp/raw.swipr
# make all stacks 10x deeper
cat /tmp/raw.swipr | sed '/STCK/{p;p;p;p;p;p;p;p;p;p;}' > /tmp/huge.swipr

will create some samples.

$ wc -l /tmp/huge.swipr
 12985527 /tmp/huge.swipr

sufficiently large. And yes, I repro

$ time .build/release/swipr-sample-conv /tmp/huge.swipr  > /tmp/huge.perf
2025-10-07T20:49:47+0100 info swipr-sample-conv: cached-sym=CachedSymbolizer(cache: 503, vmaps: 355, sym: CoreSymbolicationSymboliser) [ProfileRecorderSampleConversion] done symbolising

real	0m24.120s
user	0m23.124s
sys	0m0.743s

An indeed, at least 50% spent in JSON parsing.

Furthermore, if we use the fake symbolizer, we spend roughly the same amount of time:

$ time .build/release/swipr-sample-conv  --use-fake-symbolizer true /tmp/huge.swipr > /tmp/hugefake.perf
2025-10-07T20:51:21+0100 info swipr-sample-conv: cached-sym=CachedSymbolizer(cache: 503, vmaps: 355, sym: FakeSymbolizer) [ProfileRecorderSampleConversion] done symbolising

real	0m23.742s
user	0m23.080s
sys	0m0.617s

which proves that the actual symboliser isn't the issue here.

[weissi]

@vsarunas would you be able to apply #33 and give it a spin? Just to see that you also see a > 2x improvement here.

[vsarunas]

Great, thanks very much! Yes roughly 2x improvement:

./.build/release/swipr-sample-conv --format pprof <  > sample.pprof  6.39s user 0.13s system 98% cpu 6.618 total
./.build/release/swipr-sample-conv --format pprof <  > sample.pprof  2.15s user 0.10s system 96% cpu 2.334 total

[vsarunas]

Added a benchmark:

main:

ArrayAppend convert to pprof
╒═══════════════════════════════╤═══════════╤═══════════╤═══════════╤═══════════╤═══════════╤═══════════╤═══════════╤═══════════╕
│ Metric                        │        p0 │       p25 │       p50 │       p75 │       p90 │       p99 │      p100 │   Samples │
╞═══════════════════════════════╪═══════════╪═══════════╪═══════════╪═══════════╪═══════════╪═══════════╪═══════════╪═══════════╡
│ Instructions (G) *            │        10 │        10 │        10 │        10 │        10 │        10 │        10 │         4 │
├───────────────────────────────┼───────────┼───────────┼───────────┼───────────┼───────────┼───────────┼───────────┼───────────┤
│ Malloc (total) (K) *          │      2677 │      2679 │      2679 │      2679 │      4006 │      4006 │      4006 │         4 │
├───────────────────────────────┼───────────┼───────────┼───────────┼───────────┼───────────┼───────────┼───────────┼───────────┤
│ Memory (resident peak) (M)    │        34 │        34 │        35 │        35 │        36 │        36 │        36 │         4 │
├───────────────────────────────┼───────────┼───────────┼───────────┼───────────┼───────────┼───────────┼───────────┼───────────┤
│ Throughput (# / s) (#)        │         1 │         1 │         1 │         1 │         1 │         1 │         1 │         4 │
├───────────────────────────────┼───────────┼───────────┼───────────┼───────────┼───────────┼───────────┼───────────┼───────────┤
│ Time (total CPU) (ms) *       │       764 │       764 │       764 │       765 │       772 │       772 │       772 │         4 │
├───────────────────────────────┼───────────┼───────────┼───────────┼───────────┼───────────┼───────────┼───────────┼───────────┤
│ Time (wall clock) (ms) *      │       764 │       764 │       765 │       766 │       772 │       772 │       772 │         4 │
╘═══════════════════════════════╧═══════════╧═══════════╧═══════════╧═══════════╧═══════════╧═══════════╧═══════════╧═══════════╛

PR:

ArrayAppend convert to pprof
╒═══════════════════════════════╤═══════════╤═══════════╤═══════════╤═══════════╤═══════════╤═══════════╤═══════════╤═══════════╕
│ Metric                        │        p0 │       p25 │       p50 │       p75 │       p90 │       p99 │      p100 │   Samples │
╞═══════════════════════════════╪═══════════╪═══════════╪═══════════╪═══════════╪═══════════╪═══════════╪═══════════╪═══════════╡
│ Instructions (M) *            │      3598 │      3601 │      3603 │      3607 │      3611 │      3615 │      3615 │        13 │
├───────────────────────────────┼───────────┼───────────┼───────────┼───────────┼───────────┼───────────┼───────────┼───────────┤
│ Malloc (total) (K) *          │       439 │       440 │       885 │       887 │       887 │       960 │       960 │        13 │
├───────────────────────────────┼───────────┼───────────┼───────────┼───────────┼───────────┼───────────┼───────────┼───────────┤
│ Memory (resident peak) (M)    │        33 │        35 │        35 │        36 │        37 │        37 │        37 │        13 │
├───────────────────────────────┼───────────┼───────────┼───────────┼───────────┼───────────┼───────────┼───────────┼───────────┤
│ Throughput (# / s) (#)        │         4 │         4 │         4 │         4 │         4 │         4 │         4 │        13 │
├───────────────────────────────┼───────────┼───────────┼───────────┼───────────┼───────────┼───────────┼───────────┼───────────┤
│ Time (total CPU) (ms) *       │       243 │       246 │       246 │       247 │       249 │       249 │       249 │        13 │
├───────────────────────────────┼───────────┼───────────┼───────────┼───────────┼───────────┼───────────┼───────────┼───────────┤
│ Time (wall clock) (ms) *      │       244 │       246 │       247 │       247 │       249 │       249 │       249 │        13 │
╘═══════════════════════════════╧═══════════╧═══════════╧═══════════╧═══════════╧═══════════╧═══════════╧═══════════╧═══════════╛

[weissi]

Thanks @vsarunas , I'll get it merged!

[weissi]

@vsarunas released as https://github.com/apple/swift-profile-recorder/releases/tag/0.3.3