Re: [patch] Real-Time Preemption, -RT-2.6.10-rc3-mm1-V0.7.33-0
From: Mark_H_Johnson
Date: Thu Dec 16 2004 - 10:54:43 EST
I was curious about what was causing some of my "extended delays" during
a network stress test & captured a trace I'll summarize here & forward
the complete trace separately. If I read this right, it appears I just
had "bad luck" (lots of interrupts on the CPU with the RT task) but I
would be glad to hear of a better interpretation (if it fits the data).
The test set up was my two CPU SMP system. The kernel was .33-03 with
PREEMPT_DESKTOP and non threaded IRQ's. The RT program was a slight
variation of latencytest - modified to capture traces if the CPU loop
(nominal 1160 usec) took more than 20% longer than nominal. The non
RT stress program running concurrently was my network output test
which basically uses rcp to copy a file to another system.
times in usec
CPU Latency Cause
[00] 50 14 Audio IRQ
[01] 154 69 Network IRQ / soft IRQ
[02] 53 92 SMP timer / Network IRQ / soft IRQ
[03] 25 62 Network IRQ / soft IRQ
[04] 60 6 Network IRQ
[05] 133 70 Network IRQ / soft IRQ
[06] 53 211 Network IRQ / soft IRQ / reschedule
[07] 35 76 Network IRQ / soft IRQ
[08] 75 210 Network IRQ / soft IRQ / reschedule / soft IRQ
[09] 58 105 Audio IRQ / soft IRQ / reschedule
[10] 19 103 Network IRQ / soft IRQ
[11] 86 86 Network IRQ / soft IRQ
[12] 34 102 Network IRQ / soft IRQ
[13] 53 63 Network IRQ / soft IRQ
[14] 56 52 Network IRQ / soft IRQ / reschedule
[15] 72 23 SMP timer / soft IRQ
[16] 59 2 End of trace
Total 1075 1346 (2421 grand total - check)
None of the individual latencies are all that bad - both #06 and #08
were the worst at 210 usec. It may be possible to fix the specific causes
of those two traces (though I know we've also broken the network code
as well...). but it is the cumulative effect of the number of
interrupts that appear to be the problem.
I am also not so sure that PREEMPT_RT would have done much better
but have not run that test for a comparison. I worry about the
cost of rescheduling / IRQ threading overhead - which may explain
why I see PREEMPT_DESKTOP doing better than PREEMPT_RT in some of
my tests.
I guess I should also note that this trace appears to indicate that
ALSA is buffering audio for output [see the two interrupts during the
trace]. I expect the audio output to be a blocking write in latencytest
(that was the 2.4 behavior). Is there some way to get the same behavior
I saw in 2.4 on a 2.6 / ALSA audio set up? If you don't know, who should
I direct that question to?
--Mark
preemption latency trace v1.1.4 on 2.6.10-rc3-mm1-V0.7.33-03
--------------------------------------------------------------------
latency: 2421 µs, #2259/2259, CPU#0 | (M:preempt VP:0, KP:1, SP:0 HP:0
#P:2)
-----------------
| task: latencytest-tra-14143 (uid:0 nice:0 policy:1 rt_prio:99)
-----------------
=> started at: <00000000>
=> ended at: restore_all+0x5/0x21 <c0104000>
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
latencyt-14143 0...1 0µs : user_trace_start (sys_gettimeofday)
latencyt-14143 0d... 0µs+< (0) [00]
latencyt-14143 0d.h. 50µs : do_IRQ (8049af8 a 0)
... process audio interrupt ...
[I can argue - why did this come in here since the audio REALLY should
have finished during the write() call done later]
latencyt-14143 0d... 64µs!< (0) [01]
latencyt-14143 0d.h. 218µs : do_IRQ (8049af9 b 0)
... process network IRQ / soft IRQ ...
latencyt-14143 0d... 287µs+< (0) [02]
latencyt-14143 0d... 340µs : smp_apic_timer_interrupt (8049af9 0 0)
... timer / network IRQ / soft IRQ
latencyt-14143 0d... 432µs+< (0) [03]
latencyt-14143 0d.h. 457µs : do_IRQ (8049af8 b 0)
... network IRQ / soft IRQ ...
latencyt-14143 0d... 519µs+< (0) [04]
latencyt-14143 0d.h. 579µs : do_IRQ (8049af8 b 0)
... network IRQ ...
latencyt-14143 0d... 585µs!< (0) [05]
latencyt-14143 0d.h. 718µs : do_IRQ (8049af8 b 0)
... network IRQ / soft IRQ ...
latencyt-14143 0d... 788µs+< (0) [06]
latencyt-14143 0d.h. 841µs : do_IRQ (8049af9 b 0)
... network IRQ / soft IRQ / reschedule
latencyt-14143 0d... 1052µs+< (0) [07]
latencyt-14143 0d.h. 1087µs : do_IRQ (8049af8 b 0)
... network IRQ / soft IRQ
latencyt-14143 0d... 1163µs+< (0) [08]
latencyt-14143 0d.h. 1238µs : do_IRQ (8049af8 b 0)
... network IRQ / soft IRQ / reschedule / timer / soft IRQ
latencyt-14143 0d... 1448µs+< (0) [09]
latencyt-14143 0d.h. 1506µs : do_IRQ (8049af8 a 0)
... audio IRQ / soft IRQ / reschedule
[this on the other hand is closer to the right duration for the
audio interrupt]
latencyt-14143 0d... 1611µs+< (0) [10]
latencyt-14143 0d.h. 1630µs : do_IRQ (8049af8 b 0)
... network IRQ / soft IRQ
latencyt-14143 0d... 1733µs+< (0) [11]
latencyt-14143 0d.h. 1819µs : do_IRQ (8049af9 b 0)
... network IRQ / soft IRQ
latencyt-14143 0d... 1905µs+< (0) [12]
latencyt-14143 0d.h. 1939µs : do_IRQ (8049af8 b 0)
... network IRQ / soft IRQ
latencyt-14143 0d... 2041µs+< (0) [13]
latencyt-14143 0d.h. 2094µs : do_IRQ (8049af8 b 0)
... network IRQ / soft IRQ
latencyt-14143 0d... 2157µs+< (0) [14]
latencyt-14143 0d.h. 2213µs : do_IRQ (8049af8 b 0)
... network IRQ / soft IRQ / reschedule
latencyt-14143 0d... 2265µs+< (0) [15]
latencyt-14143 0d... 2337µs : smp_apic_timer_interrupt (8049af8 0 0)
... SMP timer / soft IRQ
latencyt-14143 0d... 2360µs+< (0) [16]
latencyt-14143 0.... 2419µs > sys_gettimeofday (00000000 00000000 0000007b)
latencyt-14143 0.... 2419µs : sys_gettimeofday (sysenter_past_esp)
latencyt-14143 0.... 2420µs : user_trace_stop (sys_gettimeofday)
latencyt-14143 0...1 2421µs : user_trace_stop (sys_gettimeofday)
-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/