Logging Optimization

Simulation Performance Optimization · Module 28 · Page 28.3

The Engineering Problem

Logging sits at the intersection of runtime and memory — it costs CPU to construct, I/O to write, and storage to keep — and it's the single most common performance problem in a UVM environment, because it's paid on every message on every transaction and it feels free. The previous chapters showed logging as a runtime bottleneck (28.1, a filtered message's construction dominating runtime) and touched it as a memory cost (28.2). This chapter confronts the reporting system as a performance concern in its own right: a testbench that logs verbosely pays three costs — constructing the message ($sformatf, convert2string — CPU), writing it (to console or file — I/O, often the slowest part), and accumulating it (a log file that grows to tens of gigabytes, filling the disk and taking forever to write and search) — millions of times, for messages nobody reads. The two traps are opposite: under-control on the disabled side — a filtered message that still costs its construction (28.1's trap), so "off" logging isn't free — and over-volume on the enabled side — running regression at a verbosity that prints per-transaction detail, so the log is slow to produce (I/O-bound), huge to store (disk-filling), and useless to read (drowned in noise). The problem this chapter solves is logging optimization: the three costs of logging, the cardinal disciplines — a disabled log must cost nothing (guard construction) and the system must be quiet by default and detailed on demand (verbosity as a volume knob) — and the I/O specifics (file not console, no per-message flush, bounded size) that keep the reporting system from becoming the bottleneck it so often is.

Logging optimization is controlling the reporting system's three costs — construction (CPU), I/O (write), and storage (disk/memory) — so logging costs nothing when disabled and the system is quiet by default, detailed on demand. The three costs, paid per message: construction (building the message string — $sformatf, convert2string — which runs before the verbosity filter, so it's paid even when the message is discarded — 28.1's trap); I/O (writing the message — to console (especially slow) or file — often the dominant cost when messages do print); and storage (the log accumulating — a multi-gigabyte file that's slow to write, store, and search). The cardinal disciplines: a disabled log must cost nothing — guard expensive construction behind a verbosity check (uvm_report_enabled) so the $sformatf only runs when the message will print; and quiet by default, detailed on demand — run regression at low verbosity (errors and key events only), and turn verbosity up only for the component under debug (ID/hierarchy-scoped), never globally in regression. The I/O specifics: log to file, not console (console rendering is slow); avoid per-message flushing (forcing a disk sync each message is slow); bound log size. The cardinal failure: verbose-by-default logging that drowns the simulation — per-transaction messages printing in regression, paying all three costs millions of times for messages nobody reads. This chapter is logging optimization: the three costs, cost-nothing-when-disabled, quiet-by-default, the I/O specifics, and not drowning the sim.

Why does logging cost CPU to construct, I/O to write, and storage to keep — so verbose-by-default logging dominates runtime and storage — and how do you make a disabled log cost nothing (guard construction) and keep the system quiet by default and detailed on demand (verbosity as a volume knob), so the reporting system isn't the bottleneck?

Motivation — why logging is the bottleneck it so often is

Logging feels free — it's just a print — but it's paid per message on every transaction, across three resources, and over-logging is the single most common performance problem. The reasons:

• Three costs, paid per message, on every transaction. Each uvm_info constructs (CPU), writes (I/O), and accumulates (storage) — and in a per-transaction log, that's millions of times. Three costs × millions is why logging dominates.
• "Off" logging isn't free by default. A filtered message still constructs its string (the macro builds it before checking verbosity — 28.1's trap), so a disabled log costs its construction. Turning verbosity down doesn't eliminate the construction cost of expensive messages.
• Over-logging is I/O-bound, so compute doesn't help. When messages do print, the bottleneck is I/O (writing) and storage (disk) — so adding farm capacity (compute) doesn't help, which misleads teams into scaling the wrong resource.
• A drowned log is useless to read. Beyond the performance cost, over-logging defeats logging's purpose: the one error you need is buried in millions of routine lines, so the log can't be used to debug — worse than less logging.
• The right balance is quiet-by-default. Too little logging means re-running to debug a failure; too much means slow, huge, useless. The balance — errors and key events always, per-transaction detail on demand — must be designed, not defaulted to verbose.

The motivation, in one line: logging is the most common performance problem because it's paid per message across three resources (construction, I/O, storage) on every transaction, "off" isn't free (construction runs anyway), over-logging is I/O-bound (so compute doesn't help) and useless to read (drowned) — so you must make disabled logs cost nothing and keep the system quiet by default, detailed on demand.

Mental Model

Hold logging as a CCTV surveillance system — record enough to investigate later, but recording everything at max resolution fills storage, saturates bandwidth, and makes review impossible:

You run a surveillance system so that, if something goes wrong, you have footage to investigate what happened. The footage is valuable — without it, you'd have to re-stage the incident to understand it, which you often can't. But recording has real costs: bandwidth and processing to capture and encode the video, and storage to keep it. So the naive approach — every camera recording at maximum resolution, every frame, all the time, kept forever — fails in three ways at once. It saturates the network and the encoders, it fills the storage drives in days, and, most ironically, it makes the footage useless: when an incident finally happens, you have millions of hours of mostly-empty hallway footage to wade through, and the ten seconds that matter are buried in it. The well-designed system is the opposite. By default, cameras record at low resolution, or only on motion, capturing just enough to know something happened. When you're actively watching a specific area — investigating a live situation — you crank that one camera to high resolution, and only that one. You retain footage for a bounded window and roll off the old. And critically, you never capture footage you're going to immediately throw away: a camera that records full-resolution video and then deletes it because nobody's watching has paid the entire cost — bandwidth, encoding, the write — for nothing. The motion sensor decides before the camera records, not after. The whole discipline is: record little by default, record a lot only where and when you're looking, keep a bounded amount, and never pay to capture what you'll discard. You run a surveillance system so that, if something goes wrong, you have footage to investigate. The footage is valuable — without it, you'd have to re-stage the incident. But recording has real costs: bandwidth and processing to capture, and storage to keep. So the naive approach — every camera at maximum resolution, every frame, all the time, kept forever — fails three ways at once: it saturates the network and encoders, fills the storage in days, and, most ironically, makes the footage useless — the ten seconds that matter are buried in millions of hours of empty-hallway footage. The well-designed system is the opposite: by default, low resolution or motion-triggered (just enough to know something happened); when actively investigating, you crank one camera to high resolution, only that one; you retain a bounded window; and critically, you never capture footage you'll immediately throw away — a camera that records then deletes because nobody's watching has paid the entire cost for nothing; the motion sensor decides before the camera records, not after. The discipline: record little by default, a lot only where and when you're looking, keep a bounded amount, and never pay to capture what you'll discard.

So logging is a CCTV system: the log messages are footage, logging is recording, reading the log to debug a failure is reviewing footage to investigate an incident, and the three costs are the CCTV's: construction (encoding the video — CPU), I/O (the write/bandwidth), and storage (the drives — disk). The disciplines map exactly: record low-resolution by default (regression at low verbosity — errors and key events only); crank one camera high only when watching (verbosity up only for the component under debug, ID/hierarchy-scoped); retain a bounded window (bounded log size, file not console); and — the key one — never capture footage you'll discard (guard expensive message construction behind the verbosity check, so a filtered message isn't built then thrown away, exactly like a camera that records-then-deletes). The cardinal failure is the naive CCTV: every camera at max resolution always (regression at high verbosity) — saturating bandwidth (I/O-bound), filling storage (disk), and burying the incident (the one error drowned). Run logging like a well-designed surveillance system: low-resolution by default, high only where you're looking, bounded retention, and never pay to capture what you'll discard — because recording everything at max resolution saturates the system and buries the one thing you needed to see. Record little by default; never capture what you'll throw away.

Visual Explanation — the three costs and the controls

The defining picture is the three costs of logging — construction, I/O, storage — and the controls that bound each.

The figure shows the three costs and the controls. Verbosity (the brand-colored — the volume knob over all three): quiet by default (regression at low verbosity, errors and key events only); turned up only for the component under debug. Construction (CPU) — guard it (the warning-colored): building the string runs before the filter, so it costs even when discarded — guard behind a verbosity check. I/O (write) — file not console, no flush (success-colored): writing to console is especially slow; log to file, avoid per-message flushing. Storage (disk) — bound the size (default-colored): the log accumulating to gigabytes is slow to write, store, and search — bound log size and verbosity. The crucial reading is that logging is not one cost but three, each paid per message, and each with its own control — and verbosity sits above all three as the master control (it determines whether a message is processed at all). The warning-colored construction is highlighted because it's the counterintuitive cost: it's paid even when the message doesn't print (the string is built before the filter), so turning verbosity down doesn't eliminate it for expensive messages — it must be separately guarded. The I/O and storage costs, by contrast, are paid only when the message prints — so they're controlled by verbosity (don't print it) and by where/how it's written (file not console, no flush, bounded). The relationship is that verbosity controls I/O and storage (a filtered message isn't written or stored) but not construction (a filtered message's string is still built) — which is exactly why construction needs a separate guard. The diagram is the logging cost model: verbosity over construction (CPU), I/O (write), storage (disk), each with its control — and verbose-by-default pays all three millions of times. Logging costs construction (CPU, paid even when filtered — guard it), I/O (write — file not console, no flush), and storage (disk — bound it), all under verbosity as the master volume knob.

RTL / Simulation Perspective — quiet by default, guarded, file not console

In code, the disciplines are concrete: guard expensive construction, set regression verbosity low, scope verbosity to the component under debug, log to file. The example shows them.

// === COST-NOTHING-WHEN-DISABLED: guard expensive construction behind the verbosity check ===
//   the message is built BEFORE uvm_info checks verbosity → guard it so $sformatf only runs if it prints
if (uvm_report_enabled(UVM_HIGH, UVM_INFO, "DRV"))
  `uvm_info("DRV", $sformatf("txn=%s", req.convert2string()), UVM_HIGH)   // built only when it would print
 
// === QUIET BY DEFAULT: errors and key events are always visible; per-transaction detail is HIGH ===
`uvm_error("SB", "data mismatch")                         // UVM_NONE-ish: always shown — the signal
`uvm_info("AGENT", "reset complete", UVM_LOW)             // key event: shown in regression
`uvm_info("DRV", $sformatf("txn=%s", ...), UVM_HIGH)      // per-transaction: HIDDEN in regression (verbosity LOW)
 
// === RUN REGRESSION AT LOW VERBOSITY (not high) ===
//   regression:  +UVM_VERBOSITY=UVM_LOW     → only errors + key events print → quiet, fast, small log
//   ✗ leaving +UVM_VERBOSITY=UVM_HIGH in the regression script prints per-txn detail → drowns the sim (DebugLab)
 
// === DETAILED ON DEMAND: scope verbosity to the component under debug, not globally ===
//   debug one failing test/component without flooding everything:
//   +uvm_set_verbosity=uvm_test_top.env.agent.driver,_ALL_,UVM_HIGH,time,0   // just the driver, at HIGH
//   (or in code: driver.set_report_verbosity_level(UVM_HIGH);)
 
// === I/O: log to FILE, not console; avoid per-message flush ===
//   console output is the slow path (terminal rendering); in regression, redirect to a file
//   the report server can write to a file; avoid forcing a disk sync on every message
 
// === RESULT: regression is quiet (small fast log); a failing test is re-run with scoped HIGH verbosity ===

The code shows the disciplines. Cost-nothing-when-disabled: guard the expensive construction — if (uvm_report_enabled(UVM_HIGH, ...)) before the uvm_info, so the $sformatf/convert2string only runs when the message would print. Quiet by default: uvm_error (always shown — the signal) and a key-event uvm_info at UVM_LOW (shown in regression) are visible, but per-transaction detail at UVM_HIGH is hidden in regression (verbosity LOW). Run regression at low verbosity: +UVM_VERBOSITY=UVM_LOW (only errors + key events → quiet, fast, small log); leaving UVM_HIGH in the regression script prints per-txn detail → drowns the sim (the DebugLab). Detailed on demand: scope verbosity to the component under debug — +uvm_set_verbosity=...driver,_ALL_,UVM_HIGH,... (just the driver, at HIGH), not globally. I/O: log to file, not console (console is the slow path); avoid per-message flush. The shape to carry: guard expensive construction (cost-nothing-when-disabled), make errors/key-events always-visible but per-transaction detail HIGH-only (quiet by default), run regression at LOW and scope HIGH to the component under debug (detailed on demand), and log to file without per-message flush (I/O). The combination makes regression quiet, fast, and small, while a failing test is re-run with scoped HIGH verbosity to get the detail. Guard expensive construction, run regression at low verbosity with errors and key events always visible, scope high verbosity to the component under debug, and log to file without per-message flush.

Verification Perspective — over-logging is I/O-bound, so compute doesn't help

The defining surprise of over-logging is that it's I/O- and storage-bound, not compute-bound — so the intuitive fix (more compute) doesn't help. Seeing which resource over-logging saturates clarifies why you reduce logging, not add cores.

The figure shows over-logging saturating I/O and storage, not compute. When regression runs at high verbosity, a message prints on every transaction, and each printed message pays I/O to write and storage to keep. Across millions of transactions and thousands of tests, the I/O bandwidth saturates (the simulation waits on writes) and the storage fills (gigabyte log files fill the disk). The verification insight is that the bottleneck is I/O and storage, not compute — so adding farm capacity (more cores) does nothing, because the cores sit waiting on I/O. This is the classic "wrong resource" mistake: a slow regression intuitively suggests "need more compute", so teams add cores — but if the bottleneck is I/O (writing logs), more cores don't help (they're idle, blocked on writes), and the disk keeps filling regardless. The warning high-verbosity → default per-message → warning I/O-saturated/disk-filling path shows the I/O-and-storage saturation, with "more cores: no help" making the wrong-resource point explicit; the success low-verbosity → fast-small-log path shows the right fix — reduce the logging, which removes the I/O and storage cost directly. The crucial point is the diagnostic distinction: a compute-bound slowness responds to more cores; an I/O-bound slowness doesn't — and over-logging is I/O-bound, so the fix is to log less (lower verbosity, file not console, no flush), not to scale compute. The way to tell is to look at where the time goes (the simulation waiting on writes) and whether the disk is filling — both signatures of I/O/storage-bound logging, not compute. The diagram is the wrong-resource trap: over-logging saturates I/O and storage, so adding compute doesn't help — the fix is to reduce logging. Over-logging is I/O- and storage-bound, not compute-bound, so adding cores doesn't help — the simulation waits on writes and the disk fills; the fix is to log less (low verbosity, file not console), not to scale compute.

Runtime / Execution Flow — diagnosing a logging bottleneck

At run time, diagnosing a logging bottleneck follows a measure-then-control discipline: recognize the I/O/storage signature, identify the cost, apply the control. The flow shows it.

The flow shows the logging diagnostic. Recognize (step 1): slow regression, GB log files, disk filling, more compute doesn't help — I/O- and storage-bound, not compute. Identify (step 2): construction (built even when filtered), I/O and storage (printing because verbosity is high), or both. Control (step 3): guard construction; regression verbosity low; file not console; no per-message flush. Re-measure → debug on demand (step 4): log small and fast; for a failure, re-run with verbosity scoped high to the component under debug. The runtime insight is the distinction between the two cost regimes: construction cost is paid even when filtered (so it's present regardless of verbosity — fixed by guarding), while I/O and storage cost is paid only when printing (so it's driven by verbosity — fixed by lowering it). The signature distinguishes which: if the log is huge (GB files, disk filling), the messages are printing → I/O/storage → lower verbosity; if the log is small but the sim is still slow in a hot loop, the construction is the cost even at low verbosity → guard it. So you identify the regime before applying the control. The re-measure confirms: a correctly-controlled logging scheme produces a small, fast log with the sim no longer waiting on writes. And the debug-on-demand step preserves logging's value: you didn't lose the detail — you moved it to on-demand (re-run the failing test with scoped high verbosity on the component under investigation), so you get full detail when you need it without paying for it in regression. The brand (signature) → success (identify/control) → warning (re-measure/debug) flow shows the controls applied and the value preserved. The flow is the logging diagnostic: I/O-bound signature → identify the cost regime → apply the control → re-measure → debug on demand. Diagnose a logging bottleneck by its I/O-and-storage signature, identify whether the cost is construction or printing, apply the matching control (guard, lower verbosity, file not console), and preserve debuggability by re-running failures with scoped high verbosity.

Waveform Perspective — a message on every transaction drowns the signal

The over-logging failure is visible: a message is written on every transaction, burying the one error that matters in a flood — unlike a quiet default where only errors and key events write. The waveform shows the flood.

The waveform shows a message on every transaction drowning the signal. At high verbosity in regression, a log message is written on every transaction (log_written pulses every cycle), so the log fills with routine per-transaction detail. The one event that matters — an error (err) — is written too, but it's buried in the flood of routine messages, and the constant writing saturates I/O and fills storage. The crucial reading is the contrast between log_written (constant) and err (sparse): log_written fires every cycle (the flood — every transaction logged), while err fires once (the signal — the thing you actually need). At high verbosity, the signal is drowned in the flood: the err pulse is one line among millions of routine lines, impossible to find, and the flood costs I/O and storage on every transaction. At low verbosity, log_written would fire only on err (and key events) — so the err pulse would stand alone, the log would be small and fast, and the simulation wouldn't wait on writes. The picture to carry is that over-logging has two costs at once: a performance cost (log_written every cycle → I/O + storage on every transaction) and a usability cost (the signal err buried in the flood) — so over-logging is bad on both axes: it slows and fills the system and makes the log useless to read. Reading the waveform this way — is a message written on every transaction, or only on the events that matter? — distinguishes over-logging (constant log_written) from healthy logging (sparse log_written, standing out). The log write on every transaction is the signature of over-logging; sparse writes that stand out is the signature of healthy logging. A log write on every transaction is the signature of over-logging — it saturates I/O and storage and buries the one error in the flood; healthy logging writes sparsely (errors and key events), so the signal stands out and the log is small and fast.

DebugLab — the regression drowned by a debug verbosity left in the run script

✗ HIGH verbosity in the regression run script — per-transaction messages PRINT on every transaction:
  // run script (leftover from debugging):  +UVM_VERBOSITY=UVM_HIGH
  // every `uvm_info(..., UVM_HIGH)` in every per-transaction loop now PRINTS
  // → millions of messages/test × thousands of tests → GB logs, I/O-bound sim, disk filling
  // → team added COMPUTE (more cores) → NO HELP: the bottleneck is I/O + storage, not compute
  //   (cores sit idle waiting on log writes; the disk fills regardless)
 
✓ LOW verbosity in regression; HIGH scoped on demand for a failing test:
  // regression run script:  +UVM_VERBOSITY=UVM_LOW    → only errors + key events print
  //   → small fast logs, sim not waiting on writes, disk not filling
  // to debug a specific failure, RE-RUN that test with scoped high verbosity on the component:
  //   +uvm_set_verbosity=uvm_test_top.env.agent.driver,_ALL_,UVM_HIGH,time,0
  //   → full detail for the driver, only on the re-run, only where you're looking
 
  // (also: log to FILE not console, and guard expensive $sformatf construction behind a verbosity check)

Common Mistakes

• Running regression at high verbosity. Per-transaction messages print on every transaction, drowning the sim in I/O and storage; run regression at low verbosity.
• Leaving a debug verbosity in the run script. A high verbosity left over from debugging floods regression; reset to low verbosity for regression.
• Adding compute for an I/O-bound logging problem. More cores don't help when the bottleneck is log writes and storage; reduce the logging instead.
• Unguarded expensive construction. A filtered message still builds its string; guard costly construction behind a verbosity check so a disabled log costs nothing.
• Logging to console and flushing per message. Console rendering and per-message disk syncs are slow; log to file and avoid per-message flush.
• Turning verbosity up globally to debug. Global high verbosity floods everything; scope high verbosity to the component under investigation.

Senior Design Review Notes

Interview Insights

Exercises

1. Guard or not. For each — a simple "reset complete" message, a per-transaction message that calls convert2string on a large object, an error message — decide whether to guard the construction and why.
2. Set the verbosity. Describe the verbosity settings for a nightly regression versus a debug re-run of a single failing test, and how you scope the debug verbosity.
3. Diagnose the resource. Given a slow regression with gigabyte logs where adding cores didn't help, identify the bottleneck and the fix.
4. The three costs. For a per-transaction uvm_info at high verbosity printing in regression, name the construction, I/O, and storage cost and how each is controlled.

Summary

• Logging optimization controls the reporting system's three costs — construction (CPU: building the string, paid even when filtered because the macro builds it before the verbosity check), I/O (writing: console especially slow, or file), and storage (the log accumulating to gigabytes) — paid per message on every transaction.
• The cardinal disciplines: a disabled log must cost nothing — guard expensive construction behind a verbosity check (uvm_report_enabled) so the $sformatf runs only when it prints; and quiet by default, detailed on demand — run regression at low verbosity (errors and key events only), turn verbosity up only for the component under debug.
• Over-logging is I/O- and storage-bound, not compute-bound — so adding compute doesn't help (cores wait on writes, the disk fills); the fix is to log less (low verbosity, file not console, no per-message flush, bounded size).
• A drowned log fails on two axes: a performance cost (I/O + storage on every transaction) and a usability cost (the one error buried in millions of routine lines) — over-logging is bad even before you count the cycles.
• The durable rule of thumb: run logging like a well-designed surveillance system — quiet by default (regression at low verbosity, errors and key events only), detailed on demand (verbosity scoped high to the component under debug on a re-run), guarding expensive message construction so a disabled log costs nothing, logging to file not console, and avoiding per-message flushing; verbose-by-default logging pays construction, I/O, and storage on every transaction for messages nobody reads, making the regression I/O-bound (so adding compute doesn't help) and the logs gigabytes of useless detail that bury the one error you needed — never capture footage you'll immediately discard, and never record every camera at max resolution all the time.

Next — Performance Profiling: the module closes by making profiling itself systematic. The earlier chapters profiled runtime and memory in isolation; the last chapter turns profiling into a repeatable methodology — what to measure (CPU, memory, I/O), the tools that measure each, how to read a profile to find the dominant cost, how to set performance budgets and catch regressions before they ship, and how to make performance a continuous property of the environment rather than a crisis addressed once.