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

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

[Eran Mann]

Ingo Molnar wrote:
...

> i've implemented the 'tracing follows the task' logic in the -32-2
> patch, available from the usual place:
> 
>     http://redhat.com/~mingo/realtime-preempt/
> 
> i've also added a CPU# field and i've reworked latency_trace format, to
> make it more readable. Whenever preempt_wakeup_timing is enabled,
> user-tracing will follow the traced task, if it's disabled then tracing
> will stay on the CPU. No other changes.
...
> 	Ingo

On my machine, disabling CONFIG_LATENCY_TRACE causes the kernel to stop 
reporting preempt latencies. After
# echo 1 > /proc/sys/kernel/preempt_max_latency

/proc/sys/kernel/preempt_max_latency always shows 1 no matter what load 
is on the machine. I´ve seen this behavior since the first time I tried 
to disable CONFIG_LATENCY_TRACE, around V0.7.31.something.

Below is the exact diff between the 2 configs (the one that shows 
latencies and the one that doesn´t). Note that the only intentional 
change is turning off CONFIG_LATENCY_TRACE.
=======================================================
--- /tmp/config-2.6.10-rc2-mm3-V0.7.32-2.lat    2004-12-07 
16:25:03.000000000 +0200
+++ /tmp/config-2.6.10-rc2-mm3-V0.7.32-2.no_lat 2004-12-07 
11:06:19.000000000 +0200
@@ -1,7 +1,7 @@
  #
  # Automatically generated make config: don't edit
  # Linux kernel version: 2.6.10-rc2-mm3-V0.7.32-2
-# Tue Dec  7 11:07:07 2004
+# Mon Dec  6 20:24:09 2004
  #
  CONFIG_X86=y
  CONFIG_MMU=y
@@ -137,6 +137,7 @@
  CONFIG_MTRR=y
  # CONFIG_EFI is not set
  CONFIG_HAVE_DEC_LOCK=y
+# CONFIG_REGPARM is not set

  #
  # Performance-monitoring counters support
@@ -1711,12 +1712,12 @@
  CONFIG_CRITICAL_IRQSOFF_TIMING=y
  CONFIG_CRITICAL_TIMING=y
  CONFIG_LATENCY_TIMING=y
-CONFIG_LATENCY_TRACE=y
-CONFIG_MCOUNT=y
+# CONFIG_LATENCY_TRACE is not set
  # CONFIG_RT_DEADLOCK_DETECT is not set
  # CONFIG_DEBUG_KOBJECT is not set
  CONFIG_DEBUG_BUGVERBOSE=y
  # CONFIG_DEBUG_INFO is not set
+CONFIG_USE_FRAME_POINTER=y
  CONFIG_FRAME_POINTER=y
  CONFIG_EARLY_PRINTK=y
  # CONFIG_DEBUG_STACKOVERFLOW is not set
=======================================================
-- 
Eran Mann

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

[Ingo Molnar]

* Eran Mann <emann@mrv.com> wrote:

> On my machine, disabling CONFIG_LATENCY_TRACE causes the kernel to
> stop reporting preempt latencies. After
>
> # echo 1 > /proc/sys/kernel/preempt_max_latency
> 
> /proc/sys/kernel/preempt_max_latency always shows 1 no matter what
> load is on the machine. I´ve seen this behavior since the first time I
> tried to disable CONFIG_LATENCY_TRACE, around V0.7.31.something.

indeed - there was a thinko in trace_stop_sched_switched() that likely
caused this problem. Does the -32-8 patch (freshly uploaded) work better
for you?

	Ingo

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

[Eran Mann]

Ingo Molnar wrote:
> * Eran Mann <emann@mrv.com> wrote:
> 
> 
>>On my machine, disabling CONFIG_LATENCY_TRACE causes the kernel to
>>stop reporting preempt latencies. After
>>
>># echo 1 > /proc/sys/kernel/preempt_max_latency
>>
>>/proc/sys/kernel/preempt_max_latency always shows 1 no matter what
>>load is on the machine. I´ve seen this behavior since the first time I
>>tried to disable CONFIG_LATENCY_TRACE, around V0.7.31.something.
> 
> indeed - there was a thinko in trace_stop_sched_switched() that likely
> caused this problem. Does the -32-8 patch (freshly uploaded) work better
> for you?
> 
> 	Ingo

V0.7.32-9 works fine. Thanks.
	Eran.

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

[Gene Heskett]

On Tuesday 07 December 2004 10:37, Ingo Molnar wrote:
>* Eran Mann <emann@mrv.com> wrote:
>> On my machine, disabling CONFIG_LATENCY_TRACE causes the kernel to
>> stop reporting preempt latencies. After
>>
>> # echo 1 > /proc/sys/kernel/preempt_max_latency
>>
>> /proc/sys/kernel/preempt_max_latency always shows 1 no matter what
>> load is on the machine. I´ve seen this behavior since the first
>> time I tried to disable CONFIG_LATENCY_TRACE, around
>> V0.7.31.something.
>
>indeed - there was a thinko in trace_stop_sched_switched() that
> likely caused this problem. Does the -32-8 patch (freshly uploaded)
> work better for you?
>
> Ingo

I'd like to report a slight improvement in the reports from tvtime
while running 32-6 with full preemtion turned on, cfq scheduler:

------
Dec  7 13:29:39 coyote kernel: wow!  That was a 15 millisec bump
Dec  7 13:29:39 coyote kernel: `IRQ 8'[838] is being piggy.
need_resched=0, cpu=0
Dec  7 13:29:39 coyote kernel: Read missed before next interrupt
-----
Each second of the log contains about 27 of these, so its pretty
steady.  Picture looks pretty good though.

Although, that particular snip was taken from the log while I was
*not* on the same screen as tvtime.  Switching back it its screen
returned the slip times to the 22 millisecond area.  And on quiting,
this was output:
-----------------
Dec  7 13:29:47 coyote kernel: rtc latency histogram of {tvtime/4038,
7565 samples}:
Dec  7 13:29:47 coyote kernel: 3 401
Dec  7 13:29:47 coyote kernel: 4 3348
Dec  7 13:29:47 coyote kernel: 5 1104
Dec  7 13:29:47 coyote kernel: 6 435
Dec  7 13:29:47 coyote kernel: 7 294
Dec  7 13:29:47 coyote kernel: 8 246
Dec  7 13:29:47 coyote kernel: 9 236
Dec  7 13:29:47 coyote kernel: 10 241
Dec  7 13:29:47 coyote kernel: 11 301
Dec  7 13:29:47 coyote kernel: 12 232
Dec  7 13:29:47 coyote kernel: 13 146
Dec  7 13:29:47 coyote kernel: 14 52
Dec  7 13:29:47 coyote kernel: 15 9
Dec  7 13:29:47 coyote kernel: 16 4
Dec  7 13:29:47 coyote kernel: 17 2
Dec  7 13:29:47 coyote kernel: 19 1
Dec  7 13:29:47 coyote kernel: 20 1
Dec  7 13:29:47 coyote kernel: 23 1
Dec  7 13:29:47 coyote kernel: 24 1
Dec  7 13:29:47 coyote kernel: 4545 1
Dec  7 13:29:47 coyote kernel: 9999 509

So there not much real change after all. Heavy duty wishfull thinking
I guess.  How can I decode the above output into english?

-- 
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.

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

[Ingo Molnar]

* Gene Heskett <gene.heskett@verizon.net> wrote:

> I'd like to report a slight improvement in the reports from tvtime
> while running 32-6 with full preemtion turned on, cfq scheduler:
> 
> ------
> Dec  7 13:29:39 coyote kernel: wow!  That was a 15 millisec bump
> Dec  7 13:29:39 coyote kernel: `IRQ 8'[838] is being piggy.
> need_resched=0, cpu=0
> Dec  7 13:29:39 coyote kernel: Read missed before next interrupt
> -----
> Each second of the log contains about 27 of these, so its pretty
> steady.  Picture looks pretty good though.
>
> Although, that particular snip was taken from the log while I was
> *not* on the same screen as tvtime.  Switching back it its screen
> returned the slip times to the 22 millisecond area. [...]

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?

also, do this:

  chrt -f 90 -p `pidof 'IRQ 8'`
  chrt -f 91 -p `pidof 'IRQ 0'`

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? If yes then you might want to disable RTC_HISTOGRAM.

	Ingo

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

[Gene Heskett]

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.

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

[john cooper]

Gene Heskett wrote:

> ...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.

Interesting to read the above.  I found similar
repeatable behavior when I launched a "make -j"
build on an arbitrary kernel tree when running
-V0.7.32-2.  I originally suspected the OOM
behavior to differ (somehow) with the 32-2 patch
compared to vanilla 2.6.10-rc2-mm3, but that was
a red herring.

I did notice the OOM killer nailing procs such as
sendmail, portmap, syslogd, lpd, etc..  fairly
early on in the build.  Eventually the login sh
got nailed and getty was respawned by init to play
again.  In oom_kill.c:badness(), 0 uid procs
should be given a limited stay, unless you run a
sprawling test load as root as I had.  This puts
everything into the same badness()-space and sys
daemons are equally likely to get wacked.

-john


-- 
john.cooper@timesys.com

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

[Gene Heskett]

On Wednesday 08 December 2004 14:48, john cooper wrote:
>Gene Heskett wrote:
>> ...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.
>
>Interesting to read the above.  I found similar
>repeatable behavior when I launched a "make -j"
>build on an arbitrary kernel tree when running
>-V0.7.32-2.  I originally suspected the OOM
>behavior to differ (somehow) with the 32-2 patch
>compared to vanilla 2.6.10-rc2-mm3, but that was
>a red herring.

Or a reasonable facsimily...  This was during the boot cycle as it was
just finished with the listing of the cursory checking as its
mounting the devices, and then hung for an extended period of time
with a low level of disk activity, as if its doing a slow e2fsck with
the output being fed to /dev/null.  Thats the best way I could
describe it.

FWIW, when it did that the first time, one of the boots I tried was
to 2.6.10-rc2, which I knew for a fact was a good boot file. 
Whatever was causing it was still doing it, which was when I walked
away to let it sort its own personal box of rattlesnakes.  Once
booted, the system seemed none the worse for wear, so other than
advising that its happened here 4 times now over the last couple of
weeks, its otherwise a <shrug>.

>-john

-- 
Cheers John, 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.