Logging and Diagnostics That Survive a Long Run

Part I · Module 22 · Chapter 22.9 · Logging and Diagnostics That Survive a Long Run

1. What a Line Has to Carry

The test for a log line is whether someone who was not there can interpret it in isolation, four hours later, without the surrounding lines.

[000000000012] INFO  fetch    reset released
[000004823991] WARN  axi0     latency 412 cycles exceeds budget 200
[000004823994] ERROR axi0     addr 0x4000A010 resp=SLVERR master=2

Four fields, and each answers a question the reader will have.

WHEN — the cycle, or a timestamp. Zero-padded, which is not cosmetic: a padded field means a plain text sort is a chronological sort, so sort and grep work on the file without a parser.

HOW BAD — the level, fixed-width so the columns line up and the eye can scan one position down the page.

WHERE — which unit, module or subsystem. This is the field most often omitted and the one that makes grep axi0 possible.

WHAT — the message, with the actual values in it. latency 412 cycles exceeds budget 200 is diagnosable; latency exceeded budget is not, because the reader now has to find the budget and the measurement somewhere else.

The third line is the shape to aim for: an address, a response code and an initiator, all in one line. A reader who has never seen this program can tell what failed, where and to whom.

Two conventions worth adopting. Values with their units — 412 cycles, not 412. And hex for anything that is an address or a mask, with the 0x and consistent width, because that is how the rest of the toolchain prints them.

2. The Level Threshold, and the Trap in Applying It

A level filter is obvious: attach a severity to each line, discard anything below a threshold. The implementation detail is not obvious and it is expensive.

// WRONG: formats, then decides
static void logEager(Level l, std::uint64_t cycle, const char* unit, const char* fmt, ...)
{
    char body[256];  /* vsnprintf into body */
    char line[384];  /* snprintf the whole line */
    if (l < threshold) { suppressed++; return; }      // decided AFTER formatting
    sink(line);
}

// RIGHT: decides, then formats
static void logLazy(Level l, std::uint64_t cycle, const char* unit, const char* fmt, ...)
{
    if (l < threshold) { suppressed++; return; }       // decided BEFORE formatting
    char body[256];  /* vsnprintf */
    char line[384];  /* snprintf */
    sink(line);
}

200000 SUPPRESSED debug calls:
  format-then-decide     60.98 ms   (200000 suppressed)
  decide-then-format      0.42 ms   (200000 suppressed)
  -> 144x. The suppressed line still cost two snprintf calls in the
     first version. Check the level FIRST.

About a hundred and forty times, for lines that were being thrown away. That run is one of nine, each number already a minimum of thirty-one repetitions; across the nine the ratio has a median of 145× and a range of 99–185×, around a median of 57 ms against 0.41 ms. The spread is wide because the quotient divides a large noisy number by a tiny one, and the absolute milliseconds move with whatever else the machine is doing — but the ratio is the load-robust quantity, because both halves run under the same conditions, and it never came close to 1. Fifty-odd milliseconds of pure waste against four-tenths of one, on two hundred thousand calls — and a real run makes millions of them.

The mistake is natural, because the formatting and the decision are both inside one function and the order looks incidental. It is not: vsnprintf is doing real work parsing a format string and converting numbers, and it was doing that work for every line that was then discarded.

Two related points.

The arguments are still evaluated. Even with the check first, the caller evaluated everything it passed. A call like log(Debug, cyc, "axi0", "state %s", expensiveToString(s)) pays for expensiveToString regardless, because C++ evaluates arguments before the call. That is what the macro in §6 is for.

This is the same shape as Chapter 22.8 §2's assert. There, the whole expression vanished under NDEBUG and the measured side effect went from 1 call to 0. Here it does not vanish — it is a run-time check — so the cost is real and the ordering matters.

3. The Arithmetic of Volume

The frozen purpose's "little enough to stay readable" is quantifiable, and doing the arithmetic once settles most granularity arguments.

at ~90 bytes/line over 100000000 cycles:
  every cycle           100000000 lines     9000.0 MB
  every bus beat          1562500 lines      140.6 MB
  every transaction         24414 lines        2.2 MB
  every error                   1 lines         0.0 MB

A hundred million cycles is a few minutes of RTL simulation or a modest model run.

Per cycle: nine gigabytes. Not merely large — unusable. Nobody greps nine gigabytes, it will not open in an editor, and writing it slows the run by more than the simulation itself.

Per bus beat: 141 MB. Possible to keep, painful to read, and the right granularity only when you already know the problem is at beat level.

Per transaction: 2.2 MB. Twenty-four thousand lines. That is a file you can open, grep, sort and read end to end if you have to — and it answers most questions, because most failures are about which transaction went wrong rather than which beat within it.

Per error: one line. Necessary and not sufficient, because the error line tells you what failed and nothing about how it got there.

So the default granularity is per transaction at INFO, per beat at DEBUG, and the beat detail off unless asked for. And the thing that makes the per-beat detail available without the 141 MB is §4.

4. The Ring Buffer

The tension between detail and volume has a standard resolution: keep the detail in memory, bounded, and write it out only when something fails.

const std::size_t CAP = 8;
std::vector<std::string> ring(CAP);
std::size_t head = 0;
auto record = [&](const std::string& s) { ring[head % CAP] = s; ++head; };

recorded 1000 lines, kept the last 8:
  beat 992
  beat 993
  ...
  beat 999
-> a fixed-size ring costs O(1) per line and nothing on disk, and on a
   failure you dump it. Full detail for the window that mattered.

A thousand lines recorded, eight kept, nothing written to disk and no allocation per line once the ring is warm. On a failure you dump the ring and you have the last N events at full detail — which is almost always the window that matters, because the cause of a failure is usually close to it in time.

Three implementation notes.

Size it in events, not bytes, and make it a configuration value. A thousand entries of a fixed-width record is a kilobyte or two.

Pre-size the storage so the steady state does not allocate. Chapter 19.3 §4's reserve measurement is the mechanism — eleven allocations become one.

Dump it on the error path, not from a signal handler. A signal handler cannot safely allocate or format, so if you want a crash dump too, the ring must hold fixed-size records rather than std::string.

This is also how most hardware trace buffers work, which makes it a familiar idea to the audience: a bounded window of full detail, read out after the event.

5. Context That Outlives the Call

The hardest diagnostic problem in a long run is not the content of a line — it is that the line does not say which activity it belongs to. Ten thousand interleaved transactions produce ten thousand interleaved log lines, and grep on a unit name returns all of them.

The fix is to carry an identifier through the work:

[000004823991] WARN  axi0 txn=4821 latency 412 cycles exceeds budget 200
[000004823994] ERROR axi0 txn=4821 addr 0x4000A010 resp=SLVERR master=2

Now grep 'txn=4821' returns the life of that one transaction. The id costs a few bytes per line and converts the log from a stream into something searchable by the thing that failed.

Three ways to carry it, in increasing order of intrusiveness:

A parameter. Explicit, impossible to lose, and it has to be threaded through every function. Correct and tedious.

A member of the object doing the work. Natural when the work is an object — a transaction, a request, a session — and it is the usual answer.

A scoped context guard, which is Chapter 22.4's RAII applied to diagnostics:

class LogContext {
public:
    explicit LogContext(std::uint64_t id) { push(id); }
    ~LogContext() { pop(); }
};

The guard is the right pattern precisely because Chapter 22.3 §2 measured that destructors run during unwinding: a context pushed at the start of a scope is popped even if the scope exits by a throw. A manual push/pop pair has Chapter 22.4 §2's defect exactly — the pop is a statement after a call that can throw, so the context leaks and every subsequent line is mislabelled, which is worse than having no context at all.

6. The Macro, and Why There Is One

Logging is the one place where a function-like macro is genuinely better than a function, and the reason is §2's second point.

#define LOG(level, fmt, ...) \
    do { if ((level) >= logThreshold) logLine((level), __FILE__, __LINE__, fmt, __VA_ARGS__); } while (0)

Two things only a macro can do.

Avoid evaluating the arguments when the line is suppressed. A function call evaluates all its arguments first, so an expensive toString() in a suppressed DEBUG line is still paid for. The macro's if guards the whole call.

Capture __FILE__ and __LINE__ at the call site, which a function cannot do before C++20's std::source_location.

That is a narrow and real justification, and it is the exception to Chapter 1.4 §8's general advice to replace macros. In C++20, std::source_location::current() as a default argument removes the second reason, and the first still stands.

The do { … } while (0) wrapper is the standard idiom so the macro behaves as a single statement in an unbraced if.

7. What to Log at Each Level

A short policy, because the levels are useless if everyone interprets them differently.

ERROR — the run has produced a wrong result or cannot continue. One per actual failure. If a run emits a hundred ERRORs, ninety-nine of them are something else.

WARN — something is suspicious but the run continues. A latency over budget, a retry, a value near a limit. These are the lines you read when the result is wrong but nothing errored.

INFO — the milestones of normal operation, at a granularity someone would want in every run. Per transaction, per phase, per test case. §3's 2.2 MB.

DEBUG — per-beat detail, off by default, enabled when you are already investigating.

TRACE — everything, including per-cycle. §3's nine gigabytes, and the ring buffer from §4 is the better way to get it.

The discipline that makes this work: a clean run should produce only INFO. If a passing run emits WARNs, the warnings stop being read, and then a real one is invisible. That is the logging equivalent of the warning-fatigue problem, and it is the most common way a log becomes useless while still being written.

8. What to Log When It Fails

The ERROR line is one line and it has a job: contain enough to start the diagnosis without needing the rest of the file.

A checklist, from the measured example in §1:

• what was being attempted — the operation, not just "failed";
• the actual values, with units — 412 cycles, 0x4000A010;
• the expected values where there are any — budget 200;
• the identity of the work — txn=4821, master=2;
• where — the unit;
• when — the cycle;
• and then dump the ring buffer (§4), so the last N events are adjacent to the error.

What not to put in it: an exception's what() alone. Chapter 22.2 §2 is the reason — what() is a const char* and carries no structure, so a handler that logs only e.what() has discarded the code(), the address and the duration that the exception type was carrying. Log the fields, then the message.

And one thing worth doing that is easy to forget: log the configuration at the start of the run. The seed, the version, the flags, the input files. A failure four hours in is not reproducible if nobody recorded what was being run.

9. The Decisions Table

10. What to Actually Do

• Check the level before formatting. Measured ~145× for lines being discarded.
• Use a macro so suppressed lines do not evaluate their arguments. The one place a macro is right.
• Put the values and their units in the message. latency 412 cycles exceeds budget 200.
• Zero-pad the timestamp so sort works.
• Include a unit or subsystem field. It is what makes grep useful.
• Default to per-transaction INFO. Measured 2.2 MB against 9 GB per cycle.
• Keep per-beat detail in a ring buffer and dump it on failure.
• Pre-size the ring so the steady state does not allocate.
• Carry an activity id and use a scoped guard to manage it — never manual push/pop.
• Log the configuration at the start of every run.
• Keep a clean run free of WARNs, so a real one is visible.
• Log an exception's fields, not only what().
• Do not format or allocate in a signal handler; fixed-size records if you need a crash dump.

11. Mistakes Worth Making Once

Formatting before checking the level. Measured 57 ms against 0.41 ms for output nobody wanted.

An expensive argument in a suppressed line. The caller evaluates it regardless; only a macro prevents that.

Per-cycle logging left on. Nine gigabytes, and the run is slower than the thing it is measuring.

A message without its values. latency exceeded budget sends the reader looking for two numbers that were right there.

An unpadded timestamp. The file no longer sorts chronologically.

No unit field. Every grep returns everything.

Manual push/pop of a diagnostic context. On the failure path the context leaks and every later line is mislabelled — Chapter 22.4 §2's defect, in the system you are using to diagnose the failure.

Logging only e.what(). Chapter 22.2 §2: the structured data in the exception type is discarded.

A clean run that emits warnings. They stop being read, and then a real one is invisible.

Not recording the seed or the version. The failure is no longer reproducible.

12. Interview Relevance

The frozen curriculum marks this chapter High, and it is a good question because it is about judgement rather than syntax.

"A test failed overnight and nobody was watching. What do you need in the log?" The four fields per line with actual values, an activity id, the configuration recorded at startup, and a ring buffer of recent detail dumped at the failure. That structure is the answer.

"How do you keep logging cheap?" Check the level before formatting — measured ~145× — and use a macro so suppressed lines do not evaluate their arguments.

"How much should you log?" Do the arithmetic: per cycle over 100M cycles is 9 GB; per transaction is 2.2 MB. Per transaction at INFO, per beat at DEBUG, per cycle only into a ring.

"How do you get per-cycle detail without per-cycle volume?" A bounded ring buffer, dumped on failure — full detail for the window that mattered.

"How do you tie interleaved lines to one activity?" An id carried through the work, managed by a scoped guard — because a manual pop does not run on the failure path.

"What goes in an ERROR line?" What was attempted, actual and expected values with units, the activity's identity, the unit, the cycle — and then the ring. Not just what().

13. What You Should Be Able to Say Now

• The four fields a line must carry, and why the timestamp is zero-padded.
• That checking the level before formatting was about 145× faster — a median 57 ms against 0.41 ms for 200,000 suppressed lines, range 99–185×.
• That the caller evaluates the arguments regardless, which is why logging is the one place a macro beats a function.
• The volume arithmetic: 9,000 MB per cycle, 140.6 MB per beat, 2.2 MB per transaction over 100M cycles.
• That the default is per-transaction INFO, with per-beat detail in a ring buffer.
• That a ring buffer kept the last 8 of 1,000 lines at O(1) with nothing on disk.
• That an activity id turns a stream into something searchable, and that it must be managed by a scoped guard because a manual pop does not run on the failure path.
• That a clean run should emit only INFO, or the warnings stop being read.
• That an ERROR line needs attempted, actual, expected, identity, where and when — and the exception's fields, not only what().

14. Exercises

Exercise 1 — the ordering. Reproduce §2's two implementations and confirm the ratio on your machine. Then add an expensive argument at the call site and show that the function-based version still pays for it.

Exercise 2 — the macro. Write §6's macro, verify with a counter that a suppressed line does not evaluate its arguments, and then do it again with C++20's std::source_location instead of __FILE__.

Exercise 3 — the arithmetic. Compute the volume for your own workload at four granularities and decide where the INFO level sits. Include the write bandwidth, not just the total.

Exercise 4 — the ring. Implement a ring of fixed-size records (no std::string), confirm zero allocations in the steady state, and dump it from an error path.

Exercise 5 — the context leak. Implement a manual push/pop context, make the guarded region throw, and show that subsequent lines are mislabelled. Then fix it with a scoped guard.

Exercise 6 — the useless line. Take five log lines from real code and rewrite each so it is interpretable in isolation. Note which were missing values and which were missing identity.

Exercise 7 — grep by activity. Add an id to a multi-transaction run and reconstruct the life of one transaction from the log alone.

Exercise 8 — the fields, not the message. Write a handler that logs an exception's structured fields and compare the result with one that logs only what().

15. Summary

• A log line must be interpretable in isolation: when (zero-padded), how bad, where, and what — with the actual values and their units.
• Measured: check the level BEFORE formatting. 200,000 suppressed lines cost a median 57 ms formatted-then-decided against 0.41 ms decided-then-formatted — ~145×, range 99–185× over nine runs — for identical (empty) output.
• The caller evaluates arguments regardless, which is why a macro with the check inside is the right tool and the one justified use of one here.
• Measured volume at ~90 bytes/line over 100M cycles: per cycle 9,000 MB, per beat 140.6 MB, per transaction 2.2 MB, per error one line. Per-cycle logging is a log nobody reads.
• Default to per-transaction INFO, per-beat DEBUG off by default.
• Measured: a ring buffer kept the last 8 of 1,000 lines at O(1) per line with nothing on disk — full detail for the window adjacent to the failure.
• Carry an activity id so grep txn=4821 reconstructs one transaction, and manage it with a scoped guard: a manual pop is a statement after a throwing call, so the context leaks and every later line is mislabelled.
• A clean run should emit only INFO, or warnings stop being read and a real one becomes invisible.
• An ERROR line needs what was attempted, actual and expected values, the activity's identity, the unit and the cycle — plus the exception's fields, not only what().
• Record the configuration at startup — seed, version, flags, inputs — or the failure is not reproducible.

That completes Module 22. Nine chapters have treated failure as a design input rather than an afterthought: three kinds of failure and three mechanisms, the unwinding that makes a destructor the only reliable cleanup, RAII as a consequence of that rather than a convention, four named levels of guarantee, the one-bit promise the type system records, the return-value half of the taxonomy, assumptions stated in code, and finally what the program leaves behind when nobody is watching. The recurring measurement across the module has been the same one this curriculum keeps finding: the failure path is where correctness lives, and it is the path no passing test exercises.

Module 23 is Files, Streams, and Data Processing, and its frozen blurb describes it as getting data in and out — which in this domain means simulation logs, test vectors, register dumps and machine-readable results. It follows directly from this module in a way worth noting: Chapter 22.4 §7 identified a close that can fail as the one honest limit of RAII, and a file is exactly that case; Chapter 22.1 §7's per-interface principle is what std::filesystem implements by offering a throwing and an error_code form of every operation; and the parsing work the module ends on is full of Chapter 22.1's expected failures, where a line that does not match is a normal outcome rather than an error.