Skip to content

perf(util): stop a suppressed log message taking the global lock twice - #7696

Merged
DennisOSRM merged 1 commit into
masterfrom
perf-log-skip-suppressed
Aug 16, 2026
Merged

perf(util): stop a suppressed log message taking the global lock twice#7696
DennisOSRM merged 1 commit into
masterfrom
perf-log-skip-suppressed

Conversation

@DennisOSRM

Copy link
Copy Markdown
Collaborator

Issue

No issue. Found while profiling an osrm-extract run that appeared to hang.

The problem

Log::Init() and Log::~Log() each take a process-wide mutex before asking whether the
message will be printed:

void Log::Init()
{
    std::lock_guard<std::mutex> lock(get_mutex());
    if (!LogPolicy::GetInstance().IsMute() && level <= LogPolicy::GetInstance().GetLevel())
    ...

So every switched-off statement, which at default verbosity means every util::Log(logDEBUG)
in the codebase, pays two round trips through one global lock to decide to print nothing.
operator<< already skips the formatting, so the lock is the whole cost, and it is the kind
that gets worse with more cores rather than better: one thread in a loop with a debug
statement in it serialises every other thread in the program.

I ran into this the hard way. Profiling an extract that would not finish, the entire sample
was Log::~Log into pthread_mutex_unlock, which told me nothing about the loop that was
actually running. Fixing this did not make the extract finish, but it made the real defect
visible (that one is #7695).

The change

Ask before locking. The body of both functions was already wrapped in exactly this
condition, so this is the same test taken sooner and there is no behaviour change: a message
that was printed before is printed now, with the same prefix, on the same stream.

The remaining cost of a suppressed message is constructing and destroying an empty
std::ostringstream. Removing that too would mean changing how call sites are written, which
is a much larger change and not one to smuggle in here.

Testing

All fourteen unit suites pass. Full cucumber: 1478 scenarios, 1463 passed, 15 skipped, 0
failed, unchanged. --verbosity DEBUG still prints what it printed before.

Was this change primarily generated using an AI tool? Yes.

🤖 Claude Code, Claude Opus 5

Tasklist

  • self-review code for correctness and following the coding guidelines
  • add tests
  • update relevant wiki pages
  • review
  • adjust for comments

Requirements / Relations

Independent of #7695, though that is where it came from. No test here: the defect is a
performance property of a mutex under contention, and I could not write an assertion for it
that would not be flaky on CI.

Log::Init() and ~Log() each took a process-wide mutex before checking whether
anything would be printed. Every switched-off statement therefore paid two
global lock round trips to decide to print nothing, and with several threads a
loop containing one serialised the whole program on it.

Measured on osrm-extract over a pedestrian area: the profile was entirely
Log::~Log calling pthread_mutex_unlock, which hid the loop that was actually
running.

The check now happens before the lock. operator<< already skips the formatting,
so a suppressed message costs the empty ostringstream and nothing else.

No behaviour change: the body of both functions was already wrapped in the same
condition, so the early return is the same test, taken sooner.
Copilot AI lite review requested due to automatic review settings August 16, 2026 13:46

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

Reduces contention in OSRM’s logging subsystem by avoiding taking the process-wide log mutex for log statements that are suppressed by the current LogPolicy (mute/verbosity), improving multi-threaded performance in hot loops (e.g., logDEBUG at default verbosity).

Changes:

  • Introduces a small helper predicate to check whether a given LogLevel is enabled by LogPolicy.
  • Short-circuits Log::Init() and Log::~Log() before acquiring the global log mutex when the message will not be emitted.

💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.

Comment thread src/util/log.cpp

namespace
{
//! Whether anything written to a Log at this level will be printed at all.
Comment thread src/util/log.cpp
Comment on lines +75 to +78
bool wanted(const LogLevel level)
{
const auto &policy = LogPolicy::GetInstance();
return !policy.IsMute() && level <= policy.GetLevel();
@codecov

codecov Bot commented Aug 16, 2026

Copy link
Copy Markdown

Codecov Report

✅ All modified and coverable lines are covered by tests.
✅ Project coverage is 94.74%. Comparing base (9229f17) to head (04179b3).

Additional details and impacted files
@@            Coverage Diff             @@
##           master    #7696      +/-   ##
==========================================
- Coverage   94.75%   94.74%   -0.02%     
==========================================
  Files         519      519              
  Lines       41582    41589       +7     
==========================================
  Hits        39402    39402              
- Misses       2180     2187       +7     

☔ View full report in Codecov by Harness.
📢 Have feedback on the report? Share it here.

🚀 New features to boost your workflow:
  • ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.
  • 📦 JS Bundle Analysis: Save yourself from yourself by tracking and limiting bundle sizes in JS merges.

@DennisOSRM
DennisOSRM merged commit c0a0308 into master Aug 16, 2026
23 of 24 checks passed
@DennisOSRM
DennisOSRM deleted the perf-log-skip-suppressed branch August 16, 2026 17:22
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants