cockroachdb / cockroachdb/cockroach

util/log: any --vmodule filter makes every log.V call process-wide expensive

Open
#172,856 1 comment 0 reactions 0 assignees View on GitHub
A-logging C-performance O-agent T-observability
Dominant language
Go
Stars
32.5k
Forks
4.1k
PR merge metrics
PR metrics pending

Description

**Summary**

Setting `--vmodule` to *any* non-empty value — even a single filter matching a
single file — puts every `log.V`, `log.VEvent*`, and `log.ExpensiveLogEnabled`
call in the **entire process** onto a slow path that performs a stack unwind and
acquires a process-global mutex. No additional output is produced; the cost is a
process-wide switch.

This was observed by @sumeerbhola on a kv0-style write workload run with
`--vmodule=multi_engine_compaction_scheduler=3`: a CPU profile attributed ~23%
of CPU to `log.(*vmoduleConfig).vDepth`, despite that filter matching exactly one
file.

Practical impact: `--vmodule` is effectively unusable as a debugging tool on a
loaded cluster, and — more insidiously — it silently skews any CPU profile taken
while it is set, which is how this surfaced.

**Mechanism**

[`vDepth`](https://github.com/cockroachdb/cockroach/blob/e3bff5d92ac171e3c45a0eb6cda5356b4182e4ed/pkg/util/log/vmodule.go#L74)
has two gates:

```go
if c.verbosity.get() >= l { return true } // --verbosity, off by default
if atomic.LoadInt32(&c.mu.filterLength) > 0 { ... } // ANY --vmodule entry
```

[`filterLength` is `len(filter)` over the whole vmodule spec](https://github.com/cockroachdb/cockroach/blob/e3bff5d92ac171e3c45a0eb6cda5356b4182e4ed/pkg/util/log/vmodule.go#L131),
not a per-file predicate. One filter sets it to 1, and every V-style call
everywhere falls into the slow branch, which does:

1. [`sync.Pool` Get/Put](https://github.com/cockroachdb/cockroach/blob/e3bff5d92ac171e3c45a0eb6cda5356b4182e4ed/pkg/util/log/vmodule.go#L89)
2. [`runtime.Callers(2+depth, pcs[:])`](https://github.com/cockroachdb/cockroach/blob/e3bff5d92ac171e3c45a0eb6cda5356b4182e4ed/pkg/util/log/vmodule.go#L96) — stack unwind for the caller PC
3. [`c.mu.Lock()` on a single process-global mutex](https://github.com/cockroachdb/cockroach/blob/e3bff5d92ac171e3c45a0eb6cda5356b4182e4ed/pkg/util/log/vmodule.go#L101) to read `vmap`

Note that the map lookup itself is not the problem — non-matching PCs are
[negatively cached as level 0](https://github.com/cockroachdb/cockroach/blob/e3bff5d92ac171e3c45a0eb6cda5356b4182e4ed/pkg/util/log/vmodule.go#L156),
so `vmap` converges within milliseconds and reads are O(1). The cost is entirely
(2) the unwind and (3) contention on one mutex taken by every goroutine on every
V call. The profile above attributes the total to `vDepth` but does not break it
out between the two.

**Blast radius**

Approximate call-site counts on master:

| API | sites |
|---|---|
| `log.V(` | ~393 |
| `log.VEvent*` | ~841 |
| `log.ExpensiveLogEnabled` | ~123 |

[`vEventf` calls `VDepth` unconditionally](https://github.com/cockroachdb/cockroach/blob/e3bff5d92ac171e3c45a0eb6cda5356b4182e4ed/pkg/util/log/trace.go#L120),
so trace-oriented call sites in KV eval, rangefeed, etc. pay it too, whether or
not a span is present.

`ExpensiveLogEnabled` is the **worst**-affected API, not the best.
[It checks the span first](https://github.com/cockroachdb/cockroach/blob/e3bff5d92ac171e3c45a0eb6cda5356b4182e4ed/pkg/util/log/log.go#L63),
so in the common production case — no verbose span, vmodule set — it pays a
`ctx.Value` walk *and then* the expensive `VDepth`. Plain `log.V` pays only the
latter.

**Call-site audit: is there a "check the span first" pattern to exploit?**

We looked for call sites that guard V-style logging behind a span check, on the
theory that a cheap span test could short-circuit the expensive `VDepth`.
**There are none**, and the theory does not hold in general. Recording both
results so this isn't re-investigated:

Four proximity hits, all coincidental:

- [`txn_coord_sender.go:548`](https://github.com/cockroachdb/cockroach/blob/e3bff5d92ac171e3c45a0eb6cda5356b4182e4ed/pkg/kv/kvclient/kvcoord/txn_coord_sender.go#L548) — `log.V(2)` nested in `sp.IsVerbose()`, but it gates adding a `ts` logtag, not a log call.
- [`rafttrace.go:310`](https://github.com/cockroachdb/cockroach/blob/e3bff5d92ac171e3c45a0eb6cda5356b4182e4ed/pkg/kv/kvserver/rafttrace/rafttrace.go#L310) — span check is a functional gate on trace registration; the nearby `VEvent` is incidental.
- [`range_controller.go:903`](https://github.com/cockroachdb/cockroach/blob/e3bff5d92ac171e3c45a0eb6cda5356b4182e4ed/pkg/kv/kvserver/kvflowcontrol/rac2/range_controller.go#L903) — span used for `RecordStructured`; the log is gated by a hoisted `expensiveLoggingEnabled`.
- [`outbox.go:246`](https://github.com/cockroachdb/cockroach/blob/e3bff5d92ac171e3c45a0eb6cda5356b4182e4ed/pkg/sql/colflow/colrpc/outbox.go#L246) — span used for tagging/`Finish`; the `VEventf` is unrelated.

There is also no `HasSpanOrEvent`-style helper that would encourage the pattern.

Whether a span check *can* substitute for `VDepth` depends on the semantics:

- **OR semantics** ("will anything consume this?") — `ExpensiveLogEnabledVDepth`. A verbose span makes the answer true regardless of `VDepth`, so checking it first genuinely short-circuits. The existing ordering there is correct.
- **Three-way semantics** — `vEventf`, which must choose between logging to DEV, recording to the trace only, or doing nothing. `VDepth`'s answer is needed in *both* span cases, so a span-first check cannot short-circuit it and only adds a `ctx.Value` walk. The existing ordering there is also correct.

Conclusion: **no caller changes are needed**, and reordering the existing checks
is not a fix. The one call-site-level mitigation that does help is *hoisting*
`ExpensiveLogEnabled` out of loops, which today only
[`range_controller.go:746`](https://github.com/cockroachdb/cockroach/blob/e3bff5d92ac171e3c45a0eb6cda5356b4182e4ed/pkg/kv/kvserver/kvflowcontrol/rac2/range_controller.go#L746)
and
[`descriptor_state.go:346`](https://github.com/cockroachdb/cockroach/blob/e3bff5d92ac171e3c45a0eb6cda5356b4182e4ed/pkg/sql/catalog/lease/descriptor_state.go#L346)
do. Not worth a repo-wide sweep, but worth doing opportunistically in hot paths.

**Secondary finding: `pcsPool` is dead weight**

[`pcs := poolObj.([1]uintptr)`](https://github.com/cockroachdb/cockroach/blob/e3bff5d92ac171e3c45a0eb6cda5356b4182e4ed/pkg/util/log/vmodule.go#L90)
copies the array *out* of the interface, so the pooled object is never written
to — `pcs` is a fresh local. The pool cannot be serving its stated purpose.
Checked against an isolated repro under `-gcflags=-m`: `runtime.Callers`' slice
argument does not force escape, so a plain `var pcs [1]uintptr` is already
allocation-free. The pool adds a Get, a Put, and a type assertion per call for
no benefit.

**Secondary finding: `vEvent` double-evaluates `VDepth`**

[`vEvent`](https://github.com/cockroachdb/cockroach/blob/e3bff5d92ac171e3c45a0eb6cda5356b4182e4ed/pkg/util/log/trace.go#L105)
computes `VDepth`, then delegates to `vEventf`, which
[computes it again](https://github.com/cockroachdb/cockroach/blob/e3bff5d92ac171e3c45a0eb6cda5356b4182e4ed/pkg/util/log/trace.go#L120)
for the same call site. On the span-present / `VDepth`-false path that is two
full slow-path evaluations — two unwinds and two mutex acquisitions — for one
log statement. Only bites under verbose tracing, so it is almost certainly not
part of the 23% above.

**Fixes, ordered by impact**

Items 1, 3, and 4 are contained, independently correct, and carry no API change
— they can just be done. Item 2 is the larger follow-up.

- [ ] **1. Lock-free `vmap` reads.** *Biggest win, small change.* Replace the
mutex + map with `atomic.Pointer[map[uintptr]Level]`, copy-on-write on
miss. The PC set is bounded by the number of call sites and converges
almost immediately, after which writes stop entirely and every read is a
single atomic load. Eliminates the contention term outright, and it is the
term that scales with core count — on a high-core machine a single global
mutex on a path hit millions of times/sec is the limiter. Contained to
`vmodule.go`.
- [ ] **2. Call-site identity to eliminate the unwind.** *Highest ceiling,
largest effort.* The `runtime.Callers` cost cannot be removed without
knowing the caller's file cheaply. The realistic approach is an opt-in
per-file handle, e.g. `var vlog = log.NewFileVFilter()` resolved once at
init, making `vlog.V(2)` a single atomic load with no unwind at all. Needs
a generation counter so runtime `SET vmodule` still invalidates. Scope it
to the hottest packages (KV eval, rangefeed) rather than repo-wide, and
land it after 1. See #34461 for prior evidence that PC/call-site caching
here has inlining subtleties.
- [ ] **3. Delete `pcsPool`.** *Trivial.* Removes a Get, a Put, and a type
assertion per call. Independent of everything else.
- [ ] **4. Thread `vEvent`'s `VDepth` result into `vEventf`.** *Trivial, narrow.*
Halves the cost for `VEvent`/`VEventf` under verbose tracing only.

Suggested landing order is 3, 4, 1 (all small and independent), then 2 as scoped
follow-up work.

**Related**

- #34461 — `log: VDepth doesn't work properly when inlined function call follows the call site` (correctness, not perf, but same PC-caching machinery)

Jira issue: CRDB-66124

Contributor guide

Open the contributing guide

Research direction

Start in pkg/util/log/vmodule.go at vDepth, filterLength, pcsPool, and the vmap access; then read pkg/util/log/trace.go at vEvent and vEventf. Choose one independently listed fix and verify that the selected overhead is removed without changing logging behavior or SET vmodule semantics; #34461 provides related context on call-site caching.

Written by the indexing model from the issue text.

Assessment

Tech stack
go
Domain
observability-sre, performance
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Quiet
Clarity
Mostly clear
Newbie friendliness
48/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.