Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm2-V0.7.32-2

[Gene Heskett <gene.heskett@verizon.net>]

On Tuesday 07 December 2004 16:47, Ingo Molnar wrote:
>
>could enable WAKEUP_TIMING and LATENCY_TRACING, boot into the new
> kernel and do:
>
> echo 0 > /proc/sys/kernel/preempt_max_latency
>
>then you'll get the worst-case trace in /proc/latency_trace. Does it
>show any millisecs-range latencies?

Here is a cat of that:
[root@coyote linux-2.6.10-rc2-mm3-V0.7.32-9]# cat /proc/latency_trace
preemption latency trace v1.1.3 on 2.6.10-rc2-mm3-V0.7.32-9
--------------------------------------------------------------------
 latency: 5 us, #22/22 | (M:rt VP:0, KP:1, SP:1 HP:1 #P:1)
    -----------------
    | task: X-3215 (uid:0 nice:-1 policy:0 rt_prio:0)
    -----------------

                 _------=> CPU#
                / _-----=> irqs-off
               | / _----=> hardirq
               || / _---=> softirq
               ||| / _--=> preempt-depth
               |||| /
               |||||     delay
   cmd     pid ||||| time  |   caller
      \   /    |||||   \   |   /
   kmail-3488  0-h.2    0µs : __trace_start_sched_wakeup
(try_to_wake_up)
   kmail-3488  0-h.1    0µs : preempt_schedule (try_to_wake_up)
   kmail-3488  0        0µs : __wake_up_common <X-3215> (72 74):
   kmail-3488  0-h.1    0µs : try_to_wake_up (__wake_up_common)
   kmail-3488  0-h..    0µs : preempt_schedule (try_to_wake_up)
   kmail-3488  0-h..    0µs : preempt_schedule_irq (try_to_wake_up)
   kmail-3488  0-h..    1µs : __schedule (preempt_schedule_irq)
   kmail-3488  0-h..    1µs : profile_hit (__schedule)
   kmail-3488  0-h.1    1µs : sched_clock (__schedule)
   kmail-3488  0-h.2    1µs : dequeue_task (__schedule)
   kmail-3488  0-h.2    1µs : recalc_task_prio (__schedule)
   kmail-3488  0-h.2    1µs : effective_prio (recalc_task_prio)
   kmail-3488  0-h.2    2µs : enqueue_task (__schedule)
       X-3215  0-..2    3µs : __switch_to (__schedule)
       X-3215  0        4µs : schedule <kmail-3488> (74 72):
       X-3215  0-..2    4µs : finish_task_switch (__schedule)
       X-3215  0-..1    4µs : trace_stop_sched_switched
(finish_task_switch)
       X-3215  0        5µs : finish_task_switch <X-3215> (72 0):
       X-3215  0-..1    6µs : trace_stop_sched_switched
(finish_task_switch)


vim:ft=help
------------------
 tvtime had been run long enough to expand the log about 10 megs
before I stopped it and did that 'cat' above.

>also, do this:
>
>  chrt -f 90 -p `pidof 'IRQ 8'`
>  chrt -f 91 -p `pidof 'IRQ 0'`

Now, this has been done, and another 30 second run of tvtime, which
generated about another 5 to 10 megs of this:
Dec  7 19:55:56 coyote kernel: wow!  That was a 21 millisec bump
Dec  7 19:55:56 coyote kernel: `IRQ 8'[838] is being piggy.
need_resched=0, cpu=0
Dec  7 19:55:56 coyote kernel: Read missed before next interrupt

and exited with this histogram output:
Dec  7 19:55:56 coyote kernel: rtc latency histogram of {tvtime/3869,
5538 samples}:
Dec  7 19:55:56 coyote kernel: 9 83
Dec  7 19:55:56 coyote kernel: 10 1793
Dec  7 19:55:56 coyote kernel: 11 1704
Dec  7 19:55:56 coyote kernel: 12 562
Dec  7 19:55:56 coyote kernel: 13 188
Dec  7 19:55:56 coyote kernel: 14 109
Dec  7 19:55:56 coyote kernel: 15 88
Dec  7 19:55:56 coyote kernel: 16 63
Dec  7 19:55:56 coyote kernel: 17 73
Dec  7 19:55:56 coyote kernel: 18 112
Dec  7 19:55:56 coyote kernel: 19 153
Dec  7 19:55:56 coyote kernel: 20 80
Dec  7 19:55:56 coyote kernel: 21 43
Dec  7 19:55:56 coyote kernel: 22 28
Dec  7 19:55:56 coyote kernel: 23 9
Dec  7 19:55:56 coyote kernel: 24 6
Dec  7 19:55:56 coyote kernel: 25 9
Dec  7 19:55:56 coyote kernel: 26 1
Dec  7 19:55:56 coyote kernel: 30 1
Dec  7 19:55:56 coyote kernel: 35 1
Dec  7 19:55:56 coyote kernel: 9999 432


>to make sure IRQ8 doesnt get preempted by other stuff. How often do
> you get the rtc histogram in the syslog? Does tvtime use /dev/rtc
> for normal operations perhaps?

I believe it does.  And with the above chrt options in effect,
tvtimes output to the logfile is essentially unchanged.

> If yes then you might want to disable RTC_HISTOGRAM.

And thats a recompile option?  Back in a few.

But couldn't find it.  And oddly, there were two reboots here as I'd
forgotten to update my grub.conf, and on the first one to 32-6, it
hung at the end of the mounting reports on screen, and took a lengthy
nap while doing something to the disks it wasn't reporting on-screen
but there was an extended period of intermittent disk activity, and
it eventually booted sometime after the blanker had kicked in.  I
took advantage of it to take a shower :)  I'd had that happen twice
before and panic'd, even hitting the reset button once and doing a
cold powerdown once, this before I noticed there was some disk
activity going on, so I figured what the hell and walked away to go
see what the missus was watching on the telly.  And when I came back
half an hour later I was looking at a login prompt once I'd moved the 
mouse.

Anyway it had time to collect some more stats, so heres that cat
again.

preemption latency trace v1.1.3 on 2.6.10-rc2-mm3-V0.7.32-9
--------------------------------------------------------------------
 latency: 5 us, #22/22 | (M:rt VP:0, KP:1, SP:1 HP:1 #P:1)
    -----------------
    | task: X-3215 (uid:0 nice:-1 policy:0 rt_prio:0)
    -----------------

                 _------=> CPU#
                / _-----=> irqs-off
               | / _----=> hardirq
               || / _---=> softirq
               ||| / _--=> preempt-depth
               |||| /
               |||||     delay
   cmd     pid ||||| time  |   caller
      \   /    |||||   \   |   /
   kmail-3488  0-h.2    0µs : __trace_start_sched_wakeup
(try_to_wake_up)
   kmail-3488  0-h.1    0µs : preempt_schedule (try_to_wake_up)
   kmail-3488  0        0µs : __wake_up_common <X-3215> (72 74):
   kmail-3488  0-h.1    0µs : try_to_wake_up (__wake_up_common)
   kmail-3488  0-h..    0µs : preempt_schedule (try_to_wake_up)
   kmail-3488  0-h..    0µs : preempt_schedule_irq (try_to_wake_up)
   kmail-3488  0-h..    1µs : __schedule (preempt_schedule_irq)
   kmail-3488  0-h..    1µs : profile_hit (__schedule)
   kmail-3488  0-h.1    1µs : sched_clock (__schedule)
   kmail-3488  0-h.2    1µs : dequeue_task (__schedule)
   kmail-3488  0-h.2    1µs : recalc_task_prio (__schedule)
   kmail-3488  0-h.2    1µs : effective_prio (recalc_task_prio)
   kmail-3488  0-h.2    2µs : enqueue_task (__schedule)
       X-3215  0-..2    3µs : __switch_to (__schedule)
       X-3215  0        4µs : schedule <kmail-3488> (74 72):
       X-3215  0-..2    4µs : finish_task_switch (__schedule)
       X-3215  0-..1    4µs : trace_stop_sched_switched
(finish_task_switch)
       X-3215  0        5µs : finish_task_switch <X-3215> (72 0):
       X-3215  0-..1    6µs : trace_stop_sched_switched
(finish_task_switch)


vim:ft=help
--------------------------
What is all this telling you/us?                    
                
-- 
Cheers, Gene
"There are four boxes to be used in defense of liberty:
 soap, ballot, jury, and ammo. Please use in that order."
-Ed Howdershelt (Author)
99.30% setiathome rank, not too shabby for a WV hillbilly
Yahoo.com attorneys please note, additions to this message
by Gene Heskett are:
Copyright 2004 by Maurice Eugene Heskett, all rights reserved.