Identifying Lock Contention in NI Linux Real-Time Trace Data

Lock contention occurs when multiple threads, processes, or applications attempt to access the same locked resource simultaneously, causing some requests to wait until the lock is released. This waiting can lead to reduced performance, increased response times, and lower system throughput.

This article provides a case study to demonstrate how to apply and use the diagnostic workflow presented in Diagnosing Timing Jitter, Scheduling Delays, and Hang Conditions in NI Linux Real-Time Systems, when troubleshooting lock contention-related issues in NI Real-Time (RT) embedded controllers.

Problem

A cRIO-9039 controller runs an application that is composed of one timed loop called Loop A and a While Loop called Loop B that are exchanging information through a queue as shown in the image below: 

With the configuration above, it has been observed that Loop A is not running as expected. The period for this timed loop has been set to 1 ms, but it is taking approximately 250 ms to complete an iteration, which is not desired. If the queue operations are removed, Loop A runs as expected, however, removing this functionality is not possible because the information generated here needs to be transferred to Loop B.

Setting Up the Code to Capture Traces

Before capturing traces, it is required to prepare the code appropriately, so it is easier to interpret them and to ensure that the issue under investigation is captured. These are the modifications that were implemented on the original code:

1. The Structure Name for Loop A has been modified. By double-clicking the timed loop’s Input Node, the following name was assigned:

2. Since Loop A is the process under investigation, code for starting and stopping capturing traces has been added there. This way, it is possible to ensure that the operation will end as soon as the unexpected behavior is expected. Please review the following images for more details:

As it can be observed, the Iteration Duration terminal of the output node of Loop A is used to stop capturing traces. This terminal returns how much it took to execute an iteration of the loop (in ms). This output is then passed to a Greater? function and determines whether the value is greater than 1 ms, which is the period set for Loop A. Theoretically, this timed loop should take less than 1 ms to execute one iteration, to ensure that the configured period is met.

Additionally, for this specific case, tracing is stopped after executing 500 iterations that took more than 1 ms to be completed. This value was used to ensure that enough information is captured before and after the behavior occurs.

It is important to note that your application may require a different stop condition. In larger applications, it may be preferable to stop capturing traces immediately after the first occurrence of the behavior. This helps prevent CPU buffers from filling up and avoids losing critical information if more traces are captured after the issue under investigation is displayed.

Trace Analysis

After opening the trace.dat file in KernelShark and plotting the traces that correspond to LoopA, the following is observed:

If the first trace for Loop A is zoomed in (the one marked in red on the image above), this plot is generated:

The hollow green bar displayed in the image above suggests that LoopA was woken up from a sleeping state, but it didn’t start running right away. There is a small delay before the task receives CPU time.

If traces are analyzed, the following behavior is exhibited:

The list of the most important events is presented below:

1. sched/sched_switch (LV_ESys2_Thr0 R ==> LoopA). This is the first event that can be observed in the traces. This means that LoopA started running and preempted LV_ESys2_Thr0, since LoopA has a greater priority than LV_ESys2_Thr0.
2. syscalls/sys_enter_futex (op= FUTEX_LOCK_PI uaddr=0x7feca80015a8). Syscalls/sys_enter_futex, means that LoopA entered a futex. A futex or fast user mutex, is a synchronization mechanism that controls the access to a shared resource. In the information associated with the event, op= FUTEX_LOCK_PI uaddr=0x7feca80015a8 was executed. FUTEX_LOCK_PI is an operation used to acquire a priority inheritance futex, and it is designed to avoid priority inversion by having the futex (lock) owner temporarily inherit the priority of higher-priority waiters. In this case LoopA represents a higher-priority waiter. 
3. sched/sched_pi_setprio (comm=LV_ESys2_Thr0, oldprio=120 newprio=40): the kernel changes the priority of LV_ESys2_Thr0 from 120 to 40, which is the one owned by LoopA. This means that LoopA tried to execute its associated tasks on a shared resource, but LV_ESys2_Thr0 was using it, causing LoopA to wait. To reduce the wait time, LV_ESys2_Thr0 inherits LoopA priority temporarily. Note: in NI Linux Real-Time, lower numeric values indicate higher priority
4. sched/sched_migrate_task (comm=LV_ESys2_Thr0, orig_cpu=0, dest_cpu=1): through the sched_migrate_task, the kernel moves LV_ESys2_Thr0 from CPU 0 to CPU 1, after it inherited LoopA priority. This is to ensure that the task receives even more resources so it can finish its execution and free the shared resource that LoopA is waiting for.

1. sched/sched_switch (swapper/1:0 R==> LV_ESys2_Thr0): the LV_ESys2_Thr0 starts running on CPU 1.
2. sched/sched_switch (LoopA S==> swapper/0:0): In CPU 0, LoopA stops running and waits for the shared resource to be freed to complete its execution. In the meantime, swapper/0:0 starts running. This is CPU 0 idle task.
3. syscall/sys_enter_futex (op=FUTEX_UNLOCK_PI, uaddr= 0x7feca80015a8). LV_ESys2_Thr0, enters futex (with address 0x7feca80015a8) to free it, so the shared resource can be used by LoopA.
4. sched/sched_waking (comm=LoopA prio=40 target_cpu=0): LV_ESys2_Thr0 wakes LoopA up.
5. sched/sched_switch (swapper/0:0 R ==> LoopA): the kernel resumes execution of LoopA in CPU 0.
6. syscall/sys_enter_clock_nanosleep: LoopA finishes executing the current iteration.

If further analysis is executed, the following behavior is observed when a new iteration of LoopA begins:

 

1. timer/hrtimer_expire_entry: the high-resolution timer associated with LoopA expires, meaning that the system is ready to execute a new iteration.
2. sched/sched_wakeup: LoopA task is woken up.
3. sched/sched_switch (swapper/0:0 R==> LoopA): LoopA starts running on CPU 0.
4. syscall/sys_exit_clock_nanosleep: at this point, a LoopA iteration begins.
5. syscall/sys_enter_futex (op=FUTEX_WAIT_REQUEUE_PI, uaddr=0x2ea6ecf0, uaddr2=0x2ea6ed20): LoopA is waiting on a condition variable (at user address (uaddr) = 0x2ea6ecf0) and will be requeued to the associated mutex (located at uaddr2 = 0x2ea6ed20) when signaled, allowing it to safely regain ownership of the shared resource. For this operation:
   
   1. uaddr: represents the futex backing the condition variable on which the thread is waiting.
   2. uaddr2: represents the futex backing the mutex associated with the condition variable.
6. sched/sched_switch (LoopA S ==> swapper/0:0): since LoopA is waiting on a futex, the kernel runs the swapper/0:0 task on CPU 0. swapper/0:0 is the NI Linux RT kernel's idle thread for CPU 0. It is scheduled when no runnable tasks are available on that processor. Its appearance in a trace typically indicates that the CPU was idle while other threads were blocked or waiting for resources. 

At this point, LoopA execution is halted. Later in the traces, the following behavior is observed:

 

The events highlighted in red on the image above are explained in more detail below:

1. syscall/syscall_enter_futex (op= FUTEX_CMP_REQUEUE_PI, uaddr=0x2ea6cf0, uaddr2=0x2ea6ed20): LV_ESys2_Thr0 executes FUTEX_CMP_REQUEUE_PI, which is the futex operation that moves one or more waiters from uaddr futex to uaddr2 futex (Priority Inheritance (PI) futex). In this case, Loop A is transferred from the condition-variable futex to the mutex futex. Since LoopA has a higher priority and becomes blocked waiting for a mutex owned by LV_ESys2_Thr0, the NI Linux RT Priority Inheritance mechanism temporarily boosts LV_ESys2_Thr0's priority to reduce priority inversion and allow the mutex to be released sooner. 
2. syscall/syscall_enter_futex (op= FUTEX_UNLOCK_PI, uaddr=0x2ea6ed20): LV_ESys2_Thr0 executes the FUTEX_UNLOCK_PI operation, meaning that it finished its execution and the shared resource can be used by LoopA.
3. sched/sched_wakeup (LoopA CPU:000): LV_ESys2_Thr0 wakes up LoopA.
4. sched/sched_switch (swapper /0:0 R==> LoopA): LoopA resumes execution on CPU 0.
5. syscall/sys_enter_clock_nanosleep: LoopA finishes executing the current iteration. According to the timestamping information, this event occurred at 5555.956060 s. The corresponding sys_exit_clock_nanosleep occurred at 5555.703690 s based on the previous image. If the difference is calculated to get the execution time of that iteration, a value of 0.25237 seconds is obtained.

When analyzing the behavior above with the Diagnostic Workflow presented in Diagnosing Timing Jitter, Scheduling Delays, and Hang Conditions in NI Linux Real-Time Systems, it is observed that on every LoopA iteration, a wake-up event occurs (i.e. a high-resolution timer is triggered), and the task runs and receives CPU time on CPU 0. However, as soon as it starts running, it enters a futex and waits because LV_ESys2_Thr0 uses a shared resource that needs to be accessed by LoopA. Therefore, it stops making progress when it runs on the CPU. Graphically, the workflow was interrupted in step 5:

 

 

 

 

Following the recommendation of the diagnostic workflow, the points below must be investigated:

• Look for futex_wait patterns in the traces.
• Identify the lock holder/peer task.

Based on the information previously analyzed, every time LoopA starts a new iteration it enters a futex and executes either a futex_wait or futex_lock operation, meaning that its execution is being stopped because it requires accessing a shared resource that is currently occupied by a peer task.

Through the analysis of the addresses that are associated with the futexes (using the search feature in KernelShark), it has been determined that LV_ESys2_Thr0 is the peer task that is utilizing the same shared resource as LoopA. At this point, it is important to determine the shared resource in the LabVIEW VI being analyzed.

Considering that the timed loop (LoopA) is transferring data to a while loop (Loop B) using a queue, it is possible to conclude that the queue is the shared resource between both processes, as observed in the image below:

Therefore, considering this information, the issue can be solved by implementing one of the changes below to the code, depending on how much data you need to transfer between both loops:

• Replace the Queue with an RT FIFO. This mechanism allows you to send and receive data deterministically between a timed loop and a while loop.
• Use a Single Process Shared Variable with RT FIFO enabled. By enabling the real-time FIFO of a shared variable, you can share data without affecting the determinism of VIs running on an RT target.

In general, it is recommended to avoid shared resources between timed structures/time-critical priority VIs and low priority processes or VIs. For more information, please refer to Avoiding Shared Resources