MOD-13602 Add queue time tracking to FT.PROFILE #8210
Conversation
Codecov Report✅ All modified and coverable lines are covered by tests. Additional details and impacted files@@ Coverage Diff @@
## master #8210 +/- ##
==========================================
+ Coverage 82.99% 83.00% +0.01%
==========================================
Files 383 383
Lines 56330 56343 +13
Branches 15161 15161
==========================================
+ Hits 46750 46770 +20
+ Misses 9426 9419 -7
Partials 154 154
Flags with carried forward coverage won't be shown. Click here to find out more. ☔ View full report in Codecov by Sentry. 🚀 New features to boost your workflow:
|
| if (profile_verbose) { | ||
| RedisModule_ReplyKV_Double(reply, "Workers queue time", | ||
| rs_wall_clock_convert_ns_to_ms_d(req->profileQueueTime)); | ||
| } |
There was a problem hiding this comment.
Missing comment for new Workers queue time block
Low Severity
The new "Workers queue time" output block is missing a descriptive comment that all other adjacent timing blocks consistently have. Lines 160, 166, 177, 183, and 191 all follow a // Print <something> time comment pattern before their respective if (profile_verbose) blocks, but the new Workers queue time block lacks this comment, breaking the established style convention in this function.
lerman25
left a comment
There was a problem hiding this comment.
Great job
some comments
| if (profile_verbose) { | ||
| RedisModule_ReplyKV_Double(reply, "Workers queue time", | ||
| rs_wall_clock_convert_ns_to_ms_d(req->profileQueueTime)); | ||
| } |
|
|
||
| if (IsProfile(req)) { | ||
| req->profileQueueTime = rs_wall_clock_elapsed_ns(&req->initClock); | ||
| rs_wall_clock_init(&req->initClock); |
There was a problem hiding this comment.
Why re-initialize the clock?
There was a problem hiding this comment.
The clock is reused: first to measure queue time, then re-initialized to measure parsing time. This avoids needing two separate clock fields
There was a problem hiding this comment.
It's a general clock meant to represent the time since the query began, I think re-initiliazing is not the correct behavior here, taking into account something else might relay on it (in backport for example). Maybe just compute: parsing time = init time - queue time
Add design document and validation tests that confirm the bug exists: - testParsingTimeIncludesWorkersQueueTime_BUG: Confirms workers queue wait time is incorrectly included in 'Parsing time' (bug) - testParsingTimeDoesNotIncludeCoordQueueTime: Confirms coordinator queue time is correctly separate from shard's Parsing time Both tests pass, confirming the bug exists as described in the design doc.
- Add profileQueueTime field to AREQ struct in aggregate.h - Capture queue time at start of AREQ_Execute_Callback() in aggregate_exec.c - Queue time = elapsed time since initClock was set before enqueueing - Reset initClock after capturing queue time for accurate parsing time - Print 'Workers queue time' in profile output in profile.c - Add testWorkersQueueTimeInProfile test to verify the fix - Mark testParsingTimeIncludesWorkersQueueTime_BUG as skipped (bug is fixed) This fixes the bug where FT.PROFILE's 'Parsing time' incorrectly included time spent waiting in the workers thread pool queue.
Track time spent waiting in the coordinator thread pool queue and report it as 'Coordinator queue time' in FT.PROFILE output. Changes: - Add coordQueueTime field to ConcurrentSearchHandlerCtx struct - Add coordQueueTime field to searchRequestCtx struct - Calculate queue time in DistSearchCommandHandler and DEBUG_DistSearchCommandHandler - Copy queue time to searchRequestCtx in FlatSearchCommandHandler - Print 'Coordinator queue time' in profileSearchReplyCoordinator
Add testCoordinatorQueueTimeInProfile to verify that coordinator queue time is correctly captured in cluster mode when the coordinator thread pool is paused.
3a5c085 to
baee726
Compare
|
Backport failed for Please cherry-pick the changes locally and resolve any conflicts. git fetch origin 8.2
git worktree add -d .worktree/backport-8210-to-8.2 origin/8.2
cd .worktree/backport-8210-to-8.2
git switch --create backport-8210-to-8.2
git cherry-pick -x 7622a9e0636492d6df01528d9c13c745586f3609 |
|
Backport failed for Please cherry-pick the changes locally and resolve any conflicts. git fetch origin 8.4
git worktree add -d .worktree/backport-8210-to-8.4 origin/8.4
cd .worktree/backport-8210-to-8.4
git switch --create backport-8210-to-8.4
git cherry-pick -x 7622a9e0636492d6df01528d9c13c745586f3609 |
|
Backport failed for Please cherry-pick the changes locally and resolve any conflicts. git fetch origin 8.6
git worktree add -d .worktree/backport-8210-to-8.6 origin/8.6
cd .worktree/backport-8210-to-8.6
git switch --create backport-8210-to-8.6
git cherry-pick -x 7622a9e0636492d6df01528d9c13c745586f3609 |
* Add validation tests for FT.PROFILE queue time bug Add design document and validation tests that confirm the bug exists: - testParsingTimeIncludesWorkersQueueTime_BUG: Confirms workers queue wait time is incorrectly included in 'Parsing time' (bug) - testParsingTimeDoesNotIncludeCoordQueueTime: Confirms coordinator queue time is correctly separate from shard's Parsing time Both tests pass, confirming the bug exists as described in the design doc. * Implement Part 1: Workers queue time in FT.PROFILE - Add profileQueueTime field to AREQ struct in aggregate.h - Capture queue time at start of AREQ_Execute_Callback() in aggregate_exec.c - Queue time = elapsed time since initClock was set before enqueueing - Reset initClock after capturing queue time for accurate parsing time - Print 'Workers queue time' in profile output in profile.c - Add testWorkersQueueTimeInProfile test to verify the fix - Mark testParsingTimeIncludesWorkersQueueTime_BUG as skipped (bug is fixed) This fixes the bug where FT.PROFILE's 'Parsing time' incorrectly included time spent waiting in the workers thread pool queue. * Add coordinator queue time tracking to FT.PROFILE Track time spent waiting in the coordinator thread pool queue and report it as 'Coordinator queue time' in FT.PROFILE output. Changes: - Add coordQueueTime field to ConcurrentSearchHandlerCtx struct - Add coordQueueTime field to searchRequestCtx struct - Calculate queue time in DistSearchCommandHandler and DEBUG_DistSearchCommandHandler - Copy queue time to searchRequestCtx in FlatSearchCommandHandler - Print 'Coordinator queue time' in profileSearchReplyCoordinator * Add test for coordinator queue time in FT.PROFILE Add testCoordinatorQueueTimeInProfile to verify that coordinator queue time is correctly captured in cluster mode when the coordinator thread pool is paused. * Remove design document (intermediate artifact) * Fix tests for new Workers queue time and Coordinator queue time fields * Address Cursor Bugbot review: remove obsolete test and unused env parameters * Add AGENTS.local.md to .gitignore * Fix test expectations for new Workers queue time field in FT.PROFILE output * Remove redundant comments from queue time tracking code * Fix test_RED_86036 index after adding Workers queue time to FT.PROFILE * Fix dead code issue * Revert unrelated changes to AGENTS.md and .gitignore * CR- larger debug pauses, clock only on profile and different output order * CR- dont init clock (cherry picked from commit 7622a9e)
* Add validation tests for FT.PROFILE queue time bug Add design document and validation tests that confirm the bug exists: - testParsingTimeIncludesWorkersQueueTime_BUG: Confirms workers queue wait time is incorrectly included in 'Parsing time' (bug) - testParsingTimeDoesNotIncludeCoordQueueTime: Confirms coordinator queue time is correctly separate from shard's Parsing time Both tests pass, confirming the bug exists as described in the design doc. * Implement Part 1: Workers queue time in FT.PROFILE - Add profileQueueTime field to AREQ struct in aggregate.h - Capture queue time at start of AREQ_Execute_Callback() in aggregate_exec.c - Queue time = elapsed time since initClock was set before enqueueing - Reset initClock after capturing queue time for accurate parsing time - Print 'Workers queue time' in profile output in profile.c - Add testWorkersQueueTimeInProfile test to verify the fix - Mark testParsingTimeIncludesWorkersQueueTime_BUG as skipped (bug is fixed) This fixes the bug where FT.PROFILE's 'Parsing time' incorrectly included time spent waiting in the workers thread pool queue. * Add coordinator queue time tracking to FT.PROFILE Track time spent waiting in the coordinator thread pool queue and report it as 'Coordinator queue time' in FT.PROFILE output. Changes: - Add coordQueueTime field to ConcurrentSearchHandlerCtx struct - Add coordQueueTime field to searchRequestCtx struct - Calculate queue time in DistSearchCommandHandler and DEBUG_DistSearchCommandHandler - Copy queue time to searchRequestCtx in FlatSearchCommandHandler - Print 'Coordinator queue time' in profileSearchReplyCoordinator * Add test for coordinator queue time in FT.PROFILE Add testCoordinatorQueueTimeInProfile to verify that coordinator queue time is correctly captured in cluster mode when the coordinator thread pool is paused. * Remove design document (intermediate artifact) * Fix tests for new Workers queue time and Coordinator queue time fields * Address Cursor Bugbot review: remove obsolete test and unused env parameters * Add AGENTS.local.md to .gitignore * Fix test expectations for new Workers queue time field in FT.PROFILE output * Remove redundant comments from queue time tracking code * Fix test_RED_86036 index after adding Workers queue time to FT.PROFILE * Fix dead code issue * Revert unrelated changes to AGENTS.md and .gitignore * CR- larger debug pauses, clock only on profile and different output order * CR- dont init clock (cherry picked from commit 7622a9e)
* Add validation tests for FT.PROFILE queue time bug Add design document and validation tests that confirm the bug exists: - testParsingTimeIncludesWorkersQueueTime_BUG: Confirms workers queue wait time is incorrectly included in 'Parsing time' (bug) - testParsingTimeDoesNotIncludeCoordQueueTime: Confirms coordinator queue time is correctly separate from shard's Parsing time Both tests pass, confirming the bug exists as described in the design doc. * Implement Part 1: Workers queue time in FT.PROFILE - Add profileQueueTime field to AREQ struct in aggregate.h - Capture queue time at start of AREQ_Execute_Callback() in aggregate_exec.c - Queue time = elapsed time since initClock was set before enqueueing - Reset initClock after capturing queue time for accurate parsing time - Print 'Workers queue time' in profile output in profile.c - Add testWorkersQueueTimeInProfile test to verify the fix - Mark testParsingTimeIncludesWorkersQueueTime_BUG as skipped (bug is fixed) This fixes the bug where FT.PROFILE's 'Parsing time' incorrectly included time spent waiting in the workers thread pool queue. * Add coordinator queue time tracking to FT.PROFILE Track time spent waiting in the coordinator thread pool queue and report it as 'Coordinator queue time' in FT.PROFILE output. Changes: - Add coordQueueTime field to ConcurrentSearchHandlerCtx struct - Add coordQueueTime field to searchRequestCtx struct - Calculate queue time in DistSearchCommandHandler and DEBUG_DistSearchCommandHandler - Copy queue time to searchRequestCtx in FlatSearchCommandHandler - Print 'Coordinator queue time' in profileSearchReplyCoordinator * Add test for coordinator queue time in FT.PROFILE Add testCoordinatorQueueTimeInProfile to verify that coordinator queue time is correctly captured in cluster mode when the coordinator thread pool is paused. * Remove design document (intermediate artifact) * Fix tests for new Workers queue time and Coordinator queue time fields * Address Cursor Bugbot review: remove obsolete test and unused env parameters * Add AGENTS.local.md to .gitignore * Fix test expectations for new Workers queue time field in FT.PROFILE output * Remove redundant comments from queue time tracking code * Fix test_RED_86036 index after adding Workers queue time to FT.PROFILE * Fix dead code issue * Revert unrelated changes to AGENTS.md and .gitignore * CR- larger debug pauses, clock only on profile and different output order * CR- dont init clock (cherry picked from commit 7622a9e) (cherry picked from commit 335414c)
* Add validation tests for FT.PROFILE queue time bug Add design document and validation tests that confirm the bug exists: - testParsingTimeIncludesWorkersQueueTime_BUG: Confirms workers queue wait time is incorrectly included in 'Parsing time' (bug) - testParsingTimeDoesNotIncludeCoordQueueTime: Confirms coordinator queue time is correctly separate from shard's Parsing time Both tests pass, confirming the bug exists as described in the design doc. * Implement Part 1: Workers queue time in FT.PROFILE - Add profileQueueTime field to AREQ struct in aggregate.h - Capture queue time at start of AREQ_Execute_Callback() in aggregate_exec.c - Queue time = elapsed time since initClock was set before enqueueing - Reset initClock after capturing queue time for accurate parsing time - Print 'Workers queue time' in profile output in profile.c - Add testWorkersQueueTimeInProfile test to verify the fix - Mark testParsingTimeIncludesWorkersQueueTime_BUG as skipped (bug is fixed) This fixes the bug where FT.PROFILE's 'Parsing time' incorrectly included time spent waiting in the workers thread pool queue. * Add coordinator queue time tracking to FT.PROFILE Track time spent waiting in the coordinator thread pool queue and report it as 'Coordinator queue time' in FT.PROFILE output. Changes: - Add coordQueueTime field to ConcurrentSearchHandlerCtx struct - Add coordQueueTime field to searchRequestCtx struct - Calculate queue time in DistSearchCommandHandler and DEBUG_DistSearchCommandHandler - Copy queue time to searchRequestCtx in FlatSearchCommandHandler - Print 'Coordinator queue time' in profileSearchReplyCoordinator * Add test for coordinator queue time in FT.PROFILE Add testCoordinatorQueueTimeInProfile to verify that coordinator queue time is correctly captured in cluster mode when the coordinator thread pool is paused. * Remove design document (intermediate artifact) * Fix tests for new Workers queue time and Coordinator queue time fields * Address Cursor Bugbot review: remove obsolete test and unused env parameters * Add AGENTS.local.md to .gitignore * Fix test expectations for new Workers queue time field in FT.PROFILE output * Remove redundant comments from queue time tracking code * Fix test_RED_86036 index after adding Workers queue time to FT.PROFILE * Fix dead code issue * Revert unrelated changes to AGENTS.md and .gitignore * CR- larger debug pauses, clock only on profile and different output order * CR- dont init clock (cherry picked from commit 7622a9e) (cherry picked from commit 335414c)
* MOD-13602 Add queue time tracking to FT.PROFILE (#8210) * Add validation tests for FT.PROFILE queue time bug Add design document and validation tests that confirm the bug exists: - testParsingTimeIncludesWorkersQueueTime_BUG: Confirms workers queue wait time is incorrectly included in 'Parsing time' (bug) - testParsingTimeDoesNotIncludeCoordQueueTime: Confirms coordinator queue time is correctly separate from shard's Parsing time Both tests pass, confirming the bug exists as described in the design doc. * Implement Part 1: Workers queue time in FT.PROFILE - Add profileQueueTime field to AREQ struct in aggregate.h - Capture queue time at start of AREQ_Execute_Callback() in aggregate_exec.c - Queue time = elapsed time since initClock was set before enqueueing - Reset initClock after capturing queue time for accurate parsing time - Print 'Workers queue time' in profile output in profile.c - Add testWorkersQueueTimeInProfile test to verify the fix - Mark testParsingTimeIncludesWorkersQueueTime_BUG as skipped (bug is fixed) This fixes the bug where FT.PROFILE's 'Parsing time' incorrectly included time spent waiting in the workers thread pool queue. * Add coordinator queue time tracking to FT.PROFILE Track time spent waiting in the coordinator thread pool queue and report it as 'Coordinator queue time' in FT.PROFILE output. Changes: - Add coordQueueTime field to ConcurrentSearchHandlerCtx struct - Add coordQueueTime field to searchRequestCtx struct - Calculate queue time in DistSearchCommandHandler and DEBUG_DistSearchCommandHandler - Copy queue time to searchRequestCtx in FlatSearchCommandHandler - Print 'Coordinator queue time' in profileSearchReplyCoordinator * Add test for coordinator queue time in FT.PROFILE Add testCoordinatorQueueTimeInProfile to verify that coordinator queue time is correctly captured in cluster mode when the coordinator thread pool is paused. * Remove design document (intermediate artifact) * Fix tests for new Workers queue time and Coordinator queue time fields * Address Cursor Bugbot review: remove obsolete test and unused env parameters * Add AGENTS.local.md to .gitignore * Fix test expectations for new Workers queue time field in FT.PROFILE output * Remove redundant comments from queue time tracking code * Fix test_RED_86036 index after adding Workers queue time to FT.PROFILE * Fix dead code issue * Revert unrelated changes to AGENTS.md and .gitignore * CR- larger debug pauses, clock only on profile and different output order * CR- dont init clock (cherry picked from commit 7622a9e) (cherry picked from commit 335414c) * Fix test_RED_86036 to use to_dict for profile access The test was using hardcoded indices to access the profile output, which broke after adding 'Workers queue time' field. Now uses to_dict() to access 'Iterators profile' by key name, making the test more robust to profile structure changes. * Refactor to use ConcurrentSearchHandlerCtx struct Backport the ConcurrentSearchHandlerCtx approach from 8.6 to pass isProfile, coordStartTime, and coordQueueTime instead of adding individual parameters to SearchCmdCtx or dispatched method signatures.
* MOD-13602 Add queue time tracking to FT.PROFILE (#8210) * Add validation tests for FT.PROFILE queue time bug Add design document and validation tests that confirm the bug exists: - testParsingTimeIncludesWorkersQueueTime_BUG: Confirms workers queue wait time is incorrectly included in 'Parsing time' (bug) - testParsingTimeDoesNotIncludeCoordQueueTime: Confirms coordinator queue time is correctly separate from shard's Parsing time Both tests pass, confirming the bug exists as described in the design doc. * Implement Part 1: Workers queue time in FT.PROFILE - Add profileQueueTime field to AREQ struct in aggregate.h - Capture queue time at start of AREQ_Execute_Callback() in aggregate_exec.c - Queue time = elapsed time since initClock was set before enqueueing - Reset initClock after capturing queue time for accurate parsing time - Print 'Workers queue time' in profile output in profile.c - Add testWorkersQueueTimeInProfile test to verify the fix - Mark testParsingTimeIncludesWorkersQueueTime_BUG as skipped (bug is fixed) This fixes the bug where FT.PROFILE's 'Parsing time' incorrectly included time spent waiting in the workers thread pool queue. * Add coordinator queue time tracking to FT.PROFILE Track time spent waiting in the coordinator thread pool queue and report it as 'Coordinator queue time' in FT.PROFILE output. Changes: - Add coordQueueTime field to ConcurrentSearchHandlerCtx struct - Add coordQueueTime field to searchRequestCtx struct - Calculate queue time in DistSearchCommandHandler and DEBUG_DistSearchCommandHandler - Copy queue time to searchRequestCtx in FlatSearchCommandHandler - Print 'Coordinator queue time' in profileSearchReplyCoordinator * Add test for coordinator queue time in FT.PROFILE Add testCoordinatorQueueTimeInProfile to verify that coordinator queue time is correctly captured in cluster mode when the coordinator thread pool is paused. * Remove design document (intermediate artifact) * Fix tests for new Workers queue time and Coordinator queue time fields * Address Cursor Bugbot review: remove obsolete test and unused env parameters * Add AGENTS.local.md to .gitignore * Fix test expectations for new Workers queue time field in FT.PROFILE output * Remove redundant comments from queue time tracking code * Fix test_RED_86036 index after adding Workers queue time to FT.PROFILE * Fix dead code issue * Revert unrelated changes to AGENTS.md and .gitignore * CR- larger debug pauses, clock only on profile and different output order * CR- dont init clock (cherry picked from commit 7622a9e) * Fix test_RED_86036 to use to_dict for profile access The test was using hardcoded indices to access the profile output, which broke after adding 'Workers queue time' field. Now uses to_dict() to access 'Iterators profile' by key name, making the test more robust to profile structure changes. * Refactor to use ConcurrentSearchHandlerCtx struct Backport the ConcurrentSearchHandlerCtx approach from 8.6 to pass isProfile, coordStartTime, and coordQueueTime instead of adding individual parameters to SearchCmdCtx or dispatched method signatures.
* Add validation tests for FT.PROFILE queue time bug Add design document and validation tests that confirm the bug exists: - testParsingTimeIncludesWorkersQueueTime_BUG: Confirms workers queue wait time is incorrectly included in 'Parsing time' (bug) - testParsingTimeDoesNotIncludeCoordQueueTime: Confirms coordinator queue time is correctly separate from shard's Parsing time Both tests pass, confirming the bug exists as described in the design doc. * Implement Part 1: Workers queue time in FT.PROFILE - Add profileQueueTime field to AREQ struct in aggregate.h - Capture queue time at start of AREQ_Execute_Callback() in aggregate_exec.c - Queue time = elapsed time since initClock was set before enqueueing - Reset initClock after capturing queue time for accurate parsing time - Print 'Workers queue time' in profile output in profile.c - Add testWorkersQueueTimeInProfile test to verify the fix - Mark testParsingTimeIncludesWorkersQueueTime_BUG as skipped (bug is fixed) This fixes the bug where FT.PROFILE's 'Parsing time' incorrectly included time spent waiting in the workers thread pool queue. * Add coordinator queue time tracking to FT.PROFILE Track time spent waiting in the coordinator thread pool queue and report it as 'Coordinator queue time' in FT.PROFILE output. Changes: - Add coordQueueTime field to ConcurrentSearchHandlerCtx struct - Add coordQueueTime field to searchRequestCtx struct - Calculate queue time in DistSearchCommandHandler and DEBUG_DistSearchCommandHandler - Copy queue time to searchRequestCtx in FlatSearchCommandHandler - Print 'Coordinator queue time' in profileSearchReplyCoordinator * Add test for coordinator queue time in FT.PROFILE Add testCoordinatorQueueTimeInProfile to verify that coordinator queue time is correctly captured in cluster mode when the coordinator thread pool is paused. * Remove design document (intermediate artifact) * Fix tests for new Workers queue time and Coordinator queue time fields * Address Cursor Bugbot review: remove obsolete test and unused env parameters * Add AGENTS.local.md to .gitignore * Fix test expectations for new Workers queue time field in FT.PROFILE output * Remove redundant comments from queue time tracking code * Fix test_RED_86036 index after adding Workers queue time to FT.PROFILE * Fix dead code issue * Revert unrelated changes to AGENTS.md and .gitignore * CR- larger debug pauses, clock only on profile and different output order * CR- dont init clock
* initial commit (cherry picked from commit ab63a17) * fix api * some redesign of how search results are maintained * expose link_static_lib to allow disk to use it * add a way to control if async api will be used * fail debug command if async io is not supported * separate functions * update debug test and command * simplify some of the flow * put async after regular version * use double buffering * dynamically increase index result buffer * use double linked list to manage and track reads * code review fixes * change disk api to simplify passing and cleaning up dmd pointer * code review fixes * simplify error handling api * fix compilation * few fixes * fix cursor code review comments * minor fixes * code review fixes * remove check * pass right allocate callback * moved async state to its own file, added state machine like tests * fix cursor's code review comment * code review fix * address code review comments * fix code review comments * small fix * fix code review comments * minor refactoring to address code review comment * cide review fixes * code review comment * address code review comments * use case insensitive comparison * update header * [MOD-13616] Use new strict FAIL timeout mechanism in FT.SEARCH coordinator (RediSearch#8191) * draft * Use abort on error path * use free priv data * test * avoid leak * skip SA * Cursor comments * profile reply with unblock * remove assert * test profile * Cleanup for PR * move postProcess to before unblocking the client * test timeout before fanout * remove double postProcess * review Phase1 * Phase 2 * fast check resp3 * fix resp3 * move clear errror * Fix error pass * Move error handling to MRCTX * check cmd before free * fix * Better assert and comment * Change check * Assign Query error if not assigned * MRcommand free safe * MOD-13701: Update deepdiff dependency version in pyproject.toml to >=8.6.1 (RediSearch#8212) * Update deepdiff dependency version in pyproject.toml to >=8.6.1 * Update dependency versions for deepdiff and orderly-set in uv.lock and pyproject.toml * Update deepdiff and orderly-set versions in uv.lock and pyproject.toml to latest releases * Pin deepdiff version to 8.6.1 in uv.lock and pyproject.toml for consistency * ci: update redisbench-admin (RediSearch#8213) * update to make sure load is recycled * bump redisbench-admin version * benchmark reqs update * update ver redisbench-admin * bump ver * update redisbench-admin * remove dataset name from load benchmark * Update tests/benchmarks/search-msmarco-6M-documents-load.yml * fix: Don't check license headers in the target directory (RediSearch#8226) * MOD-13602 Add queue time tracking to FT.PROFILE (RediSearch#8210) * Add validation tests for FT.PROFILE queue time bug Add design document and validation tests that confirm the bug exists: - testParsingTimeIncludesWorkersQueueTime_BUG: Confirms workers queue wait time is incorrectly included in 'Parsing time' (bug) - testParsingTimeDoesNotIncludeCoordQueueTime: Confirms coordinator queue time is correctly separate from shard's Parsing time Both tests pass, confirming the bug exists as described in the design doc. * Implement Part 1: Workers queue time in FT.PROFILE - Add profileQueueTime field to AREQ struct in aggregate.h - Capture queue time at start of AREQ_Execute_Callback() in aggregate_exec.c - Queue time = elapsed time since initClock was set before enqueueing - Reset initClock after capturing queue time for accurate parsing time - Print 'Workers queue time' in profile output in profile.c - Add testWorkersQueueTimeInProfile test to verify the fix - Mark testParsingTimeIncludesWorkersQueueTime_BUG as skipped (bug is fixed) This fixes the bug where FT.PROFILE's 'Parsing time' incorrectly included time spent waiting in the workers thread pool queue. * Add coordinator queue time tracking to FT.PROFILE Track time spent waiting in the coordinator thread pool queue and report it as 'Coordinator queue time' in FT.PROFILE output. Changes: - Add coordQueueTime field to ConcurrentSearchHandlerCtx struct - Add coordQueueTime field to searchRequestCtx struct - Calculate queue time in DistSearchCommandHandler and DEBUG_DistSearchCommandHandler - Copy queue time to searchRequestCtx in FlatSearchCommandHandler - Print 'Coordinator queue time' in profileSearchReplyCoordinator * Add test for coordinator queue time in FT.PROFILE Add testCoordinatorQueueTimeInProfile to verify that coordinator queue time is correctly captured in cluster mode when the coordinator thread pool is paused. * Remove design document (intermediate artifact) * Fix tests for new Workers queue time and Coordinator queue time fields * Address Cursor Bugbot review: remove obsolete test and unused env parameters * Add AGENTS.local.md to .gitignore * Fix test expectations for new Workers queue time field in FT.PROFILE output * Remove redundant comments from queue time tracking code * Fix test_RED_86036 index after adding Workers queue time to FT.PROFILE * Fix dead code issue * Revert unrelated changes to AGENTS.md and .gitignore * CR- larger debug pauses, clock only on profile and different output order * CR- dont init clock * MOD-13357: Add disk expiration support in OSS side (RediSearch#8218) Add disk expiration support in OSS side * try and align with master * add assert --------- Co-authored-by: lerman25 <[email protected]> Co-authored-by: Itzikvaknin <[email protected]> Co-authored-by: Joan Fontanals <[email protected]> Co-authored-by: Luca Palmieri <[email protected]> Co-authored-by: ofiryanai <[email protected]>
Current: FT.PROFILE's "Parsing time" incorrectly includes time spent waiting in thread pool queues, making it difficult to diagnose performance issues.
Change: Add separate "Workers queue time" and "Coordinator queue time" fields to FT.PROFILE output, and fix "Parsing time" to exclude queue wait time.
Outcome: Users can now accurately see how long queries wait in thread pool queues vs actual parsing/execution time.
Main objects modified
src/aggregate/aggregate.h/aggregate_exec.c- Workers queue time trackingsrc/concurrent_ctx.h/module.c- Coordinator queue time trackingsrc/profile.c- Profile output formattingMark if applicable
Release Notes
Note
Medium Risk
Changes the
FT.PROFILEoutput schema by adding new timing fields and adjusting existing parsing-time semantics, which may break clients/tests that rely on field ordering or exact values. Timing is computed across threaded execution paths (workers/coordinator), so regressions would primarily be incorrect metrics rather than functional query results.Overview
FT.PROFILEnow reports queue wait time separately from execution parsing time. Shard-side profiling adds "Workers queue time" (captured when a background worker starts) and updates "Parsing time" to exclude that queue delay.In cluster mode, coordinator profiling adds "Coordinator queue time" and threads this value through the distributed search handlers so it appears in the coordinator profile section. Tests are updated (including new pause/resume-based validations) to account for the new fields and shifted RESP2 positional indexes.
Written by Cursor Bugbot for commit baee726. This will update automatically on new commits. Configure here.