orchagent: add per-Executor task timing instrumentation by venkit-nexthop · Pull Request #4563 · sonic-net/sonic-swss

venkit-nexthop · 2026-05-11T17:17:16Z

What I did

Add per-Executor wall-clock and scheduling-latency stats to
orchagent, surfaced via a notification channel for a future
show orchagent tasks CLI.

ExecutorStat: count/total/max + P^2 quantile estimators
(Q1/median/Q3) for run time, with a Tukey 1.5*IQR outlier
classifier (30-sample warmup gate).
TaskTimer (RAII): wraps Executor::execute() and the inline
flush() / logRotate() call sites in OrchDaemon::start().
Also records scheduling latency = gap between consecutive runs.
Two APPL_DB notification channels (ORCH_TASK_STATS_QUERY /
ORCH_TASK_STATS_REPLY) handle show/clear on the main thread,
no atomics needed.
8 new mock unit tests for ExecutorStat, P2Quantile,
TaskTimer.

No functional change to the existing select-loop or Orch logic;
the RAII timers add a small (sub-microsecond) overhead per
Executor dispatch.

Why I did it

Incremental step to satisfy the tasks listed in the HLD - sonic-net/SONiC#2328
This improves debug ability when doing interactive debugging. It give improved visibility into the various Executors inside Orchagent.

How I verified it

Unit tests:

cd tests/mock_tests && make check

New tests:

ExecutorStatTest.RecordAndReset / ResetClearsP2
ExecutorStatTest.FieldValueTupleRoundTrip
ExecutorStatTest.OutlierClassification
P2QuantileTest.MedianConvergesOnUniform
P2QuantileTest.MedianRobustToOutliers
TaskTimerTest.RecordsOnDestruction
TaskTimerTest.RecordsSchedLatencyAfterFirstRun

Details if related

linux-foundation-easycla · 2026-05-11T17:17:26Z

The committers listed above are authorized under a signed CLA.

✅ login: venkit-nexthop / name: Venkit Kasiviswanathan (304a67d)

venkit-nexthop · 2026-05-29T22:25:26Z

@prsunny @prabhataravind @vivekrnv @deepak-singhal0408
Could you take a look and approve this PR if you think it is good.
This PR implements the backend required for the show orchagent tasks and sonic-clear orchagent tasks
(described in HLD sonic-net/SONiC#2328)

deepak-singhal0408 · 2026-07-10T21:43:53Z

@venkit-nexthop could you resolve the merge conflicts? thanks,

deepak-singhal0408 · 2026-07-10T22:32:00Z

Question: what's the vision for how show/clear orchagent tasks gets used?

Really like this — cheap, well-scoped latency visibility into the orchagent loop, and the P² estimators keep it near-free.

Before diving into specifics, I'm curious about the intended usage, since it drives the design:

Purely an interactive, on-box debug aid a developer runs by hand during an incident?
Or something scriptable / monitor-driven (possibly concurrent), and maybe streamed off-box down the line?

I ask because the data-sourcing choice ties to that. Across sonic-utilities/show/, ~21 commands read a DB table directly and 2 shell to vtysh; none do a NotificationProducer request/reply to a live daemon. This PR introduces that pattern — perfectly fine for a one-shot interactive command, with one edge if it's ever concurrent/scripted:

⚠️ the reply on ORCH_TASK_STATS_REPLY carries no id linking it to a request, so two invocations at once (a show + a clear), or a reply that lands after the 10 s timeout, can be popped by the wrong caller → silently wrong/stale output. The len(parts) != 14 guard catches schema drift but not a well-formed reply from the wrong request.

So it really comes down to the vision:

Interactive debug only → the current channel is the right scope (maybe just note the single-instance assumption).
Scriptable / telemetry → having orchagent publish into a STATE_DB table with the CLI doing a direct read would match the usual show pattern, remove the race, and make it streamable off-box for free. Or keep the channel and add an opaque request id echoed back in the reply.

mssonicbld · 2026-07-11T17:44:45Z

/azp run

azure-pipelines · 2026-07-11T17:44:56Z

Azure Pipelines successfully started running 1 pipeline(s).

venkit-nexthop · 2026-07-11T17:45:12Z

@venkit-nexthop could you resolve the merge conflicts? thanks,

Just resolved the conflicts.

venkit-nexthop · 2026-07-11T18:11:20Z

Question: what's the vision for how show/clear orchagent tasks gets used?

Really like this — cheap, well-scoped latency visibility into the orchagent loop, and the P² estimators keep it near-free.

Before diving into specifics, I'm curious about the intended usage, since it drives the design:

Purely an interactive, on-box debug aid a developer runs by hand during an incident?

This is the current intended usage. i.e an on-box debug aid that a developer or operator runs by hand.

Or something scriptable / monitor-driven (possibly concurrent), and maybe streamed off-box down the line?

This is not designed for this use-case currently. But it could be extended for that in the future.

I ask because the data-sourcing choice ties to that. Across sonic-utilities/show/, ~21 commands read a DB table directly and 2 shell to vtysh; none do a NotificationProducer request/reply to a live daemon. This PR introduces that pattern — perfectly fine for a one-shot interactive command, with one edge if it's ever concurrent/scripted:

Yes, the challenge with logging stats into redis is that it will become another periodic write into the redis DB. I wanted to avoid this. This only needs to be fetched on-demand (one-shot and interactive).

⚠️ the reply on ORCH_TASK_STATS_REPLY carries no id linking it to a request, so two invocations at once (a show + a clear), or a reply that lands after the 10 s timeout, can be popped by the wrong caller → silently wrong/stale output. The len(parts) != 14 guard catches schema drift but not a well-formed reply from the wrong request.

Assume both sessions A and B are subscribed before either reply is published (the case where "the 2nd reads the 1st's reply"). Orchagent is single-threaded, so it publishes in order: reply-A, then reply-B. Each is broadcast to
both connections. So both A's and B's buffers end up holding [reply-A, reply-B] in that order.

But each CLI does select() + pop() exactly once:

A wakes on reply-A, pops it, prints it, exits.
B also wakes on reply-A (first in its buffer), pops it, prints A's data, exits.

So in the fully-concurrent case, both sessions render session-A's snapshot, and reply-B is consumed by nobody. reply-B was generated by orchagent and delivered into both connections' buffers, but neither process ever pops a
second time. The reply-B sits unread in the per-connection buffers/m_queue of both CLI processes. The moment each sonic-cli process exits (right after its single pop()), it closes its redis connection. Redis drops that connection's subscription and its associated output buffer, and the client-side m_queue is freed with the process. reply-B is simply garbage-collected along with the connections — it never touches persistent storage and doesn't leak or grow memory on the redis server.

There is not memory leak in any or this. There is a possibility that with some timing case, one of the sessions may read garbled data. If the one sessions does a clear, it is possible that is handled first and the other session gets all 0 data as well (This is common for any regular feature with competing sessions as well).

So it really comes down to the vision:

Interactive debug only → the current channel is the right scope (maybe just note the single-instance assumption).

YES, this one.

Scriptable / telemetry → having orchagent publish into a STATE_DB table with the CLI doing a direct read would match the usual show pattern, remove the race, and make it streamable off-box for free. Or keep the channel and add an opaque request id echoed back in the reply.

NO, not designed for this yet.

venkit-nexthop · 2026-07-11T20:33:53Z

Question: what's the vision for how show/clear orchagent tasks gets used?

Really like this — cheap, well-scoped latency visibility into the orchagent loop, and the P² estimators keep it near-free.

Before diving into specifics, I'm curious about the intended usage, since it drives the design:

Purely an interactive, on-box debug aid a developer runs by hand during an incident?

Or something scriptable / monitor-driven (possibly concurrent), and maybe streamed off-box down the line?

I ask because the data-sourcing choice ties to that. Across sonic-utilities/show/, ~21 commands read a DB table directly and 2 shell to vtysh; none do a NotificationProducer request/reply to a live daemon. This PR introduces that pattern — perfectly fine for a one-shot interactive command, with one edge if it's ever concurrent/scripted:

⚠️ the reply on ORCH_TASK_STATS_REPLY carries no id linking it to a request, so two invocations at once (a show + a clear), or a reply that lands after the 10 s timeout, can be popped by the wrong caller → silently wrong/stale output. The len(parts) != 14 guard catches schema drift but not a well-formed reply from the wrong request.

So it really comes down to the vision:

Interactive debug only → the current channel is the right scope (maybe just note the single-instance assumption).

Scriptable / telemetry → having orchagent publish into a STATE_DB table with the CLI doing a direct read would match the usual show pattern, remove the race, and make it streamable off-box for free. Or keep the channel and add an opaque request id echoed back in the reply.

Also the show/clear commands are implemented in this PR => sonic-net/sonic-utilities#4536

The coverage.Azure.sonic-swss.vstest check on PR sonic-net#4563 failed because the two OrchDaemon methods added for the task-stats notification transport had no unit-test coverage: initTaskStatsChannel() and the whole show/clear/unknown-op body of handleTaskStatsQuery(). Add four tests to orchdaemon_ut.cpp: - TaskStatsChannelInit: initTaskStatsChannel() wires up the APPL_DB handle and both notification channels and registers the query consumer with the daemon's Select. - TaskStatsQueryShow: a "show" request serializes every m_taskStats slot (a populated slot with bootstrapped P^2 estimators plus an empty count==0 slot) without mutating the stats. - TaskStatsQueryClear: a "clear" request resets every slot in place. - TaskStatsQueryUnknownOp: an unrecognized op hits the error branch and leaves the stats untouched. Notification messages are injected via the mock-hiredis global reply and NotificationConsumer::readData(), the same pattern the fdborch flush tests use, so handleTaskStatsQuery() pop()s a real request off its queue. Signed-off-by: Venkit Kasiviswanathan <venkit@nexthop.ai> Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>

mssonicbld · 2026-07-11T23:28:09Z

/azp run

azure-pipelines · 2026-07-11T23:28:28Z

Azure Pipelines successfully started running 1 pipeline(s).

The coverage.Azure.sonic-swss.vstest check on PR sonic-net#4563 failed because the two OrchDaemon methods added for the task-stats notification transport had no unit-test coverage: initTaskStatsChannel() and the whole show/clear/unknown-op body of handleTaskStatsQuery(). Add four tests to orchdaemon_ut.cpp: - TaskStatsChannelInit: initTaskStatsChannel() wires up the APPL_DB handle and both notification channels and registers the query consumer with the daemon's Select. - TaskStatsQueryShow: a "show" request serializes every m_taskStats slot (a populated slot with bootstrapped P^2 estimators plus an empty count==0 slot) without mutating the stats. - TaskStatsQueryClear: a "clear" request resets every slot in place. - TaskStatsQueryUnknownOp: an unrecognized op hits the error branch and leaves the stats untouched. Notification messages are injected via the mock-hiredis global reply and NotificationConsumer::readData(), the same pattern the fdborch flush tests use, so handleTaskStatsQuery() pop()s a real request off its queue. Signed-off-by: Venkit Kasiviswanathan <venkit@nexthop.ai>

mssonicbld · 2026-07-11T23:30:52Z

/azp run

azure-pipelines · 2026-07-11T23:31:03Z

Azure Pipelines successfully started running 1 pipeline(s).

venkit-nexthop · 2026-07-12T15:53:55Z

@deepak-singhal0408 @prsunny
CI has passed. Can you take a look and approve the PR?

deepak-singhal0408

LGTM. The instumentation is lightweight. The TaskTimer cost is per batch, the P2 estimator is bounded, near-free overhead, O(1).
Agree on keeping it as on-demand for now. Multiple CLI session reading data parallely and getting occasional garbled data might be acceptable in my mind since it will mainly be used for debugging purposes.

Copilot

Pull request overview

This PR adds per-Executor timing instrumentation to orchagent (run-time wall clock + scheduling-latency) and exposes it via APPL_DB notification channels intended to back a future show orchagent tasks CLI.

Changes:

Introduce P2Quantile, ExecutorStat, and RAII TaskTimer to track counts/totals/min/max, quartiles, and Tukey-rule outliers.
Add APPL_DB notification query/reply channels (ORCH_TASK_STATS_QUERY / ORCH_TASK_STATS_REPLY) with show/clear handling on the main thread.
Add mock unit tests covering quantile convergence, stat reset/serialization, outlier classification, and TaskTimer behavior.

Reviewed changes

Copilot reviewed 3 out of 3 changed files in this pull request and generated 2 comments.

File	Description
tests/mock_tests/orchdaemon_ut.cpp	Adds unit tests for quantile/stat/timer logic and task-stats query handling.
orchagent/orchdaemon.h	Defines the quantile estimator, stats container, and RAII timer; adds task-stats channel members.
orchagent/orchdaemon.cpp	Wires up task-stats notification channels and wraps executor/inline ops with `TaskTimer`.

Comments suppressed due to low confidence (1)

orchagent/orchdaemon.cpp:1113

There is still an uninstrumented flush(); call in the diff.count() >= SELECT_TIMEOUT path, so the flush slot under-reports and the implementation no longer matches the stated goal of wrapping all flush() call sites with TaskTimer.

            { TaskTimer t(m_taskStats["flush"]); flush(); }
            /*
             * Log an error message periodically if a previous SAI API call failed with
             * an unrecoverable error.
             */
            string orchHealthError;
            if (getSaiFailureStatus(orchHealthError))
            {
                SWSS_LOG_ERROR("%s", orchHealthError.c_str());
            }

            flush();

venkit-nexthop · 2026-07-15T07:09:52Z

@prsunny can you approve this?

mssonicbld · 2026-07-17T20:46:48Z

/azp run

azure-pipelines · 2026-07-17T20:46:59Z

Azure Pipelines: Successfully started running 1 pipeline(s).

venkit-nexthop · 2026-07-17T23:51:23Z

/azp run Azure.sonic-swss

azure-pipelines · 2026-07-17T23:51:30Z

Commenter does not have sufficient privileges for PR 4563 in repo sonic-net/sonic-swss

mssonicbld · 2026-07-18T03:46:55Z

/azp run

azure-pipelines · 2026-07-18T03:47:05Z

Azure Pipelines: Successfully started running 1 pipeline(s).

mssonicbld · 2026-07-18T07:42:17Z

/azp run

azure-pipelines · 2026-07-18T07:42:27Z

Azure Pipelines: Successfully started running 1 pipeline(s).

mssonicbld · 2026-07-18T14:25:45Z

/azp run

azure-pipelines · 2026-07-18T14:25:56Z

Azure Pipelines: Successfully started running 1 pipeline(s).

mssonicbld · 2026-07-20T18:38:49Z

/azp run

azure-pipelines · 2026-07-20T18:39:00Z

Azure Pipelines: Successfully started running 1 pipeline(s).

mssonicbld · 2026-07-21T17:32:09Z

/azp run

azure-pipelines · 2026-07-21T17:32:21Z

Azure Pipelines: Successfully started running 1 pipeline(s).

deepak-singhal0408

LGTM, thanks

mssonicbld · 2026-07-23T02:51:54Z

/azp run

azure-pipelines · 2026-07-23T02:52:05Z

Azure Pipelines: Successfully started running 1 pipeline(s).

Add a small, always-on instrumentation layer that records per-Executor wall-clock run time and scheduling latency from the orchagent main select loop, plus a notification-channel transport for a CLI to query and clear those stats. When orchagent's main select loop spends most of a second on one Executor (e.g. RouteOrch during a route burst), there is currently no way for an operator to see where orchagent is spending its time without instrumenting a build. This change adds: - ExecutorStat: per-Executor stats (count, total, max) plus three independent P^2 (Jain & Chlamtac, 1985) running quantile estimators for Q1, median, Q3 of run time. A Tukey 1.5*IQR rule classifies each new sample as a high or low outlier before it is folded into the estimators; a 30-sample warmup gate avoids spurious flags during P^2 bootstrap. - Scheduling latency: the same RAII timer records the gap between consecutive runs of an Executor into a parallel set of P^2 estimators. - TaskTimer: a small RAII wrap placed around every Executor::execute() call site in OrchDaemon::start(), plus the inline flush() and logRotate() paths. - Two APPL_DB notification channels (ORCH_TASK_STATS_QUERY / ORCH_TASK_STATS_REPLY) handle show/clear requests on the main thread (no atomics needed since m_taskStats is single-thread). Unit tests cover ExecutorStat record/reset, FieldValueTuple round-trip serialization, outlier classification, P^2 convergence on a uniform stream, P^2 robustness to moderate outliers, and the TaskTimer RAII contract for both run and scheduling-latency paths. They also cover the notification transport end to end: initTaskStatsChannel() wiring, and the show / clear / unknown-op branches of handleTaskStatsQuery(), with requests injected via the mock-hiredis global reply and NotificationConsumer::readData() (the fdborch flush-test pattern). The UT-owned redisReply tree is freed after injection so the mock reply does not leak across the test binary. Signed-off-by: Venkit Kasiviswanathan <venkit@nexthop.ai>

mssonicbld · 2026-07-23T02:53:39Z

/azp run

azure-pipelines · 2026-07-23T02:53:50Z

Azure Pipelines: Successfully started running 1 pipeline(s).

venkit-nexthop requested a review from prsunny as a code owner May 11, 2026 17:17

venkit-nexthop force-pushed the orchagent-task-stats branch from afee480 to 61c930f Compare May 11, 2026 17:35

This was referenced May 12, 2026

[orchagent]: Add ZmqRouteServer for concurrent route updates #4564

Open

Performance Regression in Orchagent due to https://github.com/sonic-net/sonic-swss/pull/3910/changes sonic-net/sonic-buildimage#27098

Open

deepak-singhal0408 assigned venkit-nexthop May 14, 2026

deepak-singhal0408 added this to SONiC Routing Dashboard May 14, 2026

github-project-automation Bot moved this to Todo in SONiC Routing Dashboard May 14, 2026

deepak-singhal0408 mentioned this pull request Jul 10, 2026

[golden_config]: enable SWSS ZMQ on T2 and DRH topologies sonic-net/sonic-mgmt#26043

Open

12 tasks

venkit-nexthop force-pushed the orchagent-task-stats branch from 0e5dbe7 to 320e57c Compare July 11, 2026 23:30

deepak-singhal0408 previously approved these changes Jul 13, 2026

View reviewed changes

deepak-singhal0408 requested a review from Copilot July 13, 2026 06:28

Copilot started reviewing on behalf of deepak-singhal0408 July 13, 2026 06:29 View session

Copilot AI reviewed Jul 13, 2026

View reviewed changes

Comment thread tests/mock_tests/orchdaemon_ut.cpp

Comment thread tests/mock_tests/orchdaemon_ut.cpp

venkit-nexthop force-pushed the orchagent-task-stats branch from dde20c3 to 304a67d Compare July 17, 2026 20:46

venkit-nexthop force-pushed the orchagent-task-stats branch from 304a67d to e2772bf Compare July 18, 2026 03:46

venkit-nexthop force-pushed the orchagent-task-stats branch from 184a228 to 9cc1cdd Compare July 18, 2026 14:25

deepak-singhal0408 previously approved these changes Jul 21, 2026

View reviewed changes

prabhataravind reviewed Jul 22, 2026

View reviewed changes

Comment thread orchagent/orchdaemon.h Outdated

venkit-nexthop force-pushed the orchagent-task-stats branch from f197210 to 94665bd Compare July 23, 2026 02:51

venkit-nexthop dismissed deepak-singhal0408’s stale review via 5d614b6 July 23, 2026 02:53

venkit-nexthop force-pushed the orchagent-task-stats branch from 94665bd to 5d614b6 Compare July 23, 2026 02:53

deepak-singhal0408 approved these changes Jul 23, 2026

View reviewed changes

deepak-singhal0408 moved this from Todo to In Progress in SONiC Routing Dashboard Jul 23, 2026

prabhataravind approved these changes Jul 24, 2026

View reviewed changes

Uh oh!

Conversation

venkit-nexthop commented May 11, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

What I did

Why I did it

How I verified it

Details if related

Uh oh!

linux-foundation-easycla Bot commented May 11, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

venkit-nexthop commented May 29, 2026

Uh oh!

deepak-singhal0408 commented Jul 10, 2026

Uh oh!

deepak-singhal0408 commented Jul 10, 2026

Uh oh!

mssonicbld commented Jul 11, 2026

Uh oh!

azure-pipelines Bot commented Jul 11, 2026

Uh oh!

venkit-nexthop commented Jul 11, 2026

Uh oh!

venkit-nexthop commented Jul 11, 2026

Uh oh!

venkit-nexthop commented Jul 11, 2026

Uh oh!

mssonicbld commented Jul 11, 2026

Uh oh!

azure-pipelines Bot commented Jul 11, 2026

Uh oh!

mssonicbld commented Jul 11, 2026

Uh oh!

azure-pipelines Bot commented Jul 11, 2026

Uh oh!

venkit-nexthop commented Jul 12, 2026

Uh oh!

deepak-singhal0408 left a comment

Choose a reason for hiding this comment

Uh oh!

Copilot AI left a comment

Choose a reason for hiding this comment

Pull request overview

Reviewed changes

Uh oh!

Uh oh!

Uh oh!

venkit-nexthop commented Jul 15, 2026

Uh oh!

mssonicbld commented Jul 17, 2026

Uh oh!

azure-pipelines Bot commented Jul 17, 2026

Uh oh!

venkit-nexthop commented Jul 17, 2026

Uh oh!

azure-pipelines Bot commented Jul 17, 2026

Uh oh!

mssonicbld commented Jul 18, 2026

Uh oh!

azure-pipelines Bot commented Jul 18, 2026

Uh oh!

mssonicbld commented Jul 18, 2026

Uh oh!

azure-pipelines Bot commented Jul 18, 2026

Uh oh!

mssonicbld commented Jul 18, 2026

Uh oh!

azure-pipelines Bot commented Jul 18, 2026

Uh oh!

mssonicbld commented Jul 20, 2026

Uh oh!

azure-pipelines Bot commented Jul 20, 2026

Uh oh!

mssonicbld commented Jul 21, 2026

Uh oh!

azure-pipelines Bot commented Jul 21, 2026

Uh oh!

deepak-singhal0408 left a comment

Choose a reason for hiding this comment

venkit-nexthop commented May 11, 2026 •

edited

Loading

linux-foundation-easycla Bot commented May 11, 2026 •

edited

Loading