Log Source Profiling

Log Source Profiling

logstat is an on-demand profiler built into logme. It identifies the source locations, channels, routes, backends, and asynchronous file operations responsible for logging load while the application continues to run normally.

The feature is intended for a common production problem: a system profiler shows CPU time in FileBackend, write, queue management, or log formatting, but cannot tell which of thousands of log statements caused that work. Disabling logging globally may reduce the load, but it also removes the diagnostics needed to investigate the application.

logstat provides a narrower alternative. It attributes logging cost to individual C and C++ call sites and remains disabled until explicitly started through the control interface.

---

What the profiler measures

The profiler observes four related layers:

1. Log site — the C or C++ source location that created the record.
2. Source channel — the channel that accepted the record before links and backend fan-out.
3. Destination channel and backend — every built-in backend that accepted the formatted record after routing.
4. Asynchronous FileBackend runtime — batching, successful file writes, write failures, and queue drops after records entered the file queue.

Two metrics should normally be inspected independently:

• records finds very frequent messages. A large number of small records can spend CPU on formatting, queueing, synchronization, worker wakeups, and backend dispatch even when the byte rate is modest;
• bytes finds large records, payload dumps, verbose structured output, and other high-volume sources.

One source record can produce several backend records when channel links or multiple backends fan it out. For this reason, source-site and backend-output reports are separate.

---

Quick start

The examples below assume that the target application runs a logme control server on port 7791.

PORT=7791

logmectl -p "$PORT" logstat start

# Reproduce the workload for a representative interval.

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

start begins a new session and discards previous counters. stop disables collection but preserves the latest session so that several reports can be queried without values changing underneath them.

For performance investigations, collect at least two intervals:

• an idle interval, when the process is running but not processing the workload under investigation;
• a representative workload interval with normal traffic;
• optionally, a problem interval that reproduces the slowdown.

Comparing these intervals separates periodic background logging from logging caused by actual requests.

---

Command reference

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]

logstat start

Starts a new collection session. Existing counters are discarded before the profiler becomes active.

logstat stop

Stops collection and preserves the latest counters and interval duration. Reports remain available until the next start, reset, or process restart.

logstat status

Displays whether collection is active, whether a session exists, its duration, and aggregate source, backend, and asynchronous file counters.

logstat reset

Clears counters without changing the active state.

• If collection is active, it remains active and the interval clock restarts.
• If a stopped session exists, it remains stopped with empty counters and a zero-length interval.
• Calling reset before the first start does not create a session.

---

Finding hot source locations

logstat top

Ranks individual source locations before backend routing:

logmectl -p 7791 logstat top --sort bytes --limit 30
logmectl -p 7791 logstat top --sort records --limit 30

Each row includes:

• source file, function, and line;
• level and first observed format string;
• source channel;
• record count and records per second;
• message bytes, KiB per second, average size, and maximum size;
• share of the selected sort metric.

message-bytes measures the rendered message body at the source site. It does not include destination-channel prefixes or multiplication caused by routing to several backends.

logstat channels

Aggregates source-site activity by the channel that first accepted each record:

logmectl -p 7791 logstat channels --sort bytes --limit 30
logmectl -p 7791 logstat channels --sort records --limit 30

This is a useful first pass when the application has many named diagnostic channels.

---

Finding backend and file-output hot spots

logstat outputs

Ranks source locations by the output delivered to destination backends after channel links and fan-out:

logmectl -p 7791 logstat outputs \
  --backend FileBackend \
  --sort bytes \
  --limit 30

Each row identifies:

• the source file, function, and line;
• the source message format and level;
• the destination channel;
• the backend type;
• the number and size of records accepted by that backend.

output-bytes includes destination formatting, channel prefixes, routing fan-out, and the final record size seen by the backend.

For FileBackend:

• synchronous output is counted after a successful write;
• asynchronous output is counted after the record is accepted by the file queue;
• when file obfuscation is enabled, the obfuscated record size is counted.

Run this report twice:

logmectl -p 7791 logstat outputs --backend FileBackend --sort bytes --limit 50
logmectl -p 7791 logstat outputs --backend FileBackend --sort records --limit 50

The first command finds the largest producers. The second finds high-frequency statements that may dominate formatting, queueing, locking, and wakeup overhead even when their total byte volume is not large.

logstat backends

Aggregates output by destination channel and backend type:

logmectl -p 7791 logstat backends --sort bytes --limit 30

This answers the first diagnostic question: which channel/backend combination is responsible for most of the logging work?

The optional backend filter isolates one backend family:

logmectl -p 7791 logstat backends \
  --backend FileBackend \
  --sort records \
  --limit 30

---

Inspecting asynchronous FileBackend behavior

logstat files

This report shows what asynchronous file workers did after records entered their queues:

logmectl -p 7791 logstat files --sort written-bytes --limit 30
logmectl -p 7791 logstat files --sort batches --limit 30
logmectl -p 7791 logstat files --sort errors --limit 30
logmectl -p 7791 logstat files --sort dropped-bytes --limit 30

For each asynchronous FileBackend, the report includes:

• records and bytes accepted by the queue;
• worker batches, write operations, buffers, and input bytes;
• average and maximum batch size;
• buffers and bytes confirmed by successful file-write calls;
• failed batches, operations, buffers, and affected input bytes;
• records and bytes rejected because the queue could not accept more data.

Accepted bytes closely match written bytes

The file worker is keeping up. The dominant cost is likely the number or size of records produced by the application. Use logstat outputs to find the source sites.

Many records and small batches

The worker is waking frequently and writing small groups. Inspect output sorted by records before changing backend batching policy; a few noisy call sites may be the actual cause.

Accepted bytes exceed written bytes

Data may still be queued, especially if workload generation stopped immediately before logstat stop. Flush application logs before stopping when a fully drained interval is required. A persistent difference can also indicate write failures.

Queue-dropped values are non-zero

The asynchronous queue could not accept all output. Some log records were lost. This is a stronger signal than high CPU usage and should be investigated immediately.

Write errors are non-zero

Check filesystem availability, permissions, free space, rotation, and archive operations. Reducing log volume alone does not fix an I/O failure.

Successful byte counts are exact for completed WriteAll or WriteAllVector calls. If a low-level write partially succeeds and then fails, failed input bytes describe the affected input batch and may be larger than the bytes that remained unwritten.

---

Reading a source-site result

A backend-output result can look like this:

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
   src/policy/Condition.cpp:137 GetValue
   format: [line:%i col:%i] evaluating: %s

This means that one source location generated 30,107 file-backend records during the interval and accounted for 10.23% of the selected output-byte total.

The format line is the format template captured from the call site, not a rendered message containing runtime values.

Several adjacent rows with identical record counts often reveal a verbose trace chain. For example, one operation may always emit:

evaluating expression
expression value
comparison input
comparison result

In that situation, changing one isolated statement may not be enough. Review the whole trace sequence and decide whether it belongs at INFO, DEBUG, a separate channel, or behind rate limiting.

---

A practical diagnostic workflow

When an operating-system profiler shows FileBackend, write, or log queue code near the top, use the following sequence.

1. Determine whether the problem exists at idle

logmectl -p 7791 logstat start
sleep 60
logmectl -p 7791 logstat stop

Save the following reports:

logmectl -p 7791 logstat backends --sort bytes --limit 20
logmectl -p 7791 logstat outputs --backend FileBackend --sort bytes --limit 50
logmectl -p 7791 logstat outputs --backend FileBackend --sort records --limit 50
logmectl -p 7791 logstat files --sort batches --limit 20

2. Repeat under representative load

Start a new session, reproduce normal traffic, stop collection, and run the same reports.

3. Separate four possible causes

• A few source sites dominate records or bytes — review those statements, their level, and their channel.
• A destination channel multiplies output — inspect routing and backend fan-out.
• The file worker writes many small batches — first reduce fragmented source output, then consider batching policy.
• Writes fail or the queue drops data — investigate the filesystem or queue capacity rather than merely hiding logs.

This workflow complements VTune, perf, or another system profiler. The system profiler finds the expensive subsystem; logstat attributes the logging work to source code.

---

C and C++ call-site identification

Standard C++ logging macros use a static context cache associated with each macro expansion.

Standard native C macros also create a site-specific LogmeCContextCache, so C and C++ call sites are both separated by source file, function, and line.

Direct calls to legacy LogmeWrite* functions that do not provide a LogmeCContextCache remain grouped under the shared C API context. Applications that require exact attribution for direct C calls can use the site-aware entry points used internally by the standard macros:

LogmeWriteSite(...);
LogmeWriteSiteV(...);
LogmeWriteSiteOverride(...);
LogmeWriteSiteOverrideV(...);

For C++ stream-style output, the report may display:

format: <stream or empty>

because there is no single printf-style format template to capture.

See C API for the normal C logging interface.

---

Data handling and limitations

• Statistics are stored in process memory and are not persisted across process restart.
• The profiler stores source metadata and the first observed format template.
• It does not retain rendered message bodies or runtime argument values.
• CallbackBackend records calls but reports zero output bytes because logme cannot know what the application callback does with the context.
• format json logstat ... uses the normal control JSON envelope and currently returns the human-readable report in data.text.
• The counters are diagnostic data, not a replacement for an operating-system CPU, disk, or lock profiler.

---

Disabled-path performance

Collection is disabled by default. The inactive path is deliberately designed to add minimal overhead.

While profiling is disabled, logme performs no:

• call-site registration;
• statistics counter updates;
• mutex acquisition;
• memory allocation;
• time query;
• map or string lookup;
• source metadata copying.

For a record that has already passed normal filtering and formatting, the source-site path adds one relaxed atomic pointer load and a normally predicted null branch. Each built-in backend that accepts the record adds the same kind of check.

The asynchronous file worker performs one active-profiler check per ready batch, not per record. Existing early level and channel rejection happens before these checks.

When collection is active, established sites use relaxed atomic counters. Registration and allocation occur only when a source site, output route, or file backend is first observed in the current profiler generation.

See Performance and Why logme is fast for the broader logging hot-path model.

---

Control policy

The ControlPolicy field AllowLogStatistics can disable all logstat commands independently of other runtime-control operations. It is enabled by the built-in Full, Safe, and Diagnostic policies.

See Control Policies, Control Server, and logmectl.