[show, clear]: add 'orchagent tasks' commands

venkit-nexthop · claude · venkit-nexthop · commit b0342e7bca06 · 2026-05-11T17:19:53.000Z
Surface per-Executor runtime and scheduling-latency statistics from
orchagent without rebuilding. Operators can now answer "where is
orchagent spending its time?" from the CLI.

New commands:
  - show orchagent tasks    -&gt; per-Executor run-time + sched-latency table
  - sonic-clear orchagent tasks -&gt; reset the counters in place

The CLI talks to orchagent over two APPL_DB notification channels
(ORCH_TASK_STATS_QUERY / ORCH_TASK_STATS_REPLY) and parses the
14-field pipe-separated reply. Rows are sorted by total run-time
descending; the RUN TIME and SCHED LATENCY columns render P^2
median/q1/q3/max quartets in milliseconds, the OUTLIERS column shows
Tukey 1.5x IQR sums, and the TOTAL column shows cumulative
run/sched wall-clock.

Tests mock swsscommon so the round-trip is exercised without Redis.
Coverage: header presence, sort order, quartet formatting, outlier
counts, empty/zero-slot rendering, timeout/error paths, and that the
correct op string is sent.

doc/Command-Reference.md is updated with the new Orchagent section.

This is the CLI half; the orchagent-side instrumentation that emits
the reply lives in a companion sonic-swss change.

Co-Authored-By: Claude Opus 4.7 (1M context) &lt;noreply@anthropic.com&gt;
Signed-off-by: Venkit Kasiviswanathan &lt;venkit@nexthop.ai&gt;
diff --git a/clear/main.py b/clear/main.py
@@ -11,6 +11,7 @@
 from utilities_common import util_base
 from show.plugins.pbh import read_pbh_counters
 from config.plugins.pbh import serialize_pbh_counters
+from . import orchagent as orchagent_clear
 from . import plugins
 from . import stp
 # This is from the aliases example:
@@ -149,6 +150,11 @@ def ipv6():
 #
 cli.add_command(stp.spanning_tree)
 
+#
+# 'orchagent'
+#
+cli.add_command(orchagent_clear.orchagent)
+
 #
 # Inserting BGP functionality into cli's clear parse-chain.
 # BGP commands are determined by the routing-stack being elected.
diff --git a/clear/orchagent.py b/clear/orchagent.py
@@ -0,0 +1,49 @@
+import click
+import sys
+
+from swsscommon import swsscommon
+
+
+TASK_STATS_QUERY_CHANNEL = "ORCH_TASK_STATS_QUERY"
+TASK_STATS_REPLY_CHANNEL = "ORCH_TASK_STATS_REPLY"
+REPLY_TIMEOUT_MS = 10000
+
+
+def _send_clear():
+    db = swsscommon.DBConnector("APPL_DB", 0)
+    producer = swsscommon.NotificationProducer(db, TASK_STATS_QUERY_CHANNEL)
+    consumer = swsscommon.NotificationConsumer(db, TASK_STATS_REPLY_CHANNEL)
+
+    sel = swsscommon.Select()
+    sel.addSelectable(consumer)
+
+    producer.send("clear", "", swsscommon.FieldValuePairs([]))
+
+    state, _ = sel.select(REPLY_TIMEOUT_MS)
+    if state == swsscommon.Select.TIMEOUT:
+        raise RuntimeError(
+            f"Timed out after {REPLY_TIMEOUT_MS} ms waiting for orchagent reply")
+    if state != swsscommon.Select.OBJECT:
+        raise RuntimeError(f"Select error waiting for orchagent reply: {state}")
+
+    op_ret, data_ret, _ = consumer.pop()
+    if op_ret != "ok":
+        raise RuntimeError(
+            f"orchagent returned error: op={op_ret} data={data_ret}")
+
+
+@click.group()
+def orchagent():
+    """Clear orchagent runtime stats"""
+    pass
+
+
+@orchagent.command("tasks")
+def tasks():
+    """Reset per-Executor execution timing counters in orchagent"""
+    try:
+        _send_clear()
+    except RuntimeError as e:
+        click.echo(f"Error: {e}", err=True)
+        sys.exit(1)
+    click.echo("OK")
diff --git a/doc/Command-Reference.md b/doc/Command-Reference.md
@@ -151,6 +151,9 @@
 * [NVGRE](#nvgre)
   * [NVGRE show commands](#nvgre-show-commands)
   * [NVGRE config commands](#nvgre-config-commands)
+* [Orchagent](#orchagent)
+  * [Orchagent show commands](#orchagent-show-commands)
+  * [Orchagent clear commands](#orchagent-clear-commands)
 * [PBH](#pbh)
   * [PBH show commands](#pbh-show-commands)
   * [PBH config commands](#pbh-config-commands)
@@ -9928,6 +9931,64 @@ This command is used to delete a configured NTP server IP address.
 
 Go Back To [Beginning of the document](#) or [Beginning of this section](#NTP)
 
+## Orchagent
+
+This section explains the orchagent runtime introspection commands.
+
+`orchagent` is the SONiC orchestration agent that processes APPL_DB updates and drives the hardware via SAI. Each Executor in orchagent represents a self-scheduled task (per-table consumers, periodic timers, etc.); the commands below surface how long each task is taking and how long it waits between invocations so operators can identify select-loop starvation without rebuilding orchagent.
+
+### Orchagent show commands
+
+**show orchagent tasks**
+
+This command displays the per-Executor execution-time statistics that orchagent maintains internally. Each row corresponds to one orchagent task (an `Orch` subclass or named periodic). Rows are sorted by total run time descending; ties break by task name.
+
+Columns:
+
+- `TASK` — Executor name.
+- `RUN TIME` — `median/q1/q3/max` of per-invocation wall-clock duration, in milliseconds. Median is the headline, Q1/Q3 give spread, max exposes the worst tail.
+- `RUNS` — total number of completed invocations.
+- `OUTLIERS` — Tukey 1.5×IQR sum (high + low) — invocations whose duration fell outside the bulk of the distribution.
+- `SCHED LATENCY` — `median/q1/q3/max` of the gap between when the task finished and when it was next scheduled, in milliseconds. Exposes select-loop starvation.
+- `TOTAL` — cumulative `<run>/<sched>` wall-clock spent inside the task vs waiting before it, in milliseconds.
+
+Slots that have never run print `-` in place of the quartet/total values; `RUNS` / `OUTLIERS` remain integers.
+
+The CLI talks to orchagent over two APPL_DB notification channels (`ORCH_TASK_STATS_QUERY` / `ORCH_TASK_STATS_REPLY`); the command exits non-zero with an error message if orchagent does not reply within 10 seconds.
+
+- Usage:
+  ```
+  show orchagent tasks
+  ```
+
+- Example:
+  ```
+  admin@sonic:~$ show orchagent tasks
+  TASK         RUN TIME                          RUNS  OUTLIERS  SCHED LATENCY                    TOTAL
+               median/q1/q3/max                                  median/q1/q3/max                 run/sched
+               (in msec)                                         (in msec)                        (in msec)
+  ROUTE_TABLE  1745.53/1391.34/2242.07/3913.36     43         5  1.06/0.41/48.40/1436.01          77619.63/5.04
+  ```
+
+### Orchagent clear commands
+
+**sonic-clear orchagent tasks**
+
+This command resets orchagent's per-Executor execution-time counters in place. Subsequent `show orchagent tasks` output starts accumulating from zero.
+
+- Usage:
+  ```
+  sonic-clear orchagent tasks
+  ```
+
+- Example:
+  ```
+  admin@sonic:~$ sonic-clear orchagent tasks
+  OK
+  ```
+
+Go Back To [Beginning of the document](#) or [Beginning of this section](#orchagent)
+
 # PFC Watchdog Commands
 Detailed description of the PFC Watchdog can be found on [this wiki page](https://github.com/sonic-net/SONiC/wiki/PFC-Watchdog)
 
diff --git a/show/main.py b/show/main.py
@@ -73,6 +73,7 @@
 from . import switch
 from . import icmp
 from . import copp
+from . import orchagent
 
 # Global Variables
 PLATFORM_JSON = 'platform.json'
@@ -334,6 +335,7 @@ def cli(ctx):
 cli.add_command(switch.switch)
 cli.add_command(icmp.icmp)
 cli.add_command(copp.copp)
+cli.add_command(orchagent.orchagent)
 
 # syslog module
 cli.add_command(syslog.syslog)
diff --git a/show/orchagent.py b/show/orchagent.py
@@ -0,0 +1,177 @@
+import click
+import sys
+
+from swsscommon import swsscommon
+from tabulate import tabulate
+
+
+TASK_STATS_QUERY_CHANNEL = "ORCH_TASK_STATS_QUERY"
+TASK_STATS_REPLY_CHANNEL = "ORCH_TASK_STATS_REPLY"
+REPLY_TIMEOUT_MS = 10000
+
+
+def _ms(ns):
+    """Convert ns -> ms as a float (no unit suffix)."""
+    return ns / 1_000_000.0
+
+
+def _fmt_quartet(median_ns, q1_ns, q3_ns, max_ns):
+    """Render a 'median/q1/q3/max' quartet in ms, two decimals each."""
+    return (f"{_ms(median_ns):.2f}/"
+            f"{_ms(q1_ns):.2f}/"
+            f"{_ms(q3_ns):.2f}/"
+            f"{_ms(max_ns):.2f}")
+
+
+def _query_orchagent(op):
+    """Send a query to orchagent over APPL_DB notification channels and
+    return (op_ret, data_ret, fvs) on success.
+
+    Raises RuntimeError on timeout or transport error.
+    """
+    db = swsscommon.DBConnector("APPL_DB", 0)
+    producer = swsscommon.NotificationProducer(db, TASK_STATS_QUERY_CHANNEL)
+    consumer = swsscommon.NotificationConsumer(db, TASK_STATS_REPLY_CHANNEL)
+
+    sel = swsscommon.Select()
+    sel.addSelectable(consumer)
+
+    producer.send(op, "", swsscommon.FieldValuePairs([]))
+
+    state, _ = sel.select(REPLY_TIMEOUT_MS)
+    if state == swsscommon.Select.TIMEOUT:
+        raise RuntimeError(
+            f"Timed out after {REPLY_TIMEOUT_MS} ms waiting for orchagent reply")
+    if state != swsscommon.Select.OBJECT:
+        raise RuntimeError(f"Select error waiting for orchagent reply: {state}")
+
+    op_ret, data_ret, fvs = consumer.pop()
+    if op_ret != "ok":
+        raise RuntimeError(
+            f"orchagent returned error: op={op_ret} data={data_ret}")
+    return op_ret, data_ret, fvs
+
+
+def _parse_stats(fvs):
+    """Parse the FieldValueTuples returned by orchagent into a list of
+    dicts. Each value is 14 pipe-separated fields:
+      count | total_run_ns
+      | median_run_ns | q1_run_ns | q3_run_ns | max_run_ns
+      | high_outliers | low_outliers
+      | sched_count | total_sched_ns
+      | median_sched_ns | q1_sched_ns | q3_sched_ns | max_sched_ns
+    """
+    rows = []
+    for name, blob in fvs:
+        parts = blob.split("|")
+        if len(parts) != 14:
+            # Skip malformed rows rather than failing the whole table.
+            continue
+        try:
+            count            = int(parts[0])
+            total_ns         = int(parts[1])
+            median_ns        = int(parts[2])
+            q1_ns            = int(parts[3])
+            q3_ns            = int(parts[4])
+            max_ns           = int(parts[5])
+            high_outliers    = int(parts[6])
+            low_outliers     = int(parts[7])
+            sched_count      = int(parts[8])
+            total_sched_ns   = int(parts[9])
+            sched_median_ns  = int(parts[10])
+            sched_q1_ns      = int(parts[11])
+            sched_q3_ns      = int(parts[12])
+            sched_max_ns     = int(parts[13])
+        except ValueError:
+            continue
+        rows.append({
+            "name":            name,
+            "count":           count,
+            "total_ns":        total_ns,
+            "median_ns":       median_ns,
+            "q1_ns":           q1_ns,
+            "q3_ns":           q3_ns,
+            "max_ns":          max_ns,
+            "high_outliers":   high_outliers,
+            "low_outliers":    low_outliers,
+            "sched_count":     sched_count,
+            "total_sched_ns":  total_sched_ns,
+            "sched_median_ns": sched_median_ns,
+            "sched_q1_ns":     sched_q1_ns,
+            "sched_q3_ns":     sched_q3_ns,
+            "sched_max_ns":    sched_max_ns,
+        })
+    return rows
+
+
+def _render_table(rows):
+    # Sort: total_ns descending, ties broken by name ascending.
+    rows = sorted(rows,
+                  key=lambda r: (-r["total_ns"], r["name"]))
+
+    table = []
+    for r in rows:
+        if r["count"] == 0:
+            run_quartet  = "-"
+            total_run    = "-"
+        else:
+            run_quartet  = _fmt_quartet(r["median_ns"],
+                                        r["q1_ns"],
+                                        r["q3_ns"],
+                                        r["max_ns"])
+            total_run    = f"{_ms(r['total_ns']):.2f}"
+
+        if r["sched_count"] == 0:
+            sched_quartet = "-"
+            total_sched   = "-"
+        else:
+            sched_quartet = _fmt_quartet(r["sched_median_ns"],
+                                         r["sched_q1_ns"],
+                                         r["sched_q3_ns"],
+                                         r["sched_max_ns"])
+            total_sched   = f"{_ms(r['total_sched_ns']):.2f}"
+
+        # TOTAL column shows "<run>/<sched>" so a viewer can see at a
+        # glance how much wall-clock the loop spent inside the task vs
+        # waiting before scheduling it.
+        total_str = f"{total_run}/{total_sched}"
+
+        outliers = r["high_outliers"] + r["low_outliers"]
+
+        table.append([
+            r["name"],
+            run_quartet,
+            r["count"],
+            outliers,
+            sched_quartet,
+            total_str,
+        ])
+
+    headers = [
+        "TASK",
+        "RUN TIME\nmedian/q1/q3/max\n(in msec)",
+        "RUNS",
+        "OUTLIERS",
+        "SCHED LATENCY\nmedian/q1/q3/max\n(in msec)",
+        "TOTAL\nrun/sched\n(in msec)",
+    ]
+    return tabulate(table, headers=headers, tablefmt="plain")
+
+
+@click.group()
+def orchagent():
+    """Show orchagent runtime information"""
+    pass
+
+
+@orchagent.command("tasks")
+def tasks():
+    """Show per-Executor execution timing in orchagent"""
+    try:
+        _, _, fvs = _query_orchagent("show")
+    except RuntimeError as e:
+        click.echo(f"Error: {e}", err=True)
+        sys.exit(1)
+
+    rows = _parse_stats(fvs)
+    click.echo(_render_table(rows))
diff --git a/tests/clear_orchagent_tasks_test.py b/tests/clear_orchagent_tasks_test.py
@@ -0,0 +1,59 @@
+"""
+Unit tests for `clear orchagent tasks`.
+
+Mocks the swsscommon NotificationProducer / NotificationConsumer / Select
+to round-trip the request without needing Redis.
+"""
+
+from unittest import mock
+
+import pytest
+from click.testing import CliRunner
+
+from clear import orchagent as clear_orchagent
+
+
+@pytest.fixture
+def fake_swsscommon():
+    fake = mock.MagicMock()
+    fake.Select.OBJECT = 0
+    fake.Select.TIMEOUT = 1
+    fake.Select.return_value.select.return_value = (fake.Select.OBJECT, None)
+
+    fake.NotificationConsumer.return_value.pop.return_value = ("ok", "", [])
+    fake.NotificationProducer.return_value.send.return_value = None
+    fake.FieldValuePairs.side_effect = lambda x: x
+    fake.DBConnector.return_value = mock.MagicMock()
+
+    with mock.patch.object(clear_orchagent, "swsscommon", fake):
+        yield fake
+
+
+def test_clear_sends_clear_op_and_prints_ok(fake_swsscommon):
+    runner = CliRunner()
+    result = runner.invoke(clear_orchagent.orchagent, ["tasks"])
+    assert result.exit_code == 0, result.output
+    assert "OK" in result.output
+
+    producer = fake_swsscommon.NotificationProducer.return_value
+    assert producer.send.call_count == 1
+    op_arg = producer.send.call_args[0][0]
+    assert op_arg == "clear"
+
+
+def test_clear_timeout_reports_error(fake_swsscommon):
+    fake_swsscommon.Select.return_value.select.return_value = (
+        fake_swsscommon.Select.TIMEOUT, None)
+
+    runner = CliRunner()
+    result = runner.invoke(clear_orchagent.orchagent, ["tasks"])
+    assert result.exit_code != 0
+
+
+def test_clear_orchagent_error_reply_reports_error(fake_swsscommon):
+    fake_swsscommon.NotificationConsumer.return_value.pop.return_value = (
+        "error", "unknown op", [])
+
+    runner = CliRunner()
+    result = runner.invoke(clear_orchagent.orchagent, ["tasks"])
+    assert result.exit_code != 0
diff --git a/tests/show_orchagent_tasks_test.py b/tests/show_orchagent_tasks_test.py
