Debugging Ends with an Explanation, Not a Green Build

A cryptography-heavy application kept its CPUs near 100 percent. We found several cryptographic paths worth improving, so the diagnosis felt obvious: expensive mathematics was consuming the machine. How could logging possibly be more expensive than the work the application existed to do?

Then we measured the log stream. It was writing roughly a thousand lines per second to local disk. We reduced the emitted logging without changing the cryptographic work, and CPU use settled around 10–20 percent.

The cryptographic findings were real. They just were not the dominant cause of the saturation. The less impressive subsystem explained the machine better than the sophisticated code beside it, and that was the explanation the evidence required whether it felt intuitive or not.

A plausible defect is not yet the cause

Complex code offers an endless supply of suspicious details:

an expensive algorithm
an unnecessary allocation
a slow query
a lock with broad scope
an unbounded log path

Finding one proves that the detail exists. It says nothing yet about how much of the reported symptom it caused.

The cryptographic work had a credible mechanism: more computation consumes more CPU. It also contained genuine optimization opportunities. Those facts justified improving it, but they did not rank it against logging.

The logging hypothesis had its own mechanism:

construct records
format and serialize values
coordinate writers
make filesystem calls
copy bytes
rotate and retain files
repeat roughly 1,000 times per second

That mechanism made logging plausible; the intervention made it dominant. Code review tends to favour whatever looks difficult, so a cryptographic routine gets attention while a logger call looks harmless. Production pays for accumulated execution, not visual complexity.

Write predictions before changing the system

Competing hypotheses become useful when each predicts a different observation.

For the saturated system:

The table does not identify the cause. Its job is to stop us interpreting every possible result as confirmation.

Without predictions, we can optimize cryptography, observe some improvement, and declare victory while logging still consumes most of the machine. Any busy system will reward enough random performance work with a positive number. The useful question is not whether something became faster, but which hypothesis could have produced this particular change.

Change one causal variable when the system permits it

The decisive observation was not merely that CPU fell. Emitted logging changed while the cryptographic application work did not.

The counterfactual is simple:

if cryptographic work were the dominant cause
and cryptographic work remained unchanged
then CPU should remain near the saturated state

CPU did not remain saturated; it returned to the approximate 10–20 percent range. That does not prove logging was the only cost in the process. It supports the narrower claim that reducing the logging workload removed most of the observed saturation under the conditions remembered from the incident.

Single-variable interventions are often difficult in production. A deployment may include several fixes. Traffic may move. A host may restart. Caches may be warm on one run and cold on another. When changes cannot be isolated, narrow the conclusion:

strong: changing only log emission removed the saturation
weaker: a release containing three changes removed the saturation
invalid: the most interesting change in that release caused the improvement

The explanation can only be as strong as the isolation behind it.

Before-and-after numbers need provenance

The figures in this incident are recollections:

• CPU was sitting near 100 percent;
• the stream was roughly 1,000 local-disk lines per second; and
• CPU settled around 10–20 percent after logging was reduced.

There is no retained telemetry series, machine profile, request-rate graph, benchmark, deployment record, or exact log-volume sample available for this article. The values should not acquire extra precision through repetition.

They support the shape and scale of the observation. They do not support:

• an exact percentage improvement;
• an exact attribution between CPU, disk, locks, serialization, and runtime;
• a universal cost for one thousand log lines per second;
• a claim that traffic and host conditions were perfectly identical; or
• a regression threshold for another system.

Those limits do not erase the incident; they stop it growing more precise every time it is retold. If the evidence still existed, I would want aligned time series for request rate, CPU, disk throughput and wait, emitted records, bytes written, and the deployment or configuration event. A profile could separate formatting, locking, runtime, and filesystem work. We do not have any of that, so I am not going to pretend we do.

A secondary finding can remain worth fixing

Rejecting cryptography as the dominant cause does not make its inefficiencies imaginary. An investigation can leave several useful findings with different ranks:

dominant cause: explains most of the reported symptom
contributing cause: measurably worsens the symptom
latent defect: wrong but not active in this incident
optimization opportunity: useful without being a defect
false lead: evidence does not support the proposed mechanism

That vocabulary avoids a destructive binary. It is easy to defend the first hypothesis because abandoning it feels like discarding useful work. Keep the finding and change its rank instead.

The cryptographic opportunities could enter the backlog with their own expected benefit and benchmark. They should not inherit urgency or causal credit from the CPU incident after logging explained the saturation. “This code can be faster” and “this code caused the outage” are both useful statements, but they require different evidence.

A green check proves only its assertion

A build can pass after a performance repair while the causal question remains wide open. Unit tests may prove output equivalence and a benchmark may prove one function became faster. Neither necessarily proves that the production symptom changed.

Evidence should line up across three layers:

correctness:
    required behavior still works

mechanism:
    the changed path controls the suspected cost

symptom:
    the original operational observation changes as predicted

For this incident, a green functional suite would protect cryptographic behavior while log controls changed. An isolated logging benchmark could show that fewer emitted records do less local work. The decisive production evidence would still be CPU and log rate moving in the predicted directions under comparable demand.

No such retained regression exists. Later logging controls addressed the incident, but this article cannot claim that a test now prevents recurrence.

A test should be described by what it can catch:

level configuration test:
    catches debug emission when the declared level disables it

rate-budget test:
    catches a synthetic path exceeding a chosen event budget

production alert:
    detects sustained resource saturation

none of these alone:
    proves why a particular past incident happened

Correlation is not intervention

Production metrics often move together:

traffic rises
CPU rises
logging rises
disk writes rise
latency rises

Correlation narrows the candidates. It cannot tell us whether logging caused CPU, traffic caused both, or latency triggered retries which increased all three.

An intervention adds stronger evidence because it asks the system to respond:

hold the business workload as stable as practical
change log emission
observe whether CPU follows

Even then, the conclusion inherits the experiment’s limits. Lower logging may reduce disk contention, allocation, formatter work, locks, or several of them together. Without profiles, “logging workload” is the supported boundary. One precise internal mechanism would be guesswork.

The earlier logging article owns event rate, payload size, destinations, levels, rotation, and retention as design inputs. Here the same approximate rate matters for one reason: changing it changed the symptom and ranked the hypotheses.

Record the explanation before memory compresses it

A useful investigation record can be short:

symptom
scope and time window
competing hypotheses
prediction for each
intervention and changed variables
observed result
mechanism supported by the result
alternatives demoted or retained
uncertainties and missing evidence
regression or operational guard
reversal condition

The DBG-12 fixture validates that shape against the supplied incident. It accepts the logging explanation because the symptom, two hypotheses, single changed factor, post-intervention observation, mechanism, provenance, and limitations are present.

It rejects three weaker records:

green check only:
    no operational symptom after the change

correlation only:
    simultaneous CPU and log rate without an intervention

multi-variable release:
    logging, cryptography, and runtime all changed together

The fixture validates an evidence record; it does not reproduce performance or prove the historic CPU and logging figures. Its job is to stop the explanation quietly dropping the pieces which make the causal claim credible.

Stop when the explanation can lose

An explanation is useful only if another observation could overturn it.

The logging conclusion would weaken if CPU remained saturated after emission fell under comparable work, if profiles showed negligible logging work, or if the apparent improvement tracked a traffic collapse or host replacement instead. Cryptography would regain causal weight if changing it moved CPU while logging remained constant.

Those reversal conditions still matter after recovery. They stop a successful intervention hardening into folklore.

The surprise was not that logging consumes resources. It was that a visually ordinary subsystem explained the machine better than the sophisticated code beside it. The investigation was complete only when the dominant cause, valid secondary finding, changed variable, observed response, and missing evidence could all be stated without contradiction.

A green build says the assertions passed. A debugging explanation says why the system failed, why this change affected it, what else remains true, and what future evidence would make us revise the story.