perf(util): stop a suppressed log message taking the global lock twice - #7696
Merged
Conversation
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.
Contributor
There was a problem hiding this comment.
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
LogLevelis enabled byLogPolicy. - Short-circuits
Log::Init()andLog::~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.
|
|
||
| namespace | ||
| { | ||
| //! Whether anything written to a Log at this level will be printed at all. |
Comment on lines
+75
to
+78
| bool wanted(const LogLevel level) | ||
| { | ||
| const auto &policy = LogPolicy::GetInstance(); | ||
| return !policy.IsMute() && level <= policy.GetLevel(); |
Codecov Report✅ All modified and coverable lines are covered by tests. 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. 🚀 New features to boost your workflow:
|
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Issue
No issue. Found while profiling an
osrm-extractrun that appeared to hang.The problem
Log::Init()andLog::~Log()each take a process-wide mutex before asking whether themessage will be printed:
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 kindthat 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::~Logintopthread_mutex_unlock, which told me nothing about the loop that wasactually 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, whichis 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 DEBUGstill prints what it printed before.Was this change primarily generated using an AI tool? Yes.
🤖 Claude Code, Claude Opus 5
Tasklist
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.