Memory-Event Log: Tracking Arena Growth

SuperJ allocates through a bump arena — objects are never individually freed; scoped arena {} blocks are dropped en masse. The failure mode to watch for is not a missing free but an unbounded live set: a cache or list that keeps growing, so the arena's reserved bytes climb forever. The memory-event log records arena growth over time so you can find the leak, attribute it to a source location, and do an OOM post-mortem even after a crash.

The 30-second version

# 1. Compile with --mem-track (arms the arena instrumentation)
superj compile myapp.sj --sdk-path $SJ_HOME/sdk --link --mem-track --output myapp

# 2. Run with SJ_MEM_LOG pointing at a path (arms the log at runtime)
SJ_MEM_LOG=tmp/myapp.mlog ./myapp

# 3. Read the log
superj memlog tmp/myapp.mlog

That's it. The log is a binary file (SJML format) written via mmap — no write() syscall per event, no formatting, no allocation on the event path. It survives a SIGKILL (the kernel flushes the mmap'd pages).

How it works

The facility has three enablement tiers, so the default build pays nothing:

--mem-track arms the arena instrumentation in the runtime. SJ_MEM_LOG arms the log at runtime. The two-level design lets you toggle tracing per deploy without a rebuild.

What gets logged

Only chunk-granularity events — the per-object allocation fast path is never touched. A chunk is added every few KB, so there are thousands of events over a whole run, not millions per second.

Allocation domains

There is one default domain: the global arena (SPEC §7.2). new objects, arrays and String bodies alike are arena memory (#3527, #3528) and are covered per-event (CREATE/EXPAND/DROP).

The malloc-live figure in a SNAPSHOT record still exists and still reports what the malloc domain holds — but with Strings moved out, it no longer accounts for string growth. Read arena growth for that.

Reading a log: superj memlog

superj memlog <path>          # one-shot replay
superj memlog --tail <path>   # live-tail a running process

No path defaulting — you pass the log file explicitly. (The runtime defaults to tmp/sj_mem_<pid>.mlog when SJ_MEM_LOG is unset, but superj memlog requires an explicit argument.)

The replay report has six sections:

1. Header

== memory-event log ==
path: tmp/demo.mlog
version: 1  recordSize: 32
pid: 25583  startTsNs: 456213013850041
writeCursor: 13 / capacity: 131072
file bytes: 4194368

The writeCursor is the number of records written; capacity is how many slots the current mapping holds. If the file is smaller than header + writeCursor * 32, the log was truncated (e.g. SIGKILL before kernel flush) — the tool reads what it has and notes the truncation.

2. Events

== events ==
ARENA_CREATE:  4
ARENA_EXPAND:  5
ARENA_DROP:    3
SNAPSHOT:      1
total chunks:  9
live chunks:   9

Counts of each event type. live chunks is the number of arena chunks still alive at the end of the log (not yet dropped).

3. Global

== global ==
final reserved:    18568 bytes
high-water:        50864 bytes
timespan:          350778 ns

The global reserved total (all arenas summed) at the end, and the high-water mark over the whole run. The high-water is the peak memory the process held.

4. Per-site — is each arena block actually buying anything?

== per-site (arena blocks) ==
  demo.sj:5   entries=1  reclaimed=983040 bytes  mean=983040  max=983040  share=31%
  demo.sj:11  entries=1  reclaimed=65536 bytes   mean=65536   max=65536   share=2%
  (share = this block's reclaim as a fraction of the 3080192-byte high-water)

One row per arena block, summed over every time it ran — unlike the per-arena section below, which prints a row per entry, so a block inside a loop produces thousands of rows and answers nothing. entries is how many times the block was entered, reclaimed the bytes its arena handed back in total, and share that as a fraction of the process high-water.

This is the section to read when you want to know whether a block is worth having, because the compiler cannot tell you. W_ARENA_NO_SAVINGS warns only when every allocation in a block escapes it, so a block that reclaims a few hundred bytes while megabytes escape is silent — and the size it would need to know is genuinely invisible at compile time when the escaping value is an object whose constructor allocates the buffer, or an array whose length is a variable.

The two rows above are the same program allocating the same 819 KB two ways:

arena a { for (int i = 0; i < 200; i++) { byte[] b = new byte[4096]; use(b); } }

class Payload { byte[] data; Payload(int n) { this.data = new byte[n]; } }
arena b { for (int i = 0; i < 200; i++) { Payload p = new Payload(4096); use(p); } }

Block b reclaims one chunk instead of 983040 bytes. This transcript predates #3801; scoping is now ambient, so a provable callee's allocations join the block too. The shape below still holds for a CARVED-OUT callee, which is what an unannotated native is: only new written inside the braces is a candidate for the block's arena, so b holds the 200 Payload headers while every byte[4096] — allocated inside the constructor — belongs to the global arena and is never freed. Nothing warns, because the Payload objects really do die in the block. Their payload never entered it.

Deliberately, this section reports numbers and not a judgement: a low share can be perfectly fine (a block may exist for scoping, not savings), and every threshold tried for it was wrong in both directions.

5. Per-arena (capped by default)

Live arenas are printed in full — they are what still holds memory — and dropped ones are capped at 20 rows (#4743), with a line saying how many were withheld. Without the cap a block entered once per request produces one row per request: a 17 ms run of a 100,000-entry block gives a 6.9 MB report with the verdict at line 100,053. The per-site section above is the readable form of the same data; superj memlog --all-arenas <log> restores every row.

Arena 1 is always the process's global arena and says so. It has no creation site because it is not a block anyone wrote — printing <unknown> there reads as a resolution failure on exactly the row a global-arena leak lands you at.

The original per-arena notes

== per-arena ==
  arena 1: final=18568  dropped=0  site=(global arena — no creation site; it is not a block)  LIVE
  arena 2: final=28200  dropped=28200  site=memlog_demo.sj:15  dropped
  arena 3: final=4096  dropped=4096  site=memlog_demo.sj:21  dropped
  arena 4: final=16392  dropped=16392  site=memlog_demo.sj:29  dropped

Each arena's final reserved (if still live) or reserved-at-drop, the bytes freed on drop, and the creation site (file:line where the arena {} block was declared). arena 1 is the global arena (always live, no site).

This is the key section for attribution: if reserved keeps climbing, the arena responsible is the one still LIVE with a large final.

6. Leak verdict + scope

The verdict prints first, right after the header, because it is the question you opened the file with (#4743). When the only arena still holding memory is the global one, it also says that this log cannot attribute the growth further, and points at --mem-debug (#4739/#4741), which can.

The malloc domain section is printed only when it is non-empty: String bodies are arena memory (#3528), so on an ordinary program the malloc domain has nothing to say.

== leak verdict ==
insufficient snapshots for slope — replay the CREATE/EXPAND/DROP timeline above

== malloc domain ==
last snapshot malloc-live: 4200 bytes  (Strings/maps)

== scope ==
arena domain: per-event (CREATE/EXPAND/DROP).
malloc domain (Strings/maps): aggregate in SNAPSHOT.
creation-site attribution: available (3 sites)

The leak verdict compares reserved at the first snapshot vs the end: a positive delta means GROWING (possible leak), a negative delta prints shrinking (-N bytes since first snapshot) — no leak (reserved dropped — e.g. the run's reserved-chunk high point fell at or before the first snapshot rather than at the end), and a delta of exactly zero prints steady — no leak signal. The scope section is honest about what's covered.

The (Strings/maps) label in that output is stale, and is reproduced here as the tool actually prints it. String bodies moved to the global arena in #3528, so they are counted in the arena domain, not the malloc one — a growing string population shows up in the arena figures above, not in malloc-live. The label is a cosmetic wart in the reporter, not a measurement error.

Live-tail

superj memlog --tail tmp/myapp.mlog

Polls the log's writeCursor and streams new records as the traced process writes them. Terminates after a ~10-second quiet period (the process has exited). Relies on the runtime's write-record-then-bump-cursor ordering so a half-written slot is never read.

Worked example

The example program $SJ_HOME/demo/memlog_demo.sj simulates a request loop with two scoped arenas:

# Compile with --mem-track
superj compile $SJ_HOME/demo/memlog_demo.sj --sdk-path $SJ_HOME/sdk --link --mem-track \
  --output tmp/memlog_demo

# Run — the log is written to SJ_MEM_LOG (or tmp/sj_mem_<pid>.mlog if unset)
SJ_MEM_LOG=tmp/demo.mlog ./tmp/memlog_demo

# Read the log
superj memlog tmp/demo.mlog

Output (abridged):

processed 5000 requests, sum=122500

== per-arena ==
  arena 1: final=18568  dropped=0       site=(global arena — no creation site)   LIVE
  arena 2: final=28200  dropped=28200   site=memlog_demo.sj:15   dropped
  arena 3: final=4096   dropped=4096    site=memlog_demo.sj:21   dropped
  arena 4: final=16392  dropped=16392   site=memlog_demo.sj:29   dropped

Arena 1 is the global arena (startup objects, always live). Arena 2 is the requestBatch block at line 15 (28 KB of request results + scratch). Arena 3 is the nested scratch block at line 21. Arena 4 is the cache block at line 29. All three scoped arenas were dropped (their chunks freed), so the final reserved returns to the global arena's 18568 bytes.

If arena 4 (cache) had not been dropped — say you forgot the arena {} block and allocated keys into the global arena — it would show LIVE with a large final, and the global high-water would not come back down. That's the leak signal.

In-process query counters

Two System builtins give you the live reserved/high-water without reading a log file:

long r = System.memReservedBytes();   // current global reserved (arena domain)
long h = System.memHighWaterBytes();  // high-water mark over the process lifetime

Both are live on every build — they are plain counters on the arena chunk malloc/free path, not part of the --mem-track / SJ_MEM_LOG facility (which gates only the mmap event log). They cost two adds on a cold path and need no special build. Useful for self-monitoring (e.g. logging reserved every N requests) and for asserting that scoped memory came back — the delta across a call that opens an arena {} block should be 0:

long before = System.memReservedBytes();
handleRequest(req);
long leaked = System.memReservedBytes() - before;   // want 0

They report reserved chunk capacity (moving in chunk-sized steps, not per-object) and only the arena domain.

String bodies are arena memory and a string-building leak does move these counters — measured: a 1M-iteration "item-" + i + "-suffix" loop outside any block moves memReservedBytes by 130 MB.

SPEC §7.4 requires a string built inside an arena block and dying there to be reclaimed with the block (#3101), and it is: the same loop inside a block moves memReservedBytes by 0 (#3664, #3712).

What these counters still show growing is a string a callee built and handed back — sb.toString(), Integer.toString(i), or your own helper returning "v" + i. Arena placement is lexical, so a block cannot claim an allocation written in another frame (#3640). If a block-shaped loop grows here, look for a string producer one frame down before suspecting the counters.

Debug build: per-type histogram

For object-level attribution — which types own the live set — compile with --mem-debug instead of --mem-track. It arms everything --mem-track does and adds the histogram, so one flag covers a whole leak hunt: the log says when the arena grew, the histogram says what is in it.

superj compile myapp.sj --sdk-path $SJ_HOME/sdk --link --mem-debug --output myapp
SJ_MEM_LOG=myapp.mlog ./myapp        # histogram on stderr at exit; log as usual
superj run --mem-debug                # or from inside a project

This instruments every allocation, so it is a debug build and must never be used in production. Nothing else is needed — no hand-compiled runtime object and no hand-written link line.

At exit the histogram prints to stderr:

== memory histogram (debug build, SJ_MEM_DEBUG) ==
  type                      global_bytes   glob_cnt    block_bytes    blk_cnt  stack_cnt
  Kept                             48000       2000              0          0          0
  Tmp                                  0          0         480000      20000          0
  Churn                                0          0              0          0      20000
  TOTAL                            48000                    480000
== end histogram (3 types; global_bytes is RETAINED for the process, block_bytes is churn
   reclaimed on block exit) ==

Read the columns, not the row size (#4740). Nothing here is ever decremented — an arena frees chunks, not objects — so a single "live bytes" number would be cumulative, and on a program that churns through arena {} blocks its biggest rows would be memory that has already been handed back. The split makes each column true by construction:

In the example above Tmp and Churn each allocate 20,000 times and neither is a leak, while Kept allocates 2,000 times and is the only row that grows the process. One number could not have told them apart.

global_bytes is complete: every global allocation goes through sj_galloc*, which reports here. block_bytes is a lower bound — it counts what a callee allocates under an armed block, not an allocation written lexically inside one (codegen emits those as a direct sj_arena_malloc) nor a String body.

Which line? The per-site section

The same run prints a second table keyed by source line, ordered by retained bytes, so the first row is where to look (#4739):

== allocation sites (debug build, SJ_MEM_DEBUG) ==
  site                    global_bytes   glob_cnt    block_bytes    blk_cnt  stack_cnt
  Sites.sj:6                   1056000       4000              0          0          0
  Sites.sj:17                   128000       4000              0          0          0
  Sites.sj:18                     8000        500              0          0          0
  Sites.sj:21                        0          0         820000        100          0
  TOTAL (attributed)           1196040                    820000
  coverage: 1196040 of 1219981 retained bytes attributed to a source line (98%)

Line 6 here is a constructor's new byte[256]; line 17 is the new Session(i) that calls it. The megabyte is on line 6, and the type table could not have told you that — both lines would have read as Session and <raw/array>.

Two things to know before you trust a row:

• Read the coverage line first. A site id is emitted by the caller, so an allocation made inside the prebuilt SDK archive emits no call at all and cannot even show as unattributed. The per-type table above is the denominator. String bodies are the main uncovered kind — sj_str_alloc allocates from C with no site to report — so a string-churn leak will show in the per-type table and in the remainder, not as a row here.
• The columns mean what they mean above: a big block_bytes with global_bytes at 0 (line 21) is a block doing its job, not a leak.

Growth, not totals: System.memReport(label)

A leak is a slope. A total cannot show one — a 4 MB buffer allocated once at startup outranks a 480 KB leak in every row ordering, forever, and the leak is the bug. Call memReport around the work you suspect and read the d_global column, which measures retention since the previous report (#4741):

warmUp();
System.memReport("baseline");
for (int i = 0; i < 20000; i++) handle(i);
System.memReport("after 20k");

== allocation sites (debug build, SJ_MEM_DEBUG) — after 20k ==
  site               global_bytes   glob_cnt   block_bytes   blk_cnt  stack_cnt      d_global
  Growth.sj:14             480000      20000             0         0          0        480000
  Growth.sj:3             4000008          1             0         0          0             0
  (ordered by d_global — growth since the previous report — not by total)

Line 3 holds eight times the bytes and is not the problem; line 14 is. Once a baseline exists the table is ordered by growth, so the top row is the answer.

Every report re-baselines, so consecutive calls read as "what grew between them" with no state to manage. For a long run you would rather not edit, set SJ_MEM_HIST_EVERY=<bytes> and the runtime emits the same series every N bytes of global allocation.

memReport is a no-op on every build that is not --mem-debug, like the rest of the System.mem* family, so a call can stay in source that ships.

The debug build also poisons freed arena memory with 0xDE when an arena block is dropped, so a use-after-drop read crashes or reads the poison pattern instead of silently reading stale objects.

Wire format

The log file is a versioned 64-byte header followed by fixed 32-byte little-endian records, optionally followed by a trailing site-table section. The format is stable (version 1); the replay tool validates the magic (SJML) and version before reading.