Examining interrupt handling times

In realtime systems, it's crucial to minimize the time from the occurrence of a hardware event to the execution of code that handles it. The faster a system handles events, the more time it has to meet its deadlines. The System Profiler displays a timeline of events so you can precisely measure the times for various interrupt handling activities.

To see the sequence of events captured by the kernel event trace, click the Switch Pane dropdown in the editor controls () and select Timeline. The Timeline pane illustrates the precise timing of events generated by all owners (sources).

For each owner, the System Profiler draws a timeline, with individual events represented by vertical tick marks. Interrupts are listed at the top and their timelines show interrupt entry and exit events, which indicate the start and end times of the microkernel's processing of individual interrupts. If you click the plus sign (+) next to an interrupt name, the System Profiler draws timelines that show interrupt handler entry and exit events, for all attached handler functions (just below the interrupt's timeline). Above each handler timeline, the name of the process in which the function runs is given.

To see data for events related to a particular interrupt vector, click its name in the editor display. The name and associated timeline get highlighted in grey. In the General Statistics view, which is displayed below the editor window, you can uncheck the Show statistics for all elements box to see aggregate data about the events for the selected owners only (i.e., the interrupt itself and any handlers).

In the States table, the data reveal the number of events that marked the entry into a given state, and the average, maximum, minimum, and total times that an owner remained in that state. You can right-click in a table row and from the context menu, navigate directly to the events that mark the beginning of the maximum and minimum times in that state.

In this latest screenshot, the user has selected the Interrupt 0xA interrupt and navigated to a Handler Entry event owned by io-pkt-v4-hc. The toolbar in the upper left corner of the IDE provides buttons for navigating between events in the timeline. Because interrupt processing time is very short compared to the time period of most kernel event traces, the timeline display must be scaled, using the zoom feature, to easily distinguish events.

At this level of granularity, it's helpful to see individual events through the Trace Event Log view, which is also displayed at the bottom. This view is synchronized with the Timeline pane; selecting an event in one display navigates to that event in the other display.

Here, we can see that the selected Handler Entry event for the io-pkt-v4-hc function occurs just after the Entry event following the actual interrupt on vector 0xA. The microkernel generates this first event when it starts processing the interrupt.

You can select both events (by holding Ctrl as you click each row) and see the brief time range displayed at the top of the Timeline pane. In this case, we've measured the kernel's interrupt latency, which is the time from when it starts processing the interrupt to when the handler starts running.

You can click the Handler Entry and Handler Exit events to measure the interrupt handler's runtime, which is just 9 us. After the handler exits and the kernel finishes processing the interrupt (as marked by the Exit event), we can see a Sigevent Pulse event, which shows that the handler has returned a pulse. This pulse evidently triggers the networking stack process, because one of its threads gets scheduled to receive the pulse (as indicated by the sequence of Running, Receive Pulse, and MsgReceiveV Exit events for io-pkt-v4-hc Thread 3).

Selecting the Handler Exit and MsgReceiveV Exit events lets you measure scheduling latency, which is the time from the last instruction in the handler function to the start of a response by a user (i.e., non-handler) thread. For more information about interrupt and scheduling latency, see the “Interrupt handling” section of the System Architecture guide.

Selecting the Entry and MsgReceiveV Exit events allows you to measure the end-to-end latency from the start of interrupt processing by the kernel to the response of a user thread. Here, that latency is 31 us, which proves that the interrupt handler runtime of 9 us is a relatively small part of the overall processing time. Thus, there is noticeable time needed for scheduling a thread to run and for it to receive the pulse returned by the handler.