Allocation Profiling in Java: Finding Garbage Hot Spots

Allocation went up, throughput went up fifteenfold

The fix made the allocation rate go up.

                    ops/s        bytes/op    allocation rate
before              0.73 M       1,788       1,323 MB/s
after              11.00 M         136       1,497 MB/s
OpenJDK 21.0.12.1, G1, -Xms256m -Xmx256m, 2 vCPU Xeon 2.80 GHz, 8 GB, no container limits
means of 5 interleaved runs, 3 s warm-up + 6 s measured, one thread

Fifteen times the throughput, thirteen times fewer bytes allocated per operation, and the number on the GC dashboard went the wrong way. If your review of an "allocation fix" is a glance at the allocation rate, you'd have rejected this one. I nearly did.

That's the whole reason allocation profiling in Java has to end in bytes per operation. Here's the version I use now: find the call sites that allocate the most, fix the heaviest, profile again, and prove the result in bytes per operation instead of megabytes per second. It took me a good while longer than the lab suggests, mostly in the places where my first read of the evidence was wrong. Those are written down below so you don't have to repeat them.

Bytes per operation, not megabytes per second

Allocation rate is how fast the JVM is handing out heap, in MB/s. Allocation per operation is how much each unit of work costs. Those two numbers are only related if throughput stays still, and nobody tunes with throughput standing still.

In an allocation-bound loop the rate settles near whatever the machine and the collector can sustain. Make each operation cheaper and the loop runs faster, so it allocates just as fast as before, with smaller pieces. Across the eight variants I measured, the rate sat between 1.26 and 1.70 GB/s. Throughput went from 0.73 million to 11.0 million operations a second. The rate told me nothing about any of it.

What's actually slow here is the code at three call sites, not the garbage collector. GC was about 1.2% of wall time in the slow build. I assumed GC first anyway. That assumption got its own experiment, further down.

A statement exporter with three bad habits

The lab is a loop that renders one payment line per transaction, the kind of thing a statement export or a reconciliation job does a few hundred thousand times. Three habits, each one switchable, each one something I've seen in real code:

• String.format to build the line (call it F).
• Splitting your own output on commas to get the account back out (S).
• A temporary list per call, with trim().toUpperCase() on every field when you want one of them (L).

What you need. OpenJDK 21.0.12.1 (the Ubuntu build, java -version says 21.0.12.1+1-1-24.04.4-Ubuntu). Nothing else. No JMH: Maven Central wasn't reachable from my sandbox, so this is a hand-rolled harness with the usual caveats. I use a fresh JVM per run, a sink variable so the work can't be deleted, and interleaved runs so drift doesn't pick a winner. If you want the JMH version, -prof gc reports the same thing as my bytes/op column, under the name gc.alloc.rate.norm.

import java.lang.management.ManagementFactory;
import java.util.*;

public class Lab {
    record Txn(long id, String account, long cents, String currency) {}
    static final String[] ACCTS = new String[5000];
    static { for (int i = 0; i < ACCTS.length; i++) ACCTS[i] = "ACC-" + (100000 + i * 7); }

    static Txn[] data(int n) {
        Random r = new Random(42);
        Txn[] t = new Txn[n];
        for (int i = 0; i < n; i++)
            t[i] = new Txn(i, ACCTS[r.nextInt(ACCTS.length)], r.nextInt(1_000_000), (i % 3 == 0) ? "EUR" : "USD");
        return t;
    }

    static String lineFormat(Txn t) {            // habit F
        return String.format("%d,%s,%d.%02d,%s", t.id(), t.account(), t.cents() / 100, t.cents() % 100, t.currency());
    }
    static String lineBuilder(Txn t) {           // the fix for F
        StringBuilder sb = new StringBuilder(48);
        sb.append(t.id()).append(',').append(t.account()).append(',').append(t.cents() / 100).append('.');
        long c = t.cents() % 100;
        if (c < 10) sb.append('0');
        return sb.append(c).append(',').append(t.currency()).toString();
    }
    static String key(Txn t, String line, boolean slow) {
        if (slow) return line.split(",")[1];     // habit S: parse what we just wrote
        return t.account();
    }
    static long keysHash(String key, String line, boolean slow) {
        if (slow) {                              // habit L: a list, four trims, four upper-cases
            List<String> keys = new ArrayList<>();
            for (String p : line.split(",")) keys.add(p.trim().toUpperCase());
            return keys.size() + keys.get(1).hashCode();
        }
        return 4 + key.toUpperCase().hashCode();
    }
    static long render(Txn t, boolean f, boolean s, boolean l) {
        String line = f ? lineFormat(t) : lineBuilder(t);
        return line.length() + keysHash(key(t, line, s), line, l);
    }

    public static void main(String[] a) {
        String m = a[0]; int warm = Integer.parseInt(a[1]); int secs = Integer.parseInt(a[2]);
        boolean f = m.contains("F"), s = m.contains("S"), l = m.contains("L");   // letters present = habit ON
        Txn[] d = data(200_000);
        var tmx = (com.sun.management.ThreadMXBean) ManagementFactory.getThreadMXBean();
        long tid = Thread.currentThread().threadId();
        long sink = 0, ops = 0;
        long end = System.nanoTime() + warm * 1_000_000_000L;
        while (System.nanoTime() < end) for (Txn t : d) sink += render(t, f, s, l);
        long b0 = tmx.getThreadAllocatedBytes(tid);   // exact bytes this thread has allocated, JDK-wide counter
        long t0 = System.nanoTime(); end = t0 + secs * 1_000_000_000L;
        while (System.nanoTime() < end) { for (Txn t : d) sink += render(t, f, s, l); ops += d.length; }
        long t1 = System.nanoTime();
        long b1 = tmx.getThreadAllocatedBytes(tid);
        System.out.printf("mode=%s ops/s=%.0f bytes/op=%.1f allocMB/s=%.0f chk=%d%n",
            m, ops / ((t1 - t0) / 1e9), (b1 - b0) / (double) ops, (b1 - b0) / 1e6 / ((t1 - t0) / 1e9), sink);
    }
}

chk is printed so the JIT can't discard the loop. It isn't a correctness check across modes, because it sums over however many operations ran. Per operation the fast and slow paths return the same value by construction, and I didn't diff full output between them.

# Step 1: baseline, all three habits on
$ javac -d out Lab.java
$ java -Xms256m -Xmx256m -cp out Lab FSL 3 6
# Expected: roughly 0.7 M ops/s and ~1,790 bytes/op. Your ops/s will differ; bytes/op should land within a few bytes.

# Step 2: record it with JFR's profile settings
$ java -Xms256m -Xmx256m -XX:StartFlightRecording=filename=p.jfr,settings=profile -cp out Lab FSL 3 15

# Step 3: dump allocation events WITH deep stacks (see the trap in the profiling section)
$ jfr print --json --stack-depth 64 --events jdk.ObjectAllocationSample p.jfr > alloc.json

Cleanup is rm -rf out *.jfr *.json. Nothing here leaves a process running.

Forcing lever: a 256 MB heap and a single thread. That makes young collections frequent enough to see in a minute. A real service has more threads, a bigger heap, and some of this cost hidden behind I/O. The ratios carry; the absolute numbers won't.

What the harness measured

Run-to-run spread for a variant was 1–8% (coefficient of variation). Anything under about 10% between two rows here is noise. The one-habit-at-a-time effects are not: fixing F alone is 2.8x, fixing the list alone is 1.25x, fixing the split alone is 1.12x.

Why a stream of dead objects still costs you

Almost nothing in this loop survives. Each String, byte[], ArrayList and Formatter is dead within a microsecond. So the collector has little to do, and the pause total backs that up: 132 to 143 ms across about 11 seconds. The cost is on the allocating side. Every new object means zeroing memory, writing a header, filling the thing in, and pushing fresh cache lines through a CPU that has to evict others. A 1.3 GB/s stream of that is a CPU cost, in your own thread, before the GC ever hears about it.

How the JVM hands out that memory (thread-local allocation buffers, the refill path, why escape analysis sometimes removes the whole thing) is owned by my write-up on object allocation and TLABs, which I haven't published yet, so I'll leave it there. The only fact you need from it for profiling is this one: JFR's allocation sampler uses the same data source as the older per-TLAB events (that's what the post I read says), which means it sees buffer refills and out-of-buffer allocations, not each new. It estimates from them.

Allocation profiling in Java with JFR, step by step

JFR ships a sampled event called jdk.ObjectAllocationSample, with a throttle so it can't swamp a busy service. I checked the throttle on this JDK instead of trusting a 2021 blog post: default.jfc sets it to 150 samples a second, profile.jfc to 300. The older per-TLAB events (ObjectAllocationInNewTLAB, ObjectAllocationOutsideTLAB) were off in both recordings I took. Zero events each.

The event's own description, from jfr metadata, says what the weight means: aggregate it over a big enough set of samples for a class, thread or stack trace and you get "a statistically accurate representation of the allocation pressure". Each event is a sample, and the weight is the estimate. Don't count events.

Check that claim against the exact counter. My 18-second recording summed to 22.5 GB of weight. The harness itself had counted about 1.3 GB/s over the same stretch, which is about 23 GB. Close enough to trust the proportions.

Now the trap. My first analysis script grouped weight by the first frame of each stack, which gives this:

 14.9%  java/lang/StringLatin1.newString
 14.7%  java/util/Arrays.copyOfRangeByte
 13.7%  java/util/ArrayList.grow
 12.4%  java/util/Formatter.parse
 10.1%  java/util/regex/Matcher.<init>

That's useless. It says "strings, arrays and a list allocate". I knew that. Worse, when I tried to roll it up to the first frame in my own code, 75% of the weight came back unattributed. jfr print only keeps 5 frames per stack by default (--stack-depth, "by default 5" in its own help), and my code sat deeper than that under String.format and split. The tool truncated quietly. With --stack-depth 64:

-- weight by first frame in Lab (profile settings, 5,414 samples)
 60.8%  lineFormat      <- habit F
 23.8%  keysHash        <- habit L
 15.2%  key             <- habit S

Now there's a ranking you can act on. The method to attribute to is the one nearest your code, not the one at the top of the stack. For a service, that means grouping by the first frame under your package prefix, and keeping the leaf frame as a second column to say what kind of object it is. Here the classes were byte[] (28%), String (19%), Object[] (15%), int[] (10%) and Formatter$FormatSpecifier (8%).

The default-settings recording agreed on the order with half the samples (2,732, since the throttle is 150 a second): 65.3% / 23.0% / 11.6%. A cheap recording on a production box is enough to rank sites. It's not enough to split hairs between two sites that are within a few points of each other.

The CPU profile has a different opinion

The same recording has 1,374 jdk.ExecutionSample events (CPU samples). By the same first-frame attribution: lineFormat 69.7%, keysHash 17.4%, key 11.6%. Close, but not the same. On a loop that's all allocation, CPU and allocation weight mostly agree. They won't in a service where one method allocates a lot of cheap garbage and another burns CPU on arithmetic. Take both, and look for the sites that are high in both. If a site is hot in the allocation profile and invisible in the CPU profile, allocation is probably its whole cost, and the fix is cheap to try.

The bigger heap, and other things that did nothing

I told you I assumed GC first. Here's what I ran: the all-slow build and the all-fixed build, each at the 256 MB heap and at 2 GB, three interleaved rounds.

Eight times fewer collections. Throughput on the slow build is the same within noise. On the fixed build the 2 GB heap was slower in all three rounds, by about 8%. I don't know why. A larger young generation touches more distinct memory before it's reused, which would hurt the cache, but that's a guess and I didn't measure it. What I do know is that a bigger heap bought nothing, because the pause time was already about 1.2% of the run.

This is the tip everybody pastes when "GC overhead" shows up: raise -Xmx. It removes collections. It doesn't remove allocation, and allocation was the cost. If your GC log says pauses are a sliver of wall time (my write-up on reading GC logs covers how to get that number), the heap is not your problem.

Other readings that mislead:

• Allocation rate as the success metric. Shown above. Use bytes/op, from ThreadMXBean.getThreadAllocatedBytes in a harness or gc.alloc.rate.norm in JMH. In production, divide the rate by your request rate.
• Object pools. I'd delete most I've seen. Pooling tends to move the cost into synchronization and cache misses, and long-lived objects are harder on a generational collector (that's reasoning, not something I measured here). Fix the site first; measure before you pool.
• Reading the top frame. Above. It tells you the JDK allocates.
• Believing one recording. Two sites close in weight can swap places. Take two or three, and only act on gaps that survive.
• -XX:+UseStringDeduplication for this. It targets long-lived duplicate strings. These strings die in microseconds. I haven't tested it here, so I'm telling you why it shouldn't apply, not that I saw it fail.

Fix the heaviest site, then profile again

The ranking said format first. That's also what the experiment says: fixing F alone gives 2.8x. The list was second at 1.25x and the split last at 1.12x. The profile shares (61 / 24 / 15) and the measured byte savings per habit (56% / 19% / 16% of 1,788 bytes) line up closely enough to plan with.

Order matters in a way the table hides, so I re-recorded after the first fix. With String.format gone, the default-settings profile reads keysHash 40.0%, key 37.8%, lineBuilder 22.1%. The split moved from last to nearly first, because its share of a smaller pie grew. That's the point of profiling again after each change. Here's the path I took:

step                      ops/s     bytes/op
all slow                  0.73 M    1,788
fix format (F)            2.02 M      792
fix split (S) next        3.10 M      504
fix list (L) last         11.00 M     136

The last step is the biggest jump in throughput (3.10 M to 11.00 M) for a smaller drop in bytes than the first step, and I can't say why from this lab. The list fix removes a split, four trim calls and four toUpperCase calls in one go, so there's more than allocation going on. I didn't decompose it.

What the fixes cost: StringBuilder code is longer and harder to read than a format string, and if the schema changes, you'll change more lines. Passing the account straight through instead of re-parsing it couples two methods that used to be independent. For a hot export loop I'll pay that. For a method that runs once per request behind a database call, I wouldn't touch it.

The remaining 136 bytes per operation are the line itself, its builder, and the upper-cased copy. I didn't profile that floor, and I'd stop here. Going lower means not building the string at all.

Making the number stick

Repeated runs: five interleaved rounds per variant, spread 1–8%, with the single-fix effects well outside that. If you have a smaller gap, use the fork-and-noise method in my post on benchmark statistics, and take a baseline first with the performance baseline checklist.

In production there are three things to watch after an allocation change. Bytes per request (allocation rate divided by request rate, from the same window). Young-collection frequency in the GC log. And p99 latency, which is the number you did this for. Give it a full traffic cycle. The jdk.ThreadAllocationStatistics event is already in the recordings I took (24 events in the 18-second profile recording), and it gives cumulative bytes per thread if you'd like a per-thread view without a profiler attached.

A regression guard: put a bytes/op assertion on the hot method in a unit test, using getThreadAllocatedBytes, with a 20% tolerance. It's far less flaky than a timing assertion because it doesn't depend on the machine. My regression-testing post covers the CI side; it's not published yet.

Version safety: I ran only JDK 21.0.12.1. The foojay post places jdk.ObjectAllocationSample in JDK 16, so 17 and 21 should both have it; I ran neither 17 nor 25. The throttle defaults come from the .jfc files that ship with the JDK, so on a different JDK, read your own default.jfc and profile.jfc. On any JDK upgrade, re-take the profile. Inlining and escape analysis change between releases, and a site that was heavy on 21 can disappear on 25.

Leave these in the PR description

• Allocation rate doesn't tell you whether you improved anything. Bytes per operation does.
• Attribute allocation weight to the frame nearest your code, and pass --stack-depth to jfr print or you'll silently lose it.
• Profile again after every fix. The ranking moves.
• If GC pauses are around 1% of wall time, a bigger heap won't help. Fix the sites.
• Cheaper recordings (150 samples/s) are fine for ranking; only close calls need more.

Questions about Java allocation profiling

How do I find which code allocates the most in Java? Record with JFR (settings=profile), print jdk.ObjectAllocationSample events with a deep --stack-depth, and sum the weight by the first frame in your own packages. On JDK 21 the profile settings sample 300 times a second and the default settings 150. The weights sum to total allocation, so the shares are what you read.

Is a high allocation rate always bad in Java? No. Young collections are cheap when objects die quickly, and in my lab 1.3 GB/s cost about 1.2% of wall time in pauses. The rate matters when it comes with long pauses, a growing live set, or a CPU profile full of allocation and copying. The better question is how many bytes each request costs.

Does JFR allocation profiling slow my service down? The sampler is throttled, so event volume is capped. I didn't measure the overhead in this lab and I won't claim a number. My earlier JFR post measured overhead across recording modes, and all of it was within noise on that box.

Should I use object pools to cut allocation? Fix the allocating call site first. A pool trades allocation for contention and longer object lifetimes, and I haven't seen one beat allocating less in modern code. If you still want one, measure bytes/op and p99 before and after, under realistic concurrency.