Where does the time go?

A flame graph of one run on the JVM behind this site. Each bar is a method; its width is the share of samples taken while it, or a method it called, was running, and the bars beneath it are what it called. The wide bar at the bottom of a stack is where the time goes.

In the recorded quadratic dedupe, every sample sits under ArrayList.contains, split between indexOfRange and Integer.equals: the list is scanned again for every value. The fix, a HashSet, took 2 ms against 566, too quick for the sampler to catch it even once.

Each run’s worker threads get names of their own, and Flight Recorder’s event streaming (JEP 349) records them inside the same JVM: an execution sample every 5 ms, allocation samples, every contended monitor entry and every collection. Stacks are cut to start at the scenario’s code and folded into a tree; branches under half a percent are dropped, and their time stays counted in the parent.

Sampling has blind spots. A thread waiting for a lock is not running, so it is never sampled: the hot lock’s waits come from monitor events instead, 2,574 of them in the recorded run. And work the JIT turns into an intrinsic can be charged to its caller: a first version of the quadratic scenario drained an ArrayList from the front, and its profile showed a single bar for the loop that called it.

Performance profiling and JVM tuning are on my CV, and at Picsart I take part in tuning p99 latency and throughput. A profile is where that starts: it shows where the time goes before anything is changed.