Skip to content

profile: a theap starts over with each mi_profiler_start - #47

Merged
Jarred-Sumner merged 3 commits into
bun-dev3-v2from
claude/profiler-restart-state
Sep 15, 2026
Merged

Jarred-Sumner merged 3 commits into
bun-dev3-v2from
claude/profiler-restart-state

Conversation

@Jarred-Sumner

@Jarred-Sumner Jarred-Sumner commented Sep 15, 2026 •

Copy link
Copy Markdown
Collaborator

A theap that was sampling before a mi_profiler_stop, and that got to neither the stop nor the next mi_profiler_start in its generic path, went on with what it had: the rate that on_alloc had given it, how far it was into that period, and the bytes requested since its last sample. _mi_theap_update_profiling only acted when "the profiler is enabled" and "the theap has a rate" disagreed, which they do not for such a theap. Two effects:

  • A session at a small rate after one at a large rate sees nothing of that thread until the old period has run out. start (on_alloc returns 256 MiB); a thread allocates 32 MiB; stop; start (on_alloc returns 64 KiB); the thread allocates 32 MiB: 0 of those 32 MiB are sampled.
  • At equal rates its first sample of the new session reports bytes from before the start: 1114112 bytes with 655360 requested since the start.

Found with a heap profiler on these hooks that draws its intervals from an exponential distribution (a long draw is the first case) and that stops and starts in one process.

The change

  • mi_profiler_t.reserved is (epoch << 1) | enabled (one word, so both are read together). A start of a profiler that is not running takes a new epoch from one counter of the process, so two profilers never have the same one.
  • A theap keeps the epoch that its profile rate and countdowns belong to (profile_sample_epoch). _mi_theap_update_profiling starts it over (the initial rate, a full period, nothing requested, and with MI_SAMPLE==1 the counts of its pages synced) also when the profiler is enabled and the epoch is another one. Starting a period is one function for _mi_theap_init and _mi_theap_update_profiling; "has to look" is one predicate, also for the second look of _mi_theap_init (for a start or a stop that came in between the first one and the theap being on the heap's list).
  • _mi_theap_malloc_profiled looks at the epoch too: with MI_SAMPLE==2 a sample that comes due in alloc.c does not pass mi_malloc_generic_fallback, and the look inside _mi_malloc_generic_no_sample is put off. A sample that belongs to the period before the start is not taken.
  • The theap of the thread that calls mi_profiler_start starts over through _mi_theap_update_profiling instead of getting a rate of 1 with the countdowns it had.
  • mi_profiler_stop leaves the request to look, as mi_profiler_start does, so a theap stops counting what it hands out at its next generic allocation and not at its next sample or 1000 generic allocations later. It waits for no lock for that (what is behind a lock that is taken is left out; a theap finds out by itself as before), so it can still be called from on_alloc, from a visitor of the heaps or late in the exit of the process. mi_heap_profile and mi_subproc_profile disable the profiler they are given without it, as before.

Cost

Nothing on the fast paths and nothing for a theap that does not sample: the comparison is in _mi_theap_update_profiling, which runs on a request and every 1000 generic allocations, and in _mi_theap_malloc_profiled, per sample. clang 21, -O3 -march=nehalem, C++, MI_FREE_USE_PAGEMAP, user-mode instructions (runs of one build agree to 200):

before (69050cf3) this
25 M mi_malloc + 25 M mi_free of 16 to 1039 bytes, no profiler 2.030466 G 2.030470 G
20 M mi_malloc(128 KiB) + mi_free, no profiler, per pair 261.68 261.68
the same with a profiler running at 512 KiB (4 M samples), per pair 334.85 335.46 (3 instructions per sample)
the same after a start and a stop, per pair 261.68 261.69

In bun (release build with this commit as the pin against the same build with 69050cf3, 8 cores, interleaved runs, medians and ranges): bun -e 1 9.73 M (9.72..9.74) against 9.72 M (9.72..9.74); JSON.stringify + JSON.parse of a 200-user object 3000 times 4789.8 M (4785.4..4792.2) against 4787.3 M (4785.4..4793.3); 3M ArrayBuffers 5802 M (5774..5807) against 5792 M (5781..5803), and with a heap profile running at 512 KiB 5965 M (5932..5968) against 5959 M (5957..5969). (Measured with the first commit; the second one adds the 3 instructions per sample.)

Test

test-profile: "a thread starts over when the profiler is started again", one thread that does not allocate between a stop and the next start:

  1. a period at a rate of 256 MiB, then 32 MiB at a rate of 64 KiB of another profiler that is started for the first time. On 69050cf3, and with an epoch per profiler: 0 bytes sampled. Here 33488896.
  2. a stop half way into a period of 1 MiB, with blocks of a page in between. On 69050cf3 the first sample of the next start reports 1114112 bytes with 655360 requested since the start; here it reports no more than the thread got since the start.
  3. a rate at which every allocation is a sample, then one at which none is: 0 samples. With MI_SAMPLE==2 and without the look in _mi_theap_malloc_profiled: 1.

The bounds are in bytes of blocks, which is what a build that counts the blocks of a page when it is refilled counts, and what MI_SECURE makes larger than the request. (The first version of the test compared with requested bytes and failed with MI_SECURE=ON; an earlier version of this text said that only test-emulated-tls failed there, which was wrong.)

Not covered by the test: that a theap which starts over syncs the counts of its pages (MI_SAMPLE==1). Without it, the blocks that a page handed out since it was last refilled (up to 8 KiB a page) are counted against the first period after the start; I did not get a test to tell the two apart, the first sample moves by less than the bounds allow.

Locally, test-profile in release, debug (MI_DEBUG=FULL), secure, release and debug with MI_GUARDED=FULL, release and debug as C++, TLS pthreads, ASAN, UBSAN and TSAN (no report): 16 of 16. All of ctest: release 33 of 33, debug (MI_DEBUG=FULL) 34 of 34, guarded release 33 of 33 and debug 34 of 34; MI_SECURE=ON all but test-emulated-tls, which fails the same way on 69050cf3 on this machine.

A theap that was sampling before a stop, and that got to neither the stop
nor the next start in its generic path, went on with what it had: the rate
that on_alloc had given it, how far it was into that period, and what was
requested since its last sample. A session at a rate of 64 KiB after one at
256 MiB saw nothing of such a thread, and at equal rates its first sample
reported bytes from before the start.

`mi_profiler_t.reserved` is (epoch << 1) | enabled, and a start of a profiler
that is not running is a new epoch. A theap keeps the epoch of its profile
rate and countdowns; `_mi_theap_update_profiling` starts it over (the initial
rate, a full period, nothing requested) when the epoch is another one, and
`_mi_theap_init` asks for that look too when a start came in between its own
look and the theap being on the heap's list. The theap of the thread that
calls `mi_profiler_start` starts over through the same function.

`mi_profiler_stop` leaves the request to look as `mi_profiler_start` does, so
a theap stops counting what it hands out at its next generic allocation
(not in the child of a fork).

No change for a theap that does not sample: 25 M malloc + 25 M free of 16 to
1039 bytes are 2.030469 G instructions (2.030466 G before), a pair of
mi_malloc(128 KiB) + mi_free 261.68 (261.68), and 334.86 (334.85) with a
profiler running at 512 KiB.

test-profile: a thread that ends a session half way into a period and one
that ends it at a rate of 256 MiB, neither allocating between the stop and
the start. Before: the first sample of the next session reports 1114112
bytes with 655360 requested since the start, and 0 of 32 MiB are sampled at
64 KiB.
…cs its pages

Review of the previous commit.

- The epoch comes from one counter of the process, not from a count in each
  mi_profiler_t: a theap only keeps the number, and every profiler's first
  start was epoch 1, so a theap that had state of profiler A took it into
  the first start of profiler B.
- `_mi_theap_malloc_profiled` looks at the epoch too, not only at whether
  the profiler is enabled: with MI_SAMPLE==2 a sample that comes due in
  alloc.c does not pass `mi_malloc_generic_fallback`, and the look inside
  `_mi_malloc_generic_no_sample` is put off. The sample of the period before
  the start is not taken (3 instructions per sample).
- Starting a period is one function, `_mi_theap_start_profile_period`, for
  `_mi_theap_init` and `_mi_theap_update_profiling`; with MI_SAMPLE==1 it
  syncs the counts of the theap's pages, as a theap that goes from not
  sampling to sampling does. "Has to look" is one predicate,
  `_mi_theap_profiling_is_stale`, also for the second look of
  `_mi_theap_init`, which missed a stop.
- `mi_profiler_stop` waits for no lock when it leaves the request to look
  (it can be called from on_alloc, from a visitor of the heaps, late in the
  exit of the process), and `mi_heap_profile` / `mi_subproc_profile` disable
  a profiler without it, as before. No special case for the child of a fork.

test-profile: the short rate is of another profiler that is started for the
first time; blocks of a page between the big ones; a rate at which every
allocation is a sample before one at which none is (one stale sample with
MI_SAMPLE==2 without the look in `_mi_theap_malloc_profiled`). The bounds
are in bytes of blocks, which is what a build that counts a page's blocks
when it is refilled counts, and what MI_SECURE makes larger than the request:
the first version of the test failed there.

25 M malloc + 25 M free of 16 to 1039 bytes: 2.030470 G instructions
(2.030466 G at 69050cf); mi_malloc(128 KiB) + mi_free: 261.68 a pair
(261.68); with a profiler running at 512 KiB: 335.46 (334.85).
`_mi_theap_update_sample_rate` already syncs the counts of the pages of a
theap that goes from not sampling to sampling; `_mi_theap_start_profile_period`
does it for one that was sampling.
@Jarred-Sumner
Jarred-Sumner merged commit dbefe02 into bun-dev3-v2 Sep 15, 2026
45 of 46 checks passed
Jarred-Sumner added a commit to oven-sh/bun that referenced this pull request Sep 15, 2026
… mi_profiler_start

One commit on from the pin (69050cf3 -> dbefe024, the merge of #47 and
nothing else). A thread that had made no allocation through the allocator's
slow path between Bun.pprof.heap.stop() and the next start() went on with
the distance to its next sample that it had: a profile at 64 KiB after one
at 256 MiB had nothing of a Worker's 32 MiB (or 72 MB, with the bytes of
the first profile, when the old distance ran out), and at equal intervals
the first sample carried bytes from before the start. Every thread now
starts a period of its own at each start.

Without a profiler the allocator is the same: 25 M malloc + 25 M free
2.030470 G instructions (2.030466 G), `bun -e 1` 9.74 M (9.75 M on main),
the JSON loop 4786 M (4792 M on main, inside the spread of either).

Test: heap-fixture-restart.ts, the 256 MiB then 64 KiB case; 0 or 72 MB on
the previous pin, 32.0 MiB on this one, 40 of 40 runs.
Jarred-Sumner added a commit to oven-sh/bun that referenced this pull request Sep 15, 2026
, #51): recently used large pages are left alone for a while (#42808)

## What

`MIMALLOC_COMMIT` 69050cf3 → 6df7aa13, the head of `bun-dev3-v2`.
Relative to main's pin that is three fork PRs:

- **oven-sh/mimalloc#50**, what this PR is about: see below.
- **oven-sh/mimalloc#49**: the pthread key of the allocator's
thread-local slots is created once when several threads first use a
second heap at the same time (macOS; the code is not compiled on Linux).
Measured there: every hot path is the same instruction for instruction.
- **oven-sh/mimalloc#47**: a profiler that is started again starts every
thread over. Only reachable through the sampling-profiler hooks, which
nothing on main calls yet; #42626 (`Bun.pprof.heap`) bumps the pin to
that commit for its own sake. Whichever of the two PRs lands second
keeps the newer commit, which is this one.

Since #42668 the idle sweep hands back the free blocks of the
allocator's 4 MiB pages (buffers of 96 KiB and up) two sweeps after the
page was last allocated from, which is 100–200 ms. A server sits idle
between two requests for longer than that, so it took the buffers of
every request out of discarded memory again: a page fault for each 4 KiB
of them, on every request. About half of that was free blocks in a page
that still had a buffer in use; the other half was pages with no buffer
in use at all, which were freed outright and made anew for the next
request.

oven-sh/mimalloc#50: a large page (its free blocks, or all of it) is
left alone until it has not been allocated from for 256 epochs of the
sweep, for up to 4 MiB process-wide, the pages that were used last
first. There is no timer in this: an epoch ends only when some thread is
swept. `MIMALLOC_PURGE_HOLES_LARGE_FLOOR=0` is the behaviour before (a
bare number there is bytes: write `4MiB`, not `4096`).

## What it costs

- A process in which no thread ever parks again keeps up to 4 MiB of
large pages that it would have given back. Measured with the allocator
alone: 24 blocks of 300 KiB, 20 freed, a few short parks and then one
for good: 4460 KiB anonymous at every reading for 70 s against 1460 KiB
before (3.0 MB of the 6 MB freed; a page stays or goes whole). The
allocator's scavenger thread wakes for its 30 s safety timeout as before
and for nothing else.
- An idle server holds 0.2–1.0 MB more ten seconds after the load (3 MB
after 512 KiB bodies) and the same as before a minute after.
- A large application parked at a prompt: 1 MB.

## Numbers

Linux x64, release builds of this tree, the mimalloc commit the only
difference.

`Bun.serve` that answers a request with its own body, one connection, 5
requests a second for 20 s. Minor faults of the server
(`/proc/<pid>/stat`) and kernel instructions (`perf stat -e
instructions:k -p`), per request:

| body | main: faults | kernel instr | this PR: faults | kernel instr |
|---|---|---|---|---|
| 128 KiB | 65.4 | 627 K | 2.6 | 208 K |
| 256 KiB | 123.9 | 1031 K | 2.5 | 375 K |
| 512 KiB | 309.1 | 2331 K | 14.1 | 898 K |
| `hello` | 1.1 | 128 K | 1.1 | 114 K |

(No latencies: the machine was busy with other work and the median of
one binary moved more from run to run than the two differ. At 512 KiB it
shows through: 2.60 ms → 2.08 ms.)

Idle afterwards, anonymous RSS of the server in KiB at +10 s / +70 s:
128 KiB 3128 / 2908 → 4044 / 2940; 256 KiB 3248 / 3056 → 3280 / 3044;
512 KiB 3564 / 3356 → 6624 / 3376; `hello` 2936 / 2808 → 2784 / 2780. So
it holds up to 3 MB more ten seconds after the load and the same a
minute after.

A large `--compile`d CLI application that sits at a prompt (anonymous +
file-backed RSS in MB; 10 minutes at the first prompt, a scripted
session of 20 turns, 10 minutes parked; two runs each, all four started
together):

| | main | this PR |
|---|---|---|
| first prompt + 30 s | 121+95 / 122+95 | 124+67 / 124+95 |
| + 2 min | 100+31 / 100+38 | 101+36 / 101+36 |
| + 5 min | 96+32 / 96+38 | 97+36 / 97+37 |
| + 10 min | 96+32 / 96+39 | 97+37 / 97+38 |
| after the session + 30 s | 258+87 / 252+79 | 265+87 / 268+88 |
| + 2 min | 190+43 / 183+44 | 197+43 / 195+44 |
| + 5 min | 165+44 / 160+45 | 171+44 / 170+45 |
| + 10 min | 171+51 / 166+53 | 176+52 / 176+53 |

At the prompt that is 3 MB more for the first minute, 1 MB at two
minutes and after. After the session these four runs are 5–10 MB apart;
the same comparison with one binary and the floor switched by the
environment (`…LARGE_FLOOR=0`) came out at 171 / 161 against 168 / 173
at + 5 min, so what the floor itself keeps there (3–4 MB for two
minutes) is inside what two runs of one configuration differ by.

Instructions (`perf stat -e instructions:u`, pinned, interleaved, median
[range]):

| | main | this PR |
|---|---|---|
| `bun -e 1` (9 runs) | 10.05 M [10.04–10.07] | 10.05 M [10.05–10.07] |
| `JSON.stringify` + `JSON.parse` loop (5) | 4788.6 M [4786.5–4793.8] |
4789.3 M [4788.8–4796.6] |
| allocation loop (5) | 5760.0 M [5753.6–5766.7] | 5799.9 M
[5758.2–5824.1] |
| the allocator alone: 50 M random `malloc`/`free` | 1.9932 G | 1.9932 G
|
| the allocator alone: 20 M × `malloc(128 KiB)` + `free` | 5.0313 G |
5.0313 G |

(The allocation loop moves by that much between runs of one binary; its
ranges overlap.)

## Test

`test/js/bun/jsc/heapStats-mimalloc.test.ts`: a `Bun.serve` child that
echoes 256 KiB bodies, requests 50 ms apart with the sweep's epoch
shortened to 10 ms and the collector looking every 100 ms, minor faults
per request read from `/proc`. 2.3–2.4 with this pin, 130–131 with
main's (the bound is 20). Linux only, not ASAN.
springmin pushed a commit to springmin/bun that referenced this pull request Sep 15, 2026
Upstream:
- WebKit 65513e295c73: DFG LiveCatchVariablePreservationPhase flushes the
  right handler's live locals when two try ranges are adjacent
  (oven-sh/WebKit#629)
- deps: mimalloc to the head of bun-dev3-v2 (oven-sh/mimalloc#47/49/50/51:
  recently used large pages are left alone for a while)
- Bun.serve: send the completed responses of a pipelined read before
  JavaScript runs again (oven-sh#42796)
- Remove dead code from the SQL and node:http native classes, 13
  internal-field cells, Http2Response and the WebView ObjC wrappers
  (oven-sh#42816); .typos.toml and the bun-error images go with it
- ast: keep a class with a static accessor initializer in place (oven-sh#40887)
- react-compiler: a compound assignment to a local has the value of its
  store (oven-sh#42809)

Conflicts: none. The 4 files both sides changed (webkit.ts, the two test
files above plus serve.test.ts) auto-merged.

Impact assessment (complete, not sampled):
- all 48 files the merge touches checked for lost `ohos` references: none
- every line the OHOS side added since 7e56b40 is still present in the
  4 files both sides changed
- docs/ohos-adaptation-checklist.md markers all verified present
- no deleted file is referenced by the OHOS build or tests
- upstream moved the WebKit and mimalloc pins; the OHOS build was rebuilt
  from both and smoked (see the build log)
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.

1 participant