Often, when troubleshooting Open vSwitch (OVS) in the field, you might be left wondering if the issue is really OVS-related, or if it’s a problem with the kernel being overloaded. The kernel_delay.py<\/a> tool can help you quickly identify if the focus of your investigation should be OVS or the Linux<\/a> kernel.<\/p>\n kernel_delay.py\u00a0consists of a Python<\/a> script that uses the BCC <\/span>framework<\/a> to install eBPF probes. \u00a0The data the eBPF probes collect will be analyzed and presented to the user by the Python script. Some of the presented data can also be captured by the individual scripts included in the BBC\u00a0framework.<\/p>\n kernel_delay.py\u00a0has two modes of operation:<\/p>\n In addition, the option Before getting into more details, let’s just run the tool without any options to see what the output looks like. Notice that it will try to automatically get the process ID of the running By default, the tool will run for half a second in time mode<\/span>. To extend this, you can use the The above sample output separates the captured data on a per-thread basis. For this, it displays the thread’s id ( The following sections will describe in detail what statistics they report.<\/p>\n It also shows the total of all system calls, but it excludes the poll system call, as the purpose of this call is to wait for activity on a set of sockets, and usually, the thread gets swapped out.<\/p>\n Note that it only counts calls that started and stopped during the measurement interval!<\/p>\n Note that these statistics only count events where the thread started and stopped running on a CPU during the measurement interval. For example, if this was a PMD thread, you should see zero Note that these statistics only count events where the thread was getting ready to run and started running during the measurement interval.<\/p>\n It shows the interrupt name ( It shows the interrupt name ( In addition to reporting global syscall statistics in All you need to do is add the The Below is an example run; note that I have removed the resource-specific data to highlight the syscall events:<\/p>\n As you can see above, the output also shows the stackback trace. You can disable this using the As you can see above, the backtrace does not show a lot of useful information due to the BCC <\/span>toolkit not supporting dwarf decoding. To further analyze system call backtraces, you could use perf. The following perf script can do this for you (refer to the embedded instructions):\u00a0https:\/\/github.com\/chaudron\/perf_scripts\/blob\/master\/analyze_perf_pmd_syscall.py<\/a><\/p>\n The tool supports both start and stop triggers. This will allow you to capture statistics triggered by a specific event. First, let’s look at what combinations of stop-and-start triggers we can use.<\/p>\n If you only use If you only use If you use both Now that we know how these triggers can be used, let’s investigate what triggers are supported. What we call triggers, BCC\u00a0calls events; these are eBPF tracepoints you can attach to. For more details on the supported tracepoints, check out the BCC documentation<\/a>.<\/p>\n The list below shows the supported triggers and their argument format:<\/p>\n Here are a couple of trigger examples (more use case-specific examples can be found in the next\u00a0section):<\/p>\n This section will give some examples of how to use this tool in real-world scenarios. Let’s start with the issue where Open vSwitch reports First, let me explain this log message. It gets logged if the time delta between two Do a run with the tool using the existing USDT revalidator probes as a start and stop trigger (note that I removed the resource-specific data from the none revalidator threads):<\/p>\n You can see from the start of the output that the trigger took more than a second (1,187,986,454 nanoseconds), which we would already know by looking at the output of the From the revalidator55’s From the above data and maybe some Let’s do another run of the same command in another scenario:<\/p>\n Here you can see the revalidator run took about 263 milliseconds, which does not look odd; however, the The following is one final example where we use a We removed some of the threads and their resource-specific data, but based on the This section describes how you would use the tool on a node in an OpenShift cluster. It assumes you have console access to the node, either directly or through a debug container.<\/p>\n We will use a base Fedora Linux 38 container through Podman, as this will allow us to install some additional tools and packages we need.<\/p>\n The first thing we need to do is to start the container:<\/p>\n Next, add the You need to install Devel, debug, and source RPMs for your OVS and kernel version:<\/p>\n Now we can run the tool. Here we use the above By incorporating the\u00a0kernel_delay.py utility into your development toolkit, you can swiftly pinpoint the problem’s source and initiate focused debugging efforts.<\/p>\n echaudro@redhat.com<\/span><\/span> Troubleshooting Open vSwitch: Is the kernel to blame?<\/span><\/p>\n Often, when troubleshooting Open vSwitch (OVS) in the field, you might be left wondering if the issue is really OVS-related, or if it’s a problem with the kernel being overloaded. The kernel_delay.py<\/a> tool can help you quickly identify if the focus of your investigation should be OVS or the Linux<\/a> kernel.<\/p>\n kernel_delay.py\u00a0consists of a Python<\/a> script that uses the BCC <\/span>framework<\/a> to install eBPF probes. \u00a0The data the eBPF probes collect will be analyzed and presented to the user by the Python script. Some of the presented data can also be captured by the individual scripts included in the BBC\u00a0framework.<\/p>\n kernel_delay.py\u00a0has two modes of operation:<\/p>\n In addition, the option Before getting into more details, let’s just run the tool without any options to see what the output looks like. Notice that it will try to automatically get the process ID of the running By default, the tool will run for half a second in time mode<\/span>. To extend this, you can use the The above sample output separates the captured data on a per-thread basis. For this, it displays the thread’s id ( The following sections will describe in detail what statistics they report.<\/p>\n It also shows the total of all system calls, but it excludes the poll system call, as the purpose of this call is to wait for activity on a set of sockets, and usually, the thread gets swapped out.<\/p>\n Note that it only counts calls that started and stopped during the measurement interval!<\/p>\n Note that these statistics only count events where the thread started and stopped running on a CPU during the measurement interval. For example, if this was a PMD thread, you should see zero Note that these statistics only count events where the thread was getting ready to run and started running during the measurement interval.<\/p>\n It shows the interrupt name (About\u00a0kernel_delay.py<\/h2>\n
\n
\n
--sample-count<\/code> exists to specify how many iterations you would like to do. When using triggers, you can also ignore samples if they are less than a number of nanoseconds with the --trigger-delta<\/code> option. The latter might be useful when debugging Linux syscalls that take a long time to complete. (More on this later.) Finally, you can configure the delay between two sample runs with the --sample-interval<\/code> option.<\/p>\novs-vsdwitchd<\/code>. You can overwrite this with the --pid<\/code> option.<\/p>\n\n
$ sudo .\/kernel_delay.py\n# Start sampling @2023-06-08T12:17:22.725127 (10:17:22 UTC)\n# Stop sampling @2023-06-08T12:17:23.224781 (10:17:23 UTC)\n# Sample dump @2023-06-08T12:17:23.224855 (10:17:23 UTC)\nTID THREAD --sample-time<\/code> option.<\/p>\nWhat will it report?<\/h2>\n
TID<\/code>) and name (THREAD<\/code>), followed by resource-specific data. Which are:<\/p>\n\n
SYSCALL STATISTICS<\/code><\/li>\nTHREAD RUN STATISTICS<\/code><\/li>\nTHREAD READY STATISTICS<\/code><\/li>\nHARD IRQ STATISTICS<\/code><\/li>\nSOFT IRQ STATISTICS<\/code><\/li>\n<\/ul>\nSYSCALL STATISTICS<\/h3>\n
SYSCALL STATISTICS<\/code>\u00a0tell you which Linux system calls got executed during the measurement interval. This includes the number of times the syscall was called (COUNT<\/code>), the total time spent in the system calls (TOTAL ns<\/code>), and the worst-case duration of a single call (MAX ns<\/code>).<\/p>\nTHREAD RUN STATISTICS<\/h3>\n
THREAD RUN STATISTICS<\/code>\u00a0tell you how long the thread was running on a CPU during the measurement interval.<\/p>\nSCHED_CNT<\/code> and TOTAL_ns<\/code>. If not, there might be a misconfiguration.<\/p>\nTHREAD READY STATISTICS<\/h3>\n
THREAD READY STATISTICS<\/code> tell you the time between the thread being ready to run and it actually running on the CPU.<\/p>\nHARD IRQ STATISTICS<\/h3>\n
HARD IRQ STATISTICS<\/code> tell you how much time was spent servicing hard interrupts during the threads run time.<\/p>\nNAME<\/code>), the number of interrupts (COUNT<\/code>), the total time spent in the interrupt handler (TOTAL ns<\/code>), and the worst-case duration (MAX ns<\/code>).<\/p>\nSOFT IRQ STATISTICS<\/h3>\n
SOFT IRQ STATISTICS<\/code> tell you how much time was spent servicing soft interrupts during the threads run time.<\/p>\nNAME<\/code>), vector number (VECT_NR<\/code>), the number of interrupts (COUNT<\/code>), the total time spent in the interrupt handler (TOTAL ns<\/code>), and the worst-case duration (MAX ns<\/code>).<\/p>\nThe\u00a0–syscall-events\u00a0option<\/h1>\n
SYSCALL_STATISTICS<\/code>, the tool can also report each individual syscall. This can be a useful second step if the SYSCALL_STATISTICS<\/code> show high latency numbers.<\/p>\n--syscall-events<\/code> option, with or without the additional DURATION_NS<\/code> parameter. The DUTATION_NS<\/code> parameter allows you to exclude events that take less than the supplied time.<\/p>\n--skip-syscall-poll-events<\/code> option allows you to exclude poll syscalls from the report.<\/p>\n\n
$ sudo .\/kernel_delay.py --syscall-events 50000 --skip-syscall-poll-events\n# Start sampling @2023-06-13T17:10:46.460874 (15:10:46 UTC)\n# Stop sampling @2023-06-13T17:10:46.960727 (15:10:46 UTC)\n# Sample dump @2023-06-13T17:10:46.961033 (15:10:46 UTC)\nTID THREAD --stack-trace-size 0<\/code> option.<\/p>\nUsing triggers<\/h2>\n
--start-trigger<\/code>, the inspection start when the trigger happens and runs until the --sample-time<\/code> number of seconds has passed. The example below shows all the supported options in this scenario.<\/p>\n\n
$ sudo .\/kernel_delay.py --start-trigger up:bridge_run --sample-time 4 \\\n --sample-count 4 --sample-interval 1<\/code><\/pre>\n--stop-trigger<\/code>, the inspection starts immediately and stops when the trigger happens. The example below shows all the supported options in this scenario.<\/p>\n\n
$ sudo .\/kernel_delay.py --stop-trigger upr:bridge_run \\\n --sample-count 4 --sample-interval 1<\/code><\/pre>\n--start-trigger<\/code> and --stop-trigger<\/code> triggers, the statistics are captured between the two first occurrences of these events. The example below shows all the supported options in this scenario.<\/p>\n\n
$ sudo .\/kernel_delay.py --start-trigger up:bridge_run \\\n --stop-trigger upr:bridge_run \\\n --sample-count 4 --sample-interval 1 \\\n --trigger-delta 50000<\/code><\/pre>\n\n
[u]:{provider}:{probe}<\/code><\/p>\n<\/dd>\n[t:trace]:{system}:{event}<\/code><\/p>\n<\/dd>\n[k:kprobe]:{kernel_function}<\/code><\/p>\n<\/dd>\n[kr:kretprobe]:{kernel_function}<\/code><\/p>\n<\/dd>\n[up:uprobe]:{function}<\/code><\/p>\n<\/dd>\n[upr:uretprobe]:{function}<\/code><\/p>\n<\/dd>\n<\/dl>\n\n
--start|stop-trigger u:udpif_revalidator:start_dump\n--start|stop-trigger t:openvswitch:ovs_dp_upcall\n--start|stop-trigger k:ovs_dp_process_packet\n--start|stop-trigger kr:ovs_dp_process_packet\n--start|stop-trigger up:bridge_run\n--start|stop-trigger upr:bridge_run<\/code><\/pre>\nExamples<\/h2>\n
Unreasonably long XXXXms poll interval<\/code> on your revalidator threads. Note that there is a blog available explaining how the revalidator process works in OVS<\/a>.<\/p>\npoll_block()<\/code> calls is more than 1 second. In other words, the process was spending a lot of time processing stuff that was made available by the return of the poll_block()<\/code>.<\/p>\n\n
$ sudo .\/kernel_delay.py --start-trigger u:udpif_revalidator:start_dump --stop-trigger u:udpif_revalidator:sweep_done\n# Start sampling (trigger@791777093512008) @2023-06-14T14:52:00.110303 (12:52:00 UTC)\n# Stop sampling (trigger@791778281498462) @2023-06-14T14:52:01.297975 (12:52:01 UTC)\n# Triggered sample dump, stop-start delta 1,187,986,454 ns @2023-06-14T14:52:01.298021 (12:52:01 UTC)\nTID THREAD ovs-vsctl upcall\/show<\/code> command.<\/p>\nSYSCALL STATISTICS<\/code> statistics, we can see it spent almost 870 milliseconds handling syscalls, and there were no poll()<\/code> calls being executed. The THREAD RUN STATISTICS<\/code> statistics here are a bit misleading, as it looks like we only spent 394 milliseconds on the CPU. But earlier, we learned that this time does not include the time being on the CPU at the start or stop of an event. What is exactly the case here because we are using USDT probes.<\/p>\ntop<\/code> output, we can determine that the revalidator55 thread is taking a lot of CPU time, probably because it has to do a lot of revalidator work by itself. The solution is to increase the number of revalidator threads, so more work could be done in parallel.<\/p>\n\n
$ sudo .\/kernel_delay.py --start-trigger u:udpif_revalidator:start_dump --stop-trigger u:udpif_revalidator:sweep_done\n# Start sampling (trigger@795160501758971) @2023-06-14T15:48:23.518512 (13:48:23 UTC)\n# Stop sampling (trigger@795160764940201) @2023-06-14T15:48:23.781381 (13:48:23 UTC)\n# Triggered sample dump, stop-start delta 263,181,230 ns @2023-06-14T15:48:23.781414 (13:48:23 UTC)\nTID THREAD THREAD READY STATISTICS<\/code> information shows us we were waiting 87 milliseconds for a CPU to be run on. This means the revalidator process could have finished 87 milliseconds faster. Looking at the MAX ns<\/code> value, we see a worst-case delay of almost 46 milliseconds, which hints at an overloaded system.<\/p>\nuprobe<\/code> to get some statistics on a bridge_run()<\/code> execution that takes more than 1 \u00a0millisecond:<\/p>\n\n
$ sudo .\/kernel_delay.py --start-trigger up:bridge_run --stop-trigger ur:bridge_run --trigger-delta 1000000\n# Start sampling (trigger@2245245432101270) @2023-06-14T16:21:10.467919 (14:21:10 UTC)\n# Stop sampling (trigger@2245245432414656) @2023-06-14T16:21:10.468296 (14:21:10 UTC)\n# Sample dump skipped, delta 313,386 ns @2023-06-14T16:21:10.468419 (14:21:10 UTC)\n# Start sampling (trigger@2245245505301745) @2023-06-14T16:21:10.540970 (14:21:10 UTC)\n# Stop sampling (trigger@2245245506911119) @2023-06-14T16:21:10.542499 (14:21:10 UTC)\n# Triggered sample dump, stop-start delta 1,609,374 ns @2023-06-14T16:21:10.542565 (14:21:10 UTC)\nTID THREAD ovs-vswitchd<\/code> thread, you can see some clone3<\/code> syscalls, indicating threads were created. In this example, it was due to the deletion of a bridge, which resulted in the recreation of the revalidator and handler threads.<\/p>\nUsing kernel_delay.py with OpenShift<\/h2>\n
\n
[core@sno-master ~]$ sudo podman run -it --rm \\\n -e PS1='[(DEBUG)\\u@\\h \\W]\\$ ' \\\n --privileged --network=host --pid=host \\\n -v \/lib\/modules:\/lib\/modules:ro \\\n -v \/sys\/kernel\/debug:\/sys\/kernel\/debug \\\n -v \/proc:\/proc \\\n -v \/:\/mnt\/rootdir \\\n quay.io\/fedora\/fedora:38-x86_64\n\n[(DEBUG)root@sno-master \/]#<\/code><\/pre>\nlinux_delay.py<\/code> dependencies:<\/p>\n\n
[(DEBUG)root@sno-master \/]# dnf install -y bcc-tools perl-interpreter \\\n python3-pytz python3-psutil<\/code><\/pre>\n\n
[(DEBUG)root@sno-master home]# rpm -i \\\n openvswitch2.17-debuginfo-2.17.0-67.el8fdp.x86_64.rpm \\\n openvswitch2.17-debugsource-2.17.0-67.el8fdp.x86_64.rpm \\\n kernel-devel-4.18.0-372.41.1.el8_6.x86_64.rpm<\/code><\/pre>\nbridge_run()<\/code> example:<\/p>\n\n
[(DEBUG)root@sno-master home]# .\/kernel_delay.py --start-trigger up:bridge_run --stop-trigger ur:bridge_run\n# Start sampling (trigger@75279117343513) @2023-06-15T11:44:07.628372 (11:44:07 UTC)\n# Stop sampling (trigger@75279117443980) @2023-06-15T11:44:07.628529 (11:44:07 UTC)\n# Triggered sample dump, stop-start delta 100,467 ns @2023-06-15T11:44:07.628569 (11:44:07 UTC)\nTID THREAD Conclusion<\/h2>\n
\nMon, 07\/24\/2023 – 07:00<\/span>
\nEelco Chaudron<\/a><\/p>\n\n![\\\"IT\u96fb\u8166\u88dc\u7fd2](\\\"http:\/\/itteacheritfreelance.hk\/test\/wordpress\/wp-content\/uploads\/2016\/05\/logo2-2.png\\\"){kind=logo}
\r\nwww.itsec.hk<\/a>
\r\nwww.itsec.vip<\/a>
\r\nwww.itseceu.uk<\/a>
<\/p>","protected":false},"excerpt":{"rendered":"About\u00a0kernel_delay.py<\/h2>\n
\n
\n
--sample-count<\/code> exists to specify how many iterations you would like to do. When using triggers, you can also ignore samples if they are less than a number of nanoseconds with the --trigger-delta<\/code> option. The latter might be useful when debugging Linux syscalls that take a long time to complete. (More on this later.) Finally, you can configure the delay between two sample runs with the --sample-interval<\/code> option.<\/p>\novs-vsdwitchd<\/code>. You can overwrite this with the --pid<\/code> option.<\/p>\n\n
$ sudo .\/kernel_delay.py\n# Start sampling @2023-06-08T12:17:22.725127 (10:17:22 UTC)\n# Stop sampling @2023-06-08T12:17:23.224781 (10:17:23 UTC)\n# Sample dump @2023-06-08T12:17:23.224855 (10:17:23 UTC)\nTID THREAD --sample-time<\/code> option.<\/p>\nWhat will it report?<\/h2>\n
TID<\/code>) and name (THREAD<\/code>), followed by resource-specific data. Which are:<\/p>\n\n
SYSCALL STATISTICS<\/code><\/li>\nTHREAD RUN STATISTICS<\/code><\/li>\nTHREAD READY STATISTICS<\/code><\/li>\nHARD IRQ STATISTICS<\/code><\/li>\nSOFT IRQ STATISTICS<\/code><\/li>\n<\/ul>\nSYSCALL STATISTICS<\/h3>\n
SYSCALL STATISTICS<\/code>\u00a0tell you which Linux system calls got executed during the measurement interval. This includes the number of times the syscall was called (COUNT<\/code>), the total time spent in the system calls (TOTAL ns<\/code>), and the worst-case duration of a single call (MAX ns<\/code>).<\/p>\nTHREAD RUN STATISTICS<\/h3>\n
THREAD RUN STATISTICS<\/code>\u00a0tell you how long the thread was running on a CPU during the measurement interval.<\/p>\nSCHED_CNT<\/code> and TOTAL_ns<\/code>. If not, there might be a misconfiguration.<\/p>\nTHREAD READY STATISTICS<\/h3>\n
THREAD READY STATISTICS<\/code> tell you the time between the thread being ready to run and it actually running on the CPU.<\/p>\nHARD IRQ STATISTICS<\/h3>\n
HARD IRQ STATISTICS<\/code> tell you how much time was spent servicing hard interrupts during the threads run time.<\/p>\nNAME<\/code>), the number of interrupts (