Книга: Embedded Linux Primer: A Practical, Real-World Approach
17.4.7. Latency Tracing
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 74 microseconds, control is passed to the actual softirqd-timer/0 thread running in this particular kernel as PID 3. (The process name was truncated to fit the field width and is shown as <...> .)
Most of the fields of Listing 17-7 have obvious meanings. The irqs-off field contains a D for sections of code where interrupts are off. Because this latency trace is an interrupts off trace, we see this indicated throughout the trace. The need_resched field mirrors the state of the kernel's need_resched flag. An n indicates that the scheduler should be run at the soonest opportunity, and a period (.) means that this flag is not active. The hardirq/softirq field indicates a thread of execution in hardirq context with h, and softirq context with s. The preempt-depth field indicates the value of the kernel's preempt_count variable, an indicator of nesting level of locks within the kernel. Preemption can occur only when this variable is at zero.
Оглавление книги
