Problem
There are two timed loops running as part of the same real-time stand-alone application on a cRIO-9055, as shown in the image below:
It has been observed that TimedLoop1 is not executing consistently. Sometimes, it runs at the desired period (5 ms), but at some point, it appears to be taking longer to complete an iteration, which is not desired.
Since timed loops are used, it is expected that the code inside them runs deterministically at the desired rate within a well-defined jitter range. However, in this situation it has been noted that the jitter can vary from a few µs to a couple of seconds.
Setting Up the Code to Capture Traces
Before capturing traces, it is necessary to make some changes to the code, so it is easier to interpret the traces and to ensure that the unexpected behavior under investigation is captured. These are the modifications that were implemented on the original code:
- The Structure Name parameter was modified for both timed loops. By double-clicking on the Input Node the following names were assigned to each Timed Loop:
- Since the timed loop under investigation is TimedLoop1, code for starting and stopping the tracing was added there. This way, it is possible to ensure that the operation will be stopped as soon as the unexpected behavior is detected. Please review the following images for more details.
As observed, the Finished Late? [i-1] terminal of the output node of TimedLoop1 is used to stop capturing traces. This terminal returns True if the previous iteration finished late based on the dt (period) that was configured for the timed loop. For this case, tracing is stopped after 500 iterations finished late. 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 TimedLoop1 and TL2, the following is observed:
From the code, it is known that both tasks are running on CPU 0 of the Real-Time (RT) controller with the same priority (90). When TimedLoop1 runs, it can be observed that it runs several iterations without any issues. However, when TL2 starts running right after TimedLoop1, it takes control of CPU 0. Under normal operation, the following behavior is exhibited by TimedLoop1, according to the image below:
The following events occurred:
- syscalls/sys_exit_clock_nanosleep: the timed loop starts executing the iteration (code inside the loop).
- syscalls/sys_enter_clock_nanosleep: the timed loop finishes running the code inside the timed loop and it waits until it is time to execute the new iteration (to meet the period that was specified in the Timed Loop configuration).
- timer/hrtimer_init: initializes a new high-resolution timer that will be utilized to trigger the execution of the next iteration.
- timer/hrtimer_start: programs the timer and sets target time. This parameter specifies when the timer should be triggered.
When it is time to execute a new iteration, the following events occur:
- timer/hrtimer_expire_entry: the timer expires, and lets the system know that it is time to wake TimedLoop1 up
- sched/sched_waking: TimedLoop1 transitions to the RUN state from the SLEEP state.
- sched/sched_wakeup: TimedLoop1 enters the CPU 0 run queue.
- sched/sched_switch: the loop starts running on CPU 0.
The events are presented in the image below:
The above process is completed with every loop iteration, within the period that was specified as part of the timed loop.
The last time TimedLoop1 was executed, the following behavior is exhibited:
Through the syscalls/sys_exit_clock_nanosleep, the timed loop started a new iteration which ended with the event syscall/sys_enter_clock_nanosleep. At this point, the timed loop completed the code that has been placed inside of it, and it is sleeping waiting for the next iteration to start.
After that event, two timer events are executed: timer/hrtimer_init and timer/hrtimer_start. The timer/hrtimer_init initializes a new high-resolution timer that will trigger the execution of the next iteration of TimedLoop1. The timer is then programmed with the timer/hrtimer_start event.
Later in the trace, the timer event is triggered, and the task is put in the CPU 0 run queue (sched/sched_wakeup event), however, it is not executed right away (missing sched/sched_switch event), as shown in the image below:
The sched/sched_switch event that allows the TimedLoop1 task to run is executed approximately 2 seconds later. In this case, the CPU stops executing TL2 and starts running TimedLoop1 (TL2 S==>TimedLoop1):
It is important to mention that the plots in KernelShark also allow us to identify this behavior graphically:
The hollow green bar that is shown in the TimedLoop1-30160 graph represents when the task was woken up from a sleeping state to when it ran. If the duration of this bar is measured using markers, it is observed that it took approximately 2.045 seconds to resume/allow the execution of the TimedLoop1 task:
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 a timer was created for the task and it was fired. Once the timer expired, TimedLoop1 task was woken up, but the scheduler did not assign CPU time to it. Graphically, the workflow was interrupted in step 4:
