Skip to content

MOD-13602 Add queue time tracking to FT.PROFILE #8210

Merged
ofiryanai merged 15 commits intomasterfrom
add-ft-profile-queue-time
Jan 31, 2026
Merged

MOD-13602 Add queue time tracking to FT.PROFILE #8210
ofiryanai merged 15 commits intomasterfrom
add-ft-profile-queue-time

Conversation

@ofiryanai
Copy link
Copy Markdown
Collaborator

@ofiryanai ofiryanai commented Jan 28, 2026

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 tracking
  • src/concurrent_ctx.h / module.c - Coordinator queue time tracking
  • src/profile.c - Profile output formatting

Mark if applicable

  • This PR introduces API changes
  • This PR introduces serialization changes

Release Notes

  • This PR requires release notes
  • This PR does not require release notes

Note

Medium Risk
Changes the FT.PROFILE output 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.PROFILE now 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.

Comment thread tests/pytests/test_profile.py
Comment thread tests/pytests/test_profile.py Outdated
Comment thread src/module.c Outdated
@codecov
Copy link
Copy Markdown

codecov Bot commented Jan 28, 2026

Codecov Report

✅ All modified and coverable lines are covered by tests.
✅ Project coverage is 83.00%. Comparing base (c7cf618) to head (baee726).
⚠️ Report is 3 commits behind head on master.

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              
Flag Coverage Δ
flow 84.34% <100.00%> (-0.07%) ⬇️
unit 50.48% <0.00%> (-0.02%) ⬇️

Flags with carried forward coverage won't be shown. Click here to find out more.

☔ View full report in Codecov by Sentry.
📢 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.

Comment thread tests/pytests/test_profile.py
Comment thread tests/pytests/test_profile.py
Comment thread tests/pytests/test_aggregate_count.py Outdated
Comment thread src/module.c
Comment thread tests/pytests/test_profile.py Outdated
Comment thread src/profile.c
if (profile_verbose) {
RedisModule_ReplyKV_Double(reply, "Workers queue time",
rs_wall_clock_convert_ns_to_ms_d(req->profileQueueTime));
}
Copy link
Copy Markdown

Choose a reason for hiding this comment

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

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.

Fix in Cursor Fix in Web

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

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

@ofiryanai If you want

Copy link
Copy Markdown
Collaborator

@lerman25 lerman25 left a comment

Choose a reason for hiding this comment

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

Great job
some comments

Comment thread src/profile.c
if (profile_verbose) {
RedisModule_ReplyKV_Double(reply, "Workers queue time",
rs_wall_clock_convert_ns_to_ms_d(req->profileQueueTime));
}
Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

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

@ofiryanai If you want

Comment thread src/aggregate/aggregate_exec.c Outdated

if (IsProfile(req)) {
req->profileQueueTime = rs_wall_clock_elapsed_ns(&req->initClock);
rs_wall_clock_init(&req->initClock);
Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

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

Why re-initialize the clock?

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

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

The clock is reused: first to measure queue time, then re-initialized to measure parsing time. This avoids needing two separate clock fields

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

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

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

Comment thread src/module.c Outdated
Comment thread src/module.c
Comment thread tests/pytests/test_profile.py
Comment thread tests/pytests/test_profile.py
Copy link
Copy Markdown

@cursor cursor Bot left a comment

Choose a reason for hiding this comment

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

Cursor Bugbot has reviewed your changes and found 1 potential issue.

Comment thread src/module.c
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.
@ofiryanai ofiryanai force-pushed the add-ft-profile-queue-time branch from 3a5c085 to baee726 Compare January 29, 2026 16:48
@ofiryanai ofiryanai added this pull request to the merge queue Jan 31, 2026
Merged via the queue into master with commit 7622a9e Jan 31, 2026
60 checks passed
@ofiryanai ofiryanai deleted the add-ft-profile-queue-time branch January 31, 2026 17:39
@redisearch-backport-pull-request
Copy link
Copy Markdown
Contributor

Backport failed for 8.2, because it was unable to cherry-pick the commit(s).

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

@redisearch-backport-pull-request
Copy link
Copy Markdown
Contributor

Backport failed for 8.4, because it was unable to cherry-pick the commit(s).

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

@redisearch-backport-pull-request
Copy link
Copy Markdown
Contributor

Backport failed for 8.6, because it was unable to cherry-pick the commit(s).

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

ofiryanai added a commit that referenced this pull request Feb 1, 2026
* 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)
ofiryanai added a commit that referenced this pull request Feb 1, 2026
* 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)
ofiryanai added a commit that referenced this pull request Feb 1, 2026
* 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)
ofiryanai added a commit that referenced this pull request Feb 2, 2026
* 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)
github-merge-queue Bot pushed a commit that referenced this pull request Feb 2, 2026
* 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.
github-merge-queue Bot pushed a commit that referenced this pull request Feb 2, 2026
* 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.
kei-nan pushed a commit that referenced this pull request Feb 3, 2026
* 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
pull Bot pushed a commit to Mu-L/RediSearch that referenced this pull request Feb 3, 2026
* 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]>
This was referenced May 5, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants