17.4.6. Interrupt Off History
Enabling INTERRUPT_OFF_HIST provides functionality similar to that with WAKEUP_LATENCY_HIST. This option gathers interrupt off timing measurements into a file for later analysis. This data is formatted as a histogram, with bins ranging from 0 microseconds to just over 10,000 microseconds. In the example just given, we saw that the maximum latency was 97 microseconds from that particular sample. Therefore, we can conclude that the latency data in histogram form will not contain any useful information beyond the 97-microsecond bin.
History data is obtained by reading a special /proc file. This output is redirected to a regular file for analysis or plotting as follows:
# cat /proc/latency_hist/interrupt_off_latency/CPU0 > hist_data.txt
Listing 17-6 displays the first 10 lines of the history data.
Listing 17-6. Interrupt Off Latency History (Head)
$ cat /proc/latency_hist/interrupt_off_latency/CPU0 | head
#Minimum latency: 0 microseconds.
#Average latency: 1 microseconds.
#Maximum latency: 97 microseconds.
#Total samples: 60097595
#There are 0 samples greater or equal than 10240 microseconds
#usecs samples
0 13475417
1 38914907
2 2714349
3 442308
...
From Listing 17-6 we can see the minimum and maximum values, the average of all the values, and the total number of samples. In this case, we accumulated slightly more than 60 million samples. The histogram data follows the summary and contains up to around 10,000 bins. We can easily plot this data using gnuplot as shown in Figure 17-5.
Figure 17-5. Interrupt off latency data
17.4.7. Latency Tracing
The LATENCY_TRACE configuration option enables generation of kernel trace data associated with the last maximum latency measurement. It is also made available through the /proc file system. A latency trace can help you isolate the longest-latency code path. For each new maximum latency measurement, an associated trace is generated that facilitates tracing the code path of the associated maximum latency.
Listing 17-7 reproduces an example trace for a 78-microsecond maximum. As with the other measurement tools, enable the measurement by writing a 0 to /proc/sys/kernel/preempt_max_latency.
Listing 17-7. Interrupt Off Maximum Latency Trace
$ cat /proc/latency_trace
preemption latency trace v1.1.5 on 2.6.14-rt-intoff-tim_trace
-------------------------------------------------------------
latency: 78 us, #50/50, CPU#0 | (M:rt VP:0, KP:0, SP:1 HP:1)
-----------------
| task: softirq-timer/0-3 (uid:0 nice:0 policy:1 rt_prio:1)
-----------------
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
/ ||||| | /
cat-6637 0D... 1us : common_interrupt ((0))
cat-6637 0D.h. 2us : do_IRQ (c013d91c 0 0)
cat-6637 0D.h1 3us+: mask_and_ack_8259A (__do_IRQ)
cat-6637 0D.h1 10us : redirect_hardirq (__do_IRQ)
cat-6637 0D.h. 12us : handle_IRQ_event (__do_IRQ)
cat-6637 0D.h. 13us : timer_interrupt (handle_IRQ_event)
cat-6637 0D.h. 15us : handle_tick_update (timer_interrupt)
cat-6637 0D.h1 16us : do_timer (handle_tick_update)
... <we're in the timer interrupt function>
cat-6637 0D.h. 22us : run_local_timers (update_process_times)
cat-6637 0D.h. 22us : raise_softirq (run_local_timers)
cat-6637 0D.h. 23us : wakeup_softirqd (raise_softirq)
... <softirq work pending - need to preempt is signaled>
cat-6637 0Dnh. 34us : wake_up_process (wakeup_softirqd)
cat-6637 0Dnh. 35us+: rcu_pending (update_process_times)
cat-6637 0Dnh. 39us : scheduler_tick (update_process_times)
cat-6637 0Dnh. 39us : sched_clock (scheduler_tick)
cat-6637 0Dnh1 41us : task_timeslice (scheduler_tick)
cat-6637 0Dnh. 42us+: preempt_schedule (scheduler_tick)
cat-6637 0Dnh1 45us : note_interrupt (__do_IRQ)
cat-6637 0Dnh1 45us : enable_8259A_irq (__do_IRQ)
cat-6637 0Dnh1 47us : preempt_schedule (enable_8259A_irq)
cat-6637 0Dnh. 48us : preempt_schedule (__do_IRQ)
cat-6637 0Dnh. 48us : irq_exit (do_IRQ)
cat-6637 0Dn.. 49us : preempt_schedule_irq (need_resched)
cat-6637 0Dn.. 50us : __schedule (preempt_schedule_irq)
... <here is the context switch to softirqd-timer thread>
<...>-3 0D..2 74us+: __switch_to (__schedule)
<...>-3 0D..2 76us : __schedule <cat-6637> (74 62)
<...>-3 0D..2 77us : __schedule (schedule)
<...>-3 0D..2 78us : trace_irqs_on (__schedule)
... <output truncated here for brevity>
We have trimmed this listing significantly for clarity, but the key elements of this trace are obvious. This trace resulted from a timer interrupt. In the hardirq thread, little is done beyond queuing up some work for later in a softirq context. This is seen by the wakeup_softirqd() function at 23 microseconds and is typical for interrupt processing. This triggers the need_resched flag, as shown in the trace by the n in the third column of the second field. At 49 microseconds, after some processing in the timer softirq, the scheduler is invoked for preemption. At
