Featured image for: SCTP over UDP in the Linux kernel.

Unfortunately, we often receive reports of users escalating the "long poll interval" and "blocked waiting" log messages as issues with Open vSwitch (OVS). Regrettably, in most cases, the problems are tied to system resource issues. Because OVS raises alerts about them, it ends up being wrongly identified as the culprit.

Before delving into the debugging process, let's first clarify the meaning of these messages.

Within its internal operations, OVS employs a mechanism known as a poll loop to handle various events. Its function is similar to more advanced solutions like libevent or glib. In essence, it comprises a set of APIs enabling the registration of events, such as a timeout or the availability of data on a socket. After registering these events, your process can enter a sleep state, awaiting the occurrence of one of these events. Once event processing is complete, the process returns to a sleep state, anticipating the next event.

The "Unreasonably long poll interval" message is logged when the duration between waking up for an event and re-entering the sleep state exceeds one second. In other words, when processing an event takes more than one second.

The "blocked waiting to quiesce" message is logged when one thread is waiting for another to complete its work. This is related to ovs-vswitchd’s RCU implementation, more information can be found in the source. It is generally an indication that one or more threads are completing their work slowly and often accompanies "Unreasonably long poll interval" messages.

Reported problem

In this case, we have a system showing log messages like this:

|timeval|WARN|Unreasonably long 10540ms poll interval (42ms user, 430ms system)
|timeval|WARN|Unreasonably long 6116ms poll interval (24ms user, 80ms system)
|timeval|WARN|Unreasonably long 8699ms poll interval (15ms user, 104ms system)
|timeval|WARN|Unreasonably long 14754ms poll interval (51ms user, 209ms system)

These log messages include three timers; the first indicates elapsed wall clock time, the second is the amount of time vswitchd spent in userspace, and the third is how much time the kernel spent servicing ovs-vswitchd’s requests.

The initial observation here is that the cumulative user + system time does not align with the long poll interval time. This discrepancy suggests that the kernel might be busy doing other activities, preventing the ovs-vswitchd main thread from receiving any CPU time. However this is not always the case, hence we are going to do some additional troubleshooting

It's also important to note that in these instances no thread name follows timeval, which is the log module name. This absence indicates that the log message is reported by the main vswtichd thread, also referred to as the bridge run thread.

Below are examples illustrating other ovs-vswitchd threads, namely handler340and revalidator391, reporting similar issues:

|timeval(handler340)|WARN|Unreasonably long 1259ms poll interval (0ms user, 692ms system) 
|timeval(revalidator391)|WARN|Unreasonably long 1371ms poll interval (0ms user, 853ms system)

Getting the initial data

As you are never sure when this problem will happen again, we started requesting the below data. In our case, we are "lucky," as this problem was happening quite frequently.

The kernel_delay script's output is particularly interesting, as it provides insights into the actions of ovs-vswitchd. Refer to the article Troubleshooting Open vSwitch: Is the kernel to blame? for additional information about this script and how to run it in a Red Hat OpenShift environment.

Here we are taking 120 samples of 30 seconds, assuming this will be enough to capture the problem. If this does not work for your environment, you can adjust the parameters or restart the script if the issue has not occurred.

./kernel_delay.py --sample-time 30 --sample-count 120 | tee delay_results.txt

During occurrences of such issues, we may also encounter messages like the following:

|ovs_rcu(urcu5)|WARN|blocked 1000 ms waiting for handler496 to quiesce
|ovs_rcu(urcu5)|WARN|blocked 2001 ms waiting for handler496 to quiesce
|ovs_rcu(urcu5)|WARN|blocked 4001 ms waiting for handler496 to quiesce
|ovs_rcu(urcu5)|WARN|blocked 8000 ms waiting for handler496 to quiesce

In such instances, it becomes valuable to examine the thread’s activity. The thread may be blocked in a system call. Therefore we should proactively request the below, which dumps the kernel call stack for each ovs-vswitchd thread every 30 seconds:

for ((;;)) do date; \
  find /proc/$(pidof -s ovs-vswitchd)/task -maxdepth 1 \
    -type d \( ! -name . \) -exec \
  bash -c "echo '{}' && cat '{}'/comm && cat '{}'/stack" \; ; \
  sleep 30; \
done | tee syscall_log

Lastly, we would like to capture the CPU statistics by executing the following. This output could provide us with a general understanding of the CPU load during the issue.

mpstat -A 1 | tee cpu_log

Now, we need to actively monitor for the occurrence of the issue, indicated by the relevant log messages appearing in the ovs-vswitchd.log. Once identified, stop all the aforementioned captures, saving both the captured data and the actual ovs-vswitchd.log for further analysis.

In general, if your system supports collecting SoS reports, it would be advisable to do so after gathering all the other relevant data. For additional information on SoS reports, please refer to the following wiki.

It's important to note that not all of the collected data will be analyzed. However, it could provide valuable insights if the issue points to a different cause.

Analyzing the initial results

The first thing we look at is the ovs-vswitchd log showing the problem:

06:47:10.571Z||timeval|WARN|Unreasonably long 1435ms poll interval (7ms user, 28ms system)
06:59:37.304Z||timeval|WARN|Unreasonably long 4529ms poll interval (13ms user, 125ms system)
07:00:44.796Z||timeval|WARN|Unreasonably long 11115ms poll interval (18ms user, 215ms system)

Now that we have three events, let’s try to correlate them to the kernel_delay script’s output:

# Start sampling @06:46:47.538441 (06:46:47 UTC)
# Stop sampling @06:47:17.566780 (06:47:17 UTC)
# Sample dump @06:47:17.566919 (06:47:17 UTC)
---------- ---------------- ----------------------------------------------------------------------------
       4056 ovs-vswitchd     [SYSCALL STATISTICS]
                            NAME                 NUMBER       COUNT          TOTAL ns            MAX ns
                            poll                      7          69    27,731,273,101       511,454,506
                            sendmsg                  46        2340     1,549,422,997     1,393,773,073
                            sendto                   44        1375        42,493,227         7,949,970
                            getdents64              217         140         7,710,665           172,940
                            futex                   202         283         6,403,133           235,639
                            recvmsg                  47        2760         5,162,714            11,086
                            openat                  257          70         2,380,907            53,532
                            accept                   43         210         1,202,824            25,403
                            recvfrom                 45         106           598,966            20,157
                            getrusage                98          74           399,409           131,849
                            read                      0          70           279,191            11,853
                            fstat                     5          70           160,894             7,148
                            close                     3          71           117,364             5,633
                            clone                    56           1           107,854           107,854
                            write                     1          26            65,078            16,364
                            rt_sigprocmask           14           2             3,744             3,032
                            fcntl                    72           2             2,270             1,693
                            TOTAL( - poll):                    7600     1,616,511,237

                            [THREAD RUN STATISTICS]
                            SCHED_CNT           TOTAL ns            MIN ns            MAX ns
                                   174       249,326,672             3,044        24,811,988

                            [THREAD READY STATISTICS]
                            SCHED_CNT           TOTAL ns            MAX ns
                                   174           784,491            74,757

                            [SOFT IRQ STATISTICS]
                            NAME                 VECT_NR       COUNT          TOTAL ns            MAX ns
                            sched                      7          21           158,027            13,963
                            rcu                        9          23            83,012            15,794
                            timer                      1           9            58,868             8,354
                            TOTAL:                                53           299,907

The extract above shows the time slot for the first event in the logfile, and only for the main ovs-vswitchd, as this is the one reporting the event. The only thing outstanding in the above output is the one plus second we spend in the sendmsg() system call.

Generally, a large value in the Max NS column is notable as most of the syscalls are non-blocking. A function like sendmsg() blocking for a full second is a good indication of something to investigate further. Two notable exceptions are poll() and futex(), both of these functions are expected to block while waiting on something else and do not point to the root cause directly.

We notice a similar behavior in the time slot of the second event:

# Start sampling @06:59:12.245780 (06:59:12 UTC)
# Stop sampling @06:59:42.274987 (06:59:42 UTC)
# Sample dump @06:59:42.275134 (06:59:42 UTC)
      4056 ovs-vswitchd     [SYSCALL STATISTICS]
                            NAME                 NUMBER       COUNT          TOTAL ns            MAX ns
                            poll                      7          65    23,711,425,967       510,370,473
                            sendmsg                  46        6287     5,160,045,530     4,383,277,804
                            recvmsg                  47        7417       308,630,468         8,693,126
                            socket                   41        4891        22,110,916            36,111
                            getdents64              217         138         7,566,298           267,129
                            futex                   202         593         5,775,618           323,246
                            ioctl                    16        4996         5,541,061            11,631
                            sendto                   44          37         3,806,988           476,704
                            close                     3        4960         2,583,594             6,997
                            openat                  257          69         2,114,669            44,723
                            accept                   43         204         1,289,991            32,191
                            recvfrom                 45          91           518,709            15,596
                            getrusage                98          70           379,898           110,071
                            read                      0          66           274,984            11,724
                            write                     1          25           208,880            25,577
                            fstat                     5          69           171,851             9,024
                            clone                    56           2           166,940            84,744
                            bind                     49           6            30,762             9,308
                            getsockname              51           6            10,925             3,149
                            rt_sigprocmask           14           4             8,910             5,262
                            TOTAL( - poll):                   29931     5,521,236,992

Here you can see the sendmsg() system call took four plus seconds, also in line with the log message.

The data from the syscall_log provides additional details about what the kernel is doing during this slow syscall, but in this case doesn’t elucidate the situation further:

[<0>] rtnetlink_rcv_msg+0x268/0x370
[<0>] netlink_rcv_skb+0x4c/0x130
[<0>] netlink_unicast+0x19a/0x230
[<0>] netlink_sendmsg+0x204/0x3d0
[<0>] sock_sendmsg+0x50/0x60
[<0>] ____sys_sendmsg+0x1ef/0x250
[<0>] ___sys_sendmsg+0x7c/0xc0
[<0>] __sys_sendmsg+0x57/0xa0
[<0>] do_syscall_64+0x5b/0x1b0
[<0>] entry_SYSCALL_64_after_hwframe+0x61/0xc6

Unfortunately, the eleven-second delay event wasn't captured as the kernel_delay script restarted right in the midst of it.

To understand the reason behind the long duration of the sendmsg() call, the next step involves initiating the trace-cmd below. This command will capture the function graph of the system call, including timestamps:

trace-cmd record -p function_graph -g __sys_sendmsg -P $(pidof ovs-vswitchd) -c

Analyzing the trace-cmd data

First, we need to make sure the issue happened during the time the trace was taken, and in our case 74 log messages were recorded. Now, we can decode the data using the trace-cmd report command. The output of this command looks something like this:

ovs-vswitchd-4056  [025] 14673003.226125: funcgraph_entry:                   |  __sys_sendmsg() {
ovs-vswitchd-4056  [025] 14673003.226128: funcgraph_entry:                   |  smp_irq_work_interrupt() {
ovs-vswitchd-4056  [025] 14673003.226129: funcgraph_entry:                   |    irq_enter() {
ovs-vswitchd-4056  [025] 14673003.226129: funcgraph_entry:                   |      irq_enter_rcu() {
ovs-vswitchd-4056  [025] 14673003.226129: funcgraph_entry:        0.104 us   |        irqtime_account_irq();
ovs-vswitchd-4056  [025] 14673003.226130: funcgraph_exit:         0.730 us   |      }
ovs-vswitchd-4056  [025] 14673003.226130: funcgraph_exit:         1.229 us   |    }
ovs-vswitchd-4056  [025] 14673003.226131: funcgraph_entry:                   |    __wake_up() {
ovs-vswitchd-4056  [025] 14673003.226142: funcgraph_entry:                   |    irq_exit() {
ovs-vswitchd-4056  [025] 14673003.226142: funcgraph_entry:                   |      irq_exit_rcu() {
ovs-vswitchd-4056  [025] 14673003.226142: funcgraph_entry:        0.076 us   |        irqtime_account_irq();
ovs-vswitchd-4056  [025] 14673003.226143: funcgraph_entry:        0.047 us   |        idle_cpu();
ovs-vswitchd-4056  [025] 14673003.226143: funcgraph_exit:         0.798 us   |      }
ovs-vswitchd-4056  [025] 14673003.226143: funcgraph_exit:         1.179 us   |    }
ovs-vswitchd-4056  [025] 14673003.226143: funcgraph_exit:       + 15.070 us  |  }
ovs-vswitchd-4056  [025] 14673003.226209: funcgraph_exit:       + 64.289 us  |  }

Rather than going over this long log file, we could grep/awk/sort for the total time each call took. In our case this resulted in the following:

$ cat trace-cmd_report.txt | grep "|  }" | \
    awk '{for(i=1;i<NF;i++)if($i=="us")print $(i-1) " " $1 " " $2 " " $3}' | \
    sort -n
6048.482 ovs-vswitchd-4056 [114] 14673003.893160:
6059.754 ovs-vswitchd-4056 [114] 14673003.994271:
6345.768 ovs-vswitchd-4056 [114] 14673004.012454:
6377.403 ovs-vswitchd-4056 [114] 14673003.914774:
6410.477 ovs-vswitchd-4056 [114] 14673004.078818:
11346.105 ovs-vswitchd-4056 [119] 14673009.406664:

From the above, you can see the worst case the system call took 1.1ms, which is not even close to the 12 seconds reported in ovs-vswitchd.log for this test. If there are long delays reported, we need to dig into the file, to figure out what is causing this.

The next step would be to gather some scheduling information to determine what the kernel might be doing with our process. To do this we use the perf command. More details on perf and its use cases can be found online and at the perf wiki. For our use case, we execute the following:

perf sched record -a --output perf-sched.data -- sleep 60

In this context, we assume that the issue will manifest within the 60-second window. If not, it is advisable to restart perf, rather than increasing the run time, to prevent an excessive amount of data from being collected.

Analyzing the perf sched data

We could now look at all the kernel scheduling events with the perf sched timehist -i perf-sched.data -f command. However, this will generate a huge amount of output. We could further limit the output to only the main thread of ovs-vswitchd, by including the --tid 4056 option.

When we show this output, we see the 500ms wait time, which is expected due to the ovs-vswitch's main thread timing out after 500ms if no poll events are available:

$ perf sched timehist -i perf-sched.data -f --tid=4056
           time    cpu  task name                       wait time  sch delay   run time
                        [tid/pid]                          (msec)     (msec)     (msec)
--------------- ------  ------------------------------  ---------  ---------  ---------
14918892.771863 [0022]  ovs-vswitchd[4056]                  0.000      0.004      0.301 
14918893.273458 [0022]  ovs-vswitchd[4056]                501.336      0.005      0.258 
14918893.273485 [0022]  ovs-vswitchd[4056]                  0.003      0.000      0.023 
14918893.273565 [0022]  ovs-vswitchd[4056]                  0.002      0.000      0.078 
14918893.775038 [0022]  ovs-vswitchd[4056]                501.455      0.005      0.016 
14918893.775070 [0022]  ovs-vswitchd[4056]                  0.025      0.003      0.007 
14918893.775089 [0022]  ovs-vswitchd[4056]                  0.011      0.003      0.007 
14918894.276799 [0022]  ovs-vswitchd[4056]                501.365      0.005      0.021

Let’s filter out long wait time and sch delay values of more than 550ms:

$ perf sched timehist -i perf-sched.data -f  --tid=4056 | \
    awk '$4 > 550 || $5 > 550' | wc -l

Going over the list manually we can see an event where we are waiting for two plus seconds, corresponding to the log event we saw for this capture:

         time    cpu  task name                       wait time  sch delay   run time
                        [tid/pid]                          (msec)     (msec)     (msec)
--------------- ------  ------------------------------  ---------  ---------  ---------
14918919.383197 [0003]  ovs-vswitchd[4056]               2388.540      0.010      6.492 
|timeval|WARN|Unreasonably long 2412ms poll interval (5ms user, 12ms system)

We should further analyze the sched data to see who was running during this timeframe, and maybe why ovs-vswitch was not scheduled. Let’s first find the above event in the raw data:

$ perf script -i perf-sched.data --tid=4056 -f
    ovs-vswitchd  4056 [003] 14918916.986227: sched:sched_stat_runtime: comm=ovs-vswitchd pid=4056 runtime=816399 [ns] vruntime=899326138452 [ns]
    ovs-vswitchd  4056 [003] 14918916.987228: sched:sched_stat_runtime: comm=ovs-vswitchd pid=4056 runtime=985902 [ns] vruntime=899326244187 [ns]
    ovs-vswitchd  4056 [003] 14918916.988159: sched:sched_stat_runtime: comm=ovs-vswitchd pid=4056 runtime=915643 [ns] vruntime=899326342387 [ns]
    ovs-vswitchd  4056 [003] 14918916.988164:       sched:sched_switch: ovs-vswitchd:4056 [110] T ==> swapper/3:0 [120]
    ovs-vswitchd  4056 [003] 14918919.376769:       sched:sched_waking: comm=kworker/101:2 pid=3703381 prio=120 target_cpu=101
    ovs-vswitchd  4056 [003] 14918919.377173: sched:sched_stat_runtime: comm=ovs-vswitchd pid=4056 runtime=474745 [ns] vruntime=899326393302 [ns]
    ovs-vswitchd  4056 [003] 14918919.377184:       sched:sched_waking: comm=kworker/3:0 pid=3693404 prio=120 target_cpu=003

Now let’s find the raw data for what happened on this CPU between the two events, and save it to a file:

$ perf script -i perf-sched.data \
    --time 14918916.988164,14918919.377173 \
    --cpu 3 -f | tee perf-sched-cpu3.txt | wc -l

We can now obtain a general list of the threads that were active during this period using the following:

$ grep sched_stat_runtime perf-sched-cpu3.txt | awk '{print $1}' | sort | uniq -c
      1 :-1
      1 csi-node-driver
      4 kworker/3:0-mm_
      5 runc
      2 trace-cmd
    622 vector-worker

The data above shows that other threads were running on the CPU with higher priority, however, this should have been flagged by the THREAD READY STATISTICS. Taking a closer look at the raw trace data, we see that the ovs-vswtichd thread was stopped, indicated by the T in the below fragment:

    ovs-vswitchd  4056 [003] 14918916.988164:       sched:sched_switch: ovs-vswitchd:4056 [110] T ==> swapper/3:0 [120]

So next steps would be to further investigate why the kernel or another process stopped ovs-vswitchd. However, it's important to note that this investigation goes beyond the scope of this article, as we have established that the problem does not originate from Open vSwitch.


During this investigation, we began with only a scary-looking log message in the ovs-vswitchd log files; it is possible that poor network or system performance drew our attention to these logs. However, after thoroughly analyzing several sources of telemetry Open vSwitch has been rejected as a root cause. This highlights how the "Unreasonably long poll interval" and "blocked waiting" log messages aren’t necessarily an indication of any bug or problem with Open vSwitch, but instead more of an indication of overall system health.