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

[venkit-nexthop]

The change brought in via PR https://github.com/sonic-net/sonic-swss/pull/3910/changes removes the loop around table->pops(entries)
This lead to a significant performance regression in route download speed when Northbound ZMQ is enabled.

On 202511 based image

After the above PR

  Scale                AF     Routes     Time        Speed    Threshold        CRM   Result
  -----------------------------------------------------------------------------------------------
  500k_32          ipv4  500,000   72.35s       6,341       5,000    500,000     PASS
  500k_26           ipv4  500,000   68.21s       5,965       5,000    500,000     PASS
  250k_128          ipv6  250,000   41.50s       6,314       5,000    250,000     PASS
  250k_96           ipv6  250,000   38.90s       6,314       5,000    250,000     PASS

With the above PR reverted

Scale        AF     Routes    Time   Speed  Threshold      CRM  Result
-----------  ----  -------  ------  ------  ---------  -------  ------
500k/32 ipv4  500,000  31.39s  15,927      5,000  500,005    PASS
500k/26   ipv4  500,000  32.40s  15,434      5,000  500,005   PASS
250k/128  ipv6  250,000  30.30s   8,250      5,000  250,007    PASS
250k/96   ipv6  250,000  35.02s   7,138      5,000  250,007    PASS

[venkit-nexthop]

tagging @deepak-singhal0408
Could you set the right project for this so that it gets added to the dashboard.

[deepak-singhal0408]

Thanks @venkit-nexthop .. tag @prsunny @vivekrnv as well..

@venkit-nexthop do you have some proposal on fixing this for routes? reverting the whole PR may not be an option as it affects Dash project.

[deepak-singhal0408]

also cc @rawal01..
JFYI, Nokia has also tried reverting this PR and have observed a good performance boost.

[venkit-nexthop]

thanks @deepak-singhal0408
I am trying out a few things. I will keep you posted once I have more data.

[prsunny]

@prabhataravind, @theasianpianist for viz.

[prabhataravind]

@venkit-nexthop could you provide some insights on how the times were calculated?

[venkit-nexthop]

@venkit-nexthop could you provide some insights on how the times were calculated?

@prabhataravind This was measured using actual traffic on a Broadcom Q3D based platform. For ipv4 we observed an almost 50% drop in performance. I have been investigating this to understand more. I had requested to present this to @deepak-singhal0408 and @prsunny as well.

As part of that I have built the following:

(1) Some visibility into orchagent executor task statistics. I have built a show orchagent task and sonic-clear orchagent task command. The display looks somethingl like this

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                       1076.54/916.15/1314.50/2032.95      46           4  0.09/0.10/0.13/115.36                47531.07/121.07
FABRIC_POLL                       115.07/115.07/115.07/115.07          1           0  -                                    115.07/-
flush                             0.02/0.02/0.03/1.06                 38           1  1516.63/1186.31/1657.40/2062.76      3.06/53997.99
UPDATE_MAPS_TIMER                 0.00/0.00/0.00/0.00                 48           4  1080.17/947.23/1425.65/2033.05       0.04/54000.98
PFC_WD_COUNTERS_POLL              0.00/0.00/0.00/0.00                 47           2  1130.51/949.65/1501.77/2038.89       0.04/53999.96
P4_ACL_COUNTERS_STATS_POLL_TIMER  0.00/0.00/0.00/0.02                  5           0  10106.77/10009.08/10106.77/10250.20  0.02/40027.18
P4_EXT_COUNTERS_STATS_POLL_TIMER  0.00/0.00/0.00/0.00                  5           0  10106.80/10009.08/10106.80/10250.19  0.00/40027.20
: 
:

(2) Two trial changes to understand the flow:

First trial change:
Limit the amount of time pops() runs to keep it bounded and be able to control that.
Since drain() is synchronous (i.e it waits for response), it is better to try and amortize the cost over a larger set of routes (gMaxBulkSize).

  12 void ZmqConsumer::execute()
  13 {
  14     SWSS_LOG_ENTER();
  15
  16     size_t update_size = 0;
  17     auto table = static_cast<swss::ZmqConsumerStateTable*>(getSelectable());
  18     auto deadline = std::chrono::steady_clock::now() + std::chrono::milliseconds(gZmqExecuteTimeQuantaMsecs);
  19     do
  20     {
  21        std::deque<KeyOpFieldsValuesTuple> entries;
  22        table->pops(entries);
  23        update_size = addToSync(entries);
  24     } while (update_size != 0 && std::chrono::steady_clock::now() < deadline);
  25
  26     // Defer drain() while more ZMQ data is still queued and m_toSync hasn't yet
  27     // reached a bulker-sized batch. The Selectable stays ready (hasCachedData())
  28     // so execute() will be re-dispatched and continue accumulating until either
  29     // the upstream queue drains or m_toSync hits gMaxBulkSize. This reduces the
  30     // number of gRouteBulker.flush() calls under sustained ingress.
  31     if (!table->hasData() || m_toSync.size() >= gMaxBulkSize)
  32     {
  33        drain();
  34     }
  35 }

Second trial change:
This is a much larger change. The main points are:

• Move addToSync() work off of the orchagent main thread. The logic to do addToSync(), retry-cache lookup etc now runs in the ZMQ pollThread.
• The advantage of the above is that we can eliminate the intermediate queueing and free up main thread some more. This will help with convergence events. If there are link/portsOrch activity, it will respond faster.
• Still keep the bulking advantages of the previous trial change. This time we can keep the gMaxBulkSize to a larger value (10K) without worrying that main thread is held up.

I have data with these changes. Additionally, I want to try with sonic-net/sonic-swss#4437 AND my changes above as well and measure.

In the future we need to make additional changes to split the drain() into three different executor tasks.

1. Do the pre-flush() part of the processing
2. Do the flush() part of the process
3. Process the response from syncd

The idea is to improve performance, but keep the overall time a given executor task operates in one shot to a minimum. This will give other tasks the opportunity to run without too much delay.

[vivekrnv]

@venkit-nexthop could you provide some insights on how the times were calculated?

@prabhataravind This was measured using actual traffic on a Broadcom Q3D based platform. For ipv4 we observed an almost 50% drop in performance. I have been investigating this to understand more. I had requested to present this to @deepak-singhal0408 and @prsunny as well.

As part of that I have built the following:

(1) Some visibility into orchagent executor task statistics. I have built a show orchagent task and sonic-clear orchagent task command. The display looks somethingl like this

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                       1076.54/916.15/1314.50/2032.95      46           4  0.09/0.10/0.13/115.36                47531.07/121.07
FABRIC_POLL                       115.07/115.07/115.07/115.07          1           0  -                                    115.07/-
flush                             0.02/0.02/0.03/1.06                 38           1  1516.63/1186.31/1657.40/2062.76      3.06/53997.99
UPDATE_MAPS_TIMER                 0.00/0.00/0.00/0.00                 48           4  1080.17/947.23/1425.65/2033.05       0.04/54000.98
PFC_WD_COUNTERS_POLL              0.00/0.00/0.00/0.00                 47           2  1130.51/949.65/1501.77/2038.89       0.04/53999.96
P4_ACL_COUNTERS_STATS_POLL_TIMER  0.00/0.00/0.00/0.02                  5           0  10106.77/10009.08/10106.77/10250.20  0.02/40027.18
P4_EXT_COUNTERS_STATS_POLL_TIMER  0.00/0.00/0.00/0.00                  5           0  10106.80/10009.08/10106.80/10250.19  0.00/40027.20
: 
:

(2) Two trial changes to understand the flow:

First trial change: Limit the amount of time pops() runs to keep it bounded and be able to control that. Since drain() is synchronous (i.e it waits for response), it is better to try and amortize the cost over a larger set of routes (gMaxBulkSize).

  12 void ZmqConsumer::execute()
  13 {
  14     SWSS_LOG_ENTER();
  15
  16     size_t update_size = 0;
  17     auto table = static_cast<swss::ZmqConsumerStateTable*>(getSelectable());
  18     auto deadline = std::chrono::steady_clock::now() + std::chrono::milliseconds(gZmqExecuteTimeQuantaMsecs);
  19     do
  20     {
  21        std::deque<KeyOpFieldsValuesTuple> entries;
  22        table->pops(entries);
  23        update_size = addToSync(entries);
  24     } while (update_size != 0 && std::chrono::steady_clock::now() < deadline);
  25
  26     // Defer drain() while more ZMQ data is still queued and m_toSync hasn't yet
  27     // reached a bulker-sized batch. The Selectable stays ready (hasCachedData())
  28     // so execute() will be re-dispatched and continue accumulating until either
  29     // the upstream queue drains or m_toSync hits gMaxBulkSize. This reduces the
  30     // number of gRouteBulker.flush() calls under sustained ingress.
  31     if (!table->hasData() || m_toSync.size() >= gMaxBulkSize)
  32     {
  33        drain();
  34     }
  35 }

Second trial change: This is a much larger change. The main points are:

• Move addToSync() work off of the orchagent main thread. The logic to do addToSync(), retry-cache lookup etc now runs in the ZMQ pollThread.
• The advantage of the above is that we can eliminate the intermediate queueing and free up main thread some more. This will help with convergence events. If there are link/portsOrch activity, it will respond faster.
• Still keep the bulking advantages of the previous trial change. This time we can keep the gMaxBulkSize to a larger value (10K) without worrying that main thread is held up.

I have data with these changes. Additionally, I want to try with sonic-net/sonic-swss#4437 AND my changes above as well and measure.

In the future we need to make additional changes to split the drain() into three different executor tasks.

1. Do the pre-flush() part of the processing
2. Do the flush() part of the process
3. Process the response from syncd

The idea is to improve performance, but keep the overall time a given executor task operates in one shot to a minimum. This will give other tasks the opportunity to run without too much delay.

@venkit-nexthop, we wanted to understand how the time is checked. Does it measure time taken until the route is programmed to HW and the update pushed back to fpmsyncd? It is average value of the highest value seen?

[venkit-nexthop]

@vivekrnv there are two times involved. The first is how long it takes for traffic to converge. This is the measurement we did first with and without the PR#3910
Here are the numbers for that:

with the PR in place:

===============================================================================================
  Scale                AF     Routes     Time        Speed    Threshold        CRM   Result
  -----------------------------------------------------------------------------------------------
  500k_32          ipv4  500,000   72.35s       6,341       5,000    500,000     PASS
  500k_26           ipv4  500,000   68.21s       5,965       5,000    500,000     PASS
  250k_128          ipv6  250,000   41.50s       6,314       5,000    250,000     PASS
  250k_96           ipv6  250,000   38.90s       6,314       5,000    250,000     PASS
  ===============================================================================================  

After reverting the PR:

Scale        AF     Routes    Time   Speed  Threshold      CRM  Result
-----------  ----  -------  ------  ------  ---------  -------  ------
500k/32 ipv4  500,000  31.39s  15,927      5,000  500,005    PASS
500k/26   ipv4  500,000  32.40s  15,434      5,000  500,005   PASS
250k/128  ipv6  250,000  30.30s   8,250      5,000  250,007    PASS
250k/96   ipv6  250,000  35.02s   7,138      5,000  250,007    PASS

NOTE: This was measured with actual traffic convergence. Northbound ZMQ was enabled (but not southbound ZMQ)

The other measurement is to see how long the executor tasks run (median, 25th, 75th percentiles, max etc), how many times it ran and total time it ran for. It also includes display about how long it took to reschedule them each time it yields back to epoll loop. The sample output is above. I can show you the data for the various experiments I did.

[vivekrnv]

Is suppress-fib-pending enabled?