Re: [patch] Real-Time Preemption, -RT-2.6.10-rc1-mm3-V0.7.23

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc1-mm3-V0.7.23

[Mark_H_Johnson]

>i have released the -V0.7.23 Real-Time Preemption patch, which can be
>downloaded from the usual place:
>
>    http://redhat.com/~mingo/realtime-preempt/

A few notes on results from running with this patch (well, actually -EA
that Ingo provided separately).

[1] Build problems, separately reported to Ingo with CONFIG_PREEMPT_RT
enabled on x86 and you have modules using kunmap_atomic. Fix by adding
kunmap_virt and kmap_to_page to the list of exports.

[2] The live lock that I was having seems to have been killed based
on an hour of testing (I could usually cause it in 5 minutes or less).

[3] I am not so sure that the latency tracing works. I do not get any
trace output, even if I set preempt_max_latency to zero. I also noticed
that /proc/sys/kernel/preempt_wakeup_timing was removed at .20 but
not sure if that was deliberate. As a result, I have no reports from
the kernel tracing.

[4] Application level latencies are OK but not great.
 X test - only 90% of CPU loops are within 100 usec of nominal value.
In previous RT kernels I got > 99% with 100 usec.
 top test - looks much nicer than X test, but still have up to 30%
overhead on CPU loop.
 network I/O tests - smoothest of all test results, very nice
 disk write - very noisy, bursts of long delays with only 82% within
100 usec and worst case has over 100% overhead (2.5 msec vs 1.16 nominal)
 disk copy - fewer bursts, but worst case is similar to disk write.
About 95% within 100 usec.
 disk read - relatively clean with a pair of modest bursts early in
the test and then settled out a little worse than the network tests.
99.9% of samples within 100 usec and max of 1.65 msec.

[5] concurrent ping of system had over 13% lost packets (1089 out
of 10723 - plus I let this run after the tests had completed). The
2.4 RT kernel I use has no lost packets.

[6] I did a separate run of a script Ingo suggested that samples
the kernel profile data. It shows basically no CPU time for the
events/0 and events/1 tasks. I took 11 samples in about 1/2 hour
of testing but nothing seems to jump out of the data.

--Mark H Johnson
  <mailto:Mark_H_Johnson@raytheon.com>

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc1-mm3-V0.7.23

[Ingo Molnar]

* Mark_H_Johnson@raytheon.com <Mark_H_Johnson@raytheon.com> wrote:

> [3] I am not so sure that the latency tracing works. I do not get any
> trace output, even if I set preempt_max_latency to zero.

What is the value of preempt_thresh? If it's set then it overrides the
preempt_max_latency value. (previously the bogus timing values probably
triggered even a relatively high preempt-threshold, but now with a
correct tracer it's not possible anymore.)

> [...] I also noticed that /proc/sys/kernel/preempt_wakeup_timing was
> removed at .20 but not sure if that was deliberate. [...]

yeah, this was deliberate - it's a side-effect of separating it from the
other timing options.

	Ingo

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc1-mm3-V0.7.23

[Ingo Molnar]

* Mark_H_Johnson@raytheon.com <Mark_H_Johnson@raytheon.com> wrote:

> >i have released the -V0.7.23 Real-Time Preemption patch, which can be
> >downloaded from the usual place:
> >
> >    http://redhat.com/~mingo/realtime-preempt/
> 
> A few notes on results from running with this patch (well, actually
> -EA that Ingo provided separately).
> 
> [1] Build problems, separately reported to Ingo with CONFIG_PREEMPT_RT
> enabled on x86 and you have modules using kunmap_atomic. Fix by adding
> kunmap_virt and kmap_to_page to the list of exports.

these should be fixed in -V0.7.24 which i uploaded shortly after
-V0.7.23, based on your reports. In any case, the export problems
trigger with CONFIG_HIGHMEM and the affected subsystems compiled as
modules.

> [2] The live lock that I was having seems to have been killed based on
> an hour of testing (I could usually cause it in 5 minutes or less).

great!

> [4] Application level latencies are OK but not great.
>  X test - only 90% of CPU loops are within 100 usec of nominal value.
> In previous RT kernels I got > 99% with 100 usec.

this might be a side-effect of the chrt-ing of events/[0|1] and/or
ksoftirqd (which we did to debug the 'freeze' problems) - are those
still chrt-ed? Please review and double-check all SCHED_FIFO tasks in
the system and keep only those that are absolutely necessary for
latencytest's operation [i.e. the soundcard IRQ and latencytest itself]
- everything else should be SCHED_OTHER. Do latencies get any better if
you do this?

	Ingo

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc1-mm3-V0.7.23

[Mark_H_Johnson]

>you have to build another kernel for them. irqs-off and preempt-off
>timing can be mixed freely (and both can be enabled in the same kernel),
>but wakeup timing deserves its own .config space and since it's not
>mixable with the other two methods i didnt see much point in enabling
>all 3 at once with strange dependencies between them. Is this a big
>issue? Normally i think the wakeup timing is more than enough to get a
>feel of latencies, and if something specific is suspected the other ones
>can be turned on.

Just that it takes an hour or so to rebuild the kernel plus the
disk storage to keep two kernels instead of one.

The wakeup latencies I am seeing are all quite small, but the overhead
I am seeing at the application level have been quite high. Only 40 wakeup
latencies > 50 usec in a half hour of testing. I guess I'll build a
.24 without wakeup timing to see what kind of problems I'm having.
I can send you the wakeup timing traces if you are interested but
they are all really short (< 100 usec) or appear to indicate a hardware
contention problem (one step at 100 usec or so).

 --Mark

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc1-mm3-V0.7.23

[Ingo Molnar]

* Mark_H_Johnson@raytheon.com <Mark_H_Johnson@raytheon.com> wrote:

> >you have to build another kernel for them. irqs-off and preempt-off
> >timing can be mixed freely (and both can be enabled in the same kernel),
> >but wakeup timing deserves its own .config space and since it's not
> >mixable with the other two methods i didnt see much point in enabling
> >all 3 at once with strange dependencies between them. Is this a big
> >issue? Normally i think the wakeup timing is more than enough to get a
> >feel of latencies, and if something specific is suspected the other ones
> >can be turned on.
> 
> Just that it takes an hour or so to rebuild the kernel plus the disk
> storage to keep two kernels instead of one.

ok, i added runtime configurability of the 3 options back, so that you
can build all 3 in and switch between them via the preempt_wakeup_timing
flag. Will be in the next release.

	Ingo

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc1-mm3-V0.7.23

[Mark_H_Johnson]

>I may do a variant on this anyway. I think its important to see if
>the symptom (> 100 usec CPU delay) is really:
>- lots of short delays
>OR
>- relatively few long delays
>and I have an idea of how to code that up and add to latencytrace.

A follow up on this message. My first test completed with the following
results. The new code indicates:

X     - Min delay was     0. Max delay was     3. Ave delay was  0.015295.
top   - Min delay was     0. Max delay was    23. Ave delay was  0.025659.
netO  - Min delay was     0. Max delay was    31. Ave delay was  1.169024.
netI  - Min delay was     1. Max delay was    35. Ave delay was  1.182864.
diskW - Min delay was     0. Max delay was    18. Ave delay was  1.166944.
diskC - Min delay was     0. Max delay was    18. Ave delay was  1.080036.
diskR - Min delay was     0. Max delay was     7. Ave delay was  0.803804.

A "delay" was counted if 1000 iterations of the CPU inner loop took
longer than 10 usec. For comparison, I moved this code to my 2.4 system
and got the following results:

X     - Min delay was     0. Max delay was    17. Ave delay was  1.277730.
top   - Min delay was     0. Max delay was    12. Ave delay was  1.452692.
netO  - Min delay was     0. Max delay was    12. Ave delay was  1.633742.
netI  - Min delay was     0. Max delay was    12. Ave delay was  1.626565.
diskW - Min delay was     0. Max delay was    14. Ave delay was  1.566188.
diskC - Min delay was     0. Max delay was    12. Ave delay was  1.701542.
diskR - Min delay was     0. Max delay was    12. Ave delay was  1.650909.

Looks pretty comparable at this level. The 2.4 results appear to be more
consistent.

Grr. The new code does have an impact on the application measurements
under 2.4. It appears the TSC accesses are being delayed while the disk
is active. The within 100 usec rate was only 77% (was 90%) but the peak
is still pretty close (2.60 vs. 2.38 msec).

I am also not sure this is the "right" measurement either. I probably
need to count the delays or divide the overall loop time by the number
of delays to see if that is a more meaningful value.

  --Mark

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc1-mm3-V0.7.23

[Mark_H_Johnson]

>> [...] I also noticed that /proc/sys/kernel/preempt_wakeup_timing was
>> removed at .20 but not sure if that was deliberate. [...]
>
>yeah, this was deliberate - it's a side-effect of separating it from the
>other timing options.

OK. So maybe I didn't understand what you said previously. Now, if I build
to get maximum-latency wakeup values, I can't get the IRQ off or
preempt off timing and traces? If that's not true, how do I switch
between the different sampling methods?

--Mark H Johnson
  <mailto:Mark_H_Johnson@raytheon.com>

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc1-mm3-V0.7.23

[Ingo Molnar]

* Mark_H_Johnson@raytheon.com <Mark_H_Johnson@raytheon.com> wrote:

> OK. So maybe I didn't understand what you said previously. Now, if I
> build to get maximum-latency wakeup values, I can't get the IRQ off or
> preempt off timing and traces? If that's not true, how do I switch
> between the different sampling methods?

you have to build another kernel for them. irqs-off and preempt-off
timing can be mixed freely (and both can be enabled in the same kernel),
but wakeup timing deserves its own .config space and since it's not
mixable with the other two methods i didnt see much point in enabling
all 3 at once with strange dependencies between them. Is this a big
issue? Normally i think the wakeup timing is more than enough to get a
feel of latencies, and if something specific is suspected the other ones
can be turned on.

	Ingo

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc1-mm3-V0.7.23

[Mark_H_Johnson]

>* Mark_H_Johnson@raytheon.com <Mark_H_Johnson@raytheon.com> wrote:
>
>> >- everything else should be SCHED_OTHER. Do latencies get any better if
>> >you do this?
>
>> I can, but that is not necessarily an "apples to apples" comparison.
>
>the goal now would be to simplify the test and work down the issues in
>isolation, instead of looking at a complex setup of mixed workloads and
>just seeing 'it sucks' without knowing which component causes what.

However based on the results of the last several weeks, it is apparent
to me that the simple tests are finding only a subset of the problems.
The stressful series of tests is finding a number of symptoms much
sooner and more repeatable than those simple tests.

I was thinking about this problem this morning and was wondering if
we could do something like an "end trigger" to help determine the cause
of some of these pauses. Something like:
 - start to fill / refresh the trace buffer (already doing this?)
 - run RT CPU loop & sample TSC every 100 iterations or so
 - if delta T exceeds 100 usec (or so), then set "end trigger" and
dump the data from /proc/latency_trace.
Repeat with some rate limit so we don't get too much data.
I can still run the stressful test cases to cause the situations and
get the "just in time" data for the analysis. Perhaps a variant of
the interface you provided before on tracing a specific path.

I may do a variant on this anyway. I think its important to see if
the symptom (> 100 usec CPU delay) is really:
 - lots of short delays
OR
 - relatively few long delays
and I have an idea of how to code that up and add to latencytrace.

--Mark H Johnson
  <mailto:Mark_H_Johnson@raytheon.com>

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc1-mm3-V0.7.23

[Ingo Molnar]

* Mark_H_Johnson@raytheon.com <Mark_H_Johnson@raytheon.com> wrote:

> I was thinking about this problem this morning and was wondering if
> we could do something like an "end trigger" to help determine the cause
> of some of these pauses. Something like:
>  - start to fill / refresh the trace buffer (already doing this?)
>  - run RT CPU loop & sample TSC every 100 iterations or so
>  - if delta T exceeds 100 usec (or so), then set "end trigger" and
> dump the data from /proc/latency_trace.
> Repeat with some rate limit so we don't get too much data.

we had most of this in the tracer already, just obscured a bit.

In the current tree i've separated all the functionality into the
following flags: trace_enabled, trace_user_triggered, trace_freerunning.
When user_triggered is enabled all the other timing related tracing
activities stops (wakeup & critical/irq timing), and userspace is the
master of when tracing starts and stops. The way to turn the tracer
on/off is still the gettimeofday API hack:

	gettimeofday(0,1);
	gettimeofday(0,0);

i enhanced this user-defined tracing with a timing mechanism: the kernel
measures the latency between on and off and does the usual max-latency
or threshold tracking and saves the latency trace into
/proc/latency_trace only if the latency condition triggers. So userspace 
only has to add the start/stop hooks and the kernel will deal with the 
rest.

the freerunning flag can be used to generate traces where there's no
natural 'start' event, only some well-defined "we have a latency
problem" point. The application can start tracing at startup (or you can
start it via a different app), and it's enough to stop tracing when
there's a problem - the last ~4000 trace entries will be copied into
/proc/latency_trace. (the timing mechanism is still present in this mode
as well.)

(Freerunning mode can also be used if for some reason the delays are too
long to be fully traced and if the 'interesting' stuff is at the end of
the delay.)

This stuff will show up in the next release, later today. It should
cover the needs that your tests have at the moment, correct? 

	Ingo

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc1-mm3-V0.7.23

[Mark_H_Johnson]

>* Mark_H_Johnson@raytheon.com <Mark_H_Johnson@raytheon.com> wrote:
>
>> [3] I am not so sure that the latency tracing works. I do not get any
>> trace output, even if I set preempt_max_latency to zero.
>
>What is the value of preempt_thresh?
It was zero at boot time. Now that I check, set it somewhere to 200.
Setting it back to zero, I now see that I have some extremely
small reports, max so far is 63 usec. Will run my big test again
to see what turns up.

  --Mark

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc1-mm3-V0.7.23

[Mark_H_Johnson]

>> [4] Application level latencies are OK but not great.
>>  X test - only 90% of CPU loops are within 100 usec of nominal value.
>> In previous RT kernels I got > 99% with 100 usec.
>
>this might be a side-effect of the chrt-ing of events/[0|1] and/or
>ksoftirqd (which we did to debug the 'freeze' problems) - are those
>still chrt-ed?
For reference:
# ps -eo pid,pri,rtprio,cmd | grep '\['
    1  23      - init [5]
    2 139     99 [migration/0]
    3  34      - [ksoftirqd/0]
    4  34      - [desched/0]
    5 139     99 [migration/1]
    6  34      - [ksoftirqd/1]
    7  34      - [desched/1]
    8  41      1 [events/0]
    9  41      1 [events/1]
   10  34      - [khelper]
   15  32      - [kthread]
   27  34      - [kblockd/0]
   28  34      - [kblockd/1]
   36  24      - [khubd]
  103  23      - [kswapd0]
  104  32      - [aio/0]
  105  33      - [aio/1]
  180 139     99 [IRQ 8]
  195  14      - [kseriod]
  201 139     99 [IRQ 12]
  237 139     99 [IRQ 14]
  239 139     99 [IRQ 15]
  278 139     99 [IRQ 1]
  310  24      - [kirqd]
  313 139     99 [IRQ 4]
  320  24      - [kjournald]
  605 139     99 [IRQ 10]
 1206  24      - [kjournald]
 1207  24      - [kjournald]
 1309 139     99 [IRQ 3]
 1323  31      - [IRQ 7]
 1494 139     99 [IRQ 6]
 1748 139     99 [IRQ 11]
14131  23      - [pdflush]
14242  24      - [pdflush]
17337  21      - grep \[

>Please review and double-check all SCHED_FIFO tasks in
>the system and keep only those that are absolutely necessary for
>latencytest's operation [i.e. the soundcard IRQ and latencytest itself]
>- everything else should be SCHED_OTHER. Do latencies get any better if
>you do this?
I can, but that is not necessarily an "apples to apples" comparison.
When I compare with 2.4 preempt + low latency kernels, the X stress
test had > 99% of the samples within 100 usec of the nominal value.
Don't forget - on a 2.4 kernel, the IRQ's are all unthreaded. On
the 2.4 kernel, heavy disk I/O is where I get the worst behavior
and even then, I get > 90% of samples within 100 usec.

I still maintain that a 2.6 RT kernel has to do as well or better
than a 2.4 RT kernel (or else, why would I step up??).

  --Mark

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc1-mm3-V0.7.23

[Ingo Molnar]

* Mark_H_Johnson@raytheon.com <Mark_H_Johnson@raytheon.com> wrote:

> >- everything else should be SCHED_OTHER. Do latencies get any better if
> >you do this?

> I can, but that is not necessarily an "apples to apples" comparison.

the goal now would be to simplify the test and work down the issues in
isolation, instead of looking at a complex setup of mixed workloads and
just seeing 'it sucks' without knowing which component causes what. 
That's why e.g. rtc_wakeup is so useful - it's simple and dependable and
still it showed a good deal of problems and helped debug/fix them.

	Ingo

[patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U9

[Ingo Molnar]

i have released the -U9 Real-Time Preemption patch, which can be
downloaded from:

  http://redhat.com/~mingo/realtime-preempt/

this too is a fixes-only release. It includes more driver fixes and
improvements from Thomas Gleixner.

Changes since -U8.1:

 - USB semaphore->completion conversion from Thomas Gleixner

 - netconsole fixes from Michal Schmidt

 - fbcon fixes

 - added counted semaphores, this is now used by firewire, XFS and ACPI. 
   This could fix the firewire breakage - but testing would be welcome.

 - PREEMPT_ACTIVE irqs-enabled critical path removal.

 - fixed irqs-off raw spinlock primitives on UP: they enabled irqs 
   before enabling preemption, creating a window for an interrupt to
   slip in and increase the critical path.

 - made the deadlock detector not crash the current process - it will
   just hang. This produces far nicer log output while still not
   endangering stability. Also, fixed a bug in the detector that happens 
   if the trace buffer overflows.

 - made the atomic-counter-underflow detector non-fatal as well, for the
   same reasons.

to create a -U9 tree from scratch, the patching order is:

   http://kernel.org/pub/linux/kernel/v2.6/linux-2.6.8.tar.bz2
 + http://kernel.org/pub/linux/kernel/v2.6/testing/patch-2.6.9-rc4.bz2
 + http://kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.9-rc4/2.6.9-rc4-mm1/2.6.9-rc4-mm1.bz2
 + http://redhat.com/~mingo/realtime-preempt/realtime-preempt-2.6.9-rc4-mm1-U9

	Ingo

[patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U9.3

[Ingo Molnar]

i have released the -U9.3 Real-Time Preemption patch, which can be
downloaded from:

  http://redhat.com/~mingo/realtime-preempt/

this too is a fixes-only release.

Changes since -U9.2:

 - tons more driver/mutex/completion conversion done by Thomas Gleixner 
   for: ppp, ipmi, parport/ieeee1284, scsi, hotplug, and more.

 - iptables/netfilter deadlock fix, this should fix the bug reported by 
   Michal Schmidt.

 - .config housekeeping: disallow the turning off of PREEMPT_BKL when 
   PREEMPT_REALTIME is on. This solves the build error reported by 
   Matthew L Foster.

 - print the full stacktrace of the current task in the deadlock 
   detector and dont use show_stack(). This explains some of the weird
   partial stackdumps reported.

 - some more minor updates to the case when the deadlock detector turns
   itself off due to reaching the limit. We kept the spinlock locked.

to create a -U9.3 tree from scratch, the patching order is:

   http://kernel.org/pub/linux/kernel/v2.6/linux-2.6.8.tar.bz2
 + http://kernel.org/pub/linux/kernel/v2.6/testing/patch-2.6.9-rc4.bz2
 + http://kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.9-rc4/2.6.9-rc4-mm1/2.6.9-rc4-mm1.bz2
 + http://redhat.com/~mingo/realtime-preempt/realtime-preempt-2.6.9-rc4-mm1-U9.3

	Ingo

[patch] Real-Time Preemption, -RT-2.6.9-mm1-U10

[Ingo Molnar]

i have released the -U10 Real-Time Preemption patch, which can be
downloaded from:
 
  http://redhat.com/~mingo/realtime-preempt/

this is purely a rebasing of -U9.3 to 2.6.9-mm1.

to create a -U10 tree from scratch, the patching order is:

   http://kernel.org/pub/linux/kernel/v2.6/linux-2.6.9.tar.bz2
 + http://kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.9/2.6.9-mm1/2.6.9-mm1.bz2
 + http://redhat.com/~mingo/realtime-preempt/realtime-preempt-2.6.9-mm1-U10

	Ingo

[patch] Real-Time Preemption, -RT-2.6.9-mm1-U10.2

[Ingo Molnar]

i have released the -U10.2 Real-Time Preemption patch, which can be
downloaded from:

  http://redhat.com/~mingo/realtime-preempt/
 
this is a fixes-only release.

Changes since -U10:

 - fixed a big bug present ever since: the BKL got dropped when a
   spinlock-mutex was acquired and it scheduled away. This reduced the
   locking efficiency of the BKL. A number of outstanding problems could
   be affected, in particular this should fix the tty locking breakage
   reported by Alexander Batyrshin and Adam Heath. UP and SMP systems 
   are affected too, with SMP systems having a higher chance to trigger
   this condition.

 - tulip.c breakage fix from Thomas Gleixner

 - tg3 and 3c59x fixes.

 - made the hardirq threads SCHED_FIFO by default. They get priorities 
   between 25 and 50, depending on the irq #. (this is pretty random but 
   i found no better scheme.) Made the softirq thread SCHED_FIFO by 
   default as well, albeit this probably will have to change. These 
   changes should make it easier to debug a hung system.

to create a -U10.2 tree from scratch, the patching order is:

   http://kernel.org/pub/linux/kernel/v2.6/linux-2.6.9.tar.bz2
 + http://kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.9/2.6.9-mm1/2.6.9-mm1.bz2
 + http://redhat.com/~mingo/realtime-preempt/realtime-preempt-2.6.9-mm1-U10.2

	Ingo

[patch] Real-Time Preemption, -RT-2.6.9-mm1-V0

[Ingo Molnar]

i have released the -V0 Real-Time Preemption patch, which can be
downloaded from:

  http://redhat.com/~mingo/realtime-preempt/

NOTE: this is a highly experimental release, a more experimental one
than -U10.3.

the big change in the '-V' series of the patchset is that i have
converted the last couple of non-preemptible kernel subsystems to
fully-preemptible mutex-based locking. These subsystems are:

 - the SLAB allocator
 - the buddy page allocator
 - waitqueue handling
 - soft-timer subsystem
 - security/selinux
 - workqueues
 - the random driver

this is probably the last 'big leap forward' in terms of the scope of
the patch. (having reached the ultimate scope: it now encompasses
everything ;)

But as an inevitable result of this big leap it will likely break in a
couple of places. Unfortunately these subsystems were largely
interdependent so it's an all-or-nothing step with not much middle
ground between the locking done in -U10.3 and in -V0.

another result of these changes is that the number of critical sections
in -V0 is roughly 30% of that in -U10.3. Now we only have the scheduler
and very lowlevel IRQ-hardware locks as raw spinlocks. (plus the lone
holdout vga_lock - which i will probably make a mutex too in the near
future)

[ NOTE: there's one known bug in this release: selinux on one of my
testsystems broke, it hangs during bootup. With CONFIG_SECURITY disabled
it works fine. I'm working on the fix. So please keep CONFIG_SECURITY
disabled for the time being. ]

other changes in -V0:

 - build fixes: more driver fixes from Thomas Gleixner

 - crash fix: fixed a bug found by Thomas Gleixner: rwsem runtime
   initialization was racy.

 - deadlock fix: fixed lockup bug caused by __schedule clearing
   PREEMPT_ACTIVE. The need_resched loop is now outside of __schedule(). 
   This might solve lockups/slowdowns reported by some people.

 - latency fix: made keventd SCHED_FIFO - this could fix the mouse
   related delays reported by a number of people.

 - latency fix: fixed SMP lock-break mechanism of mutexes.

 - usability feature: hard-interrupts get decreasing SCHED_FIFO priority
   starting at prio 49 and stopping at prio 25. This should give a good
   default.

 - debug feature: implemented SysRq-D to show the list of tasks with
   locks blocked on, if RW_SEM_DEADLOCK_DETECTION is enabled.

to create a -V0 tree from scratch, the patching order is:

   http://kernel.org/pub/linux/kernel/v2.6/linux-2.6.9.tar.bz2
 + http://kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.9/2.6.9-mm1/2.6.9-mm1.bz2
 + http://redhat.com/~mingo/realtime-preempt/realtime-preempt-2.6.9-mm1-V0

	Ingo

[patch] Real-Time Preemption, -RT-2.6.9-mm1-V0.3

[Ingo Molnar]

i have released the -V0.3 Real-Time Preemption patch, which can be
downloaded from:

	http://redhat.com/~mingo/realtime-preempt/

this is a fixes-only release, but still experimental.

this release should fix a number of bugs that were reported for the V0
series: the futex.c assert, the lockups and the 'slowdown problem'.

The slowdown problem was an architectural issue that surfaced sometime
around U10 and increased in prominence as the the number of mutexes
increased and the number of spinlocks decreased. The futex.c assert was
related to this architectural issue as well, and most of the lockups
reported were i believe livelocks caused by the same issue. Also, the
scheduler path had an easy-to-trigger deadlock that often just silently
locked up.

some of the networking lockups might be related to this issue too, but i
think PREEMPT_REALTIME still has separate lock odering issues within the
networking code. Please re-report any deadlock-tracer asserts that you
might encounter.

Changes since -V0.2:

 - HEAP_SIZE fix from Karsten Wiese

 - fix hdparm-triggered debugging message reported by Mark H Johnson

 - fixed mutex related preemption to not impact the task state, just 
   like a normal spinlock does. This necessiated the introduction of
   TASK_RUNNING_MUTEX handling and related kernel infrastructure. This 
   framework avoids spurious wakeups done by mutex handling by isolating
   the state changes done by normal wakeups vs. the state changes caused
   by the mutex code.

 - added per-CPU deschedule threads. This fixes a deadlock scenario and
   it is also much faster than keventd.

 - fix debugging message upon console unblanking

to create a -V0.3 tree from scratch, the patching order is:

   http://kernel.org/pub/linux/kernel/v2.6/linux-2.6.9.tar.bz2
 + http://kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.9/2.6.9-mm1/2.6.9-mm1.bz2
 + http://redhat.com/~mingo/realtime-preempt/realtime-preempt-2.6.9-mm1-V0.3

	Ingo

[patch] Real-Time Preemption, -RT-2.6.10-rc1-mm2-V0.7.1

[Ingo Molnar]

i have released the -V0.7.1 Real-Time Preemption patch, which can be
downloaded from:

    http://redhat.com/~mingo/realtime-preempt/

this release is mainly a merge of -V0.6.9 to 2.6.10-rc2-mm2.

I havent done a proper changelog for a couple of days so here is a list
of bigger changes since -V0.4:

 - implemented a first version of the priority inheritance handling and
   priority inversion avoidance logic. This feature, after some initial
   stability problems, solved the jackd and rtc_wakeup latencies that
   were introduced by the ultra-finegrained locking in the -V series.

   (the -T/U series had a coarser locking scheme triggered much lower
   levels of priority inversion scenarios. The locking in the -V series
   was clearly the tipping point.)

   The new PI code covers all synchronization objects in Linux (on
   PREEMPT_REALTIME): spinlocks, rwlocks, semaphores and rwsems. 
   Feedback on the design of this code would be welcome, and patches as
   well, if you have a better scheme. The code is pretty modular so feel 
   free to experiment with alternative schemes.

 - completely reworked the debugging framework. All lock types
   (spinlocks, rwlocks, semaphores and rwsems) are now tracked, both
   their symbolic name and their place of acquire are traced and printed
   out upon detection of a deadlock. More and better information is
   printed upon a deadlock. Got rid of the 'semaphore owners array' in
   debugging mode, this reduces the footprint of semaphores quite
   significantly and speeds up deadlock detection.

 - got rid of the separate 'counted semaphores' implementation, it was
   too intrusive. Made the core 'generic semaphores' implementation
   compatible with vanilla Linux counted semaphore semantics. This also
   enabled the unrolling of the completion-handling cleanups which,
   while being very nice, were getting intrusive as well.

 - countless build and driver related reports/fixes from lots of people

 - more latency breaks in the remaining critical sections. A
   particularly important one was the irqs-off latency bugfix from
   Thomas Gleixner.

 - sped up the i8259 PIC and the PIT timer hardirq handling routines -
   these are now in the path of the longest latency.

 - cleaned up IRQ and signal preemption - there were missed
   check-rescheds and possibilities for IRQ recursion.

 - made ALSA's ioctl()s not use the BKL - this fixes more jackd
   latencies.

to create a -V0.7.1 tree from scratch, the patching order is:

   http://kernel.org/pub/linux/kernel/v2.6/linux-2.6.9.tar.bz2
   http://kernel.org/pub/linux/kernel/v2.6/testing/patch-2.6.10-rc1.bz2
   http://kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.10-rc1/2.6.10-rc1-mm2/2.6.10-rc1-mm2.bz2
   http://redhat.com/~mingo/realtime-preempt/realtime-preempt-2.6.10-rc1-mm2-V0.7.1

	Ingo

[patch] Real-Time Preemption, -RT-2.6.10-rc1-mm3-V0.7.18

[Ingo Molnar]

i have released the -V0.7.18 Real-Time Preemption patch, which can be
downloaded from:

   http://redhat.com/~mingo/realtime-preempt/

this release includes fixes and cleanups.

Changes between -V0.7.12 and -V0.7.18:

 - merged to 2.6.10-rc1-mm3

 - fixed the e1000 xmit warnings reported by Amit Shah. Same fix for tg3
   too.

 - added irq-latency fix from Thomas Gleixner: re-enable interrupts
   before adding timings to the entropy pool.

 - fixed excessive ksoftirqd overhead during outgoing TCP traffic. 
   ksoftirqd kept getting re-woken while it had no way to progress.

 - added upstream fix from Andi Kleen for the vmalloc bug causing module
   load problems/crashes. Added ipc/shm fix too.

Changes between -V0.7.1 and -V0.7.12:

 - big source level cleanups: completely rearranged the mutex type
   definitions and source files, to make it reflect the code. Made
   all locking objects based on a new, central lock type: struct
   rt_mutex. This type is never exposed externally, it is internal to
   the RT code. Unified all the RT locking code in kernel/rt.c, this 
   also simplified and sped things up. Undid collateral damage to the
   generic rwsem code - it is now untouched and independent of the RT
   code.

 - rearranged the way spinlocks interact with the RT code and cleaned 
   up the RT spinlock definitions. Found and fixed a bug in the process:
   rwlocks were dropping the BKL upon contention.

 - small x86 speedup: call __schedule not preempt_schedule_irq from
   work_resched.

 - ported PREEMPT_RT to x64. This resulted in the generalization of some
   of the x86 changes.

 - hopefully fixed fbcon kernel logging

 - hacked reiser4 to make it work on PREEMPT_REALTIME.

 - dropped the swap-layout-improvements patch. While it was working fine 
   it's not necessary for latencies anymore under the PREEMPT_REALTIME
   approach, and the swap-patch was getting intrusive.

 - fixed preemption-bug in drain_cpu_caches() on SMP [bug introduced by
   PREEMPT_REALTIME]

 - new attempt at getting rid of the networking related deadlocks

 - selinux deadlock fix and RCU-code conversion to RT semantics

to create a -V0.7.18 tree from scratch, the patching order is:

   http://kernel.org/pub/linux/kernel/v2.6/linux-2.6.9.tar.bz2
   http://kernel.org/pub/linux/kernel/v2.6/testing/patch-2.6.10-rc1.bz2
   http://kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.10-rc1/2.6.10-rc1-mm3/2.6.10-rc1-mm3.bz2
   http://redhat.com/~mingo/realtime-preempt/realtime-preempt-2.6.10-rc1-mm3-V0.7.18

	Ingo

[patch] Real-Time Preemption, -RT-2.6.10-rc1-mm3-V0.7.19

[Ingo Molnar]

i have released the -V0.7.19 Real-Time Preemption patch, which can be
downloaded from the usual place:

   http://redhat.com/~mingo/realtime-preempt/

this release includes fixes only.

Changes since -V0.7.18:

 - fixed a merge bug introduced in -V0.7.18, breaking bit-spinlocks used
   by ext3's journalling code. This could/should fix the kjournald crash
   reported by Adam Heath, Gunther Persoons and Eran Mann. Bug triggered
   on !SMP kernels only.

 - added upstream patch to fix a crash in bttv/btcx_riscmem_free(), 
   reported by Shane Shrybman.

 - made modlist_lock raw again - this could fix the /proc/acpi related
   asserts reported by Karsten Wiese.

 - fixed -RT locking bug in zap_completion_queue(), this could fix the 
   asserts reported by Shane Shrybman and others.

to create a -V0.7.19 tree from scratch, the patching order is:

   http://kernel.org/pub/linux/kernel/v2.6/linux-2.6.9.tar.bz2
   http://kernel.org/pub/linux/kernel/v2.6/testing/patch-2.6.10-rc1.bz2
   http://kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.10-rc1/2.6.10-rc1-mm3/2.6.10-rc1-mm3.bz2
   http://redhat.com/~mingo/realtime-preempt/realtime-preempt-2.6.10-rc1-mm3-V0.7.19

	Ingo

[patch] Real-Time Preemption, -RT-2.6.10-rc1-mm3-V0.7.21

[Ingo Molnar]

i have released the -V0.7.21 Real-Time Preemption patch, which can be
downloaded from the usual place:

   http://redhat.com/~mingo/realtime-preempt/

this release includes fixes and debugging-improvements.

Changes since -V0.7.20:

 - reverted the modlist_lock change - it caused more problems than it 
   solved.

 - implemented irqs-off critical section timing/tracing, inspired by the 
   positive results Thomas Gleixner got with a different kind of cli/sti
   tracer. To activate it, enable CONFIG_CRITICAL_TIMING and 
   CONFIG_CRITICAL_IRQSOFF_TIMING and cli/sti latencies will be reported
   'integrated' into the preempt on/off latencies.

 - sped up tracing in a number of ways. Performance of the tracer slowly
   eroded in the past week or two, it needed alignment and size fixes ,
   inlining/branch-prediction updates and i got rid of unnecessary code.
   The max latency is now traced in cycles - this got rid of an
   expensive 64-bit division in the fastpath. (the /proc/sys tunables
   are still in usecs so userspace should not notice anything.) It's
   still not cheap but roughly 5 times faster than -V0.7.20's tracer, on
   a fast desktop box.

 - renamed CONFIG_PREEMPT_REALTIME to CONFIG_PREEMPT_RT - it's shorter.

 - renamed CONFIG_PREEMPT_TIMING to CONFIG_CRITICAL_TIMING and 
   introduced CONFIG_CRITICAL_IRQSOFF_TIMING to enable cli/sti timing.

to create a -V0.7.21 tree from scratch, the patching order is:

   http://kernel.org/pub/linux/kernel/v2.6/linux-2.6.9.tar.bz2
   http://kernel.org/pub/linux/kernel/v2.6/testing/patch-2.6.10-rc1.bz2
   http://kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.10-rc1/2.6.10-rc1-mm3/2.6.10-rc1-mm3.bz2
   http://redhat.com/~mingo/realtime-preempt/realtime-preempt-2.6.10-rc1-mm3-V0.7.21

	Ingo

[patch] Real-Time Preemption, -RT-2.6.10-rc1-mm3-V0.7.23

[Ingo Molnar]

i have released the -V0.7.23 Real-Time Preemption patch, which can be
downloaded from the usual place:

    http://redhat.com/~mingo/realtime-preempt/

this release includes fixes, development/debugging improvements and
latency improvements and other speedups.

the biggest change is the reworked timing/tracing framework. Wakeup
timing became a compile-time thing and can be selected independently of
the preemption mode - i.e. it can now be used on near-vanilla !PREEMPT
kernels too, providing good wakeup-latency comparison of the various
preemption models.

irqs-off and preempt-off critical section timing/tracing can be selected
if wakeup timing is disabled, the two options can be selected separately
or together as well.

another improvement is that wakeup-timing now works correctly on SMP too
- the tracer 'follows' the highest-priority task in the system as it
gets bounced between CPUs and always traces the CPU where the task is
pending.

other changes since -V0.7.22:

 - semaphore livelock fix: feedback from Mark H. Johnson pinpointed a 
   bug in the down_trylock() semaphore code: if preempted in the wrong
   moment a lower-prio task could cause a higher-prio task to livelock
   indefinitely. This fix could solve the 'keventd looping' problem 
   reported by Mark.

   the fix is to make the down_trylock() code a bit simpler, but this
   also introduces the potential for down_trylock() to get 'spurious' 
   locking-rejects. Hopefully this wont be a big problem - we dont 
   really guarantee that down_trylock() succeeds - but code using higher
   semaphore counts to track resources could be negatively impacted by
   this. We'll see.

 - console assert fix: implemented a different type of fbcon
   RT-preemption handling variant, this could solve the assert reported
   by Amit Shah.

 - debugging improvement: implemented a sequence counter for max latency 
   traces. This has the advantage of solving the 'slow console on SMP
   problem': the latency-timing code used to get confused by another CPU 
   printing a timing message to a slow console and thus delaying that 
   other CPU. Now any latency that gets generated while a maximum is 
   printed is skipped.

 - further shrunk the non-debug size of struct rt_mutex by moving the 
   save_state logic into the debug paths - size is now 4 machine-words.

 - fixed CONFIG_HIGHMEM latencies: all atomic-kmap APIs are now wrapped 
   seemlessly and in a preemptible way.

 - implemented an IO-APIC register cache to speed up the IRQ-redirection
   latency hotpath. Also, made the POST flush a bit faster.

 - disable KGDB if PREEMPT_RT - it's broken for now.

 - move some runtime checks to under DEBUG_PREEMPT - this speeds up 
   CRITICAL_PREEMPT_TIMING.

to create a -V0.7.23 tree from scratch, the patching order is:

   http://kernel.org/pub/linux/kernel/v2.6/linux-2.6.9.tar.bz2
   http://kernel.org/pub/linux/kernel/v2.6/testing/patch-2.6.10-rc1.bz2
   http://kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.10-rc1/2.6.10-rc1-mm3/2.6.10-rc1-mm3.bz2
   http://redhat.com/~mingo/realtime-preempt/realtime-preempt-2.6.10-rc1-mm3-V0.7.23

	Ingo

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc1-mm3-V0.7.23

[Karsten Wiese]

Am Dienstag 09 November 2004 17:05 schrieb Ingo Molnar:
> 
> i have released the -V0.7.23 Real-Time Preemption patch, which can be
> downloaded from the usual place:
> 
>     http://redhat.com/~mingo/realtime-preempt/

Hi

On SMP/HT/P4 I get:
 BUG: lock held at task exit time!

This was captured via netconsole:
<NETCONSOLELOG>
apm: disabled - APM is not SMP safe.
sh:5429 BUG: lock held at task exit time!
 [c03af1c4] {kernel_sem.lock}
.. held by:                sh/ 5429 [f4d2c420, 117]
... acquired at:  __reacquire_kernel_lock+0x2e/0x60
sh/5429: BUG in __up_mutex at /home/ka/kernel/2.6/linux-2.6.9-rc1-mm3-RT/kernel/rt.c:1064
BUG: sleeping function called from invalid context sh(5429) at /home/ka/kernel/2.6/linux-2.6.9-rc1-mm3-RT/kernel/rt.c:1314
in_atomic():1 [00000003], irqs_disabled():0
 [<c010704e>] dump_stack+0x23/0x25 (20)
 [<c011d10b>] __might_sleep+0xbc/0xcf (36)
 [<c013a136>] __spin_lock+0x34/0x50 (24)
 [<c013a16f>] _spin_lock+0x1d/0x1f (16)
 [<c014e36b>] kmem_cache_alloc+0x37/0xf1 (32)
 [<c02c95d4>] alloc_skb+0x28/0xe6 (32)
 [<c02da818>] find_skb+0x31/0x9b (24)
 [<c02da97a>] netpoll_send_udp+0x40/0x25a (48)
 [<c028f246>] write_msg+0x56/0xfa (52)
 [<c0120e06>] __call_console_drivers+0x56/0x65 (32)
 [<c0120f49>] call_console_drivers+0xac/0x163 (36)
 [<c0121326>] release_console_sem+0x33/0xde (32)
 [<c012122c>] vprintk+0x134/0x16d (36)
 [<c01210f6>] printk+0x1d/0x1f (16)
 [<c01390ee>] __up_mutex+0x270/0x443 (68)
 [<c0139fc2>] up+0xe0/0xec (36)
 [<c0342e95>] __schedule+0x985/0xdb4 (124)
 [<c0123afc>] do_exit+0x331/0x59f (48)
 [<c0123e81>] do_group_exit+0x39/0xd1 (40)
 [<c01061a1>] sysenter_past_esp+0x52/0x71 (-4028)
---------------------------
| preempt count: 00000004 ]
| 4-level deep critical section nesting:
----------------------------------------
.. [<c0344e5b>] .... _raw_spin_lock+0x1c/0x73
.....[<c0142848>] ..   ( <= __do_IRQ+0xf6/0x16e)
.. [<c0344e5b>] .... _raw_spin_lock+0x1c/0x73
.....[<c010b340>] ..   ( <= timer_interrupt+0xd3/0x10f)
.. [<c0344e5b>] .... _raw_spin_lock+0x1c/0x73
.....[<c013b1c9>] ..   ( <= trace_start_sched_wakeup+0x22/0x7e)
.. [<c013b764>] .... print_traces+0x1b/0x52
.....[<c010704e>] ..   ( <= dump_stack+0x23/0x25)

 [<c010704e>] dump_stack+0x23/0x25 (20)
 [<c01390f3>] __up_mutex+0x275/0x443 (68)
 [<c0139fc2>] up+0xe0/0xec (36)
 [<c0342e95>] __schedule+0x985/0xdb4 (124)
 [<c0123afc>] do_exit+0x331/0x59f (48)
 [<c0123e81>] do_group_exit+0x39/0xd1 (40)
 [<c01061a1>] sysenter_past_esp+0x52/0x71 (-4028)
---------------------------
| preempt count: 00000004 ]
| 4-level deep critical section nesting:
----------------------------------------
.. [<c0344e5b>] .... _raw_spin_lock+0x1c/0x73
.....[<c0142848>] ..   ( <= __do_IRQ+0xf6/0x16e)
.. [<c0344e5b>] .... _raw_spin_lock+0x1c/0x73
.....[<c010b340>] ..   ( <= timer_interrupt+0xd3/0x10f)
.. [<c0344e5b>] .... _raw_spin_lock+0x1c/0x73
.....[<c013b1c9>] ..   ( <= trace_start_sched_wakeup+0x22/0x7e)
.. [<c013b764>] .... print_traces+0x1b/0x52
.....[<c010704e>] ..   ( <= dump_stack+0x23/0x25)

autom4te/5419: BUG in lock_new_owner at /home/ka/kernel/2.6/linux-2.6.9-rc1-mm3-RT/kernel/rt.c:651
 [<c010704e>] dump_stack+0x23/0x25 (20)
BUG: scheduling while atomic: autom4te/0x00000001/5419
caller is schedule+0x38/0x12e
 [<c010704e>] dump_stack+0x23/0x25 (20)
 [<c0342f06>] __schedule+0x9f6/0xdb4 (124)
 [<c03432fc>] schedule+0x38/0x12e (36)
 [<c0344758>] __down_mutex+0x225/0x30f (84)
 [<c013a148>] __spin_lock+0x46/0x50 (24)
 [<c013a1cc>] _spin_lock_irqsave+0x1d/0x21 (16)
 [<c028b31e>] e100_xmit_frame+0x13f/0x2d8 (60)
 [<c02da8a5>] netpoll_send_skb+0x23/0xb8 (28)
 [<c028f246>] write_msg+0x56/0xfa (52)
 [<c0120e06>] __call_console_drivers+0x56/0x65 (32)
 [<c0120f49>] call_console_drivers+0xac/0x163 (36)
 [<c0121326>] release_console_sem+0x33/0xde (32)
 [<c012122c>] vprintk+0x134/0x16d (36)
 [<c01210f6>] printk+0x1d/0x1f (16)
 [<c0106f4c>] show_trace+0x89/0xcd (36)
 [<c010704e>] dump_stack+0x23/0x25 (20)
 [<c0138be0>] lock_new_owner+0xbe/0xe2 (40)
 [<c034462e>] __down_mutex+0xfb/0x30f (84)
 [<c013a148>] __spin_lock+0x46/0x50 (24)
 [<c013a1cc>] _spin_lock_irqsave+0x1d/0x21 (16)
 [<c012a6d8>] del_timer+0x2c/0xe4 (32)
 [<c012a7e1>] del_timer_sync+0x51/0x14b (104)
 [<c0330469>] __rpc_execute+0x8d/0x3db (112)
 [<c032bd4e>] rpc_call_sync+0x9b/0xc8 (40)
 [<c01b7b4d>] nfs3_rpc_wrapper+0x3d/0x82 (40)
 [<c01b7d31>] nfs3_proc_getattr+0x50/0x81 (40)
 [<c01aeeec>] __nfs_revalidate_inode+0xf3/0x3b7 (192)
 [<c01aac1c>] nfs_lookup_revalidate+0x37e/0x54c (352)
 [<c0173220>] do_lookup+0x53/0x8d (32)
 [<c01733da>] link_path_walk+0x180/0x1071 (108)
 [<c01745f2>] path_lookup+0xa5/0x1b0 (32)
 [<c017489f>] __user_walk+0x30/0x4d (32)
 [<c016ed2b>] vfs_stat+0x1f/0x5a (92)
 [<c016f3c4>] sys_stat64+0x1e/0x3d (100)
 [<c01061a1>] sysenter_past_esp+0x52/0x71 (-4028)
---------------------------
| preempt count: 00000002 ]
| 2-level deep critical section nesting:
----------------------------------------
.. [<c0344e5b>] .... _raw_spin_lock+0x1c/0x73
.....[<c0118894>] ..   ( <= task_rq_lock+0x32/0x5b)
.. [<c013b764>] .... print_traces+0x1b/0x52
.....[<c010704e>] ..   ( <= dump_stack+0x23/0x25)
</NETCONSOLELOG>

The "lock_new_owner" BUGs then repeated until the machine was restarted.

With HIGHMEM enabled, there were really weired things happening.
<HIGHMEMENABLEDLOG>
BUG at /home/ka/kernel/2.6/linux-2.6.9-rc1-mm3-RT/mm/highmem.c:191!
------------[ cut here ]------------
BUG: sleeping function called from invalid context init(1) at /home/ka/kernel/2.6/linux-2.6.9-rc1-mm3-RT/kernel/rt.c:1314
in_atomic():1 [00000001], irqs_disabled():0
 [<c010704e>] dump_stack+0x23/0x25 (20)
 [<c011d3db>] __might_sleep+0xbc/0xcf (36)
 [<c013a3e6>] __spin_lock+0x34/0x50 (24)
 [<c013a41f>] _spin_lock+0x1d/0x1f (16)
 [<c014e632>] kmem_cache_alloc+0x37/0xf1 (32)
 [<c02ca4f4>] alloc_skb+0x28/0xe6 (32)
 [<c02db938>] find_skb+0x31/0x9b (24)
 [<c02dba9a>] netpoll_send_udp+0x40/0x25a (48)
 [<c02900c6>] write_msg+0x56/0xfa (52)
 [<c01210d6>] __call_console_drivers+0x56/0x65 (32)
 [<c0121219>] call_console_drivers+0xac/0x163 (36)
 [<c01215f6>] release_console_sem+0x33/0xde (32)
 [<c01214fc>] vprintk+0x134/0x16d (36)
 [<c01213c6>] printk+0x1d/0x1f (16)
 [<c0107299>] handle_BUG+0x63/0x9e (28)
 [<c0107356>] die+0x82/0x195 (64)
 [<c01079ac>] do_invalid_op+0x127/0x129 (192)
 [<c0106c73>] error_code+0x2b/0x30 (76)
 [<c01541dc>] copy_pte_range+0xd8/0x1e3 (48)
 [<c015439b>] copy_pmd_range+0xb4/0xca (52)
 [<c015441e>] copy_pgd_range+0x6d/0x8c (48)
 [<c0154483>] copy_page_range+0x46/0x4e (48)
 [<c011e76c>] copy_mm+0x28a/0x3ac (76)
 [<c011f352>] copy_process+0x54a/0xf1b (76)
 [<c011fe2c>] do_fork+0x6e/0x1ce (132)
 [<c0104d08>] sys_fork+0x3d/0x3f (32)
 [<c01061a1>] sysenter_past_esp+0x52/0x71 (-4028)
---------------------------
| preempt count: 00000002 ]
| 2-level deep critical section nesting:
----------------------------------------
.. [<c0345fad>] .... _raw_spin_lock_irqsave+0x1b/0x70
.....[<c0107318>] ..   ( <= die+0x44/0x195)
.. [<c013ba14>] .... print_traces+0x1b/0x52
.....[<c010704e>] ..   ( <= dump_stack+0x23/0x25)

</HIGHMEMENABLEDLOG>

looks like some machinecode was undigestible for the cpu, no?

Best regards,
Karsten

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc1-mm3-V0.7.23

[Karsten Wiese]

Am Mittwoch 10 November 2004 14:52 schrieb Karsten Wiese:
> Am Dienstag 09 November 2004 17:05 schrieb Ingo Molnar:
> > 
> > i have released the -V0.7.23 Real-Time Preemption patch, which can be
> > downloaded from the usual place:
> > 
> >     http://redhat.com/~mingo/realtime-preempt/
> 
> Hi
> 
> On SMP/HT/P4 I get:
>  BUG: lock held at task exit time!

Forgot to write that this happened with V0.7.24.

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc1-mm3-V0.7.23

[Ingo Molnar]

* Karsten Wiese <annabellesgarden@yahoo.de> wrote:

> Hi
> 
> On SMP/HT/P4 I get:
>  BUG: lock held at task exit time!

> sh/5429: BUG in __up_mutex at /home/ka/kernel/2.6/linux-2.6.9-rc1-mm3-RT/kernel/rt.c:1064
> BUG: sleeping function called from invalid context sh(5429) at /home/ka/kernel/2.6/linux-2.6.9-rc1-mm3-RT/kernel/rt.c:1314
> in_atomic():1 [00000003], irqs_disabled():0

hm, apparently something leaked a BKL count. Unfortunately we dont know
precisely what did it, only that it happened. Did this happen during
bootup, or during normal use. Can you trigger it arbitrarily?

	Ingo

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc1-mm3-V0.7.23

[Karsten Wiese]

Am Mittwoch 10 November 2004 16:01 schrieb Ingo Molnar:
> 
> * Karsten Wiese <annabellesgarden@yahoo.de> wrote:
> 
> > Hi
> > 
> > On SMP/HT/P4 I get:
> >  BUG: lock held at task exit time!
> 
> > sh/5429: BUG in __up_mutex at /home/ka/kernel/2.6/linux-2.6.9-rc1-mm3-RT/kernel/rt.c:1064
> > BUG: sleeping function called from invalid context sh(5429) at /home/ka/kernel/2.6/linux-2.6.9-rc1-mm3-RT/kernel/rt.c:1314
> > in_atomic():1 [00000003], irqs_disabled():0
> 
> hm, apparently something leaked a BKL count. Unfortunately we dont know
> precisely what did it, only that it happened. Did this happen during
> bootup, or during normal use. Can you trigger it arbitrarily?

Yes, it always happens, when callling ./cvscompile script of a project, that is mounted via nfs.
Haven't tried to do that ./cvscompile locally, should I?

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc1-mm3-V0.7.23

[Karsten Wiese]

Am Mittwoch 10 November 2004 15:20 schrieb Karsten Wiese:
> Am Mittwoch 10 November 2004 16:01 schrieb Ingo Molnar:
> > 
> > * Karsten Wiese <annabellesgarden@yahoo.de> wrote:
> > 
> > > Hi
> > > 
> > > On SMP/HT/P4 I get:
> > >  BUG: lock held at task exit time!
> > 
> > > sh/5429: BUG in __up_mutex at /home/ka/kernel/2.6/linux-2.6.9-rc1-mm3-RT/kernel/rt.c:1064
> > > BUG: sleeping function called from invalid context sh(5429) at /home/ka/kernel/2.6/linux-2.6.9-rc1-mm3-RT/kernel/rt.c:1314
> > > in_atomic():1 [00000003], irqs_disabled():0
> > 
> > hm, apparently something leaked a BKL count. Unfortunately we dont know
> > precisely what did it, only that it happened. Did this happen during
> > bootup, or during normal use. Can you trigger it arbitrarily?
> 
> Yes, it always happens, when callling ./cvscompile script of a project, that is mounted via nfs.
> Haven't tried to do that ./cvscompile locally, should I?

./cvscompile locally is ok.
Also if I disable HT in BIOS, the machine survives the crash "./cvscompile"ing via nfs 
and the next "./cvscompile"s over nfs are ok. Also if I unmount / mount the nfs share again.
So it always happens the first time calling this ./cvscompile via nfs.

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc1-mm3-V0.7.23

[Ingo Molnar]

* Karsten Wiese <annabellesgarden@yahoo.de> wrote:

> Yes, it always happens, when callling ./cvscompile script of a
> project, that is mounted via nfs. Haven't tried to do that
> ./cvscompile locally, should I?

very interesting, nfs is indeed one of the frequent BKL users.

a 'BKL leak' is an unbalanced lock, e.g.:

	lock_kernel();
	... do stuff ...
	if (error)
		return;
	... do more stuff ...
	unlock_kernel();

the BKL is a very special type of lock which fact has the side-effect
that in the stock kernel a 'BKL leak' can go unnoticed very easily: it
causes no problems other than hard-to-debug (but severe) scalability
regressions. The moment the BKL count leaked from the NFS code that
process has been 'scalability-poisoned' and will be handicapped until it
exits.

In the PREEMPT_RT patchset i added a strict locking checker to do_exit()
that found this apparent NFS bug. Unfortunately the deadlock detector
only reported a pretty common place where the BKL gets
dropped/reacquired frequently so we dont know where the NFS code has the
lock/unlock imbalance. Could you report this bug to the NFS maintainers
(along with the above and the previous analysis)?

	Ingo

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc1-mm3-V0.7.23

[K.R. Foley]

Ingo Molnar wrote:
> i have released the -V0.7.23 Real-Time Preemption patch, which can be
> downloaded from the usual place:
> 
>     http://redhat.com/~mingo/realtime-preempt/
> 

I have found some test results that I find interesting with -V0.7.24. I 
modified the rtc-debug patch to work with any program that can use the 
rtc driver. It measures the latency between handling an interrupt and 
the actual read. The amlat program normally used with this patch sets up 
a signal handler that reads /dev/rtc when there is data available and 
then sleeps until it receives the signal. Realfeel just does a blocking 
read on /dev/rtc. Oh and both of them setup the rtc for periodic 
interrupts. I would probably expect the blocking read to be a bit faster 
but not dramatically. Here are the results of a couple of very short 
runs to illustrate the difference:

amlat results (sleep/sighandler):
Nov 10 21:10:39 daffy kernel: rtc histogram:
Nov 10 21:10:39 daffy kernel: 26 1
Nov 10 21:10:39 daffy kernel: 28 2152
Nov 10 21:10:39 daffy kernel: 29 4286
Nov 10 21:10:39 daffy kernel: 30 6857
Nov 10 21:10:39 daffy kernel: 31 408
Nov 10 21:10:39 daffy kernel: 32 9
Nov 10 21:10:39 daffy kernel: 33 32
Nov 10 21:10:39 daffy kernel: 34 217
Nov 10 21:10:39 daffy kernel: 35 145
Nov 10 21:10:39 daffy kernel: 36 26
Nov 10 21:10:39 daffy kernel: 40 2
Nov 10 21:10:39 daffy kernel: 41 9
Nov 10 21:10:39 daffy kernel: 42 100
Nov 10 21:10:39 daffy kernel: 43 180
Nov 10 21:10:39 daffy kernel: 44 113
Nov 10 21:10:39 daffy kernel: 45 30
Nov 10 21:10:39 daffy kernel: 46 2
Nov 10 21:10:39 daffy kernel: 47 4
Nov 10 21:10:39 daffy kernel: 48 15
Nov 10 21:10:39 daffy kernel: 49 4
Nov 10 21:10:39 daffy kernel: 50 5
Nov 10 21:10:39 daffy kernel:
Nov 10 21:10:39 daffy kernel: Total samples: 14597

realfeel results (blocking read):
Nov 10 21:11:32 daffy kernel: rtc histogram:
Nov 10 21:11:32 daffy kernel: 3 17844
Nov 10 21:11:32 daffy kernel: 4 859
Nov 10 21:11:32 daffy kernel: 5 34
Nov 10 21:11:32 daffy kernel: 6 1
Nov 10 21:11:32 daffy kernel: 8 1
Nov 10 21:11:32 daffy kernel: 12 19
Nov 10 21:11:32 daffy kernel: 13 41
Nov 10 21:11:32 daffy kernel: 14 7
Nov 10 21:11:32 daffy kernel:
Nov 10 21:11:32 daffy kernel: Total samples: 18806

Both of the above runs were with 'IRQ 8' running at SCHED_FF 99. Amlat 
and realfeel were both running at SCHED_FF 98. The updated  rtc-debug 
patch to follow in case anyone is interested.

kr

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc1-mm3-V0.7.23

[K.R. Foley]

[-- Attachment #1: Type: text/plain, Size: 601 bytes --]

Ingo Molnar wrote:
> i have released the -V0.7.23 Real-Time Preemption patch, which can be
> downloaded from the usual place:
> 

Here is the updated rtc-debug patch. This version unlike previous 
versions doesn't change the way the rtc driver works. The output of 
/dev/rtc is preserved also so it doesn't break the existing 
functionality of rtc. By the same token it won't produce output usable 
by amlat, but it works for measuring the latency from interrupt to read. 
It doesn't measure when a poll is satisfied yet because I didn't need 
that yet. It doesn't trigger the end until the read.

kr

[-- Attachment #2: rtc-debug2.patch --]
[-- Type: text/x-patch, Size: 4504 bytes --]

--- linux-2.6.10-rc1-mm3/drivers/char/rtc.c.orig	2004-11-10 21:27:39.106900807 -0600
+++ linux-2.6.10-rc1-mm3/drivers/char/rtc.c	2004-11-10 20:45:39.000000000 -0600
@@ -86,6 +86,18 @@
 #include <asm/hpet.h>
 #endif
 
+static unsigned long long last_interrupt_time;
+
+#include <asm/timex.h>
+
+
+#define CPU_MHZ	(cpu_khz / 1000)
+#define HISTSIZE	10000
+static int histogram[HISTSIZE];
+
+int rtc_debug;
+int rtc_running;
+
 #ifdef __sparc__
 #include <linux/pci.h>
 #include <asm/ebus.h>
@@ -191,6 +203,14 @@
 static const unsigned char days_in_mo[] = 
 {0, 31, 28, 31, 30, 31, 30, 31, 31, 30, 31, 30, 31};
 
+static int rtc_state;
+
+enum rtc_states {
+	S_IDLE,			/* Waiting for an interrupt */
+	S_WAITING_FOR_READ,	/* Signal delivered. waiting for rtc_read() */
+	S_READ_MISSED,		/* Signal delivered, read() deadline missed */
+};
+
 /*
  * Returns true if a clock update is in progress
  */
@@ -259,7 +279,37 @@
 	spin_unlock_irqrestore(&rtc_task_lock, flags);
 	wake_up_interruptible(&rtc_wait);	
 
-	kill_fasync (&rtc_async_queue, SIGIO, POLL_IN);
+	if (!(rtc_status & RTC_IS_OPEN))
+		goto tata;
+
+	switch (rtc_state) {
+	case S_IDLE:			/* Waiting for an interrupt */
+		rdtscll(last_interrupt_time);
+		kill_fasync (&rtc_async_queue, SIGIO, POLL_IN);
+		rtc_state = S_WAITING_FOR_READ;
+		break;
+	case S_WAITING_FOR_READ:	/* Signal has been delivered. waiting for rtc_read() */
+		/*
+		 * Well foo.  The usermode application didn't schedule and read in time.
+		 */
+		rtc_state = S_READ_MISSED;
+		if (strcmp(current->comm, "amlat") != 0) {
+			printk("`%s'[%d] is being piggy.  "
+					"need_resched=%d, cpu=%d\n",
+				current->comm, current->pid,
+				need_resched(), smp_processor_id());
+			/* show_trace_smp(); */
+		}
+		printk("Read missed before next interrupt\n");
+		break;
+	case S_READ_MISSED:		/* Signal has been delivered, read() deadline was missed */
+		/*
+		 * Not much we can do here.  We're waiting for the usermode
+		 * application to read the rtc
+		 */
+		break;
+	}
+tata:
 
 	return IRQ_HANDLED;
 }
@@ -328,6 +378,7 @@
 	DECLARE_WAITQUEUE(wait, current);
 	unsigned long data;
 	ssize_t retval;
+	unsigned long long now;
 	
 	if (rtc_has_irq == 0)
 		return -EIO;
@@ -363,6 +414,56 @@
 		schedule();
 	} while (1);
 
+	rdtscll(now);
+
+	switch (rtc_state) {
+	case S_IDLE:			/* Waiting for an interrupt */
+		/*
+		 * err...  This can't be happening
+		 */
+		printk("rtc_read(): called in state S_IDLE!\n");
+		break;
+	case S_WAITING_FOR_READ:	/*
+					 * Signal has been delivered.
+					 * waiting for rtc_read()
+					 */
+		/*
+		 * Well done
+		 */
+	case S_READ_MISSED:		/*
+					 * Signal has been delivered, read()
+					 * deadline was missed
+					 */
+		/*
+		 * So, you finally got here.
+		 */
+		if (last_interrupt_time == 0)
+			printk("rtc_read(): we screwed up.  "
+					"last_interrupt_time = 0\n");
+		rtc_state = S_IDLE;
+		{
+			unsigned long long latency = now - last_interrupt_time;
+			unsigned long delta;	/* Nocroseconds */
+
+			delta = latency;
+			delta /= CPU_MHZ;
+			if (delta > 1000 * 1000) {
+				printk("rtc: eek\n");
+			} else {
+				unsigned long slot = delta;
+				if (slot >= HISTSIZE)
+					slot = HISTSIZE - 1;
+				histogram[slot]++;
+				if (delta > 2000)
+					printk("wow!  That was a "
+							"%ld millisec bump\n",
+						delta / 1000);
+			}
+		}
+		rtc_state = S_IDLE;
+		break;
+	}
+
 	if (count < sizeof(unsigned long))
 		retval = put_user(data, (unsigned int __user *)buf) ?: sizeof(int); 
 	else
@@ -692,6 +793,8 @@
  * needed here. Or anywhere else in this driver. */
 static int rtc_open(struct inode *inode, struct file *file)
 {
+	int i;
+
 	spin_lock_irq (&rtc_lock);
 
 	if(rtc_status & RTC_IS_OPEN)
@@ -700,6 +803,14 @@
 	rtc_status |= RTC_IS_OPEN;
 
 	rtc_irq_data = 0;
+	last_interrupt_time = 0;
+	rtc_state = S_IDLE;
+	rtc_irq_data = 0;
+
+	rtc_running = 1;
+	for (i = 0; i < HISTSIZE; i++)
+		histogram[i] = 0;
+
 	spin_unlock_irq (&rtc_lock);
 	return 0;
 
@@ -753,6 +864,19 @@
 	rtc_irq_data = 0;
 	rtc_status &= ~RTC_IS_OPEN;
 	spin_unlock_irq (&rtc_lock);
+	{
+		int i = 0;
+		unsigned long total = 0;
+		printk("rtc histogram:\n");
+		for (i = 0; i < HISTSIZE; i++) {
+			if (histogram[i]) {
+				total += histogram[i];
+				printk("%d %d\n", i, histogram[i]);
+			}
+		}
+		printk("\nTotal samples: %lu\n", total);
+		rtc_running = 0;
+	}
 	return 0;
 }
 
@@ -1127,6 +1251,7 @@
 	wake_up_interruptible(&rtc_wait);
 
 	kill_fasync (&rtc_async_queue, SIGIO, POLL_IN);
+	return;
 }
 #endif
 

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc1-mm3-V0.7.23

[Ingo Molnar]

* K.R. Foley <kr@cybsft.com> wrote:

> Ingo Molnar wrote:
> >i have released the -V0.7.23 Real-Time Preemption patch, which can be
> >downloaded from the usual place:
> >
> 
> Here is the updated rtc-debug patch. This version unlike previous
> versions doesn't change the way the rtc driver works. The output of
> /dev/rtc is preserved also so it doesn't break the existing
> functionality of rtc. By the same token it won't produce output usable
> by amlat, but it works for measuring the latency from interrupt to
> read. 

looks good - i've added this to my tree. (with minor portability fixes:
rdtscll -> get_cycles(), long long -> cycles_t)

	Ingo

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc1-mm3-V0.7.23

[Ingo Molnar]

[-- Attachment #1: Type: text/plain, Size: 768 bytes --]


* K.R. Foley <kr@cybsft.com> wrote:

> Here is the updated rtc-debug patch. This version unlike previous
> versions doesn't change the way the rtc driver works. The output of
> /dev/rtc is preserved also so it doesn't break the existing
> functionality of rtc. By the same token it won't produce output usable
> by amlat, but it works for measuring the latency from interrupt to
> read.  It doesn't measure when a poll is satisfied yet because I
> didn't need that yet. It doesn't trigger the end until the read.

i've done some further cleanups: made it .config configurable
(CONFIG_RTC_HISTOGRAM), moved the latency-histogram construction code
into separate functions to make it more apparent that there is no impact
to the normal codepaths. Patch attached.

	Ingo

[-- Attachment #2: rtc-hist-2.6.10-rc1-mm3-A0 --]
[-- Type: text/plain, Size: 5121 bytes --]

--- linux/drivers/char/Kconfig.orig
+++ linux/drivers/char/Kconfig
@@ -729,6 +729,15 @@ config RTC
 	  To compile this driver as a module, choose M here: the
 	  module will be called rtc.
 
+config RTC_HISTOGRAM
+	tristate "Real Time Clock Histogram Support"
+	default y
+	depends on RTC
+	---help---
+	  If you say Y here then the kernel will track the delivery and
+	  wakeup latency of /dev/rtc using tasks and will report a
+	  histogram to the kernel log when the application closes /dev/rtc.
+
 config SGI_DS1286
 	tristate "SGI DS1286 RTC support"
 	depends on SGI_IP22
--- linux/drivers/char/rtc.c.orig
+++ linux/drivers/char/rtc.c
@@ -86,6 +86,28 @@
 #include <asm/hpet.h>
 #endif
 
+#ifdef CONFIG_RTC_HISTOGRAM
+
+static int rtc_running;
+static cycles_t last_interrupt_time;
+
+#include <asm/timex.h>
+
+#define CPU_MHZ		(cpu_khz / 1000)
+
+#define HISTSIZE	10000
+static int histogram[HISTSIZE];
+
+static int rtc_state;
+
+enum rtc_states {
+	S_IDLE,			/* Waiting for an interrupt */
+	S_WAITING_FOR_READ,	/* Signal delivered. waiting for rtc_read() */
+	S_READ_MISSED,		/* Signal delivered, read() deadline missed */
+};
+
+#endif
+
 #ifdef __sparc__
 #include <linux/pci.h>
 #include <asm/ebus.h>
@@ -205,6 +227,132 @@ static inline unsigned char rtc_is_updat
 }
 
 #ifdef RTC_IRQ
+
+static inline void rtc_open_event(void)
+{
+#ifdef CONFIG_RTC_HISTOGRAM
+	int i;
+
+	last_interrupt_time = 0;
+	rtc_state = S_IDLE;
+	rtc_irq_data = 0;
+
+	rtc_running = 1;
+	for (i = 0; i < HISTSIZE; i++)
+		histogram[i] = 0;
+#endif
+}
+
+static inline void rtc_wake_event(void)
+{
+#ifndef CONFIG_RTC_HISTOGRAM
+	kill_fasync (&rtc_async_queue, SIGIO, POLL_IN);
+#else
+	if (!(rtc_status & RTC_IS_OPEN))
+		return;
+
+	switch (rtc_state) {
+	case S_IDLE:			/* Waiting for an interrupt */
+		last_interrupt_time = get_cycles();
+		kill_fasync (&rtc_async_queue, SIGIO, POLL_IN);
+		rtc_state = S_WAITING_FOR_READ;
+		break;
+	case S_WAITING_FOR_READ:	/* Signal has been delivered. waiting for rtc_read() */
+		/*
+		 * Well foo.  The usermode application didn't schedule and read in time.
+		 */
+		rtc_state = S_READ_MISSED;
+		if (strcmp(current->comm, "amlat") != 0) {
+			printk("`%s'[%d] is being piggy.  "
+					"need_resched=%d, cpu=%d\n",
+				current->comm, current->pid,
+				need_resched(), smp_processor_id());
+			/* show_trace_smp(); */
+		}
+		printk("Read missed before next interrupt\n");
+		break;
+	case S_READ_MISSED:		/* Signal has been delivered, read() deadline was missed */
+		/*
+		 * Not much we can do here.  We're waiting for the usermode
+		 * application to read the rtc
+		 */
+		break;
+	}
+#endif
+}
+
+static inline void rtc_read_event(void)
+{
+#ifdef CONFIG_RTC_HISTOGRAM
+	cycles_t now = get_cycles();
+
+	switch (rtc_state) {
+	case S_IDLE:			/* Waiting for an interrupt */
+		/*
+		 * err...  This can't be happening
+		 */
+		printk("rtc_read(): called in state S_IDLE!\n");
+		break;
+	case S_WAITING_FOR_READ:	/*
+					 * Signal has been delivered.
+					 * waiting for rtc_read()
+					 */
+		/*
+		 * Well done
+		 */
+	case S_READ_MISSED:		/*
+					 * Signal has been delivered, read()
+					 * deadline was missed
+					 */
+		/*
+		 * So, you finally got here.
+		 */
+		if (last_interrupt_time == 0)
+			printk("rtc_read(): we screwed up.  "
+					"last_interrupt_time = 0\n");
+		rtc_state = S_IDLE;
+		{
+			cycles_t latency = now - last_interrupt_time;
+			unsigned long delta;	/* Nocroseconds */
+
+			delta = latency;
+			delta /= CPU_MHZ;
+			if (delta > 1000 * 1000) {
+				printk("rtc: eek\n");
+			} else {
+				unsigned long slot = delta;
+				if (slot >= HISTSIZE)
+					slot = HISTSIZE - 1;
+				histogram[slot]++;
+				if (delta > 2000)
+					printk("wow!  That was a "
+							"%ld millisec bump\n",
+						delta / 1000);
+			}
+		}
+		rtc_state = S_IDLE;
+		break;
+	}
+#endif
+}
+
+static inline void rtc_close_event(void)
+{
+#ifdef CONFIG_RTC_HISTOGRAM
+	int i = 0;
+	unsigned long total = 0;
+	printk("rtc histogram:\n");
+	for (i = 0; i < HISTSIZE; i++) {
+		if (histogram[i]) {
+			total += histogram[i];
+			printk("%d %d\n", i, histogram[i]);
+		}
+	}
+	printk("\nTotal samples: %lu\n", total);
+	rtc_running = 0;
+#endif
+}
+
 /*
  *	A very tiny interrupt handler. It runs with SA_INTERRUPT set,
  *	but there is possibility of conflicting with the set_rtc_mmss()
@@ -250,7 +398,7 @@ irqreturn_t rtc_interrupt(int irq, void 
 	spin_unlock(&rtc_task_lock);
 	wake_up_interruptible(&rtc_wait);	
 
-	kill_fasync (&rtc_async_queue, SIGIO, POLL_IN);
+	rtc_wake_event();
 
 	return IRQ_HANDLED;
 }
@@ -354,6 +502,8 @@ static ssize_t rtc_read(struct file *fil
 		schedule();
 	} while (1);
 
+	rtc_read_event();
+
 	if (count < sizeof(unsigned long))
 		retval = put_user(data, (unsigned int __user *)buf) ?: sizeof(int); 
 	else
@@ -692,6 +848,7 @@ static int rtc_open(struct inode *inode,
 	rtc_status |= RTC_IS_OPEN;
 
 	rtc_irq_data = 0;
+	rtc_open_event();
 	spin_unlock_irq (&rtc_lock);
 	return 0;
 
@@ -744,6 +901,7 @@ no_irq:
 	rtc_irq_data = 0;
 	rtc_status &= ~RTC_IS_OPEN;
 	spin_unlock_irq (&rtc_lock);
+	rtc_close_event();
 	return 0;
 }
 

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc1-mm3-V0.7.23

[Ingo Molnar]

[-- Attachment #1: Type: text/plain, Size: 681 bytes --]


* Ingo Molnar <mingo@elte.hu> wrote:

> i've done some further cleanups: made it .config configurable
> (CONFIG_RTC_HISTOGRAM), moved the latency-histogram construction code
> into separate functions to make it more apparent that there is no
> impact to the normal codepaths. Patch attached.

i've attached another update with a few more smaller details fixed:

 - only print the histogram if a /dev/rtc using application indeed used 
   it to get interrupts. This removes bogus printouts triggered by 
   hwclock.

 - skip the first RTC interrupt from the histogram - most of the
   /dev/rtc applications do not handle the first event very well,
   skewing the histogram.

	Ingo

[-- Attachment #2: rtc-hist-2.6.10-rc1-mm3-A1 --]
[-- Type: text/plain, Size: 5237 bytes --]

--- linux/drivers/char/Kconfig.orig
+++ linux/drivers/char/Kconfig
@@ -729,6 +729,15 @@ config RTC
 	  To compile this driver as a module, choose M here: the
 	  module will be called rtc.
 
+config RTC_HISTOGRAM
+	tristate "Real Time Clock Histogram Support"
+	default y
+	depends on RTC
+	---help---
+	  If you say Y here then the kernel will track the delivery and
+	  wakeup latency of /dev/rtc using tasks and will report a
+	  histogram to the kernel log when the application closes /dev/rtc.
+
 config SGI_DS1286
 	tristate "SGI DS1286 RTC support"
 	depends on SGI_IP22
--- linux/drivers/char/rtc.c.orig
+++ linux/drivers/char/rtc.c
@@ -86,6 +86,28 @@
 #include <asm/hpet.h>
 #endif
 
+#ifdef CONFIG_RTC_HISTOGRAM
+
+static cycles_t last_interrupt_time;
+
+#include <asm/timex.h>
+
+#define CPU_MHZ		(cpu_khz / 1000)
+
+#define HISTSIZE	10000
+static int histogram[HISTSIZE];
+
+static int rtc_state;
+
+enum rtc_states {
+	S_STARTUP,		/* First round - let the application start */
+	S_IDLE,			/* Waiting for an interrupt */
+	S_WAITING_FOR_READ,	/* Signal delivered. waiting for rtc_read() */
+	S_READ_MISSED,		/* Signal delivered, read() deadline missed */
+};
+
+#endif
+
 #ifdef __sparc__
 #include <linux/pci.h>
 #include <asm/ebus.h>
@@ -205,6 +227,144 @@ static inline unsigned char rtc_is_updat
 }
 
 #ifdef RTC_IRQ
+
+static inline void rtc_open_event(void)
+{
+#ifdef CONFIG_RTC_HISTOGRAM
+	int i;
+
+	last_interrupt_time = 0;
+	rtc_state = S_STARTUP;
+	rtc_irq_data = 0;
+
+	for (i = 0; i < HISTSIZE; i++)
+		histogram[i] = 0;
+#endif
+}
+
+static inline void rtc_wake_event(void)
+{
+#ifndef CONFIG_RTC_HISTOGRAM
+	kill_fasync (&rtc_async_queue, SIGIO, POLL_IN);
+#else
+	if (!(rtc_status & RTC_IS_OPEN))
+		return;
+
+	switch (rtc_state) {
+	/* Startup */
+	case S_STARTUP:
+		kill_fasync (&rtc_async_queue, SIGIO, POLL_IN);
+		break;
+	/* Waiting for an interrupt */
+	case S_IDLE:
+		kill_fasync (&rtc_async_queue, SIGIO, POLL_IN);
+		last_interrupt_time = get_cycles();
+		rtc_state = S_WAITING_FOR_READ;
+		break;
+
+	/* Signal has been delivered. waiting for rtc_read() */
+	case S_WAITING_FOR_READ:
+		/*
+		 * Well foo.  The usermode application didn't
+		 * schedule and read in time.
+		 */
+		rtc_state = S_READ_MISSED;
+		printk("`%s'[%d] is being piggy. need_resched=%d, cpu=%d\n",
+			current->comm, current->pid,
+				need_resched(), smp_processor_id());
+		printk("Read missed before next interrupt\n");
+		break;
+	/* Signal has been delivered, read() deadline was missed */
+	case S_READ_MISSED:
+		/*
+		 * Not much we can do here.  We're waiting for the usermode
+		 * application to read the rtc
+		 */
+		break;
+	}
+#endif
+
+}
+
+static inline void rtc_read_event(void)
+{
+#ifdef CONFIG_RTC_HISTOGRAM
+	cycles_t now = get_cycles();
+
+	switch (rtc_state) {
+	/* Startup */
+	case S_STARTUP:
+		rtc_state = S_IDLE;
+		break;
+		
+	/* Waiting for an interrupt */
+	case S_IDLE:
+		printk("bug in rtc_read(): called in state S_IDLE!\n");
+		break;
+	case S_WAITING_FOR_READ:	/*
+					 * Signal has been delivered.
+					 * waiting for rtc_read()
+					 */
+		/*
+		 * Well done
+		 */
+	case S_READ_MISSED:		/*
+					 * Signal has been delivered, read()
+					 * deadline was missed
+					 */
+		/*
+		 * So, you finally got here.
+		 */
+		if (!last_interrupt_time)
+			printk("bug in rtc_read(): last_interrupt_time = 0\n");
+		rtc_state = S_IDLE;
+		{
+			cycles_t latency = now - last_interrupt_time;
+			unsigned long delta;	/* Microseconds */
+
+			delta = latency;
+			delta /= CPU_MHZ;
+
+			if (delta > 1000 * 1000) {
+				printk("rtc: eek\n");
+			} else {
+				unsigned long slot = delta;
+				if (slot >= HISTSIZE)
+					slot = HISTSIZE - 1;
+				histogram[slot]++;
+				if (delta > 2000)
+					printk("wow!  That was a "
+							"%ld millisec bump\n",
+						delta / 1000);
+			}
+		}
+		rtc_state = S_IDLE;
+		break;
+	}
+#endif
+
+}
+
+static inline void rtc_close_event(void)
+{
+#ifdef CONFIG_RTC_HISTOGRAM
+	int i = 0;
+	unsigned long total = 0;
+
+	for (i = 0; i < HISTSIZE; i++)
+		total += histogram[i];
+	if (!total)
+		return;
+
+	printk("\nrtc latency histogram of {%s/%d, %lu samples}:\n",
+		current->comm, current->pid, total);
+	for (i = 0; i < HISTSIZE; i++) {
+		if (histogram[i])
+			printk("%d %d\n", i, histogram[i]);
+	}
+#endif
+}
+
 /*
  *	A very tiny interrupt handler. It runs with SA_INTERRUPT set,
  *	but there is possibility of conflicting with the set_rtc_mmss()
@@ -250,7 +410,7 @@ irqreturn_t rtc_interrupt(int irq, void 
 	spin_unlock(&rtc_task_lock);
 	wake_up_interruptible(&rtc_wait);	
 
-	kill_fasync (&rtc_async_queue, SIGIO, POLL_IN);
+	rtc_wake_event();
 
 	return IRQ_HANDLED;
 }
@@ -354,6 +514,8 @@ static ssize_t rtc_read(struct file *fil
 		schedule();
 	} while (1);
 
+	rtc_read_event();
+
 	if (count < sizeof(unsigned long))
 		retval = put_user(data, (unsigned int __user *)buf) ?: sizeof(int); 
 	else
@@ -689,6 +857,7 @@ static int rtc_open(struct inode *inode,
 	if(rtc_status & RTC_IS_OPEN)
 		goto out_busy;
 
+	rtc_open_event();
 	rtc_status |= RTC_IS_OPEN;
 
 	rtc_irq_data = 0;
@@ -744,6 +913,7 @@ no_irq:
 	rtc_irq_data = 0;
 	rtc_status &= ~RTC_IS_OPEN;
 	spin_unlock_irq (&rtc_lock);
+	rtc_close_event();
 	return 0;
 }
 

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc1-mm3-V0.7.23

[K.R. Foley]

Ingo Molnar wrote:
> * Ingo Molnar <mingo@elte.hu> wrote:
> 
> 
>>i've done some further cleanups: made it .config configurable
>>(CONFIG_RTC_HISTOGRAM), moved the latency-histogram construction code
>>into separate functions to make it more apparent that there is no
>>impact to the normal codepaths. Patch attached.
> 
> 
> i've attached another update with a few more smaller details fixed:
> 
>  - only print the histogram if a /dev/rtc using application indeed used 
>    it to get interrupts. This removes bogus printouts triggered by 
>    hwclock.
> 
>  - skip the first RTC interrupt from the histogram - most of the
>    /dev/rtc applications do not handle the first event very well,
>    skewing the histogram.
> 
> 	Ingo

Very nicely done. Also much less of a hack now the way you took all of 
the code out of the normal codepaths and made it into inlines that 
pretty much compile out if not being used.

kr