← Writing

Five profiles, one evening, and a bug in our own summarizer

· 7 min read

What happened when we pointed flamelens at our own app

On the evening of 27 July, someone spent about two and a half hours debugging a Spring Boot inventory app called warehouseorganizer. They took five profiler snapshots along the way, from IntelliJ, roughly twenty minutes apart:

20:52   4.8 MB
21:09   6.8 MB
21:22   5.8 MB
21:42  51.0 MB
23:27  43.4 MB

Those five files sat in ~/IdeaSnapshots for a week. We ran all five back through flamelens as a single tuning session — the same feature we sell, where consecutive scans are diffed so you can see whether your fix worked.

We expected a story about a bottleneck getting fixed. What we got was a bug report against ourselves.

Every single scan said the same thing

20:52 21:09 21:22 21:42 23:27
Samples 202,561 — 185,966 2,571,148 1,926,060
Threads waiting 98.3% 99.7% 99.5% 99.9% 99.9%
Samples in running threads ~3,479 ~592 ~827 ~2,451 ~1,641
Machine CPU 37% 40% 39% 21% 28%

Five recordings, taken hours apart, under different workloads, agreeing to within a rounding error. Each report opened with some version of "this application is almost entirely idle; whatever is slow about it is not CPU-bound."

That is a satisfying finding. It is also wrong, and the giveaway is the consistency. Real measurements of a system being actively debugged do not agree to one decimal place.

What the files actually were

.jfr is a container format, and the JVM's own Flight Recorder is not the only thing that writes it. Reading the recording metadata instead of just the samples:

jdk.ActiveRecording   name        = win-async-profiler 4.1
jdk.ActiveSetting     event       = wall
jdk.ActiveSetting     interval    = 10000000

These are async-profiler recordings in wall-clock mode, which is what IntelliJ's profiler button gives you by default. Wall-clock sampling walks every thread every 10ms, whether or not it holds a CPU. A parked thread in a connection pool is sampled exactly as often as a thread doing work.

So "99.9% of samples were waiting threads" is not a fact about warehouseorganizer. It is a fact about Tomcat having 200 idle worker threads, and it would have been true of any thread-pool service on earth. Our summarizer read wall-clock samples as if they were CPU samples, and manufactured the same confident, useless conclusion five times.

The same misreading explains two other things we had written off as quirks:

The self-contradicting GC section. Several scans attributed most running-thread time to GC_active while the GC section reported zero collections and zero pause. async-profiler never emits jdk.GarbageCollection at all. We were printing "0 collections" for an event type that was never in the file, and then the model — correctly noticing the contradiction — spent a paragraph of every report trying to reconcile it.

The 56-year recording. Some events arrive stamped at the Unix epoch, so a fifteen-minute recording reported a duration of about fifty-six years. We had already clamped that to "unknown"; now we know where it comes from.

What we changed

The summarizer now reads jdk.ActiveRecording and jdk.ActiveSetting before it reads a single sample, and the recorder and sampling mode go into the prompt:

Recorded by: win-async-profiler 4.1 (sampling event: wall)
Thread state: 99.9% of samples were threads WAITING, 0.1% were running code
  NOTE: this is a WALL-CLOCK profile — the profiler samples every thread on a fixed
  interval whether or not it is running. A large waiting share is how this mode always
  looks for a service with a thread pool, and is NOT evidence that the application is
  idle. Do not draw a conclusion from the waiting percentage itself.

GC: not recorded — this profiler does not emit collection events... This is NOT a report
  of zero collections; treat any GC frame in the hot list as unquantified.

Two distinctions we did not have before, and both matter more than the numbers around them:

  • CPU time is not wall time. The same sample counts support opposite conclusions depending on which one you captured.
  • Absent is not zero. "No monitor contention events" and "this profiler does not record monitor contention" look identical in an empty section, and only one of them licenses the sentence "there is no lock contention."

Both are pinned by regression tests, including one that asserts the wall-clock hedging does not appear for a genuine JVM recording — where an absent event really does mean the thing didn't happen.

What the data did support

Strip out the mode artifact and there is real signal left, because allocation sampling is not affected by any of this. The same theme recurs across all five recordings:

recording Thymeleaf/attoparser Spring type + expression total sampled
20:52 3.3 MB 7.3 MB 729 MB
21:09 — 29.4 MB 504 MB
21:22 — 99.4 MB 810 MB
21:42 — 78.0 MB 1,419 MB
23:27 18.3 MB 160.2 MB 1,278 MB

(Only the top 20 allocating classes are kept per recording, so these are lower bounds.)

ResolvableType, TypeDescriptor, MethodParameter, SerializableTypeWrapper, java.lang.reflect.Method — that is SpEL and Thymeleaf re-resolving types on every render, and it climbs steadily through the evening as the session moves to heavier pages. The developer's own read was that their wins came from not rendering elements in Thymeleaf on the backend, and this is the allocation signature of exactly that: server-side template expression evaluation, not the business logic underneath it.

Two other consistent findings:

The debugger was attached. Every recording contains com.intellij.rt.debugger.agent.CaptureStorage allocations — 14 MB in the first scan — plus matching StackTraceElement and Throwable.fillInStackTrace volume. That is IntelliJ's async-stack-trace capture instrumenting method entry and exit. Whatever these recordings measured, it was not the application as it ships.

Classpath work never stops. WinNTFileSystem.canonicalize0, ZipFile$Source.getEntryPos, URLClassPath.getLoader — a large share of running-thread samples in the last scan, persisting across recordings taken hours apart.

Does recording size tell you anything about traffic?

We wondered whether file size tracked request volume — a 51 MB recording sounds like a busy one. It doesn't. That file is 99.6% jdk.ExecutionSample:

1,911,566  jdk.ExecutionSample        (99.6%)
   12,279  jdk.ObjectAllocationSample
    1,742  jdk.CPULoad

At a fixed 10ms interval across every thread, size is duration × thread count, and an idle thread costs exactly as much as a busy one. There is not a single request-shaped event in the file — no socket, HTTP, servlet, or JDBC events at all. The 51 MB recording is not busier than the 4.8 MB one; it is longer, and it was taken with more threads alive.

The diff told on us too

The session's scan-to-scan diff looked like this:

scan 2:  resolved 3, persisting 1, introduced 4
scan 3:  resolved 3, persisting 2, introduced 4
scan 4:  resolved 3, persisting 3, introduced 3
scan 5:  resolved 3, persisting 3, introduced 2

Read that as a progress report and you would conclude the developer fixed three things every twenty minutes and broke three more. They didn't. The findings churn because the ranking beneath them is built on a few hundred to a few thousand samples. Rank noise and the ranking moves.

A progress diff is only meaningful when both scans had something to measure. We are changing the session view to say so rather than present a churn count as if it were progress.

What we would tell this developer

  1. Re-record in CPU mode (asprof -e cpu, or JFR's own -XX:StartFlightRecording) if the question is "what is burning CPU". Wall mode answers a different and also useful question — where is wall time going — but you have to know which one you captured.
  2. Detach the debugger. The capture instrumentation is in every one of these files.
  3. Record under load. Ten seconds of the slow request beats two hours of sitting there.
  4. The SpEL and Thymeleaf allocation churn is real and survives all of the above.

What it cost

Five scans, 67 cents. Roughly 2,300 input and 4,900 output tokens each — the reduction step means a 51 MB recording and a 4.8 MB one cost about the same, because both collapse to about a kilobyte of summary before the model sees them.

The honest conclusion

We built this tool on the premise that the hard part of profiling is not reading a flame graph, it is noticing that your capture never contained the problem. Then we shipped a summarizer that couldn't tell which kind of capture it was holding, and it produced five confident reports of an idle application that was not idle.

The model did not invent that. It was told "99.9% of samples were threads waiting, this process was mostly idle" and reasoned correctly from a false premise. That is the failure mode that matters in this category of product: not hallucination, but a summarizer that quietly discards the one piece of context that made the numbers mean something.

Everything a model says about your profile is downstream of what the reduction step chose to keep.

flamelens analyses profiler recordings — JFR, V8 .cpuprofile, py-spy, dotnet-trace, and perf — and gives you ranked findings with the evidence behind them. The aggregated, anonymized version of what everyone is finding lives at /blog, free, including for the maintainers of the libraries that show up in it.

Run this on your own profile

flamelens turns a profiler recording — JFR, V8 .cpuprofile, py-spy, dotnet-trace, or perf — into ranked findings with the evidence behind them. The first five scans are free.

Start scanning