Log Source Profiling: Which Log Statement Is Responsible?

How log source profiling traces CPU and file I/O back to individual C and C++ call sites without disabling production diagnostics

Log source profiling starts where a normal CPU profiler stops. A system profiler can tell you that a logging thread is consuming CPU and show write(), a file-backend worker, queue synchronization, memory copies, and formatting functions near the top of the profile.

However, that is useful only up to a point, because it does not answer the question that matters:

Which log statements are creating the load?

For example, in a large service, the file backend may receive records from hundreds of source files, dozens of channels, linked channels, and several output routes. A profiler sees the common endpoint. It does not know whether the load comes from one payload dump, ten verbose trace statements, or 50,000 tiny status messages per second.

Unfortunately, the usual reaction is dangerous: “logging is expensive, so disable it.” This may improve a benchmark, but it also removes the evidence needed to investigate failures in production.

Instead, a better response is to use log source profiling to measure the logging itself.

This article describes how I added on-demand log source profiling to logme, how the implementation keeps the disabled path almost free, and what the profiler revealed in a real network service.

The original performance investigation

The story started with a Linux service that had recently been moved to an event-driven I/O model. Even with no requests being processed, four CPU cores were fully occupied.

The first VTune profile was unambiguous: worker threads were spinning in a loop around epoll_wait() and epoll_ctl(). A persistent EPOLLRDHUP condition was being rearmed without completing an operation, so epoll_wait() returned immediately again and again.

Afterward, CPU usage dropped dramatically. The next profile looked much healthier: there was no longer a single stack consuming almost all CPU time. Real work became visible—TLS, HTTP/2 processing, policy evaluation, thread synchronization, and logging.

One of the upper stacks was now:

libc.so.6!write
liblogme.so!Logme::FileIo::WriteRaw
liblogme.so!Logme::FileIo::WriteAll
liblogme.so!Logme::FileBackend::WriteReadyData
liblogme.so!Logme::FileBackend::WorkerFunc
liblogme.so!Logme::FileManager::ManagementThread

Nevertheless, this did not prove that the logger was defective. It proved only that the application was asking the logger to write enough data, or enough individual records, for the work to become visible.

The next question could not be answered by VTune:

Which source locations were responsible for those writes?

Why log source profiling needs more than backend counters

Logging libraries often expose useful aggregate counters: bytes written, queue size, dropped records, write errors, rotations, and flush counts. Those counters describe the health of the backend, but they do not attribute work to the code that created it.

For instance, suppose a file backend writes 80 KiB/s. That rate may come from:

• one large JSON or payload dump every second;
• 1,000 small messages per second;
• a single source record duplicated through several channel links;
• several unrelated channels sharing the same backend;
• a burst that the asynchronous worker is still draining.

Consequently, these cases require different fixes. Reducing message size will not solve excessive queue wakeups. Increasing the batch size will not fix a multi-megabyte payload dump. Disabling an entire channel may hide important error records because one verbose call site was placed there incorrectly.

Useful log source profiling must preserve the relationship between four layers:

1. the source site that created the record;
2. the source channel that initially accepted it;
3. every destination channel and backend reached after routing and fan-out;
4. the runtime behavior of the file worker after the record entered its queue.

Moreover, it must keep two metrics separate:

• records identify high-frequency sources that spend CPU on formatting, queues, locks, atomics, and worker wakeups;
• bytes identify large messages, dumps, and high-volume output.

In practice, the distinction matters. A logging subsystem can be expensive even when disk bandwidth is low.

Log source profiling begins with a first-class log site

Every C++ logging macro in logme already creates a static context cache at the source location. Conceptually, a call such as:

LogmeI(PCH, "evaluating expression: %s", expression);

has a unique static object associated with its file and line. That object was originally used for other call-site features. It also provides a natural stable identity for profiling.

The profiler registers a log site lazily and stores metadata such as:

source file
function
line
level
first observed format string

It does not retain rendered message contents or runtime arguments. The report can show:

format: evaluating expression: %s

but it does not store the actual expression. This keeps memory usage bounded and avoids turning the profiler into a second log containing potentially sensitive values.

Meanwhile, native C macros required one additional change. The old C API used a shared cache inside the library, so separate C call sites could not be distinguished. The standard C macros now create a site-local static cache too. Existing direct function calls remain ABI-compatible, while site-aware API functions are available when exact attribution is required.

Keeping log source profiling almost free when disabled

Adding a profiler to a logging library can easily create the problem it is meant to diagnose. The profiler therefore remains inactive until explicitly started through the control interface.

When profiling is disabled, the hot path must not perform any of the following:

• call-site registration;
• counter updates;
• mutex acquisition;
• memory allocation;
• map lookup;
• metadata copying;
• clock queries.

After normal log-level and channel filtering, an accepted record reaches a check equivalent to:

LogStatisticsCollector* statistics =
  ActiveLogStatistics.load(std::memory_order_relaxed);

if (statistics != nullptr)
{
  // The profiling path runs only while collection is active.
}

The backend instrumentation uses the same model. When the pointer is null, it does not register destinations or update counters.

This design is important for two reasons.

First, records rejected by the normal logging filters never reach the profiling check. The cost of disabled or filtered logging remains unchanged.

Second, all expensive work is moved to the active path. When profiling starts, the first record from a source site performs lazy registration. Subsequent records use cached pointers and relaxed atomic increments.

For example, in a deliberately cheap NullBackend microbenchmark with three million accepted records, the measured difference between the original path and the compiled-but-disabled profiler was roughly 0.5–1.4 ns per call, depending on the run. The median difference in later comparisons was around 0.7 ns. This test exaggerates relative overhead because the backend itself does almost nothing; in realistic file and network logging the relative cost is much smaller. A separate asynchronous FileBackend benchmark showed no regression outside measurement noise. This result is consistent with the broader measurements in my C++ logging performance benchmark.

Therefore, the goal was not to claim a mathematically zero cost. The goal was to ensure that inactive profiling did not add locks, allocations, registration, time collection, or counter traffic to normal application execution.

Log source profiling across channels and backends

In addition, one source record may be routed to more than one destination. A channel can have several backends, or it can link to another channel that has its own outputs.

For example:

source site
  -> channel policy
       -> FileBackend
       -> ConsoleBackend
       -> linked channel diagnostics
            -> another FileBackend

The source site generated one message, but the logging system performed four backend deliveries.

For that reason, logme exposes separate reports:

logstat top
logstat channels
logstat outputs
logstat backends

top measures source messages before routing. outputs attributes formatted backend output to the original call site after routing and fan-out. backends aggregates the same data by destination channel and backend type.

Specifically, for file output, output-bytes includes the fully formatted record as accepted by the backend, including channel prefixes and other enabled fields. In asynchronous mode it is counted when the file queue accepts the record. In synchronous mode it is counted after a successful write.

The file worker needs its own view

Although attribution tells us who produced the load, it does not tell us how efficiently the file worker handled it.

The logstat files report adds runtime counters for asynchronous FileBackend instances:

records and bytes accepted by the queue
worker batches
write operations
buffers and input bytes
successfully written bytes
failed write operations
queue-dropped records and bytes
average and maximum batch sizes

As a result, this separates two common problems.

For example, if accepted bytes closely match written bytes, errors are zero, and batches are reasonably sized, the backend is keeping up. The correct fix is probably at the source sites.

If the worker performs almost one write operation per record, batching may be ineffective. This is one reason asynchronous logging is not a silver bullet. If queue-drop counters are non-zero, records are already being lost. If write errors are present, the problem may be filesystem availability, permissions, free space, rotation, or archive handling rather than excessive application logging.

Running log source profiling in a live service

In practice, log source profiling is controlled through the regular logme control server, normally with logmectl. Collection is disabled by default.

A minimal session looks like this:

PORT=7791

logmectl -p "$PORT" logstat start

# Reproduce a representative workload.
sleep 60

logmectl -p "$PORT" logstat stop

logmectl -p "$PORT" logstat backends \
  --sort bytes \
  --limit 20

logmectl -p "$PORT" logstat outputs \
  --backend FileBackend \
  --sort bytes \
  --limit 30

logmectl -p "$PORT" logstat outputs \
  --backend FileBackend \
  --sort records \
  --limit 30

logmectl -p "$PORT" logstat files \
  --sort written-bytes \
  --limit 20

logstat start creates a new interval and resets the previous counters. logstat stop disables collection but preserves the result, so several reports can be queried without values changing underneath them.

For a serious investigation, however, I collect at least two intervals:

• an idle interval with the service running but no representative requests;
• a normal workload interval;
• optionally, a problem interval that reproduces the reported slowdown.

Thus, the difference separates periodic background messages from request-driven logging.

The full command set is:

logstat start
logstat stop
logstat status
logstat reset
logstat top [--sort bytes|records] [--limit count]
logstat channels [--sort bytes|records] [--limit count]
logstat outputs [--sort bytes|records] [--limit count] [--backend type]
logstat backends [--sort bytes|records] [--limit count] [--backend type]
logstat files [--sort written-bytes|batches|errors|dropped-bytes] [--limit count]

JSON output is available through the normal logmectl --format json mode for scripts and automated comparisons.

What log source profiling found in the real service

I ran the profiler for 287.184 seconds under a representative workload. Paths and channel names in the excerpt below are shortened, but the counts are unchanged.

Log backend statistics: stopped
Duration: 287.184 s
Sort: output-bytes
Backend filter: FileBackend
Total: records=252771 output-bytes=24802272

1. share=10.23% records=30107 records/s=104.84
   output-bytes=2536226 KiB/s=8.62 avg=84.2 max=165
   level=INFO channel=policy backend=FileBackend
   Entity/Condition.cpp:137 GetValue
   format: [line:%i col:%i] evaluating: %s

2. share=10.01% records=30107 records/s=104.84
   output-bytes=2483250 KiB/s=8.44 avg=82.5 max=216
   level=INFO channel=policy backend=FileBackend
   Eval/Calculator.cpp:590 Evaluate
   format: Evaluate expression: %s

3. share=8.54% records=30107 records/s=104.84
   output-bytes=2117192 KiB/s=7.20 avg=70.3 max=204
   level=INFO channel=policy backend=FileBackend
   Eval/Calculator.cpp:680 Evaluate
   format: %s is %s

4. share=7.79% records=30107 records/s=104.84
   output-bytes=1931391 KiB/s=6.57 avg=64.2 max=145
   level=INFO channel=policy backend=FileBackend
   Entity/Condition.cpp:176 GetValue
   format: %s is %s

Most importantly, the identical records=30107 value was the key clue. It showed that every expression evaluation produced the same sequence of detailed messages.

Moreover, additional entries from Calculator, Subcondition, and Entry completed the chain. Eight evaluation-related call sites accounted for approximately 56.5% of all bytes delivered to FileBackend during the interval.

Another group came from per-event network diagnostics:

async queue: ... size=... queued=...
async TLS protocol result: op=... bytes=... state=...
call policy engine with text size: ...
<full frame or payload dump>

Altogether, with frame dumps and small completion messages included, this group accounted for roughly another 15% of file output.

The profiler had converted a vague statement—“logging is high in VTune”—into a short, reviewable list of source locations.

The byte rate was not the main problem

During the interval, the application produced:

252,771 file-backend records
24,802,272 output bytes
287.184 seconds

That is approximately:

880 records per second
84 KiB per second

At first glance, eighty-four KiB/s is trivial for a modern disk. If we looked only at throughput, we might conclude that logging could not matter.

However, 880 records/s means 880 repeated units of work:

• format the message;
• construct output fields and prefixes;
• route it through channels;
• append it to an asynchronous queue;
• synchronize producer and worker state;
• wake or schedule the worker when needed;
• group buffers and issue writes;
• update file-management state.

Consequently, write(), mutexes, condition variables, and memory operations appeared in the CPU profile even though the raw byte rate was modest.

For this case, sorting by records was at least as important as sorting by bytes.

What should be changed after a hot site is found?

Importantly, the profiler deliberately does not decide which messages are unnecessary. That remains a semantic decision for the application owner.

For example, a detailed step-by-step interpreter trace may belong at DEBUG, or in a dedicated channel that can be enabled temporarily. A full payload dump, by contrast, may require an explicit diagnostic option. Repeated progress markers such as "." or "done" may have no value at all. Finally, a high-frequency expected condition may need aggregation, collapse, or rate limiting.

However, error records require more care. In the same profile, several ERROR sites appeared thousands of times. It would be unsafe to downgrade them merely because they were frequent. First determine whether they represent a genuine recurring failure or an expected fallback path that was assigned the wrong level. The correct fix may be state-transition logging, deduplication, or fixing the underlying error.

Ultimately, the point is not to eliminate logging. It is to make each diagnostic record earn its cost.

Why the profiler belongs inside the logging library

A generic CPU profiler sees functions and system calls. An external file monitor sees paths and byte counts. Neither has enough context to reconstruct source-site identity, channel routing, backend fan-out, and asynchronous queue behavior.

By contrast, the logging library already owns that information. It knows:

• the call-site cache;
• file, function, line, level, and format template;
• source and destination channels;
• which backend accepted the record;
• the size after backend formatting;
• whether an asynchronous file queue accepted or dropped it;
• how worker batches were written.

Therefore, adding on-demand attribution at these boundaries produces a much more actionable profile than sampling the final write() call.

At the same time, however, the feature must remain optional. A production logging library should not impose continuous profiling costs on every application. That is why the active collector is selected by a nullable atomic pointer, call sites are registered lazily, and all counters are inactive until explicitly enabled.

Access can also be controlled independently through ControlPolicy::AllowLogStatistics, just like other runtime control operations.

A practical log source profiling workflow

When a profiler shows logging near the top, I now use this sequence:

1. Fix any obvious busy loop or unrelated dominant defect first.
2. Collect an idle logstat interval.
3. Collect a representative workload interval.
4. Use backends to identify the dominant channel/backend pair.
5. Use outputs sorted by bytes to find large producers.
6. Use outputs sorted by records to find high-frequency producers.
7. Use files to verify batching, write errors, and queue drops.
8. Change only the responsible sites or policies.
9. Repeat the same interval and compare the rates.

As a result, this is a safer alternative to disabling logging globally, and it produces evidence that can be reviewed in code.

Conclusion

In conclusion, a hot logging backend is not a diagnosis. Log source profiling follows that endpoint back to the individual source statements that created the work.

For example, in the real service described here, a few detailed policy-evaluation messages produced more than half of the file output. Another small group of per-event network diagnostics contributed much of the remainder. The total bandwidth was modest, but the service was creating around 880 separate records per second.

Without source attribution, therefore, the natural response would have been to blame the entire logging subsystem. With source attribution, the problem became a concrete list of files, functions, lines, levels, channels, record rates, and byte rates.

That is the difference between disabling diagnostics and improving them.

The implementation and documentation are available in the logme repository. The runtime profiling guide contains the command reference and operational examples. More articles about the library are collected on the Logme topic page.