Add lock and task wait time logging#64
Open
krleonid wants to merge 9 commits into
Open
Conversation
- Add enqueue_time field to Task class for measuring queue wait times - Log when tasks wait more than 10ms in queue before worker picks them up - Add lock wait time logging to BlockManager methods (>10ms threshold) - Use DUCKDB_LOG_WARNING for proper logging integration Co-Authored-By: Claude Haiku 4.5 <noreply@anthropic.com>
Fixed issues from review:
1. (High) Moved logging OUTSIDE lock scope to avoid observer effect
- Lock wait is now measured accurately without amplifying contention
- Wrapped locked work in inner block, log AFTER lock_guard releases
2. (High) Use steady_clock instead of high_resolution_clock
- steady_clock is guaranteed monotonic (won't jump back)
- high_resolution_clock is alias for system_clock (wallclock)
- Prevents spurious warnings from NTP/manual clock adjustments
- Consistent with existing block_manager.cpp code
3. (Medium) Guard against default-constructed timestamps
- Skip logging if enqueue_time == epoch (time_point{})
- Prevents false positives from tasks that bypass enqueue path
- Defensive programming against future code changes
Changes:
- Task class: added enqueue_time field (steady_clock)
- Task scheduler: measure queue wait, log if >10ms (with guards)
- BlockManager: measure lock wait, log if >10ms (with guards)
- All logging happens AFTER releasing the lock
Co-Authored-By: Claude Haiku 4.5 <noreply@anthropic.com>
- Space after time_point type - Proper line continuation alignment for long expressions - Indent alignment in DUCKDB_LOG_WARNING call Co-Authored-By: Claude Haiku 4.5 <noreply@anthropic.com>
Enrich the queue-wait warning with the busy worker count, total worker count and queue depth so production spikes can be classified as saturation vs. a genuine scheduler stall. Also tag the warning with the task type (via Task::TaskType()). Add a second warning that measures how long a task held a worker inside Execute(), tagged with task type and execution mode (all/partial). A long non-preemptive task here is the cause of the queue waits reported by the first log, making the head-of-line relationship visible from logs alone. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
krleonid
force-pushed
the
feature/lock-wait-logging
branch
from
6b560bc to
adae208
Compare
PipelineTask now includes [src=...][sink=...] and PipelineFinishTask includes [sink=...] in their TaskType() strings, making slow-task log lines actionable without a separate profiling run. Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>
For ILIKE / NOT ILIKE (and the ... ESCAPE variants), when the pattern is constant at runtime, lowercase the pattern once instead of per row and reuse a single scratch buffer to lowercase each string value (avoids two heap allocations + a redundant pattern case-fold per row). When the escape character does not occur in the pattern, build a case-folded LikeMatcher and use the SIMD FindStrInStr contains path; otherwise fall back to the generic escape-aware matcher on the lowercased values. Non-constant patterns keep the existing per-row path. This roughly halves time on the realistic multi-token search shape (ILIKE '%term%' ESCAPE '\\' OR-ed across many columns) on unicode-possible data. Add tests for the constant-pattern ILIKE and ILIKE ... ESCAPE fast paths, and an ilike_regular micro-benchmark mirroring like_regular. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
Cover the remaining branches of the constant-pattern ILIKE ... ESCAPE path: - escape char inactive but pattern has '_' wildcard => matcher disabled, escape-aware recursive fallback with a non-zero escape char (match + no-match) - ESCAPE NULL => NULL result - non-constant (per-row) escape column => generic ternary fallback Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
The unicode ILIKE path routed plain ILIKE through the escape-aware matcher
with escape='\0', so an embedded NUL byte in the pattern was treated as a
LIKE escape character and identical strings failed to match (e.g.
'goo\0se' ILIKE 'goo\0se' returned false). The ASCII operator and plain LIKE
already used the non-escape matcher.
Treat '\0' as the "no escape" sentinel in ILikeOperatorFunction and the
ILikeEscapeFunction constant fast-path fallback, matching embedded NUL bytes
literally and bringing all ILIKE code paths into agreement.
Update test/fuzzer/duckfuzz/array_hash.test: its !~~* join over
test_all_types() ('goo\0se' next to a multi-codepoint value) previously
recorded the buggy 4-row result; the correct result is 3 rows.
Add test/sql/function/string/test_ilike_embedded_null.test covering the
constant-fold, ASCII-operator, unicode per-row, constant-pattern fast path,
case-insensitivity, wildcard and ESCAPE '' cases.
Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
…nction The ESCAPE fallback path was written for upstream main's count-less TernaryExecutor::Execute API; this branch still requires an explicit idx_t count argument. Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>
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
1 participant
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.
Summary
Changes
enqueue_timefield to track queue entry timeBlockIsRegistered()TryGetBlock()RegisterBlock()UnregisterBlock()Integration
DUCKDB_LOG_WARNINGmacro for proper loggingTesting
Run queries and observe warnings when: