Profiling

I blamed the garbage collector for a slow parser this week. It was a satisfying theory because it required no evidence and made the runtime somebody else’s problem. Then I collected a CPU profile.

The programme only needed a profile file and a bounded run:

f, err := os.Create("cpu.prof")
if err != nil {
	return err
}
defer f.Close()

pprof.StartCPUProfile(f)
defer pprof.StopCPUProfile()

parseAll(files)

The exact profiling API and command-line tools are still moving with the snapshots, but the important method is stable enough: measure a representative workload, inspect where samples accumulate, change one thing, and measure again.

My surprise was a tiny character-class helper near the top of the profile. It performed a linear search through a string for every input byte. The allocator appeared, but it was not remotely the villain I had prepared a speech about. Replacing the repeated search with a direct table lookup changed the run far more than any speculative memory trick.

A CPU profile is sampling, not a complete diary. At intervals, the runtime records where execution is spending time. Enough samples reveal hot stacks without instrumenting every function call. That means very short runs can mislead, and blocked time is not the same as CPU time. A programme waiting on disk may feel slow while producing an uninteresting CPU profile.

Heap information answers another question: what remains live or what has been allocated, depending on the profile and tool. I have learned not to blur those together. A high allocation rate can increase collection work even if the live heap stays modest. A large live heap can be perfectly reasonable if the programme genuinely needs the data.

I prefer profiles to stopwatch calls scattered through the source. The profile keeps context: not just how long a region took, but which call paths led there. A small benchmark is still useful after the profile identifies the narrow piece worth isolating.

The caveat is representativeness. Profiling a toy input optimizes the toy. Debug output, cold caches, and a different machine can also distort results. I record the snapshot version and input beside the profile because both are part of the result.

The parser is faster now. More importantly, the garbage collector has been acquitted for lack of evidence, which is the closest a runtime component gets to an apology.

I was certain my parser spent its time converting decimal numbers. Certainty is a useful indication that I should profile before touching anything.

The tools include a real-time sampling profiler named 6prof. Despite the name, it also understands the other supported architectures. The interface is still moving, so this is a note about the weekly release on my desk rather than scripture.

I let the profiler start the real program:

$ 6prof ./logsum
  46.8%  bytes.(*Buffer).Write
  21.1%  runtime.memmove
   8.7%  parseNumber

On Linux/amd64 I can ask it to write pprof data, provided the program was linked with 6l -e:

$ 6prof -P cpu.prof ./logsum

The exact output format varies, but the result was unambiguous. My “efficient” reporting path repeatedly grew a byte buffer. Number parsing was visible and not remotely the first problem.

Preallocating a reasonable output buffer removed most growth and copies. Runtime dropped by roughly a third on the same input. Replacing the decimal parser with a clever version afterward produced noise-sized improvement, so I reverted it. Clever code that cannot beat measurement is just decorative risk.

Sampling has limits. A short run may not gather enough samples, and compiler optimization can make line attribution odd. This profiler samples threads while they are running, asleep, or waiting for I/O, so a hot entry may be telling me about waiting rather than arithmetic. I feed several seconds of representative data and repeat runs. I also keep wall-clock timing around the complete operation because users do not experience percentages.

Input matters just as much. A profile from the tiny sample used by unit tests mostly measures startup and can confidently direct optimization toward irrelevant code. I use a captured workload large enough to reach steady behavior.

The young runtime itself appears in profiles. Garbage collection, allocation, copying, and scheduler work are part of the program’s cost, even if I did not type those function names. They should not automatically be dismissed as profiler clutter. Often they point back to an allocation pattern I control.

Now I reproduce, time, profile, change one thing, and time again. This lacks the emotional satisfaction of immediately rewriting the function I dislike. Annoyingly, it makes the program faster.