Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U6

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U6

[Mark_H_Johnson]

>i have released the -U6 Real-Time Preemption patch:
>
>
http://redhat.com/~mingo/realtime-preempt/realtime-preempt-2.6.9-rc4-mm1-U6

Booted to single user and was able to get some network operations going
with
this version (w/ previously mentioned update). However, at the step where
I start CUPS, I got a number of traces on the display referring to
parport_pc
related function calls [but I don't use a parallel printer...]. It ended
with:

NMI Watchdog detected LOCKUP on CPU1, eip c0139b22, registers:
[not sure you want the all the details, I'll put a few key items in
and can try to reproduce on request]

Modules linked in: parport_pc lp parport autofs4 sunrpc 8139too mii dm_mod
uhci_hcd ext3 jbd
CPU:    1
... EIP is at sub_preempt_count+0x82/0xa0
... Process ksoftirqd/1 (pid:5 ...)

Pid: 1825, comm:    modprobe
... CPU: 0
... EIP is at flush_tlb_others+0x90/0xf0

(stack trace shows sys_init_module, parport_pc_init, ...
parport_announce_port,
 mcount, parport_pc_probe_port, parport_announce_port, __mcount,
parport_daisy_init, ...
 parport_wait_event, down_write_interruptible, error_code, show_stack,
etc.)
preempt count: 00010006
...
console shuts up...

Alt-Sysrq keys are recognized (displays command) but don't display any
data.
Will send whatever made it into to the system log shortly.

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

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U6

[Ingo Molnar]

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

> Booted to single user and was able to get some network operations
> going with this version (w/ previously mentioned update). However, at
> the step where I start CUPS, I got a number of traces on the display
> referring to parport_pc related function calls [but I don't use a
> parallel printer...]. It ended with:

thanks for the logs - there are some semaphore assumptions in
ieee1284.c, it should use completions & wait_for_completion_timeout()
too. The workaround is to disable CONFIG_PARPORT_1284. (or
CONFIG_PARPORT altogether.)

	Ingo

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U6

[K.R. Foley]

Ingo Molnar wrote:
> * Mark_H_Johnson@raytheon.com <Mark_H_Johnson@raytheon.com> wrote:
> 
> 
>>Booted to single user and was able to get some network operations
>>going with this version (w/ previously mentioned update). However, at
>>the step where I start CUPS, I got a number of traces on the display
>>referring to parport_pc related function calls [but I don't use a
>>parallel printer...]. It ended with:
> 
> 
> thanks for the logs - there are some semaphore assumptions in
> ieee1284.c, it should use completions & wait_for_completion_timeout()
> too. The workaround is to disable CONFIG_PARPORT_1284. (or
> CONFIG_PARPORT altogether.)
> 
> 	Ingo
> 

If only he had been a little faster getting this in, I wouldn't have sat 
and written the entire screen full down on paper. :) Mine wasn't making 
it to the logs. At least he saved me from typing it all back in. Thanks 
Mark. Disabling PARPORT fixed my problem as well.

kr

[patch] VP-2.6.9-rc4-mm1-T6

[Ingo Molnar]

i've uploaded -T6:

  http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc4-mm1-T6

this should fix the UP build issues reported by many. -T6 also brings
back the ->break_lock framework and converts a few more locks to raw.

SMP is still expected to be flaky due to the zombie-task problem(s). But
UP is not out of the 'extremely experimental' status either.

to create a -T6 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/voluntary-preempt/voluntary-preempt-2.6.9-rc4-mm1-T6

	Ingo

Re: [patch] VP-2.6.9-rc4-mm1-T6

[Ingo Molnar]

i've uploaded -T7:

  http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc4-mm1-T7

Changes since -T6:

- further stabilization of PREEMPT_REALTIME: fixed the task-reaping
  problem by moving TASK_ZOMBIE out of p->state and thus completely
  separating preemption from the child-exit mechanism. This got rid of 
  the 'Badness in exit.c' warnings on my SMP testbox (and related
  crashes).

- fixed the _mutex_trylock_bh missing symbol problem reported by K.R. 
  Foley and Florian Schmidt.

- turned the sysrq lock into a raw spinlock, to enable direct keyboard
  irqs.

PREEMPT_REALTIME is still experimental, but it's already looking much
better on my testboxes.

to create a -T7 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/voluntary-preempt/voluntary-preempt-2.6.9-rc4-mm1-T7

	Ingo

[patch] VP-2.6.9-rc4-mm1-T8

[Ingo Molnar]

i've uploaded the -T8 VP patch:

  http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc4-mm1-T8

lots of stabilization of CONFIG_PREEMPT_REALTIME. It's still in
experimental status but general stability is improving.

Changes since -T7:

 - fixed a nasty category of bugs that were introduced by the use of 
   rwsems for rwlocks. rwsems are not read-recursive, while rwlocks are. 
   Fortunately it was not too hard to identify & fix recursive users of
   tasklist_lock, in fact each of these also qualifies as a cleanup. The 
   symptom of this bug was a soft-deadlocking of the system. 

 - fixed profiler locks, i believe this could resolve the bootup crash
   reported by K.R. Foley.

 - fixed VP / XFS namespace collision reported by Mark H. Johnson

 - fix one more final detail of the new zombie-task handling code

 - fixed 3c59x.c, fasync-handling, ipv6, module-loader runtime
   warnings reported by K.R. Foley.

 - fixed the ali5451 locking

to create a -T8 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/voluntary-preempt/voluntary-preempt-2.6.9-rc4-mm1-T8

	Ingo

[patch] VP-2.6.9-rc4-mm1-T9

[Ingo Molnar]

i've uploaded the -T9 VP patch:

  http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc4-mm1-T9

this is a bugfixes-only release that should fix the highmem-related
issues reported by K.R. Foley and Mark H. Johnson: 3 more locks had to
be converted to raw.

to create a -T9 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/voluntary-preempt/voluntary-preempt-2.6.9-rc4-mm1-T9

	Ingo

[patch] Real-Time Preemption, -VP-2.6.9-rc4-mm1-U0

[Ingo Molnar]

i'm pleased to announce a significantly improved version of the
Real-Time Preemption (PREEMPT_REALTIME) feature that i have been working
towards in the past couple of weeks.

the patch (against 2.6.9-rc4-mm1) can be downloaded from:

  http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc4-mm1-U0

this is i believe the first correct conversion of the Linux kernel to a
fully preemptible (fully mutex-based) preemption model, while still
keeping all locking properties of Linux.

I also think that this feature can and should be integrated into the
upstream kernel sometime in the future. It will need improvements and
fixes and lots of testing, but i believe the basic concept is sound and
inclusion is manageable and desirable. So comments, testing and feedback
is more than welcome!

to recap the conceptual issues that needed solving: the previous patch
already converted a fair portion of spinlocks to mutexes, but that in a
fully preemptible kernel model the following locking primitives are
especially problematic:

	- RCU locking
	- per-cpu counters and per-cpu variables
	- tlb gather/release logic
	- seqlocks
	- atomic-kmaps
	- pte mapping

note that while we tend to think about these as SMP locking primitives,
in a fully preemptible model these locking rules are necessary for
correctness, even on a single-CPU embedded box.

Unfortunately none of the existing preemption patches solve these
problems: they concentrate on UP but these locking rules must not be
ignored on UP either!

(Bill Huey's mutex patch he just released is the one notable exception i
know about, which is also a correct implementation i believe, but it
doesnt attack these locking rules [yet]. Bill's locking hierarchy is i
believe quite similar to the -T9 patch - this i believe is roughly the
best one can get when only using spinlocks as a vehicle.)

In the previous (-T9) version of the Real-Time Preemption patch, the
above locking primitives kept large portions of kernel code
non-preemptable, causing a 'spreadout' of raw spinlocks and
non-preemptible sections to various kernel subsystems.

Another, even more problematic effect was that both network drivers and
block IO drivers got 'contaminated' by raw spinlocks, triggering lots of
per-driver changes and thus limiting testability. It is basically an
opt-in model to correctness which is bad from a maintainance and
upstream acceptance point of view. The -T9 patch was a prime example of
the problems the Linux locking primitives cause in a fully preemptible
kernel model.


To solve all these fundamental problems, i improved/fixed/changed all of
these locking methods to be preemption-friendly. Most of the time it was
necessary to introduce an additional API variant because e.g.
rcu_read_lock() is anonymous (it doesnt identify the data protected), so
i introduced a variant that takes the write-lock as an argument. In the
PREEMPT_REALTIME case we can thus properly serialize on that lock.

For per-cpu variables i introduced a new API variant that creates a
spinlock-array for the per-cpu-variable, and users must make sure the
cpu field doesnt change. Migration to another CPU can happen within the
critical section, but 'statistically' the variable is still per-CPU and
update correctness is fully preserved.

TLB shootdown was the source of another nasty type of critical section:
it keeps preemption disabled during much of the pagetable zapping and
also relies on a per-CPU variable to keep TLB state. The fix for
PREEMPT_REALTIME (on x86) was to implement a simpler but preemptible TLB
flushing method. This necessiated two minor API changes to the generic
TLB shootdown code - pretty straightforward ones.

Atomic kmaps were another source of non-preemptible sections:
pte_map/pte_unmap both used nontrivial functions within and ran for a
long time, creating a lock dependency and a latency problem as well. I
wrapped them via normal kmaps, which thus become preemptible. (The main
reason for atomic kmaps were non-preemptability constraints - but those
are not present in a fully preemptible model.)

seqlocks (used within the VFS and other places) were another problem:
the are now preemptible by default, the same auto-type-detection logic
applies to them as to preemptible/raw spinlocks: switching between a
preemptible and a non-preemptible type is done by changing the
prototype, the locking APIs stay the same.

The improvements to locking allowed the gradual 'pulling out' of all
raw-spinlocks from various kernel subsystems. In the -U0 patch i have
almost completely finished this 'pullout', and as a result the following
kernel subsystems are now completely spinlock-free and 100% mutex-based:

	- networking
	- IO subsystem
	- VFS and lowlevel filesystems
	- memory management (except the SLAB allocator lock)
	- signal code
	- all of drivers/* and sound/*

note: it is important that when PREEMPT_REALTIME is disabled, the old
locking rules apply and there is no performance impact whatsoever. So
what this implements is in essence a compile-time multi-tier locking
architecture enabling 4 types of preemption models:

  - stock                      (casual voluntary kernel preemption)
  - CONFIG_PREEMPT_VOLUNTARY   (lots of cond_resched() points)
  - CONFIG_PREEMPT             (involuntary preemption plus spinlocks)
  - CONFIG_PREEMPT_REALTIME    (everything is a mutex)

these models cover all the variants people are interested in: servers
with almost no latency worries, desktops with ~1msec needs and hard-RT
applications needing both microsecond-range latencies and provable
maximum latencies.

to quantitatively see the effects of these changes to the locking
landscape, here's the output of a script that disassembles the kernel
image and counts the number of actual spin lock/unlock function calls
done versus mutex lock/unlocks:

With PREEMPT_REALTIME disabled, all locks are spinlocks and old
semaphores:

        spinlock API calls:      5359  (71.6%)
        | old mutex API calls:   2120  (28.3%)
        | new mutex API calls:      2  (0%)
        all mutex API calls:     2122  (28.3%)
        --------------------------------------
        lock API calls:          7481 (100.0%)

with the -T9 kernel, which had the 'spread out' locking model, a
considerable portion of spinlocks were replaced by mutexes, but more
than 20% of usage was still spinlocks:

        spinlock API calls:      1835  (23.1%)
        | old mutex API calls:   2142  (26.9%)
        | new mutex API calls:   3961  (49.8%)
        all mutex API calls:     6103  (76.8%)
        --------------------------------------
        lock API calls:          7938 (100.0%)

here are some fresh numbers from Bill Huey's mmLinux kernel:

        spinlock API calls:      2452  (30.3%)
        all mutex API calls:     5614  (69.6%)
        --------------------------------------
        lock API calls:          8066 (100.0%)

(his mutex implementation directly falls back to up()/down() so the new
mutexes become part of the old mutexes.)

while i believe that the locking design is fundamentally incomplete in
the MontaVista kernel and thus is not directly comparable to
PREEMPT_REALTIME nor the mmLinux kernel, here are the stats from it
using a similar .config:

        spinlock API calls:      1444  (26.1%)
        | old mutex API calls:   2095  (37.9%)
        | new mutex API calls:   1981  (35.8%)
        all mutex API calls:     4076  (73.8%)
        --------------------------------------
        lock API calls:          5520 (100.0%)

(here it is visible that apparently a significant amount of [i believe
necessary] locking is missing from this kernel.)

finally, here are the stats from the new PREEMPT_REALTIME -U0 kernel:

        spinlock API calls:       491  (6.0%)
        | old mutex API calls:   2142  (26.2%)
        | new mutex API calls:   5536  (67.7%)
        all mutex API calls:     7678  (93.9%)
        --------------------------------------
        lock API calls:          8169 (100.0%)

note that almost all of the remaining spinlocks are held for a short
amount of time and have a finite maximum duration. They involve hardware
access, scheduling and interrupt handling and timers - almost all of
that code has O(1) characteristics.

what this means is that we are approaching hard-real-time domains ... 
using what is in essence the stock Linux kernel!

note that priority inheritance is still not part of this patch, but that
effort can now be centralized to the two basic Linux semaphore types,
solving the full spectrum of priority inheritance problems!

the code is still x86-only but only for practical reasons - other
architectures will be covered in the future as well.

to create a -U0 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/voluntary-preempt/voluntary-preempt-2.6.9-rc4-mm1-U0

	Ingo

[patch] Real-Time Preemption, -VP-2.6.9-rc4-mm1-U1

[Ingo Molnar]

i have released the -U1 PREEMPT_REALTIME patch:
 
  http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc4-mm1-U1

this is a strict bugfixes-only release. With -U1 i cannot reproduce any
of the bugs on my testsystems anymore, but take care nevertheless, this
is still experimental code.

Changes since -U0:

 - bugfix: fixed the highmem related crash reported by Adam Heath and i 
   think this could also fix the crash reported by Mark H Johnson.

 - bugfix: fixed a number of networking related soft-lockups, caused by
   a deadlock scenarios in the ipv4, netfilter and net-xmit locking
   code. This could fix the lockup reported by Lorenzo Allegrucci.

 - bugfix: enable interrupts in the int3 handler - gdb will otherwise
   trigger a kernel debug message.

 - cleanup: reworked the RCU API wrappers, we now have the following
   variants:
 
     rcu_read_[un]lock_spin(&spinlock)
     rcu_read_[un]lock_bh_spin(&spinlock)
     rcu_read_[un]lock_sem(&semaphore)

   this change was necessary for the network locking fixes.

 - debugging helper: SysRq-T will now print the stacktrace of currently
   running tasks too. (They might be a bit unreliable occasionally but
   very useful to debug deadlocks.)

 - configurability fix: disabled the /proc/kernel/softirq_preemption and
   hardirq_preemption runtime flags (and the softirq-preempt= and
   hardirq-preempt= boot flags) if PREEMPT_REALTIME is enabled - in the
   fully preemptible model these must always be on.

there are no known bugs at this moment, so please re-report any issues 
you might still encounter.

to create a -U1 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/voluntary-preempt/voluntary-preempt-2.6.9-rc4-mm1-U1

	Ingo

[patch] Real-Time Preemption, -VP-2.6.9-rc4-mm1-U2

[Ingo Molnar]

i have released the -U2 PREEMPT_REALTIME patch:

  http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc4-mm1-U2

this too is a bugfixes-only release, and it is still experimental code.

Changes since -U1:

 - bugfix: fix page_lock_anon_vma() crash reported by Adam Heath and 
   Lorenzo Allegrucci.

 - bugfix: fix selinux atomic-schedule warning messages, reported by
   Mark H Johnson.

 - bugfix: ip_tables atomic-schedule fix, fixes the messages reported by 
   Daniel Walker and K.R. Foley.

 - bugfix: fix warnings/deadlocks in inet_create(), reported by Mark H 
   Johnson.

 - bugfix: fixed a crash-in-shmfs-during-heavy-swapout bug

 - bugfix: enable preemption while doing mmdrop() in the scheduler - it 
   may schedule.

 - debugging feature: when PREEMPT_TIMING is enabled then the code also 
   keeps a trace/stack of preemption enabler EIPs. (if LATENCY_TRACE is 
   enabled as well then the parent EIP is recorded as well.) Whenever a 
   stack trace due to atomicity violations is printed, the preemption
   stack is printed as well. This makes it much easier to identify the 
   place that did the illegal preemption-disabling.

to create a -U2 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/voluntary-preempt/voluntary-preempt-2.6.9-rc4-mm1-U2

	Ingo

[patch] Real-Time Preemption, -VP-2.6.9-rc4-mm1-U3

[Ingo Molnar]

i have released the -U3 PREEMPT_REALTIME patch:

  http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc4-mm1-U3

this is a buildfixes-only release, and it is still experimental code.

Changes since -U2:

 - build fix: fixes the latency.c compilation error reported by Adam 
   Heath.

 - build fix: fixes !HIGHMEM compilation, patch from Andrew Rodland

to create a -U3 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/voluntary-preempt/voluntary-preempt-2.6.9-rc4-mm1-U3

	Ingo

[patch] Real-Time Preemption, -VP-2.6.9-rc4-mm1-U4

[Ingo Molnar]

i have released the -U4 PREEMPT_REALTIME patch:

   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc4-mm1-U4

this is a fixes-only release, and it is still experimental code.

Changes since -U3:

 - crash fix: fix the rtc_lock related crash reported by Bill Huey, the 
   rtc_lock is now a raw spinlock again.

 - crash fix: avoid recursion into timer code when PREEMPT_TIMING is 
   enabled.

 - crash/printout fix: revert some of selinux's locks back to raw 
   spinlocks. This could fix the problems reported by Mark H. Johnson, 
   Adam Heath.

 - build fix: fix the compilation problems reported by Lee Revell

 - debug feature: implemented 'print backtrace on all CPUs' on SMP 
   systems, SysRq+L will trigger it.

 - build cleanup: restructure the debug config options. This should 
   resolve the build problems and incompatible debug-options
   problems reported.

 - cleanup: move definitions around, turn on generic rwlocks instead of
   the x86-specific version.

i think all bugs that were reported with logs are fixed in -U4. Please
re-report any issue that might remain.

to create a -U4 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/voluntary-preempt/voluntary-preempt-2.6.9-rc4-mm1-U4

	Ingo

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

[Ingo Molnar]

i have released the -U5 Real-Time Preemption patch:

  http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc4-mm1-U5

this is a release intended to increase stability, but since it also
includes new debug features and related cleanups it might introduce new
regressions. Be careful.

there are two big changes:

 - debug feature: automatic semaphore/rwsem deadlock detection, based on
   the code from Igor Manyilov and Bill Huey.

this is a very nice feature that should help in debugging the remaining
deadlocks. The deadlock detection feature has already helped me fix a
bug that was causing hangs in the VFS, so it's really useful.

 - generic semaphore implementation

the generic semaphore implementation (which uses rwsems) makes it
possible to use the deadlock detection mechanism for all the mutex types
we currently have: semaphores, rw-semaphores, spinlock-mutexes and
rwlock-mutexes. Another benefit is that PREEMPT_REALTIME becomes much
more portable this way. (although it's still x86-only at the moment.)

other changes since -U4:

 - crash fix: fixed a possible "unbound recursion upon IRQ entry" bug.
   introduced preempt_schedule_irq() which now schedules without
   enabling interrupts again, preventing new IRQs from hitting this
   task again and triggering preemption. This might fix the
   'infinite stackdumps' problem Rui Nuno Capela was seeing.

 - deadlock fix: is_subdir()'s PREEMPT_REALTIME locking was buggy. This 
   could perhaps fix the other problem reported by Rui Nuno Capela.

 - i8253_lock fixes: apm, hd.c, gameport.c and analog.c were all 
   improperly importing the variable while overriding the prototype. 
   This fixes the bug reported by Florian Schmidt.

 - possible crash fix: one particular lock in selinux has to be 
   mutex-based, because while held it calls other mutex-using code.

 - two more selinux locks converted to raw spinlocks, because they were
   called from within raw-critical sections.

 - debug feature: enforce interrupts-enabled upon schedule().
   (Note that this does not break sleep_on() because sleep_on() does not
   disable interrupts in the PREEMPT_REALTIME mode. It might break with 
   !PREEMPT_REALTIME though.)

 - locking cleanup: converted the IPC code from raw spinlocks & RCU to
   spinlock-mutexes.

 - code cleanup: cleaned up the generic rwsem code.

 - debug feature: implemented /proc/sys/kernel/trace_verbose runtime
   flag (default:0), which enables a much more verbose printout in
   /proc/latency_trace.  This trace format can be useful in e.g. 
   debugging timestamp weirdnesses.

 - irqs-off fix: there was one codepath where irqd would call schedule() 
   with interrupts disabled.

 - debug feature: the NMI entries in the latency trace now also include 
   the last-observed-EFLAGS value. Can be useful in figuring out what a
   certain CPU is doing and why.

 - cleanup: fixed preemption-off ordering: often the spinlock (and 
   scheduler) code would re-enable preemption and interrupts in the
   wrong order, opening up a small window for an interrupt handler to
   fit in and increase the latency of that almost-finished critical
   section.

 - cleanup: consolidated various bug-printouts. It should now be easy to
   find whether anything bad happens even amongst lots of preempt-timing
   printouts: 'dmesg | grep BUG'.

to create a -U5 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/voluntary-preempt/voluntary-preempt-2.6.9-rc4-mm1-U5

	Ingo

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

[Ingo Molnar]

i have released the -U6 Real-Time Preemption patch:
 
  http://redhat.com/~mingo/realtime-preempt/realtime-preempt-2.6.9-rc4-mm1-U6

this is a fixes-only release.

found and fixed the 'big bug' that was probably the one causing
stability problems for a number of people. There was a small window for
a task double-free race to occur, causing all sorts of crashes later on.
This bug could trigger on UP and SMP systems alike, on SMP being a bit
more frequent.

Also, a common networking deadlock was found and fixed as well, using
the deadlock detector.

Changes since -U5:

- crash bug: fix task double free caused by irq-preemption of 
  do_exit(). This got introduced in -U5 as part of a simplification of
  the zombie-reaping rewrite that the -U series did. That rewrite had an 
  unrobustness which got triggered by -U5 in a subtle way, opening up a
  small window at the end of do_exit() for an interrupt-triggered
  preemption to cause a double-free. This could fix some of the crashes
  reported by Rui Nuno Capela, Mark H Johnson.

- deadlock bug: fix networking deadlock reported by Matthew L Foster.
  Restructured the way the RT-RCU locking of ptype_lock is done - it's
  cleaner and more obvious now (besides being correct). This could also
  fix the deadlock reported by Michal Schmidt.

- deadlock bug: fix NFS startup breakage related to semaphore abuse,
  patch from Thomas Gleixner.

- build bug: fix aha152x.c, based on patch from K.R. Foley.

- build bug: fix compilation error in qla2xxx. (reported by Fernando
  Pablo Lopez-Lezcano and Mark H Johnson)

- build bug: fix !PREEMPT_REALTIME compilation error. (reported by
  Matthew L Foster)

- build bug: fix ipmi-watchdog compilation error. (reported by Mark H 
  Johnson)

- tracer fix: if an assert happens within the tracer then we'd get into
  infinite recursion. The fix was to correctly nest tracing on/off
  points.

- debug enhancement: added a few more asserts to catch underflowing 
  atomic counters. (this made the task double-free trigger earlier.)

- debug enhancement: extended CONFIG_DEBUG_STACKOVERFLOW to be 
  mcount()-driven as well. This helps in catching stack overflows much
  more reliably than the do_IRQ() based method.

to create a -U6 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-U6

	Ingo

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U6

[Ingo Molnar]

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

> i have released the -U6 Real-Time Preemption patch:
>  
>   http://redhat.com/~mingo/realtime-preempt/realtime-preempt-2.6.9-rc4-mm1-U6

i've re-released the patch because shortly after releasing it i found a
false-positive in the deadlock-detector that was triggering in oowriter. 

The latest patch is thus:

 $ md5sum realtime-preempt-2.6.9-rc4-mm1-U6
 9fd546bdd2d45ff1a8d5a88160135170  realtime-preempt-2.6.9-rc4-mm1-U6

if you've got the earlier one and have CONFIG_RWSEM_DEADLOCK_DETECT
enabled then please download the new patch.

	Ingo

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U6

[Rui Nuno Capela]

Ingo Molnar wrote:
>
>> i have released the -U6 Real-Time Preemption patch:
>>
>>   http://redhat.com/~mingo/realtime-preempt/realtime-preempt-2.6.9-rc4-mm1-U6
>

I'm experiencing terrible kernel panics at a very early bootstrap stage
while testing the U5 and U6 latest patch(es) on my laptop (P4/UP) --
(Ingo: this is about the very same trouble I've reported while pre-testing
U6).

Sorry that I can't show any trace dumps; only a hard-screenshot (with
digital camera?) would be possible but rather incomplete. The serial
console hack is not an option--these "modern" laptops doesn't come with
serial ports anymore, and netconsole is a no-op at a so early point of the
boot process. Or so I believe.

OK. After some incremental configurations, I've isolated that those
oops(es) only occurs if PREEMPT_TIMING and/or LATENCY_TRACE areset (Y). My
first suspect was that newest RWSEM_DEADLOCK_DETECT, but it wasn't the
case.

So something has broken on that non-preemptible critical section timing
stuff since U4.

Hasn't anybody else stumbled on this?
-- 
rncbc aka Rui Nuno Capela
rncbc@rncbc.org

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U6

[Thomas Gleixner]

On Tue, 2004-10-19 at 17:23, Rui Nuno Capela wrote:
> Ingo Molnar wrote:
> >
> >> i have released the -U6 Real-Time Preemption patch:
> >>
> >>   http://redhat.com/~mingo/realtime-preempt/realtime-preempt-2.6.9-rc4-mm1-U6
> >
> 
> I'm experiencing terrible kernel panics at a very early bootstrap stage
> while testing the U5 and U6 latest patch(es) on my laptop (P4/UP) --
> (Ingo: this is about the very same trouble I've reported while pre-testing
> U6).
> 
> Sorry that I can't show any trace dumps; only a hard-screenshot (with
> digital camera?) would be possible but rather incomplete. The serial
> console hack is not an option--these "modern" laptops doesn't come with
> serial ports anymore, and netconsole is a no-op at a so early point of the
> boot process. Or so I believe.
> 
> OK. After some incremental configurations, I've isolated that those
> oops(es) only occurs if PREEMPT_TIMING and/or LATENCY_TRACE areset (Y). My
> first suspect was that newest RWSEM_DEADLOCK_DETECT, but it wasn't the
> case.

Same here on al DELL P4/UP. 

tglx

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U6

[Ingo Molnar]

* Thomas Gleixner <tglx@linutronix.de> wrote:

> > Sorry that I can't show any trace dumps; only a hard-screenshot (with
> > digital camera?) would be possible but rather incomplete. The serial
> > console hack is not an option--these "modern" laptops doesn't come with
> > serial ports anymore, and netconsole is a no-op at a so early point of the
> > boot process. Or so I believe.
> > 
> > OK. After some incremental configurations, I've isolated that those
> > oops(es) only occurs if PREEMPT_TIMING and/or LATENCY_TRACE areset (Y). My
> > first suspect was that newest RWSEM_DEADLOCK_DETECT, but it wasn't the
> > case.
> 
> Same here on al DELL P4/UP. 

any chance for serial logging on that box?

and does this bootup crash go away if you unset PREEMPT_TIMING or
LATENCY_TRACE, as suggested by Rui?

	Ingo

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U6

[Thomas Gleixner]

On Tue, 2004-10-19 at 17:57, Ingo Molnar wrote:
> any chance for serial logging on that box?

No

> and does this bootup crash go away if you unset PREEMPT_TIMING or
> LATENCY_TRACE, as suggested by Rui?

It comes into init now, but dies when loading the AGP driver. Have to
look into this.

tglx

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U6

[Thomas Gleixner]

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

On Tue, 2004-10-19 at 18:44, Thomas Gleixner wrote:
> On Tue, 2004-10-19 at 17:57, Ingo Molnar wrote:

The laptop boots now. The culprits, which break the boot are:
pci-hotplug and firewire drivers. 

agp loads correct.

No deeper insight yet.

The IPV6 code triggers the irqs_disabled() check in schedule. dmesg
output attached.

tglx


[-- Attachment #2: dmesg-lap.txt --]
[-- Type: text/plain, Size: 15403 bytes --]

0000 (reserved)
0MB HIGHMEM available.
511MB LOWMEM available.
On node 0 totalpages: 131023
  DMA zone: 4096 pages, LIFO batch:1
  Normal zone: 126927 pages, LIFO batch:16
  HighMem zone: 0 pages, LIFO batch:1
DMI 2.3 present.
ACPI: RSDP (v000 DELL                                  ) @ 0x000fdea0
ACPI: RSDT (v001 DELL    CPi R   0x27d40113 ASL  0x00000061) @ 0x1fff0000
ACPI: FADT (v001 DELL    CPi R   0x27d40113 ASL  0x00000061) @ 0x1fff0400
ACPI: MADT (v001 DELL    CPi R   0x27d40113 ASL  0x00000047) @ 0x1fff0c00
ACPI: DSDT (v001 INT430 SYSFexxx 0x00001001 MSFT 0x0100000e) @ 0x00000000
ACPI: PM-Timer IO Port: 0x1008
ACPI: Local APIC address 0xfee00000
ACPI: LAPIC (acpi_id[0x00] lapic_id[0x00] enabled)
Processor #0 15:2 APIC version 20
ACPI: LAPIC (acpi_id[0x01] lapic_id[0x01] disabled)
ACPI: LAPIC_NMI (acpi_id[0x00] high edge lint[0x1])
ACPI: LAPIC_NMI (acpi_id[0x01] high edge lint[0x1])
ACPI: IOAPIC (id[0x01] address[0xfec00000] gsi_base[0])
IOAPIC[0]: apic_id 1, version 32, address 0xfec00000, GSI 0-23
ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
ACPI: IRQ0 used by override.
ACPI: IRQ2 used by override.
ACPI: IRQ9 used by override.
Enabling APIC mode:  Flat.  Using 1 I/O APICs
Using ACPI (MADT) for SMP configuration information
Built 1 zonelists
Initializing CPU#0
Kernel command line: root=/dev/hdc6 ro 
PID hash table entries: 2048 (order: 11, 32768 bytes)
Detected 3056.985 MHz processor.
Using pmtmr for high-res timesource
Console: colour VGA+ 80x25
Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
Memory: 515412k/524092k available (1776k kernel code, 8124k reserved, 811k data, 148k init, 0k highmem)
Checking if this processor honours the WP bit even in supervisor mode... Ok.
Calibrating delay loop... 6062.08 BogoMIPS (lpj=3031040)
Security Scaffold v1.0.0 initialized
Mount-cache hash table entries: 512 (order: 0, 4096 bytes)
CPU: After generic identify, caps: bfebfbff 00000000 00000000 00000000
CPU: After vendor identify, caps:  bfebfbff 00000000 00000000 00000000
CPU: Trace cache: 12K uops, L1 D cache: 8K
CPU: L2 cache: 512K
CPU: After all inits, caps:        bfebfbff 00000000 00000000 00000080
Intel machine check architecture supported.
Intel machine check reporting enabled on CPU#0.
CPU0: Intel P4/Xeon Extended MCE MSRs (12) available
CPU0: Thermal monitoring enabled
CPU: Intel Mobile Intel(R) Pentium(R) 4     CPU 3.06GHz stepping 09
Enabling fast FPU save and restore... done.
Enabling unmasked SIMD FPU exception support... done.
Checking 'hlt' instruction... OK.
ENABLING IO-APIC IRQs
..TIMER: vector=0x31 pin1=2 pin2=-1
ksoftirqd started up.
NET: Registered protocol family 16
PCI: PCI BIOS revision 2.10 entry at 0xfcf1e, last bus=2
PCI: Using configuration type 1
mtrr: v2.0 (20020519)
ACPI: Subsystem revision 20040816
ACPI: Interpreter enabled
ACPI: Using IOAPIC for interrupt routing
ACPI: PCI Root Bridge [PCI0] (00:00)
PCI: Probing PCI hardware (bus 00)
PCI: Ignoring BAR0-3 of IDE controller 0000:00:1f.1
PCI: Transparent bridge - 0000:00:1e.0
ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT]
ACPI: PCI Interrupt Link [LNKA] (IRQs 9 10 *11)
ACPI: PCI Interrupt Link [LNKB] (IRQs 5 7) *11
ACPI: PCI Interrupt Link [LNKC] (IRQs 9 10 *11)
ACPI: PCI Interrupt Link [LNKD] (IRQs 5 7 9 10 *11)
ACPI: PCI Interrupt Link [LNKE] (IRQs 3 4 5 6 7 9 10 *11 12 14 15)
ACPI: PCI Interrupt Link [LNKH] (IRQs 3 4 5 6 7 9 10 *11 12 14 15)
ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.AGP_._PRT]
ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.PCIE._PRT]
Linux Plug and Play Support v0.97 (c) Adam Belay
PnPBIOS: Scanning system for PnP BIOS support...
PnPBIOS: Found PnP BIOS installation structure at 0xc00fe2d0
PnPBIOS: PnP BIOS version 1.0, entry 0xf0000:0xe2f4, dseg 0x40
PnPBIOS: 12 nodes reported by PnP BIOS; 12 recorded by driver
PCI: Using ACPI for IRQ routing
** PCI interrupts are no longer routed automatically.  If this
** causes a device to stop working, it is probably because the
** driver failed to call pci_enable_device().  As a temporary
** workaround, the "pci=routeirq" argument restores the old
** behavior.  If this argument makes the device work again,
** please email the output of "lspci" to bjorn.helgaas@hp.com
** so I can fix the driver.
pnp: 00:01: ioport range 0x1000-0x105f could not be reserved
pnp: 00:01: ioport range 0x1060-0x107f has been reserved
pnp: 00:01: ioport range 0x1080-0x10bf has been reserved
pnp: 00:01: ioport range 0x10c0-0x10ff could not be reserved
pnp: 00:01: ioport range 0xf400-0xf4fe has been reserved
VFS: Disk quotas dquot_6.5.1
Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
devfs: 2004-01-31 Richard Gooch (rgooch@atnf.csiro.au)
devfs: boot_options: 0x0
Initializing Cryptographic API
isapnp: Scanning for PnP cards...
isapnp: No Plug & Play device found
ACPI: PS/2 Keyboard Controller [KBC] at I/O 0x60, 0x66, irq 1
ACPI: PS/2 Mouse Controller [PS2M] at irq 12
i8042.c: Can't read CTR while initializing i8042.
Serial: 8250/16550 driver $Revision: 1.90 $ 48 ports, IRQ sharing enabled
ACPI: PCI interrupt 0000:00:1f.6[B] -> GSI 17 (level, low) -> IRQ 17
io scheduler noop registered
io scheduler anticipatory registered
io scheduler deadline registered
io scheduler cfq registered
RAMDISK driver initialized: 16 RAM disks of 8192K size 1024 blocksize
Uniform Multi-Platform E-IDE driver Revision: 7.00alpha2
ide: Assuming 33MHz system bus speed for PIO modes; override with idebus=xx
ICH4: IDE controller at PCI slot 0000:00:1f.1
PCI: Enabling device 0000:00:1f.1 (0005 -> 0007)
ACPI: PCI interrupt 0000:00:1f.1[A] -> GSI 16 (level, low) -> IRQ 16
ICH4: chipset revision 1
ICH4: not 100% native mode: will probe irqs later
    ide0: BM-DMA at 0xbfa0-0xbfa7, BIOS settings: hda:DMA, hdb:pio
    ide1: BM-DMA at 0xbfa8-0xbfaf, BIOS settings: hdc:DMA, hdd:pio
Probing IDE interface ide0...
hda: HL-DT-STCD-RW/DVD-ROM GCC-4241N, ATAPI CD/DVD-ROM drive
elevator: using anticipatory as default io scheduler
ide0 at 0x1f0-0x1f7,0x3f6 on irq 14
Probing IDE interface ide1...
hdc: IC25N040ATMR04-0, ATA DISK drive
ide1 at 0x170-0x177,0x376 on irq 15
Probing IDE interface ide2...
ide2: Wait for ready failed before probe !
Probing IDE interface ide3...
ide3: Wait for ready failed before probe !
Probing IDE interface ide4...
ide4: Wait for ready failed before probe !
Probing IDE interface ide5...
ide5: Wait for ready failed before probe !
hdc: max request size: 1024KiB
hdc: 78140160 sectors (40007 MB) w/1740KiB Cache, CHS=16383/255/63, UDMA(100)
hdc: cache flushes supported
 /dev/ide/host0/bus1/target0/lun0: p1 p2 p3 p4 < p5 p6 p7 >
NET: Registered protocol family 2
IP: routing cache hash table of 64 buckets, 18Kbytes
TCP: Hash tables configured (established 512 bind 923)
NET: Registered protocol family 8
NET: Registered protocol family 20
ACPI: (supports S0 S1 S3 S4 S4bios S5)
ACPI wakeup devices: 
 LID PBTN PCI0 USB0 USB1 USB2 USB3 MODM PCIE 
EXT3-fs: INFO: recovery required on readonly filesystem.
EXT3-fs: write access will be enabled during recovery.
EXT3-fs: recovery complete.
kjournald starting.  Commit interval 5 seconds
EXT3-fs: mounted filesystem with ordered data mode.
VFS: Mounted root (ext3 filesystem) readonly.
Freeing unused kernel memory: 148k freed
NET: Registered protocol family 1
EXT3 FS on hdc6, internal journal
Real Time Clock Driver v1.12
hda: ATAPI 24X DVD-ROM CD-R/RW drive, 2048kB Cache, UDMA(33)
Uniform CD-ROM driver Revision: 3.20
b44.c:v0.95 (Aug 3, 2004)
ACPI: PCI interrupt 0000:02:01.0[A] -> GSI 17 (level, low) -> IRQ 17
eth0: Broadcom 4400 10/100BaseT Ethernet 00:0d:56:39:10:9e
device-mapper: 4.1.0-ioctl (2003-12-10) initialised: dm@uk.sistina.com
kjournald starting.  Commit interval 5 seconds
EXT3 FS on hdc3, internal journal
EXT3-fs: mounted filesystem with ordered data mode.
kjournald starting.  Commit interval 5 seconds
EXT3 FS on hdc7, internal journal
EXT3-fs: mounted filesystem with ordered data mode.
ACPI: PCI interrupt 0000:00:1f.5[B] -> GSI 17 (level, low) -> IRQ 17
PCI: Setting latency timer of device 0000:00:1f.5 to 64
intel8x0_measure_ac97_clock: measured 49346 usecs
intel8x0: clocking to 48000
usbcore: registered new driver usbfs
usbcore: registered new driver hub
ACPI: PCI interrupt 0000:00:1d.7[D] -> GSI 23 (level, low) -> IRQ 23
ehci_hcd 0000:00:1d.7: Intel Corp. 82801DB/DBM (ICH4/ICH4-M) USB 2.0 EHCI Controller
PCI: Setting latency timer of device 0000:00:1d.7 to 64
ehci_hcd 0000:00:1d.7: irq 23, pci mem 0xf4fffc00
ehci_hcd 0000:00:1d.7: new USB bus registered, assigned bus number 1
PCI: cache line size of 128 is not supported by device 0000:00:1d.7
ehci_hcd 0000:00:1d.7: USB 2.0 enabled, EHCI 1.00, driver 2004-May-10
hub 1-0:1.0: USB hub found
hub 1-0:1.0: 6 ports detected
Linux Kernel Card Services
  options:  [pci] [cardbus] [pm]
PCI: Enabling device 0000:02:04.0 (0000 -> 0002)
ACPI: PCI interrupt 0000:02:04.0[A] -> GSI 16 (level, low) -> IRQ 16
Yenta: CardBus bridge found at 0000:02:04.0 [1028:015f]
Yenta: ISA IRQ mask 0x0cf8, PCI irq 16
Socket status: 30000006
input: PC Speaker
USB Universal Host Controller Interface driver v2.2
ACPI: PCI interrupt 0000:00:1d.0[A] -> GSI 16 (level, low) -> IRQ 16
uhci_hcd 0000:00:1d.0: Intel Corp. 82801DB/DBL/DBM (ICH4/ICH4-L/ICH4-M) USB UHCI Controller #1
PCI: Setting latency timer of device 0000:00:1d.0 to 64
uhci_hcd 0000:00:1d.0: irq 16, io base 0xbf80
uhci_hcd 0000:00:1d.0: new USB bus registered, assigned bus number 2
hub 2-0:1.0: USB hub found
hub 2-0:1.0: 2 ports detected
ACPI: PCI interrupt 0000:00:1d.1[B] -> GSI 19 (level, low) -> IRQ 19
uhci_hcd 0000:00:1d.1: Intel Corp. 82801DB/DBL/DBM (ICH4/ICH4-L/ICH4-M) USB UHCI Controller #2
PCI: Setting latency timer of device 0000:00:1d.1 to 64
uhci_hcd 0000:00:1d.1: irq 19, io base 0xbf40
uhci_hcd 0000:00:1d.1: new USB bus registered, assigned bus number 3
hub 3-0:1.0: USB hub found
hub 3-0:1.0: 2 ports detected
ACPI: PCI interrupt 0000:00:1d.2[C] -> GSI 18 (level, low) -> IRQ 18
uhci_hcd 0000:00:1d.2: Intel Corp. 82801DB/DBL/DBM (ICH4/ICH4-L/ICH4-M) USB UHCI Controller #3
PCI: Setting latency timer of device 0000:00:1d.2 to 64
uhci_hcd 0000:00:1d.2: irq 18, io base 0xbf20
uhci_hcd 0000:00:1d.2: new USB bus registered, assigned bus number 4
usb 2-1: new low speed USB device using address 2
hub 4-0:1.0: USB hub found
hub 4-0:1.0: 2 ports detected
usbcore: registered new driver hiddev
input: USB HID v1.10 Keyboard [Logitech USB Receiver] on usb-0000:00:1d.0-1
input: USB HID v1.10 Mouse [Logitech USB Receiver] on usb-0000:00:1d.0-1
usbcore: registered new driver usbhid
/home/thomas/work/LibeRTOS/work/2.6.9-rc4-mm1-VP-U4-LRT1/drivers/usb/input/hid-core.c: v2.0:USB HID core driver
mice: PS/2 mouse device common for all mice
hw_random: RNG not detected
Intel 810 + AC97 Audio, version 1.01, 18:13:38 Oct 19 2004
ACPI: PCI interrupt 0000:00:1f.6[B] -> GSI 17 (level, low) -> IRQ 17
PCI: Setting latency timer of device 0000:00:1f.6 to 64
MC'97 1 converters and GPIO not ready (0xff00)
b44: eth0: Link is down.
NET: Registered protocol family 17
b44: eth0: Link is up at 100 Mbps, full duplex.
b44: eth0: Flow control is on for TX and on for RX.
Capability LSM initialized
NET: Registered protocol family 10
Disabled Privacy Extensions on device c0353400(lo)
BUG: sleeping function called from invalid context modprobe(3296) at /home/thomas/work/LibeRTOS/work/2.6.9-rc4-mm1-VP-U4-LRT1/lib/rwsem-generic.c:313
in_atomic():1 [00000001], irqs_disabled():0
 [<c0119e85>] __might_sleep+0xba/0xc9
 [<c02bac00>] down_read+0x1b/0x1d1
 [<c0130cd8>] _rw_mutex_read_lock+0x13/0x22
 [<e09b6d36>] ndisc_constructor+0x3d/0x21a [ipv6]
 [<c025bf7f>] neigh_create+0x1dd/0x1e9
 [<c025bc38>] neigh_lookup+0x9e/0x103
 [<e09b3303>] addrconf_dst_alloc+0x164/0x17a [ipv6]
 [<e09aa7ee>] ipv6_add_addr+0xbf/0x26a [ipv6]
 [<e09acd8b>] init_loopback+0x59/0x10f [ipv6]
 [<e09ad220>] addrconf_notify+0xfa/0x190 [ipv6]
 [<c0129358>] notifier_chain_register+0x44/0x4c
 [<c0257160>] register_netdevice_notifier+0x6c/0x6e
 [<e08a830c>] addrconf_init+0xf/0x81 [ipv6]
 [<e08a81c6>] inet6_init+0x13c/0x203 [ipv6]
 [<c0134ee1>] sys_init_module+0x17a/0x227
 [<c01060df>] syscall_call+0x7/0xb
preempt count: 00000002
. 2-level deep critical section nesting:
.. entry 1: ndisc_constructor+0x31/0x21a [ipv6] / (0x0)
.. entry 2: print_traces+0x17/0x50 / (0x0)

BUG: scheduling while atomic: modprobe/0x04000001/3296
caller is cond_resched+0x58/0x73
 [<c02ba15e>] __sched_text_start+0x56e/0x5be
 [<c02ba833>] cond_resched+0x58/0x73
 [<c0106ee5>] dump_stack+0x1c/0x20
 [<c0119e85>] __might_sleep+0xba/0xc9
 [<c02ba833>] cond_resched+0x58/0x73
 [<c02bac05>] down_read+0x20/0x1d1
 [<c0130cd8>] _rw_mutex_read_lock+0x13/0x22
 [<e09b6d36>] ndisc_constructor+0x3d/0x21a [ipv6]
 [<c025bf7f>] neigh_create+0x1dd/0x1e9
 [<c025bc38>] neigh_lookup+0x9e/0x103
 [<e09b3303>] addrconf_dst_alloc+0x164/0x17a [ipv6]
 [<e09aa7ee>] ipv6_add_addr+0xbf/0x26a [ipv6]
 [<e09acd8b>] init_loopback+0x59/0x10f [ipv6]
 [<e09ad220>] addrconf_notify+0xfa/0x190 [ipv6]
 [<c0129358>] notifier_chain_register+0x44/0x4c
 [<c0257160>] register_netdevice_notifier+0x6c/0x6e
 [<e08a830c>] addrconf_init+0xf/0x81 [ipv6]
 [<e08a81c6>] inet6_init+0x13c/0x203 [ipv6]
 [<c0134ee1>] sys_init_module+0x17a/0x227
 [<c01060df>] syscall_call+0x7/0xb
preempt count: 04000002
. 2-level deep critical section nesting:
.. entry 1: ndisc_constructor+0x31/0x21a [ipv6] / (0x0)
.. entry 2: print_traces+0x17/0x50 / (0x0)

IPv6 over IPv4 tunneling driver
apm: BIOS not found.
lp: driver loaded but no devices found
BUG: sleeping function called from invalid context ksoftirqd/0(2) at /home/thomas/work/LibeRTOS/work/2.6.9-rc4-mm1-VP-U4-LRT1/lib/rwsem-generic.c:313
in_atomic():1 [00000001], irqs_disabled():0
 [<c0119e85>] __might_sleep+0xba/0xc9
 [<c02bac00>] down_read+0x1b/0x1d1
 [<c0130cd8>] _rw_mutex_read_lock+0x13/0x22
 [<e09b6d36>] ndisc_constructor+0x3d/0x21a [ipv6]
 [<c025bf7f>] neigh_create+0x1dd/0x1e9
 [<c025bc38>] neigh_lookup+0x9e/0x103
 [<e09b1eb7>] ndisc_dst_alloc+0x130/0x13a [ipv6]
 [<e09b7b5d>] ndisc_send_rs+0x95/0x4bf [ipv6]
 [<e09a6d7f>] ip6_output+0x0/0x44 [ipv6]
 [<e09b56f4>] fib6_prune_clones+0x27/0x2b [ipv6]
 [<e09ada6b>] addrconf_dad_completed+0xa0/0xe9 [ipv6]
 [<e09ad90f>] addrconf_dad_timer+0x37/0xf3 [ipv6]
 [<c0118e4b>] __wake_up+0x59/0x85
 [<e09ad8d8>] addrconf_dad_timer+0x0/0xf3 [ipv6]
 [<c0125414>] run_timer_softirq+0x11f/0x2db
 [<c01216a9>] ___do_softirq+0x79/0xbc
 [<c01219be>] ksoftirqd+0x0/0xc8
 [<c0121774>] _do_softirq+0x17/0x19
 [<c0121a49>] ksoftirqd+0x8b/0xc8
 [<c0130129>] kthread+0xa5/0xab
 [<c0130084>] kthread+0x0/0xab
 [<c0104285>] kernel_thread_helper+0x5/0xb
preempt count: 00000002
. 2-level deep critical section nesting:
.. entry 1: ndisc_constructor+0x31/0x21a [ipv6] / (0x0)
.. entry 2: print_traces+0x17/0x50 / (0x0)

Installing knfsd (copyright (C) 1996 okir@monad.swb.de).
cs: IO port probe 0x0100-0x04ff: excluding 0x4d0-0x4d7
cs: IO port probe 0x0800-0x08ff: excluding 0x800-0x807
cs: IO port probe 0x0c00-0x0cff: clean.
cs: IO port probe 0x0a00-0x0aff: clean.
apm: BIOS not found.
eth0: no IPv6 routers present
apm: BIOS not found.
/home/thomas/work/LibeRTOS/work/2.6.9-rc4-mm1-VP-U4-LRT1/drivers/usb/input/hid-input.c: event field not found
/home/thomas/work/LibeRTOS/work/2.6.9-rc4-mm1-VP-U4-LRT1/drivers/usb/input/hid-input.c: event field not found

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U6

[Ingo Molnar]

* Thomas Gleixner <tglx@linutronix.de> wrote:

> The IPV6 code triggers the irqs_disabled() check in schedule. dmesg
> output attached.

ok, does the patch below, ontop of -U7, fix them?

	Ingo

--- linux.old/include/net/protocol.h	
+++ linux.new/include/net/protocol.h	
@@ -83,6 +83,7 @@ extern spinlock_t inet_proto_lock;
 
 #if defined(CONFIG_IPV6) || defined (CONFIG_IPV6_MODULE)
 extern struct inet6_protocol *inet6_protos[MAX_INET_PROTOS];
+extern rwlock_t inet6_proto_lock;
 #endif
 
 extern int	inet_add_protocol(struct net_protocol *prot, unsigned char num);
--- linux.old/net/ipv6/af_inet6.c	
+++ linux.new/net/ipv6/af_inet6.c	
@@ -94,7 +94,7 @@ atomic_t inet6_sock_nr;
  * build a new socket.
  */
 static struct list_head inetsw6[SOCK_MAX];
-static spinlock_t inetsw6_lock = SPIN_LOCK_UNLOCKED;
+static rwlock_t inetsw6_lock = RW_LOCK_UNLOCKED;
 
 static void inet6_sock_destruct(struct sock *sk)
 {
@@ -127,7 +127,7 @@ static int inet6_create(struct socket *s
 
 	/* Look for the requested type/protocol pair. */
 	answer = NULL;
-	rcu_read_lock();
+	rcu_read_lock_read(&inetsw6_lock);
 	list_for_each_rcu(p, &inetsw6[sock->type]) {
 		answer = list_entry(p, struct inet_protosw, list);
 
@@ -162,7 +162,7 @@ static int inet6_create(struct socket *s
 	answer_prot = answer->prot;
 	answer_no_check = answer->no_check;
 	answer_flags = answer->flags;
-	rcu_read_unlock();
+	rcu_read_unlock_read(&inetsw6_lock);
 
 	BUG_TRAP(answer_prot->slab != NULL);
 
@@ -242,7 +242,7 @@ static int inet6_create(struct socket *s
 out:
 	return rc;
 out_rcu_unlock:
-	rcu_read_unlock();
+	rcu_read_unlock_read(&inetsw6_lock);
 	goto out;
 }
 
@@ -542,7 +542,7 @@ inet6_register_protosw(struct inet_proto
 	int protocol = p->protocol;
 	struct list_head *last_perm;
 
-	spin_lock_bh(&inetsw6_lock);
+	write_lock_bh(&inetsw6_lock);
 
 	if (p->type >= SOCK_MAX)
 		goto out_illegal;
@@ -573,7 +573,7 @@ inet6_register_protosw(struct inet_proto
 	 */
 	list_add_rcu(&p->list, last_perm);
 out:
-	spin_unlock_bh(&inetsw6_lock);
+	write_unlock_bh(&inetsw6_lock);
 	return;
 
 out_permanent:
@@ -596,9 +596,9 @@ inet6_unregister_protosw(struct inet_pro
 		       "Attempt to unregister permanent protocol %d.\n",
 		       p->protocol);
 	} else {
-		spin_lock_bh(&inetsw6_lock);
+		write_lock_bh(&inetsw6_lock);
 		list_del_rcu(&p->list);
-		spin_unlock_bh(&inetsw6_lock);
+		write_unlock_bh(&inetsw6_lock);
 
 		synchronize_net();
 	}
--- linux.old/net/ipv6/icmp.c	
+++ linux.new/net/ipv6/icmp.c	
@@ -537,11 +537,11 @@ static void icmpv6_notify(struct sk_buff
 
 	hash = nexthdr & (MAX_INET_PROTOS - 1);
 
-	rcu_read_lock();
+	rcu_read_lock_read(&inet6_proto_lock);
 	ipprot = rcu_dereference(inet6_protos[hash]);
 	if (ipprot && ipprot->err_handler)
 		ipprot->err_handler(skb, NULL, type, code, inner_offset, info);
-	rcu_read_unlock();
+	rcu_read_unlock_read(&inet6_proto_lock);
 
 	read_lock(&raw_v6_lock);
 	if ((sk = sk_head(&raw_v6_htable[hash])) != NULL) {
--- linux.old/net/ipv6/ip6_input.c	
+++ linux.new/net/ipv6/ip6_input.c	
@@ -156,7 +156,7 @@ static inline int ip6_input_finish(struc
 		skb->h.raw += (skb->h.raw[1]+1)<<3;
 	}
 
-	rcu_read_lock();
+	rcu_read_lock_read(&raw_v6_lock);
 resubmit:
 	if (!pskb_pull(skb, skb->h.raw - skb->data))
 		goto discard;
@@ -205,12 +205,12 @@ resubmit:
 			kfree_skb(skb);
 		}
 	}
-	rcu_read_unlock();
+	rcu_read_unlock_read(&raw_v6_lock);
 	return 0;
 
 discard:
 	IP6_INC_STATS_BH(IPSTATS_MIB_INDISCARDS);
-	rcu_read_unlock();
+	rcu_read_unlock_read(&raw_v6_lock);
 	kfree_skb(skb);
 	return 0;
 }
--- linux.old/net/ipv6/ndisc.c	
+++ linux.new/net/ipv6/ndisc.c	
@@ -289,17 +289,17 @@ static int ndisc_constructor(struct neig
 	struct neigh_parms *parms;
 	int is_multicast = ipv6_addr_is_multicast(addr);
 
-	rcu_read_lock();
+	rcu_read_lock_read(&addrconf_lock);
 	in6_dev = in6_dev_get(dev);
 	if (in6_dev == NULL) {
-		rcu_read_unlock();
+		rcu_read_unlock_read(&addrconf_lock);
 		return -EINVAL;
 	}
 
 	parms = in6_dev->nd_parms;
 	__neigh_parms_put(neigh->parms);
 	neigh->parms = neigh_parms_clone(parms);
-	rcu_read_unlock();
+	rcu_read_unlock_read(&addrconf_lock);
 
 	neigh->type = is_multicast ? RTN_MULTICAST : RTN_UNICAST;
 	if (dev->hard_header == NULL) {
--- linux.old/net/ipv6/protocol.c	
+++ linux.new/net/ipv6/protocol.c	
@@ -40,14 +40,14 @@
 #include <net/protocol.h>
 
 struct inet6_protocol *inet6_protos[MAX_INET_PROTOS];
-static spinlock_t inet6_proto_lock = SPIN_LOCK_UNLOCKED;
+rwlock_t inet6_proto_lock = RW_LOCK_UNLOCKED;
 
 
 int inet6_add_protocol(struct inet6_protocol *prot, unsigned char protocol)
 {
 	int ret, hash = protocol & (MAX_INET_PROTOS - 1);
 
-	spin_lock_bh(&inet6_proto_lock);
+	write_lock_bh(&inet6_proto_lock);
 
 	if (inet6_protos[hash]) {
 		ret = -1;
@@ -56,7 +56,7 @@ int inet6_add_protocol(struct inet6_prot
 		ret = 0;
 	}
 
-	spin_unlock_bh(&inet6_proto_lock);
+	write_unlock_bh(&inet6_proto_lock);
 
 	return ret;
 }
@@ -69,7 +69,7 @@ int inet6_del_protocol(struct inet6_prot
 {
 	int ret, hash = protocol & (MAX_INET_PROTOS - 1);
 
-	spin_lock_bh(&inet6_proto_lock);
+	write_lock_bh(&inet6_proto_lock);
 
 	if (inet6_protos[hash] != prot) {
 		ret = -1;
@@ -78,7 +78,7 @@ int inet6_del_protocol(struct inet6_prot
 		ret = 0;
 	}
 
-	spin_unlock_bh(&inet6_proto_lock);
+	write_unlock_bh(&inet6_proto_lock);
 
 	synchronize_net();
 

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U6

[Thomas Gleixner]

On Tue, 2004-10-19 at 20:26, Ingo Molnar wrote:
> * Thomas Gleixner <tglx@linutronix.de> wrote:
> 
> > The IPV6 code triggers the irqs_disabled() check in schedule. dmesg
> > output attached.
> 
> ok, does the patch below, ontop of -U7, fix them?

Yes, it does. Thanks.

tglx

> --- linux.old/include/net/protocol.h	
> +++ linux.new/include/net/protocol.h	
> @@ -83,6 +83,7 @@ extern spinlock_t inet_proto_lock;
>  
>  #if defined(CONFIG_IPV6) || defined (CONFIG_IPV6_MODULE)
>  extern struct inet6_protocol *inet6_protos[MAX_INET_PROTOS];
> +extern rwlock_t inet6_proto_lock;
>  #endif
>  
>  extern int	inet_add_protocol(struct net_protocol *prot, unsigned char num);
> --- linux.old/net/ipv6/af_inet6.c	
> +++ linux.new/net/ipv6/af_inet6.c	
> @@ -94,7 +94,7 @@ atomic_t inet6_sock_nr;
>   * build a new socket.
>   */
>  static struct list_head inetsw6[SOCK_MAX];
> -static spinlock_t inetsw6_lock = SPIN_LOCK_UNLOCKED;
> +static rwlock_t inetsw6_lock = RW_LOCK_UNLOCKED;
>  
>  static void inet6_sock_destruct(struct sock *sk)
>  {
> @@ -127,7 +127,7 @@ static int inet6_create(struct socket *s
>  
>  	/* Look for the requested type/protocol pair. */
>  	answer = NULL;
> -	rcu_read_lock();
> +	rcu_read_lock_read(&inetsw6_lock);
>  	list_for_each_rcu(p, &inetsw6[sock->type]) {
>  		answer = list_entry(p, struct inet_protosw, list);
>  
> @@ -162,7 +162,7 @@ static int inet6_create(struct socket *s
>  	answer_prot = answer->prot;
>  	answer_no_check = answer->no_check;
>  	answer_flags = answer->flags;
> -	rcu_read_unlock();
> +	rcu_read_unlock_read(&inetsw6_lock);
>  
>  	BUG_TRAP(answer_prot->slab != NULL);
>  
> @@ -242,7 +242,7 @@ static int inet6_create(struct socket *s
>  out:
>  	return rc;
>  out_rcu_unlock:
> -	rcu_read_unlock();
> +	rcu_read_unlock_read(&inetsw6_lock);
>  	goto out;
>  }
>  
> @@ -542,7 +542,7 @@ inet6_register_protosw(struct inet_proto
>  	int protocol = p->protocol;
>  	struct list_head *last_perm;
>  
> -	spin_lock_bh(&inetsw6_lock);
> +	write_lock_bh(&inetsw6_lock);
>  
>  	if (p->type >= SOCK_MAX)
>  		goto out_illegal;
> @@ -573,7 +573,7 @@ inet6_register_protosw(struct inet_proto
>  	 */
>  	list_add_rcu(&p->list, last_perm);
>  out:
> -	spin_unlock_bh(&inetsw6_lock);
> +	write_unlock_bh(&inetsw6_lock);
>  	return;
>  
>  out_permanent:
> @@ -596,9 +596,9 @@ inet6_unregister_protosw(struct inet_pro
>  		       "Attempt to unregister permanent protocol %d.\n",
>  		       p->protocol);
>  	} else {
> -		spin_lock_bh(&inetsw6_lock);
> +		write_lock_bh(&inetsw6_lock);
>  		list_del_rcu(&p->list);
> -		spin_unlock_bh(&inetsw6_lock);
> +		write_unlock_bh(&inetsw6_lock);
>  
>  		synchronize_net();
>  	}
> --- linux.old/net/ipv6/icmp.c	
> +++ linux.new/net/ipv6/icmp.c	
> @@ -537,11 +537,11 @@ static void icmpv6_notify(struct sk_buff
>  
>  	hash = nexthdr & (MAX_INET_PROTOS - 1);
>  
> -	rcu_read_lock();
> +	rcu_read_lock_read(&inet6_proto_lock);
>  	ipprot = rcu_dereference(inet6_protos[hash]);
>  	if (ipprot && ipprot->err_handler)
>  		ipprot->err_handler(skb, NULL, type, code, inner_offset, info);
> -	rcu_read_unlock();
> +	rcu_read_unlock_read(&inet6_proto_lock);
>  
>  	read_lock(&raw_v6_lock);
>  	if ((sk = sk_head(&raw_v6_htable[hash])) != NULL) {
> --- linux.old/net/ipv6/ip6_input.c	
> +++ linux.new/net/ipv6/ip6_input.c	
> @@ -156,7 +156,7 @@ static inline int ip6_input_finish(struc
>  		skb->h.raw += (skb->h.raw[1]+1)<<3;
>  	}
>  
> -	rcu_read_lock();
> +	rcu_read_lock_read(&raw_v6_lock);
>  resubmit:
>  	if (!pskb_pull(skb, skb->h.raw - skb->data))
>  		goto discard;
> @@ -205,12 +205,12 @@ resubmit:
>  			kfree_skb(skb);
>  		}
>  	}
> -	rcu_read_unlock();
> +	rcu_read_unlock_read(&raw_v6_lock);
>  	return 0;
>  
>  discard:
>  	IP6_INC_STATS_BH(IPSTATS_MIB_INDISCARDS);
> -	rcu_read_unlock();
> +	rcu_read_unlock_read(&raw_v6_lock);
>  	kfree_skb(skb);
>  	return 0;
>  }
> --- linux.old/net/ipv6/ndisc.c	
> +++ linux.new/net/ipv6/ndisc.c	
> @@ -289,17 +289,17 @@ static int ndisc_constructor(struct neig
>  	struct neigh_parms *parms;
>  	int is_multicast = ipv6_addr_is_multicast(addr);
>  
> -	rcu_read_lock();
> +	rcu_read_lock_read(&addrconf_lock);
>  	in6_dev = in6_dev_get(dev);
>  	if (in6_dev == NULL) {
> -		rcu_read_unlock();
> +		rcu_read_unlock_read(&addrconf_lock);
>  		return -EINVAL;
>  	}
>  
>  	parms = in6_dev->nd_parms;
>  	__neigh_parms_put(neigh->parms);
>  	neigh->parms = neigh_parms_clone(parms);
> -	rcu_read_unlock();
> +	rcu_read_unlock_read(&addrconf_lock);
>  
>  	neigh->type = is_multicast ? RTN_MULTICAST : RTN_UNICAST;
>  	if (dev->hard_header == NULL) {
> --- linux.old/net/ipv6/protocol.c	
> +++ linux.new/net/ipv6/protocol.c	
> @@ -40,14 +40,14 @@
>  #include <net/protocol.h>
>  
>  struct inet6_protocol *inet6_protos[MAX_INET_PROTOS];
> -static spinlock_t inet6_proto_lock = SPIN_LOCK_UNLOCKED;
> +rwlock_t inet6_proto_lock = RW_LOCK_UNLOCKED;
>  
> 
>  int inet6_add_protocol(struct inet6_protocol *prot, unsigned char protocol)
>  {
>  	int ret, hash = protocol & (MAX_INET_PROTOS - 1);
>  
> -	spin_lock_bh(&inet6_proto_lock);
> +	write_lock_bh(&inet6_proto_lock);
>  
>  	if (inet6_protos[hash]) {
>  		ret = -1;
> @@ -56,7 +56,7 @@ int inet6_add_protocol(struct inet6_prot
>  		ret = 0;
>  	}
>  
> -	spin_unlock_bh(&inet6_proto_lock);
> +	write_unlock_bh(&inet6_proto_lock);
>  
>  	return ret;
>  }
> @@ -69,7 +69,7 @@ int inet6_del_protocol(struct inet6_prot
>  {
>  	int ret, hash = protocol & (MAX_INET_PROTOS - 1);
>  
> -	spin_lock_bh(&inet6_proto_lock);
> +	write_lock_bh(&inet6_proto_lock);
>  
>  	if (inet6_protos[hash] != prot) {
>  		ret = -1;
> @@ -78,7 +78,7 @@ int inet6_del_protocol(struct inet6_prot
>  		ret = 0;
>  	}
>  
> -	spin_unlock_bh(&inet6_proto_lock);
> +	write_unlock_bh(&inet6_proto_lock);
>  
>  	synchronize_net();
>  

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U6

[Ingo Molnar]

* Rui Nuno Capela <rncbc@rncbc.org> wrote:

> OK. After some incremental configurations, I've isolated that those
> oops(es) only occurs if PREEMPT_TIMING and/or LATENCY_TRACE areset
> (Y). My first suspect was that newest RWSEM_DEADLOCK_DETECT, but it
> wasn't the case.
> 
> So something has broken on that non-preemptible critical section
> timing stuff since U4.
> 
> Hasn't anybody else stumbled on this?

i'm using it myself and havent seen the problem yet. Could you send me
the latest .configs, the working and the broken one too? I'll try to
reprodue it (or maybe someone else with a serial console sees it too).

	Ingo

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U6

[K.R. Foley]

Ingo Molnar wrote:
> * Rui Nuno Capela <rncbc@rncbc.org> wrote:
> 
> 
>>OK. After some incremental configurations, I've isolated that those
>>oops(es) only occurs if PREEMPT_TIMING and/or LATENCY_TRACE areset
>>(Y). My first suspect was that newest RWSEM_DEADLOCK_DETECT, but it
>>wasn't the case.
>>
>>So something has broken on that non-preemptible critical section
>>timing stuff since U4.
>>
>>Hasn't anybody else stumbled on this?
> 
> 
> i'm using it myself and havent seen the problem yet. Could you send me
> the latest .configs, the working and the broken one too? I'll try to
> reprodue it (or maybe someone else with a serial console sees it too).
> 
> 	Ingo
> 

I am seeing something similar here with both U5 and U6 on both of my SMP 
systems (actually I haven't gotten to try U6 on my SMP system at home 
yet.) On my SMP system here (dual Xeon) I get a handful of traces during 
the boot and then the last thing I see is a trace that has something to 
do with parport, but the key MIGHT be that it always seems to crap out 
when I get traces for 3-level deep critical section nesting. I will try 
to capture the trace the old-fashioned way when I get a chance shortly.

I do have U5 booted on my UP system at home though.

kr

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U6

[Ingo Molnar]

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

> > Hasn't anybody else stumbled on this?
> 
> i'm using it myself and havent seen the problem yet. Could you send me
> the latest .configs, the working and the broken one too? I'll try to
> reprodue it (or maybe someone else with a serial console sees it too).

i found older .config's from you and i tried your desktop one and it
didnt crash. But when i tried your laptop's U3 .config then i got the
bootup crash immediately. Debugging it ...

	Ingo

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U6

[Ingo Molnar]

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

> 
> * Ingo Molnar <mingo@elte.hu> wrote:
> 
> > > Hasn't anybody else stumbled on this?
> > 
> > i'm using it myself and havent seen the problem yet. Could you send me
> > the latest .configs, the working and the broken one too? I'll try to
> > reprodue it (or maybe someone else with a serial console sees it too).
> 
> i found older .config's from you and i tried your desktop one and it
> didnt crash. But when i tried your laptop's U3 .config then i got the
> bootup crash immediately. Debugging it ...

one difference in your config is that you have 4K stacks enabled. Could
you disable them? Especially with rwsem-detection and tracing enabled
the stack footprint can get pretty large ...

	Ingo

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U6

[Ingo Molnar]

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

> > i found older .config's from you and i tried your desktop one and it
> > didnt crash. But when i tried your laptop's U3 .config then i got the
> > bootup crash immediately. Debugging it ...
> 
> one difference in your config is that you have 4K stacks enabled.
> Could you disable them? Especially with rwsem-detection and tracing
> enabled the stack footprint can get pretty large ...

indeed, this is what triggers with your .config:

 testing NMI watchdog ... OK.
 ENABLING IO-APIC IRQs
 ..TIMER: vector=0x31 pin1=2 pin2=-1
 mcount: stack overflow: 1008
  [<c012cd9f>] ___trace+0x105/0x117
  [<c012cdd7>] __mcount+0x1d/0x1f
  [<c013e015>] cache_grow+0xe/0x1ab
  [<c013e3cd>] cache_alloc_refill+0x21b/0x253

enabling 8K stacks ought to help this one. I've made the limit a bit too
conservative - there's still 1000 bytes left and the assert hits. Here's
the full trace, the large footprint seems to be in zlib initialization:

mcount: stack overflow: 1008
 [<c012cd9f>] ___trace+0x105/0x117
 [<c012cdd7>] __mcount+0x1d/0x1f
 [<c013e015>] cache_grow+0xe/0x1ab
 [<c013e3cd>] cache_alloc_refill+0x21b/0x253
 [<c010efec>] mcount+0x14/0x18
 [<c013e015>] cache_grow+0xe/0x1ab
 [<c013e3cd>] cache_alloc_refill+0x21b/0x253
 [<c013e730>] __kmalloc+0x82/0x9f
 [<c03607c8>] malloc+0x1e/0x20
 [<c01008c9>] huft_build+0x309/0x5e8
 [<c0101bec>] inflate+0x4c/0xb0
 [<c010efec>] mcount+0x14/0x18
 [<c0101279>] inflate_fixed+0xcb/0x1a4
 [<c0101bec>] inflate+0x4c/0xb0
 [<c010efec>] mcount+0x14/0x18
 [<c0101eae>] gunzip+0x1d4/0x396
 [<c036130e>] unpack_to_rootfs+0x162/0x225
 [<c010efec>] mcount+0x14/0x18
 [<c0100434>] init+0x0/0x124
 [<c03613fe>] populate_rootfs+0x2d/0x3f
 [<c010046b>] init+0x37/0x124
 [<c0102365>] kernel_thread_helper+0x5/0xb

	Ingo

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U6

[Ingo Molnar]

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

> enabling 8K stacks ought to help this one. I've made the limit a bit
> too conservative - there's still 1000 bytes left and the assert hits.
> Here's the full trace, the large footprint seems to be in zlib
> initialization:
> 
> mcount: stack overflow: 1008

i've added a stackframe-size field to the end of every stack trace
entry:

mcount: stack overflow: 1008
 [<c012cdaf>] ___trace+0x105/0x117 (12)
 [<c012cde7>] __mcount+0x1d/0x1f (32)
 [<c013e025>] cache_grow+0xe/0x1ab (4)
 [<c013e3dd>] cache_alloc_refill+0x21b/0x253 (4)
 [<c010effc>] mcount+0x14/0x18 (8)
 [<c013e025>] cache_grow+0xe/0x1ab (20)
 [<c013e3dd>] cache_alloc_refill+0x21b/0x253 (52)
 [<c013e740>] __kmalloc+0x82/0x9f (48)
 [<c03607c8>] malloc+0x1e/0x20 (28)
 [<c01008c9>] huft_build+0x309/0x5e8 (16)
 [<c0101bec>] inflate+0x4c/0xb0 (1444)
 [<c010effc>] mcount+0x14/0x18 (8)
 [<c0101279>] inflate_fixed+0xcb/0x1a4 (20)
 [<c0101bec>] inflate+0x4c/0xb0 (1212)
 [<c010effc>] mcount+0x14/0x18 (12)
 [<c0101eae>] gunzip+0x1d4/0x396 (20)
 [<c036130e>] unpack_to_rootfs+0x162/0x225 (28)
 [<c010effc>] mcount+0x14/0x18 (8)
 [<c0100434>] init+0x0/0x124 (4)
 [<c03613fe>] populate_rootfs+0x2d/0x3f (16)
 [<c010046b>] init+0x37/0x124 (20)
 [<c0102365>] kernel_thread_helper+0x5/0xb (20)

as suspected, zlib's huft_build() is fun:

  lib/inflate.c:

  #define N_MAX 288       /* maximum number of codes in any set */

  STATIC int huft_build(
  ...
  {

    unsigned v[N_MAX];            /* values in order of bit length */

a whopping 1152 bytes for this local variable alone! The patch below
fixes this, but there are other overflows as well, later in the bootup.

	Ingo

--- linux/lib/inflate.c.orig
+++ linux/lib/inflate.c
@@ -300,7 +300,7 @@ STATIC int huft_build(
   register struct huft *q;      /* points to current table */
   struct huft r;                /* table entry for structure assignment */
   struct huft *u[BMAX];         /* table stack */
-  unsigned v[N_MAX];            /* values in order of bit length */
+  unsigned *v;                  /* values in order of bit length */
   register int w;               /* bits before this table == (l * h) */
   unsigned x[BMAX+1];           /* bit offsets, then code stack */
   unsigned *xp;                 /* pointer into x */
@@ -309,6 +309,10 @@ STATIC int huft_build(
 
 DEBG("huft1 ");
 
+  /* allocate new table */
+  v = (unsigned *)malloc(sizeof(unsigned)*N_MAX);
+  if (!v)
+    return 3;             /* not enough memory */
   /* Generate counts for each bit length */
   memzero(c, sizeof(c));
   p = b;  i = n;
@@ -322,6 +326,7 @@ DEBG("huft1 ");
   {
     *t = (struct huft *)NULL;
     *m = 0;
+    free(v);
     return 0;
   }
 
@@ -347,10 +352,14 @@ DEBG("huft3 ");
 
   /* Adjust last length count to fill out codes, if needed */
   for (y = 1 << j; j < i; j++, y <<= 1)
-    if ((y -= c[j]) < 0)
+    if ((y -= c[j]) < 0) {
+      free(v);
       return 2;                 /* bad input: more codes than bits */
-  if ((y -= c[i]) < 0)
+    }
+  if ((y -= c[i]) < 0) {
+    free(v);
     return 2;
+  }
   c[i] += y;
 
 DEBG("huft4 ");
@@ -422,6 +431,7 @@ DEBG1("3 ");
         {
           if (h)
             huft_free(u[0]);
+          free(v);
           return 3;             /* not enough memory */
         }
 DEBG1("4 ");
@@ -485,6 +495,7 @@ DEBG("h6f ");
 
 DEBG("huft7 ");
 
+  free(v);
   /* Return true (1) if we were given an incomplete table */
   return y != 0 && g != 1;
 }

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U6

[Florian Schmidt]

On Tue, 19 Oct 2004 16:23:49 +0100 (WEST)
"Rui Nuno Capela" <rncbc@rncbc.org> wrote:

> I'm experiencing terrible kernel panics at a very early bootstrap stage
> while testing the U5 and U6 latest patch(es) on my laptop (P4/UP) --
> (Ingo: this is about the very same trouble I've reported while pre-testing
> U6).

[..]

> OK. After some incremental configurations, I've isolated that those
> oops(es) only occurs if PREEMPT_TIMING and/or LATENCY_TRACE areset (Y). My
> first suspect was that newest RWSEM_DEADLOCK_DETECT, but it wasn't the
> case.
> 
> So something has broken on that non-preemptible critical section timing
> stuff since U4.
> 
> Hasn't anybody else stumbled on this?

I don't get any oopses or panics, but i can observer a rather interesting
behaviour. When i enable the latency traces via

echo 1 > /proc/sys/kernel/trace_enabled

my machine starts to make little pauses of ca 3-4 secs. X "hangs" for this
duration and so does aplay when playing a .wav file. "hangs" means that the
X display seems to be locked. Interestingly enough all keystrokes i entered
during the "hang" seem to arrive fine after the hang has ended. aplay
experiences an xrun.

jackd OTOH is not affected (probably since it runs SCHED_FIFO). I can
happily continue noodling with my guitar through jackd and jack-rack..

But besides that it runs fine here. I get some fairly long non preemptible
critical sections reports though.

here's one (i snipped off quite a few in the middle to make the email
smaller):

preemption latency trace v1.0.7 on 2.6.9-rc4-mm1-RT-U6
-------------------------------------------------------
 latency: 1841 us, entries: 4000 (12990)   |   [VP:1 KP:1 SP:1 HP:1 #CPUS:1]
    -----------------
    | task: aplay/2160, uid:1000 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: __schedule+0x3b/0x5d0 <c02a767b>
 => ended at:   finish_task_switch+0x43/0xb0 <c0114ae3>
=======>
00000001 0.000ms (+0.000ms): __schedule (ksoftirqd)
00000001 0.000ms (+0.000ms): sched_clock (__schedule)
00000002 0.000ms (+0.000ms): deactivate_task (__schedule)
00000002 0.000ms (+0.000ms): dequeue_task (deactivate_task)
04000002 0.000ms (+0.000ms): __switch_to (__schedule)
04000002 0.001ms (+0.000ms): finish_task_switch (__schedule)
04000000 0.001ms (+0.000ms): schedule (down_write)
04000000 0.001ms (+0.000ms): __schedule (down_write)
04000001 0.001ms (+0.000ms): sched_clock (__schedule)
04000000 0.001ms (+0.000ms): schedule (down_write)
04000000 0.001ms (+0.000ms): __schedule (down_write)
04000001 0.002ms (+0.000ms): sched_clock (__schedule)
04000000 0.002ms (+0.000ms): schedule (down_write)
04000000 0.002ms (+0.000ms): __schedule (down_write)
04000001 0.002ms (+0.000ms): sched_clock (__schedule)
04000000 0.002ms (+0.000ms): schedule (down_write)
04000000 0.002ms (+0.000ms): __schedule (down_write)
04000001 0.003ms (+0.000ms): sched_clock (__schedule)
04000000 0.003ms (+0.000ms): schedule (down_write)
04000000 0.003ms (+0.000ms): __schedule (down_write)
04000001 0.003ms (+0.000ms): sched_clock (__schedule)
04000000 0.003ms (+0.000ms): schedule (down_write)
04000000 0.003ms (+0.000ms): __schedule (down_write)
04000001 0.003ms (+0.000ms): sched_clock (__schedule)
04000000 0.004ms (+0.000ms): schedule (down_write)
04000000 0.004ms (+0.000ms): __schedule (down_write)
04000001 0.004ms (+0.000ms): sched_clock (__schedule)
04000000 0.004ms (+0.000ms): schedule (down_write)
04000000 0.004ms (+0.000ms): __schedule (down_write)
04000001 0.004ms (+0.000ms): sched_clock (__schedule)
04000000 0.005ms (+0.000ms): schedule (down_write)
04000000 0.005ms (+0.000ms): __schedule (down_write)
04000001 0.005ms (+0.000ms): sched_clock (__schedule)
04000000 0.005ms (+0.000ms): schedule (down_write)
04000000 0.005ms (+0.000ms): __schedule (down_write)
04000001 0.005ms (+0.000ms): sched_clock (__schedule)
04000000 0.006ms (+0.000ms): schedule (down_write)
04000000 0.006ms (+0.000ms): __schedule (down_write)
04000001 0.006ms (+0.000ms): sched_clock (__schedule)
04000000 0.006ms (+0.000ms): schedule (down_write)
04000000 0.006ms (+0.000ms): __schedule (down_write)
04000001 0.006ms (+0.000ms): sched_clock (__schedule)
04000000 0.006ms (+0.000ms): schedule (down_write)
04000000 0.007ms (+0.000ms): __schedule (down_write)
04000001 0.007ms (+0.000ms): sched_clock (__schedule)
04000000 0.007ms (+0.000ms): schedule (down_write)
04000000 0.007ms (+0.000ms): __schedule (down_write)
04000001 0.007ms (+0.000ms): sched_clock (__schedule)
04000000 0.007ms (+0.000ms): schedule (down_write)
04000000 0.007ms (+0.000ms): __schedule (down_write)
04000001 0.008ms (+0.000ms): sched_clock (__schedule)
04000000 0.008ms (+0.000ms): schedule (down_write)
04000000 0.008ms (+0.000ms): __schedule (down_write)
04000001 0.008ms (+0.000ms): sched_clock (__schedule)
04000000 0.008ms (+0.000ms): schedule (down_write)
04000000 0.008ms (+0.000ms): __schedule (down_write)
04000001 0.009ms (+0.000ms): sched_clock (__schedule)
04000000 0.009ms (+0.000ms): schedule (down_write)
04000000 0.009ms (+0.000ms): __schedule (down_write)
04000001 0.009ms (+0.000ms): sched_clock (__schedule)
04000000 0.009ms (+0.000ms): schedule (down_write)
04000000 0.009ms (+0.000ms): __schedule (down_write)
04000001 0.009ms (+0.000ms): sched_clock (__schedule)
04000000 0.010ms (+0.000ms): schedule (down_write)
04000000 0.010ms (+0.000ms): __schedule (down_write)
04000001 0.010ms (+0.000ms): sched_clock (__schedule)
04000000 0.010ms (+0.000ms): schedule (down_write)
04000000 0.010ms (+0.000ms): __schedule (down_write)
04000001 0.010ms (+0.000ms): sched_clock (__schedule)
04000000 0.011ms (+0.000ms): schedule (down_write)
04000000 0.011ms (+0.000ms): __schedule (down_write)
04000001 0.011ms (+0.000ms): sched_clock (__schedule)
04000000 0.011ms (+0.000ms): schedule (down_write)
04000000 0.011ms (+0.000ms): __schedule (down_write)
04000001 0.011ms (+0.000ms): sched_clock (__schedule)
04000000 0.012ms (+0.000ms): schedule (down_write)
04000000 0.012ms (+0.000ms): __schedule (down_write)
04000001 0.012ms (+0.000ms): sched_clock (__schedule)
04000000 0.012ms (+0.000ms): schedule (down_write)
04000000 0.012ms (+0.000ms): __schedule (down_write)
04000001 0.012ms (+0.000ms): sched_clock (__schedule)
04000000 0.012ms (+0.000ms): schedule (down_write)
04000000 0.013ms (+0.000ms): __schedule (down_write)
04000001 0.013ms (+0.000ms): sched_clock (__schedule)
04000000 0.013ms (+0.000ms): schedule (down_write)
04000000 0.013ms (+0.000ms): __schedule (down_write)
04000001 0.013ms (+0.000ms): sched_clock (__schedule)
04000000 0.013ms (+0.000ms): schedule (down_write)
04000000 0.013ms (+0.000ms): __schedule (down_write)
04000001 0.014ms (+0.000ms): sched_clock (__schedule)
04000000 0.014ms (+0.000ms): schedule (down_write)
04000000 0.014ms (+0.000ms): __schedule (down_write)
04000001 0.014ms (+0.000ms): sched_clock (__schedule)
04000000 0.014ms (+0.000ms): schedule (down_write)
04000000 0.014ms (+0.000ms): __schedule (down_write)
04000001 0.014ms (+0.000ms): sched_clock (__schedule)
04000000 0.015ms (+0.000ms): schedule (down_write)
04000000 0.015ms (+0.000ms): __schedule (down_write)
04000001 0.015ms (+0.000ms): sched_clock (__schedule)
04000000 0.015ms (+0.000ms): schedule (down_write)
04000000 0.015ms (+0.000ms): __schedule (down_write)
04000001 0.015ms (+0.000ms): sched_clock (__schedule)
04000000 0.016ms (+0.000ms): schedule (down_write)
04000000 0.016ms (+0.000ms): __schedule (down_write)
04000001 0.016ms (+0.000ms): sched_clock (__schedule)
04000000 0.016ms (+0.000ms): schedule (down_write)
04000000 0.016ms (+0.000ms): __schedule (down_write)
04000001 0.016ms (+0.000ms): sched_clock (__schedule)
04000000 0.017ms (+0.000ms): schedule (down_write)
04000000 0.017ms (+0.000ms): __schedule (down_write)
04000001 0.017ms (+0.000ms): sched_clock (__schedule)
04000000 0.017ms (+0.000ms): schedule (down_write)
04000000 0.017ms (+0.000ms): __schedule (down_write)
04000001 0.017ms (+0.000ms): sched_clock (__schedule)
04000000 0.018ms (+0.000ms): schedule (down_write)
04000000 0.018ms (+0.000ms): __schedule (down_write)
04000001 0.018ms (+0.000ms): sched_clock (__schedule)
04000000 0.018ms (+0.000ms): schedule (down_write)
04000000 0.018ms (+0.000ms): __schedule (down_write)
04000001 0.018ms (+0.000ms): sched_clock (__schedule)
04000000 0.018ms (+0.000ms): schedule (down_write)
04000000 0.019ms (+0.000ms): __schedule (down_write)
04000001 0.019ms (+0.000ms): sched_clock (__schedule)
04000000 0.019ms (+0.000ms): schedule (down_write)
04000000 0.019ms (+0.000ms): __schedule (down_write)
04000001 0.019ms (+0.000ms): sched_clock (__schedule)
04000000 0.019ms (+0.000ms): schedule (down_write)
04000000 0.019ms (+0.000ms): __schedule (down_write)
04000001 0.020ms (+0.000ms): sched_clock (__schedule)
04000000 0.020ms (+0.000ms): schedule (down_write)
04000000 0.020ms (+0.000ms): __schedule (down_write)
04000001 0.020ms (+0.000ms): sched_clock (__schedule)
04000000 0.020ms (+0.000ms): schedule (down_write)
04000000 0.020ms (+0.000ms): __schedule (down_write)
04000001 0.020ms (+0.000ms): sched_clock (__schedule)
04000000 0.021ms (+0.000ms): schedule (down_write)
04000000 0.021ms (+0.000ms): __schedule (down_write)
04000001 0.021ms (+0.000ms): sched_clock (__schedule)
04000000 0.021ms (+0.000ms): schedule (down_write)
04000000 0.021ms (+0.000ms): __schedule (down_write)
04000001 0.021ms (+0.000ms): sched_clock (__schedule)
04000000 0.022ms (+0.000ms): schedule (down_write)
04000000 0.022ms (+0.000ms): __schedule (down_write)
04000001 0.022ms (+0.000ms): sched_clock (__schedule)
04000000 0.022ms (+0.000ms): schedule (down_write)
04000000 0.022ms (+0.000ms): __schedule (down_write)
04000001 0.022ms (+0.000ms): sched_clock (__schedule)
04000000 0.023ms (+0.000ms): schedule (down_write)
04000000 0.023ms (+0.000ms): __schedule (down_write)
04000001 0.023ms (+0.000ms): sched_clock (__schedule)
04000000 0.023ms (+0.000ms): schedule (down_write)
04000000 0.023ms (+0.000ms): __schedule (down_write)
04000001 0.023ms (+0.000ms): sched_clock (__schedule)
04000000 0.023ms (+0.000ms): schedule (down_write)
04000000 0.024ms (+0.000ms): __schedule (down_write)
04000001 0.024ms (+0.000ms): sched_clock (__schedule)
04000000 0.024ms (+0.000ms): schedule (down_write)
04000000 0.024ms (+0.000ms): __schedule (down_write)
04000001 0.024ms (+0.000ms): sched_clock (__schedule)
04000000 0.024ms (+0.000ms): schedule (down_write)
04000000 0.025ms (+0.000ms): __schedule (down_write)
04000001 0.025ms (+0.000ms): sched_clock (__schedule)
04000000 0.025ms (+0.000ms): schedule (down_write)
04000000 0.025ms (+0.000ms): __schedule (down_write)
04000001 0.025ms (+0.000ms): sched_clock (__schedule)
04000000 0.025ms (+0.000ms): schedule (down_write)
04000000 0.025ms (+0.000ms): __schedule (down_write)
04000001 0.026ms (+0.000ms): sched_clock (__schedule)
04000000 0.026ms (+0.000ms): schedule (down_write)
04000000 0.026ms (+0.000ms): __schedule (down_write)
04000001 0.026ms (+0.000ms): sched_clock (__schedule)
04000000 0.026ms (+0.000ms): schedule (down_write)
04000000 0.026ms (+0.000ms): __schedule (down_write)
04000001 0.026ms (+0.000ms): sched_clock (__schedule)
04000000 0.027ms (+0.000ms): schedule (down_write)
04000000 0.027ms (+0.000ms): __schedule (down_write)
04000001 0.027ms (+0.000ms): sched_clock (__schedule)
04000000 0.027ms (+0.000ms): schedule (down_write)
04000000 0.027ms (+0.000ms): __schedule (down_write)
04000001 0.027ms (+0.000ms): sched_clock (__schedule)
04000000 0.028ms (+0.000ms): schedule (down_write)
04000000 0.028ms (+0.000ms): __schedule (down_write)
04000001 0.028ms (+0.000ms): sched_clock (__schedule)
04000000 0.028ms (+0.000ms): schedule (down_write)
04000000 0.028ms (+0.000ms): __schedule (down_write)
04000001 0.028ms (+0.000ms): sched_clock (__schedule)
04000000 0.029ms (+0.000ms): schedule (down_write)
04000000 0.029ms (+0.000ms): __schedule (down_write)
04000001 0.029ms (+0.000ms): sched_clock (__schedule)
04000000 0.029ms (+0.000ms): schedule (down_write)
04000000 0.029ms (+0.000ms): __schedule (down_write)
04000001 0.029ms (+0.000ms): sched_clock (__schedule)
04000000 0.029ms (+0.000ms): schedule (down_write)
04000000 0.030ms (+0.000ms): __schedule (down_write)
04000001 0.030ms (+0.000ms): sched_clock (__schedule)
04000000 0.030ms (+0.000ms): schedule (down_write)
04000000 0.030ms (+0.000ms): __schedule (down_write)
04000001 0.030ms (+0.000ms): sched_clock (__schedule)
04000000 0.030ms (+0.000ms): schedule (down_write)
04000000 0.030ms (+0.000ms): __schedule (down_write)
04000001 0.031ms (+0.000ms): sched_clock (__schedule)
04000000 0.031ms (+0.000ms): schedule (down_write)
04000000 0.031ms (+0.000ms): __schedule (down_write)
04000001 0.031ms (+0.000ms): sched_clock (__schedule)
04000000 0.031ms (+0.000ms): schedule (down_write)
04000000 0.031ms (+0.000ms): __schedule (down_write)
04000001 0.031ms (+0.000ms): sched_clock (__schedule)
04000000 0.032ms (+0.000ms): schedule (down_write)
04000000 0.032ms (+0.000ms): __schedule (down_write)
04000001 0.032ms (+0.000ms): sched_clock (__schedule)
04000000 0.032ms (+0.000ms): schedule (down_write)
04000000 0.032ms (+0.000ms): __schedule (down_write)
04000001 0.032ms (+0.000ms): sched_clock (__schedule)
04000000 0.033ms (+0.000ms): schedule (down_write)
04000000 0.033ms (+0.000ms): __schedule (down_write)
04000001 0.033ms (+0.000ms): sched_clock (__schedule)
04000000 0.033ms (+0.000ms): schedule (down_write)
04000000 0.033ms (+0.000ms): __schedule (down_write)
04000001 0.033ms (+0.000ms): sched_clock (__schedule)
04000000 0.034ms (+0.000ms): schedule (down_write)
04000000 0.034ms (+0.000ms): __schedule (down_write)
04000001 0.034ms (+0.000ms): sched_clock (__schedule)
04000000 0.034ms (+0.000ms): schedule (down_write)
04000000 0.034ms (+0.000ms): __schedule (down_write)
04000001 0.034ms (+0.000ms): sched_clock (__schedule)
04000000 0.035ms (+0.000ms): schedule (down_write)
04000000 0.035ms (+0.000ms): __schedule (down_write)
04000001 0.035ms (+0.000ms): sched_clock (__schedule)
04000000 0.035ms (+0.000ms): schedule (down_write)
04000000 0.035ms (+0.000ms): __schedule (down_write)
04000001 0.035ms (+0.000ms): sched_clock (__schedule)
04000000 0.035ms (+0.000ms): schedule (down_write)
04000000 0.036ms (+0.000ms): __schedule (down_write)

[...many many more of similar ones...]

04000000 0.554ms (+0.000ms): __schedule (down_write)
04000001 0.554ms (+0.000ms): sched_clock (__schedule)
04000000 0.554ms (+0.000ms): schedule (down_write)
04000000 0.554ms (+0.000ms): __schedule (down_write)
04000001 0.554ms (+0.000ms): sched_clock (__schedule)
04000000 0.555ms (+0.000ms): schedule (down_write)
04000000 0.555ms (+0.000ms): __schedule (down_write)
04000001 0.555ms (+0.000ms): sched_clock (__schedule)
04000000 0.555ms (+0.000ms): schedule (down_write)
04000000 0.555ms (+0.000ms): __schedule (down_write)
04000001 0.555ms (+0.000ms): sched_clock (__schedule)
04000000 0.555ms (+0.000ms): schedule (down_write)
04000000 0.556ms (+0.000ms): __schedule (down_write)
04000001 0.556ms (+0.000ms): sched_clock (__schedule)
04000000 0.556ms (+0.000ms): schedule (down_write)
04000000 0.556ms (+0.000ms): __schedule (down_write)
04000001 0.556ms (+0.000ms): sched_clock (__schedule)
04000000 0.556ms (+0.000ms): schedule (down_write)
04000000 0.556ms (+0.000ms): __schedule (down_write)
04000001 0.557ms (+0.000ms): sched_clock (__schedule)
04000000 0.557ms (+0.000ms): schedule (down_write)
04000000 0.557ms (+0.000ms): __schedule (down_write)
04000001 0.557ms (+0.000ms): sched_clock (__schedule)
04000000 0.557ms (+0.000ms): schedule (down_write)
04000000 0.557ms (+0.000ms): __schedule (down_write)
04000001 0.557ms (+0.000ms): sched_clock (__schedule)
04000000 0.558ms (+0.000ms): schedule (down_write)
04000000 0.558ms (+0.000ms): __schedule (down_write)
04000001 0.558ms (+0.000ms): sched_clock (__schedule)
04000000 0.558ms (+0.000ms): schedule (down_write)
04000000 0.558ms (+0.000ms): __schedule (down_write)
04000001 0.558ms (+0.000ms): sched_clock (__schedule)
04000000 0.559ms (+0.000ms): schedule (down_write)
04000000 0.559ms (+0.000ms): __schedule (down_write)
04000001 0.559ms (+0.000ms): sched_clock (__schedule)
04000000 0.559ms (+0.000ms): schedule (down_write)
04000000 0.559ms (+0.000ms): __schedule (down_write)
04000001 0.559ms (+0.000ms): sched_clock (__schedule)
04000000 0.560ms (+0.000ms): schedule (down_write)
04000000 0.560ms (+0.000ms): __schedule (down_write)
04000001 0.560ms (+0.000ms): sched_clock (__schedule)
04000000 0.560ms (+0.000ms): schedule (down_write)
04000000 0.560ms (+0.000ms): __schedule (down_write)
04000001 0.560ms (+0.000ms): sched_clock (__schedule)
04000000 0.561ms (+0.000ms): schedule (down_write)
04000000 0.561ms (+0.000ms): __schedule (down_write)
04000001 0.561ms (+0.000ms): sched_clock (__schedule)
04000000 0.561ms (+0.000ms): schedule (down_write)
04000000 0.561ms (+0.000ms): __schedule (down_write)
04000001 0.561ms (+0.000ms): sched_clock (__schedule)
04000000 0.561ms (+0.000ms): schedule (down_write)
04000000 0.562ms (+0.000ms): __schedule (down_write)
04000001 0.562ms (+0.000ms): sched_clock (__schedule)
04000000 0.562ms (+0.000ms): schedule (down_write)
04000000 0.562ms (+0.000ms): __schedule (down_write)
04000001 0.562ms (+0.000ms): sched_clock (__schedule)
04000000 0.562ms (+0.000ms): schedule (down_write)
04000000 0.562ms (+0.000ms): __schedule (down_write)
04000001 0.563ms (+0.000ms): sched_clock (__schedule)
04000000 0.563ms (+0.000ms): schedule (down_write)
04000000 0.563ms (+0.000ms): __schedule (down_write)
04000001 0.563ms (+0.000ms): sched_clock (__schedule)
04000000 0.563ms (+0.000ms): schedule (down_write)
04000000 0.563ms (+0.000ms): __schedule (down_write)
04000001 0.563ms (+0.000ms): sched_clock (__schedule)
04000000 0.564ms (+0.000ms): schedule (down_write)
04000000 0.564ms (+0.000ms): __schedule (down_write)
04000001 0.564ms (+0.000ms): sched_clock (__schedule)
04000000 0.564ms (+0.000ms): schedule (down_write)
04000000 0.564ms (+0.000ms): __schedule (down_write)
04000001 0.564ms (+0.000ms): sched_clock (__schedule)
04000000 0.565ms (+0.000ms): schedule (down_write)
04000000 0.565ms (+0.000ms): __schedule (down_write)
04000001 0.565ms (+0.000ms): sched_clock (__schedule)
04000000 0.565ms (+0.000ms): schedule (down_write)
04000000 0.565ms (+0.000ms): __schedule (down_write)
04000001 0.565ms (+0.000ms): sched_clock (__schedule)
04000000 0.566ms (+0.000ms): schedule (down_write)
04000000 0.566ms (+0.000ms): __schedule (down_write)
04000001 0.566ms (+0.000ms): sched_clock (__schedule)
04000000 0.566ms (+0.000ms): schedule (down_write)
04000000 0.566ms (+0.000ms): __schedule (down_write)
04000001 0.566ms (+0.000ms): sched_clock (__schedule)
04000000 0.567ms (+0.000ms): schedule (down_write)
04000000 0.567ms (+0.000ms): __schedule (down_write)
04000001 0.567ms (+0.000ms): sched_clock (__schedule)
04000000 0.567ms (+0.000ms): schedule (down_write)
04000000 0.567ms (+0.000ms): __schedule (down_write)
04000001 0.567ms (+0.000ms): sched_clock (__schedule)
04000000 0.567ms (+0.000ms): schedule (down_write)
04000000 0.568ms (+0.000ms): __schedule (down_write)
04000001 0.568ms (+0.000ms): sched_clock (__schedule)
04000000 0.568ms (+0.000ms): schedule (down_write)
04000000 0.568ms (+0.000ms): __schedule (down_write)
04000001 0.568ms (+0.000ms): sched_clock (__schedule)
04000000 0.568ms (+0.000ms): schedule (down_write)
04000000 0.568ms (+0.000ms): __schedule (down_write)
04000001 0.569ms (+0.000ms): sched_clock (__schedule)
04000000 0.569ms (+0.000ms): schedule (down_write)
04000000 0.569ms (+0.000ms): __schedule (down_write)
04000001 0.569ms (+0.000ms): sched_clock (__schedule)
04000000 0.569ms (+0.000ms): schedule (down_write)
04000000 0.569ms (+0.000ms): __schedule (down_write)
04000001 0.569ms (+0.000ms): sched_clock (__schedule)
04000000 0.570ms (+0.000ms): schedule (down_write)
04000000 0.570ms (+0.000ms): __schedule (down_write)
04000001 0.570ms (+0.000ms): sched_clock (__schedule)
04000000 0.570ms (+0.000ms): schedule (down_write)
04000000 0.570ms (+0.000ms): __schedule (down_write)
04000001 0.570ms (+0.000ms): sched_clock (__schedule)
04000000 0.571ms (+0.000ms): schedule (down_write)
04000000 0.571ms (+0.000ms): __schedule (down_write)
04000001 0.571ms (+0.000ms): sched_clock (__schedule)
04000000 0.571ms (+0.000ms): schedule (down_write)
04000000 0.571ms (+0.000ms): __schedule (down_write)
04000001 0.571ms (+0.000ms): sched_clock (__schedule)
04000000 0.572ms (+0.000ms): schedule (down_write)
04000000 0.572ms (+0.000ms): __schedule (down_write)
04000001 0.572ms (+0.000ms): sched_clock (__schedule)
04000000 0.572ms (+0.000ms): schedule (down_write)
04000000 0.572ms (+0.000ms): __schedule (down_write)
04000001 0.572ms (+0.000ms): sched_clock (__schedule)
04000000 0.572ms (+0.000ms): schedule (down_write)
04000000 0.573ms (+0.000ms): __schedule (down_write)
04000001 0.573ms (+0.000ms): sched_clock (__schedule)
04000000 0.573ms (+0.000ms): schedule (down_write)
04000000 0.573ms (+0.000ms): __schedule (down_write)
04000001 0.573ms (+0.000ms): sched_clock (__schedule)
04000000 0.573ms (+0.000ms): schedule (down_write)
04000000 0.574ms (+0.000ms): __schedule (down_write)
04000001 0.574ms (+0.000ms): sched_clock (__schedule)
04000000 0.574ms (+0.000ms): schedule (down_write)
04000000 0.574ms (+0.000ms): __schedule (down_write)
04000001 0.574ms (+0.000ms): sched_clock (__schedule)
04000000 0.574ms (+0.000ms): schedule (down_write)
04000000 0.574ms (+0.000ms): __schedule (down_write)
04000001 0.575ms (+0.000ms): sched_clock (__schedule)
04000000 0.575ms (+0.000ms): schedule (down_write)
04000000 0.575ms (+0.000ms): __schedule (down_write)
04000001 0.575ms (+0.000ms): sched_clock (__schedule)
04000000 0.575ms (+0.000ms): schedule (down_write)
04000000 0.575ms (+0.000ms): __schedule (down_write)
04000001 0.575ms (+0.000ms): sched_clock (__schedule)
04000000 0.576ms (+0.000ms): schedule (down_write)
04000000 0.576ms (+0.000ms): __schedule (down_write)
04000001 0.576ms (+0.000ms): sched_clock (__schedule)
04000000 0.576ms (+0.000ms): schedule (down_write)
04000000 0.576ms (+0.000ms): __schedule (down_write)
04000001 0.576ms (+0.000ms): sched_clock (__schedule)
04000000 0.577ms (+0.000ms): schedule (down_write)
04000000 0.577ms (+0.000ms): __schedule (down_write)
04000001 0.577ms (+0.000ms): sched_clock (__schedule)
04000000 0.577ms (+0.000ms): schedule (down_write)
04000000 0.577ms (+0.000ms): __schedule (down_write)
04000001 0.577ms (+0.000ms): sched_clock (__schedule)
04000000 0.578ms (+0.000ms): schedule (down_write)
04000000 0.578ms (+0.000ms): __schedule (down_write)
04000001 0.578ms (+0.000ms): sched_clock (__schedule)
04000000 0.578ms (+0.000ms): schedule (down_write)
04000000 0.578ms (+0.000ms): __schedule (down_write)
04000001 0.578ms (+0.000ms): sched_clock (__schedule)
04000000 0.578ms (+0.000ms): schedule (down_write)
04000000 0.579ms (+0.000ms): __schedule (down_write)
04000001 0.579ms (+0.000ms): sched_clock (__schedule)
04000000 0.579ms (+0.000ms): schedule (down_write)
04000000 0.579ms (+0.000ms): __schedule (down_write)
04000001 0.579ms (+0.000ms): sched_clock (__schedule)
04000000 0.579ms (+0.000ms): schedule (down_write)
04000000 0.579ms (+0.000ms): __schedule (down_write)
04000001 0.580ms (+0.000ms): sched_clock (__schedule)
04000000 0.580ms (+0.000ms): schedule (down_write)
04000000 0.580ms (+0.000ms): __schedule (down_write)
04000001 0.580ms (+0.000ms): sched_clock (__schedule)
04000000 0.580ms (+0.000ms): schedule (down_write)
04000000 0.580ms (+0.000ms): __schedule (down_write)
04000001 0.581ms (+0.000ms): sched_clock (__schedule)
04000000 0.581ms (+0.000ms): schedule (down_write)
04000000 0.581ms (+0.000ms): __schedule (down_write)
04000001 0.581ms (+0.000ms): sched_clock (__schedule)
04000000 0.581ms (+0.000ms): schedule (down_write)
04000000 0.581ms (+0.000ms): __schedule (down_write)
04000001 0.581ms (+0.000ms): sched_clock (__schedule)
04000000 0.582ms (+0.000ms): schedule (down_write)
04000000 0.582ms (+0.000ms): __schedule (down_write)
04000001 0.582ms (+0.000ms): sched_clock (__schedule)
04000000 0.582ms (+0.000ms): schedule (down_write)
04000000 0.582ms (+0.000ms): __schedule (down_write)
04000001 0.582ms (+0.000ms): sched_clock (__schedule)
04000000 0.583ms (+0.000ms): schedule (down_write)
04000000 0.583ms (+0.000ms): __schedule (down_write)
04000001 0.583ms (+0.000ms): sched_clock (__schedule)
04000000 0.583ms (+0.000ms): schedule (down_write)
04000000 0.583ms (+0.000ms): __schedule (down_write)
04000001 0.583ms (+0.000ms): sched_clock (__schedule)
04000000 0.584ms (+0.000ms): schedule (down_write)
04000000 0.584ms (+0.000ms): __schedule (down_write)
04000001 0.584ms (+0.000ms): sched_clock (__schedule)
04000000 0.584ms (+0.000ms): schedule (down_write)
04000000 0.584ms (+0.000ms): __schedule (down_write)
04000001 0.584ms (+0.000ms): sched_clock (__schedule)
04000000 0.584ms (+0.000ms): schedule (down_write)
04000000 0.585ms (+0.000ms): __schedule (down_write)
04000001 0.585ms (+0.000ms): sched_clock (__schedule)
04000000 0.585ms (+0.000ms): schedule (down_write)
04000000 0.585ms (+0.000ms): __schedule (down_write)
04000001 0.585ms (+0.000ms): sched_clock (__schedule)
04000000 0.585ms (+0.000ms): schedule (down_write)
04000000 0.585ms (+0.000ms): __schedule (down_write)
04000001 0.586ms (+0.000ms): sched_clock (__schedule)
04000000 0.586ms (+0.000ms): schedule (down_write)
04000000 0.586ms (+0.000ms): __schedule (down_write)
04000001 0.586ms (+0.000ms): sched_clock (__schedule)
04000000 0.586ms (+0.000ms): schedule (down_write)
04000000 0.586ms (+0.000ms): __schedule (down_write)
04000001 0.586ms (+0.000ms): sched_clock (__schedule)
04000000 0.587ms (+0.000ms): schedule (down_write)
04000000 0.587ms (+0.000ms): __schedule (down_write)
04000001 0.587ms (+0.000ms): sched_clock (__schedule)
04000000 0.587ms (+0.000ms): schedule (down_write)
04000000 0.587ms (+0.000ms): __schedule (down_write)
04000001 0.587ms (+0.000ms): sched_clock (__schedule)
04000000 0.588ms (+0.000ms): schedule (down_write)
04000000 0.588ms (+0.000ms): __schedule (down_write)
04000001 0.588ms (+0.000ms): sched_clock (__schedule)
04000000 0.588ms (+0.000ms): schedule (down_write)
04000000 0.588ms (+0.000ms): __schedule (down_write)
04000001 0.588ms (+0.000ms): sched_clock (__schedule)
04000000 0.589ms (+0.000ms): schedule (down_write)
04000000 0.589ms (+0.000ms): __schedule (down_write)
04000001 0.589ms (+0.000ms): sched_clock (__schedule)
04000000 0.589ms (+0.000ms): schedule (down_write)
04000000 0.589ms (+0.000ms): __schedule (down_write)
04000001 0.589ms (+0.000ms): sched_clock (__schedule)
04000000 0.590ms (+0.000ms): schedule (down_write)
04000000 0.590ms (+0.000ms): __schedule (down_write)
04000001 0.590ms (+0.000ms): sched_clock (__schedule)
04000000 0.590ms (+0.000ms): schedule (down_write)
04000000 0.590ms (+0.000ms): __schedule (down_write)
04000001 0.590ms (+0.000ms): sched_clock (__schedule)
04000000 0.590ms (+0.000ms): schedule (down_write)
04000000 0.591ms (+0.000ms): __schedule (down_write)
04000001 0.591ms (+0.000ms): sched_clock (__schedule)
04000000 0.591ms (+0.000ms): schedule (down_write)
04000000 0.591ms (+0.000ms): __schedule (down_write)
04000001 0.591ms (+0.000ms): sched_clock (__schedule)
04000000 0.591ms (+0.000ms): schedule (down_write)
04000000 0.591ms (+0.000ms): __schedule (down_write)
04000001 0.592ms (+0.000ms): sched_clock (__schedule)
04000000 0.592ms (+0.000ms): schedule (down_write)
04000000 0.592ms (+0.000ms): __schedule (down_write)
04000001 0.592ms (+0.000ms): sched_clock (__schedule)
04000000 0.592ms (+0.000ms): schedule (down_write)
04000000 0.592ms (+0.000ms): __schedule (down_write)
04000001 0.592ms (+0.000ms): sched_clock (__schedule)
04000000 0.593ms (+0.000ms): schedule (down_write)
04000000 0.593ms (+0.000ms): __schedule (down_write)
04000001 0.593ms (+0.000ms): sched_clock (__schedule)
04000000 0.593ms (+0.000ms): schedule (down_write)
04000000 0.593ms (+0.000ms): __schedule (down_write)
04000001 0.593ms (+0.000ms): sched_clock (__schedule)
04000000 0.594ms (+0.000ms): schedule (down_write)
04000000 0.594ms (+0.000ms): __schedule (down_write)
04000001 0.594ms (+0.000ms): sched_clock (__schedule)
04000000 0.594ms (+0.000ms): schedule (down_write)
04000000 0.594ms (+0.000ms): __schedule (down_write)
04000001 0.594ms (+0.000ms): sched_clock (__schedule)
04000000 0.595ms (+0.000ms): schedule (down_write)
04000000 0.595ms (+0.000ms): __schedule (down_write)
04000001 0.595ms (+0.000ms): sched_clock (__schedule)
04000000 0.595ms (+0.000ms): schedule (down_write)
04000000 0.595ms (+0.000ms): __schedule (down_write)
04000001 0.595ms (+0.000ms): sched_clock (__schedule)
04000000 0.596ms (+0.000ms): schedule (down_write)
04000000 0.596ms (+0.000ms): __schedule (down_write)
04000001 0.596ms (+0.000ms): sched_clock (__schedule)
04000000 0.596ms (+0.000ms): schedule (down_write)
04000000 0.596ms (+0.000ms): __schedule (down_write)
04000001 0.596ms (+0.000ms): sched_clock (__schedule)
04000000 0.596ms (+0.000ms): schedule (down_write)
04000000 0.597ms (+0.000ms): __schedule (down_write)
04000001 0.597ms (+0.000ms): sched_clock (__schedule)
04000000 0.597ms (+0.000ms): schedule (down_write)
04000000 0.597ms (+0.000ms): __schedule (down_write)
04000001 0.597ms (+0.000ms): sched_clock (__schedule)
04000000 0.597ms (+0.000ms): schedule (down_write)
04000000 0.597ms (+0.000ms): __schedule (down_write)
04000001 0.598ms (+0.000ms): sched_clock (__schedule)
04000000 0.598ms (+0.000ms): schedule (down_write)
04000000 0.598ms (+0.000ms): __schedule (down_write)
04000001 0.598ms (+0.000ms): sched_clock (__schedule)
04000000 0.598ms (+0.000ms): schedule (down_write)
04000000 0.598ms (+0.000ms): __schedule (down_write)
04000001 0.598ms (+0.000ms): sched_clock (__schedule)
04000000 0.599ms (+0.000ms): schedule (down_write)
04000000 0.599ms (+0.000ms): __schedule (down_write)
04000001 0.599ms (+0.000ms): sched_clock (__schedule)
04000000 0.599ms (+0.000ms): schedule (down_write)
04000000 0.599ms (+0.000ms): __schedule (down_write)
04000001 0.599ms (+0.000ms): sched_clock (__schedule)
04000000 0.600ms (+0.000ms): schedule (down_write)
04000000 0.600ms (+0.000ms): __schedule (down_write)
04000001 0.600ms (+0.000ms): sched_clock (__schedule)
04000000 0.600ms (+0.000ms): schedule (down_write)
04000000 0.600ms (+0.000ms): __schedule (down_write)
04000001 0.600ms (+0.000ms): sched_clock (__schedule)
04000000 0.601ms (+0.000ms): schedule (down_write)
04000000 0.601ms (+0.000ms): __schedule (down_write)
04000001 0.601ms (+0.000ms): sched_clock (__schedule)
04000000 0.601ms (+0.000ms): schedule (down_write)
04000000 0.601ms (+0.000ms): __schedule (down_write)
04000001 0.601ms (+0.000ms): sched_clock (__schedule)
04000000 0.601ms (+0.000ms): schedule (down_write)
04000000 0.602ms (+0.000ms): __schedule (down_write)
04000001 0.602ms (+0.000ms): sched_clock (__schedule)
04000000 0.602ms (+0.000ms): schedule (down_write)
04000000 0.602ms (+0.000ms): __schedule (down_write)
04000001 0.602ms (+0.000ms): sched_clock (__schedule)
04000000 0.602ms (+0.000ms): schedule (down_write)
04000000 0.602ms (+0.000ms): __schedule (down_write)
04000001 0.603ms (+0.000ms): sched_clock (__schedule)
04000000 0.603ms (+0.000ms): schedule (down_write)
04000000 0.603ms (+0.000ms): __schedule (down_write)
04000001 0.603ms (+0.000ms): sched_clock (__schedule)
04000000 0.603ms (+0.000ms): schedule (down_write)
04000000 0.603ms (+0.000ms): __schedule (down_write)
04000001 0.604ms (+0.000ms): sched_clock (__schedule)
04000000 0.604ms (+0.000ms): schedule (down_write)
04000000 0.604ms (+0.000ms): __schedule (down_write)
04000001 0.604ms (+0.000ms): sched_clock (__schedule)
04000000 0.604ms (+0.000ms): schedule (down_write)
04000000 0.604ms (+0.000ms): __schedule (down_write)
04000001 0.604ms (+0.000ms): sched_clock (__schedule)
04000000 0.605ms (+0.000ms): schedule (down_write)
04000000 0.605ms (+0.000ms): __schedule (down_write)
04000001 0.605ms (+0.000ms): sched_clock (__schedule)
04000000 0.605ms (+0.000ms): schedule (down_write)
04000000 0.605ms (+0.000ms): __schedule (down_write)
04000001 0.605ms (+0.000ms): sched_clock (__schedule)
04000000 0.606ms (+0.000ms): schedule (down_write)
04000000 0.606ms (+0.000ms): __schedule (down_write)
04000001 0.606ms (+0.000ms): sched_clock (__schedule)
04000000 0.606ms (+0.000ms): schedule (down_write)
04000000 0.606ms (+0.000ms): __schedule (down_write)
04000001 0.606ms (+0.000ms): sched_clock (__schedule)
04000000 0.607ms (+0.000ms): schedule (down_write)
04000000 0.607ms (+0.000ms): __schedule (down_write)
04000001 0.607ms (+0.000ms): sched_clock (__schedule)
04000000 0.607ms (+0.000ms): schedule (down_write)
04000000 0.607ms (+0.000ms): __schedule (down_write)
04000001 0.607ms (+0.000ms): sched_clock (__schedule)
04000000 0.607ms (+0.000ms): schedule (down_write)
04000000 0.608ms (+0.000ms): __schedule (down_write)
04000001 0.608ms (+0.000ms): sched_clock (__schedule)
04000000 0.608ms (+0.000ms): schedule (down_write)
04000000 0.608ms (+0.000ms): __schedule (down_write)
04000001 0.608ms (+0.000ms): sched_clock (__schedule)
04000000 0.608ms (+0.000ms): schedule (down_write)
04000000 0.608ms (+0.000ms): __schedule (down_write)
04000001 0.609ms (+0.000ms): sched_clock (__schedule)
04000000 0.609ms (+0.000ms): schedule (down_write)
04000000 0.609ms (+0.000ms): __schedule (down_write)
04000001 0.609ms (+0.000ms): sched_clock (__schedule)
04000000 0.609ms (+0.000ms): schedule (down_write)
04000000 0.609ms (+0.000ms): __schedule (down_write)
04000001 0.610ms (+0.000ms): sched_clock (__schedule)
04000000 0.610ms (+0.000ms): schedule (down_write)
04000000 0.610ms (+0.000ms): __schedule (down_write)
04000001 0.610ms (+0.000ms): sched_clock (__schedule)
04000000 0.610ms (+0.000ms): schedule (down_write)
04000000 0.610ms (+0.000ms): __schedule (down_write)
04000001 0.610ms (+0.000ms): sched_clock (__schedule)
04000000 0.611ms (+0.000ms): schedule (down_write)
04000000 0.611ms (+0.000ms): __schedule (down_write)
04000001 0.611ms (+0.000ms): sched_clock (__schedule)
04000000 0.611ms (+0.000ms): schedule (down_write)
04000000 0.611ms (+0.000ms): __schedule (down_write)
04000001 0.611ms (+0.000ms): sched_clock (__schedule)
04000000 0.612ms (+0.000ms): schedule (down_write)
04000000 0.612ms (+0.000ms): __schedule (down_write)
04000001 0.612ms (+0.000ms): sched_clock (__schedule)
04000000 0.612ms (+0.000ms): schedule (down_write)
04000000 0.612ms (+0.000ms): __schedule (down_write)
04000001 0.612ms (+0.000ms): sched_clock (__schedule)
04000000 0.613ms (+0.000ms): schedule (down_write)
04000000 0.613ms (+0.000ms): __schedule (down_write)
04000001 0.613ms (+0.000ms): sched_clock (__schedule)
04000000 0.613ms (+0.000ms): schedule (down_write)
04000000 0.613ms (+0.000ms): __schedule (down_write)
04000001 0.613ms (+0.000ms): sched_clock (__schedule)
04000000 0.613ms (+1168210.574ms): schedule (down_write)


mango:~# uname -a
Linux mango.fruits.de 2.6.9-rc4-mm1-RT-U6 #1 Tue Oct 19 17:59:48 CEST 2004 i686 GNU/Linux

mango:~# cat /proc/cpuinfo 
processor       : 0
vendor_id       : AuthenticAMD
cpu family      : 6
model           : 4
model name      : AMD Athlon(tm) Processor
stepping        : 2
cpu MHz         : 1195.144
cache size      : 256 KB
fdiv_bug        : no
hlt_bug         : no
f00f_bug        : no
coma_bug        : no
fpu             : yes
fpu_exception   : yes
cpuid level     : 1
wp              : yes
flags           : fpu vme de pse tsc msr pae mce cx8 sep mtrr pge mca cmov pat pse36 mmx fxsr syscall mmxext 3dnowext 3dnow
bogomips        : 2359.29

#
# Automatically generated make config: don't edit
# Linux kernel version: 2.6.9-rc4-mm1-RT-U6
# Tue Oct 19 17:39:11 2004
#
CONFIG_X86=y
CONFIG_MMU=y
CONFIG_UID16=y
CONFIG_GENERIC_ISA_DMA=y
CONFIG_GENERIC_IOMAP=y

#
# Code maturity level options
#
CONFIG_EXPERIMENTAL=y
CONFIG_CLEAN_COMPILE=y
CONFIG_BROKEN_ON_SMP=y

#
# General setup
#
CONFIG_LOCALVERSION=""
CONFIG_SWAP=y
CONFIG_SYSVIPC=y
CONFIG_POSIX_MQUEUE=y
CONFIG_BSD_PROCESS_ACCT=y
# CONFIG_BSD_PROCESS_ACCT_V3 is not set
CONFIG_SYSCTL=y
# CONFIG_AUDIT is not set
CONFIG_LOG_BUF_SHIFT=14
# CONFIG_HOTPLUG is not set
CONFIG_KOBJECT_UEVENT=y
CONFIG_IKCONFIG=y
CONFIG_IKCONFIG_PROC=y
# CONFIG_EMBEDDED is not set
CONFIG_KALLSYMS=y
# CONFIG_KALLSYMS_ALL is not set
# CONFIG_KALLSYMS_EXTRA_PASS is not set
CONFIG_FUTEX=y
CONFIG_EPOLL=y
CONFIG_IOSCHED_NOOP=y
CONFIG_IOSCHED_AS=y
CONFIG_IOSCHED_DEADLINE=y
CONFIG_IOSCHED_CFQ=y
# CONFIG_CC_OPTIMIZE_FOR_SIZE is not set
CONFIG_SHMEM=y
# CONFIG_TINY_SHMEM is not set

#
# Loadable module support
#
CONFIG_MODULES=y
CONFIG_MODULE_UNLOAD=y
# CONFIG_MODULE_FORCE_UNLOAD is not set
CONFIG_OBSOLETE_MODPARM=y
CONFIG_MODVERSIONS=y
# CONFIG_MODULE_SRCVERSION_ALL is not set
CONFIG_KMOD=y

#
# Processor type and features
#
CONFIG_X86_PC=y
# CONFIG_X86_ELAN is not set
# CONFIG_X86_VOYAGER is not set
# CONFIG_X86_NUMAQ is not set
# CONFIG_X86_SUMMIT is not set
# CONFIG_X86_BIGSMP is not set
# CONFIG_X86_VISWS is not set
# CONFIG_X86_GENERICARCH is not set
# CONFIG_X86_ES7000 is not set
# CONFIG_M386 is not set
# CONFIG_M486 is not set
# CONFIG_M586 is not set
# CONFIG_M586TSC is not set
# CONFIG_M586MMX is not set
# CONFIG_M686 is not set
# CONFIG_MPENTIUMII is not set
# CONFIG_MPENTIUMIII is not set
# CONFIG_MPENTIUMM is not set
# CONFIG_MPENTIUM4 is not set
# CONFIG_MK6 is not set
CONFIG_MK7=y
# CONFIG_MK8 is not set
# CONFIG_MCRUSOE is not set
# CONFIG_MWINCHIPC6 is not set
# CONFIG_MWINCHIP2 is not set
# CONFIG_MWINCHIP3D is not set
# CONFIG_MCYRIXIII is not set
# CONFIG_MVIAC3_2 is not set
# CONFIG_X86_GENERIC is not set
CONFIG_X86_CMPXCHG=y
CONFIG_X86_XADD=y
CONFIG_X86_L1_CACHE_SHIFT=6
CONFIG_RWSEM_GENERIC=y
CONFIG_GENERIC_SEMAPHORES=y
CONFIG_X86_WP_WORKS_OK=y
CONFIG_X86_INVLPG=y
CONFIG_X86_BSWAP=y
CONFIG_X86_POPAD_OK=y
CONFIG_X86_GOOD_APIC=y
CONFIG_X86_INTEL_USERCOPY=y
CONFIG_X86_USE_PPRO_CHECKSUM=y
CONFIG_X86_USE_3DNOW=y
# CONFIG_SMP is not set
CONFIG_PREEMPT=y
CONFIG_PREEMPT_BKL=y
CONFIG_PREEMPT_VOLUNTARY=y
CONFIG_PREEMPT_SOFTIRQS=y
CONFIG_PREEMPT_HARDIRQS=y
CONFIG_PREEMPT_REALTIME=y
# CONFIG_X86_UP_APIC is not set
CONFIG_X86_TSC=y
# CONFIG_X86_MCE is not set
# CONFIG_TOSHIBA is not set
# CONFIG_I8K is not set
# CONFIG_MICROCODE is not set
# CONFIG_X86_MSR is not set
# CONFIG_X86_CPUID is not set

#
# Firmware Drivers
#
# CONFIG_EDD is not set
CONFIG_NOHIGHMEM=y
# CONFIG_HIGHMEM4G is not set
# CONFIG_HIGHMEM64G is not set
# CONFIG_MATH_EMULATION is not set
CONFIG_MTRR=y
CONFIG_HAVE_DEC_LOCK=y

#
# Performance-monitoring counters support
#
# CONFIG_PERFCTR is not set
# CONFIG_KEXEC is not set

#
# Power management options (ACPI, APM)
#
CONFIG_PM=y
# CONFIG_PM_DEBUG is not set
# CONFIG_SOFTWARE_SUSPEND is not set

#
# ACPI (Advanced Configuration and Power Interface) Support
#
# CONFIG_ACPI is not set
CONFIG_ACPI_BLACKLIST_YEAR=0

#
# APM (Advanced Power Management) BIOS Support
#
CONFIG_APM=y
# CONFIG_APM_IGNORE_USER_SUSPEND is not set
# CONFIG_APM_DO_ENABLE is not set
# CONFIG_APM_CPU_IDLE is not set
# CONFIG_APM_DISPLAY_BLANK is not set
# CONFIG_APM_RTC_IS_GMT is not set
# CONFIG_APM_ALLOW_INTS is not set
CONFIG_APM_REAL_MODE_POWER_OFF=y

#
# CPU Frequency scaling
#
# CONFIG_CPU_FREQ is not set

#
# Bus options (PCI, PCMCIA, EISA, MCA, ISA)
#
CONFIG_PCI=y
# CONFIG_PCI_GOBIOS is not set
# CONFIG_PCI_GOMMCONFIG is not set
# CONFIG_PCI_GODIRECT is not set
CONFIG_PCI_GOANY=y
CONFIG_PCI_BIOS=y
CONFIG_PCI_DIRECT=y
# CONFIG_PCI_LEGACY_PROC is not set
CONFIG_PCI_NAMES=y
# CONFIG_ISA is not set
# CONFIG_MCA is not set
# CONFIG_SCx200 is not set

#
# Executable file formats
#
CONFIG_BINFMT_ELF=y
CONFIG_BINFMT_AOUT=y
CONFIG_BINFMT_MISC=y

#
# Device Drivers
#

#
# Generic Driver Options
#
CONFIG_STANDALONE=y
CONFIG_PREVENT_FIRMWARE_BUILD=y
# CONFIG_DEBUG_DRIVER is not set

#
# Memory Technology Devices (MTD)
#
# CONFIG_MTD is not set

#
# Parallel port support
#
# CONFIG_PARPORT is not set

#
# Plug and Play support
#

#
# Block devices
#
CONFIG_BLK_DEV_FD=m
# CONFIG_BLK_CPQ_DA is not set
# CONFIG_BLK_CPQ_CISS_DA is not set
# CONFIG_BLK_DEV_DAC960 is not set
# CONFIG_BLK_DEV_UMEM is not set
CONFIG_BLK_DEV_LOOP=m
CONFIG_BLK_DEV_CRYPTOLOOP=m
CONFIG_BLK_DEV_NBD=m
# CONFIG_BLK_DEV_SX8 is not set
CONFIG_BLK_DEV_RAM=y
CONFIG_BLK_DEV_RAM_SIZE=4096
CONFIG_BLK_DEV_INITRD=y
CONFIG_INITRAMFS_SOURCE=""
# CONFIG_LBD is not set
# CONFIG_CDROM_PKTCDVD is not set

#
# ATA/ATAPI/MFM/RLL support
#
CONFIG_IDE=y
CONFIG_BLK_DEV_IDE=y

#
# Please see Documentation/ide.txt for help/info on IDE drives
#
# CONFIG_BLK_DEV_IDE_SATA is not set
# CONFIG_BLK_DEV_HD_IDE is not set
CONFIG_BLK_DEV_IDEDISK=y
CONFIG_IDEDISK_MULTI_MODE=y
CONFIG_BLK_DEV_IDECD=y
# CONFIG_BLK_DEV_IDETAPE is not set
# CONFIG_BLK_DEV_IDEFLOPPY is not set
CONFIG_BLK_DEV_IDESCSI=m
# CONFIG_IDE_TASK_IOCTL is not set

#
# IDE chipset support/bugfixes
#
CONFIG_IDE_GENERIC=y
# CONFIG_BLK_DEV_CMD640 is not set
CONFIG_BLK_DEV_IDEPCI=y
CONFIG_IDEPCI_SHARE_IRQ=y
# CONFIG_BLK_DEV_OFFBOARD is not set
CONFIG_BLK_DEV_GENERIC=y
# CONFIG_BLK_DEV_OPTI621 is not set
# CONFIG_BLK_DEV_RZ1000 is not set
CONFIG_BLK_DEV_IDEDMA_PCI=y
# CONFIG_BLK_DEV_IDEDMA_FORCED is not set
CONFIG_IDEDMA_PCI_AUTO=y
# CONFIG_IDEDMA_ONLYDISK is not set
# CONFIG_BLK_DEV_AEC62XX is not set
# CONFIG_BLK_DEV_ALI15X3 is not set
# CONFIG_BLK_DEV_AMD74XX is not set
# CONFIG_BLK_DEV_ATIIXP is not set
# CONFIG_BLK_DEV_CMD64X is not set
# CONFIG_BLK_DEV_TRIFLEX is not set
# CONFIG_BLK_DEV_CY82C693 is not set
# CONFIG_BLK_DEV_CS5520 is not set
# CONFIG_BLK_DEV_CS5530 is not set
# CONFIG_BLK_DEV_HPT34X is not set
# CONFIG_BLK_DEV_HPT366 is not set
# CONFIG_BLK_DEV_SC1200 is not set
# CONFIG_BLK_DEV_PIIX is not set
# CONFIG_BLK_DEV_NS87415 is not set
# CONFIG_BLK_DEV_PDC202XX_OLD is not set
# CONFIG_BLK_DEV_PDC202XX_NEW is not set
# CONFIG_BLK_DEV_SVWKS is not set
# CONFIG_BLK_DEV_SIIMAGE is not set
CONFIG_BLK_DEV_SIS5513=y
# CONFIG_BLK_DEV_SLC90E66 is not set
# CONFIG_BLK_DEV_TRM290 is not set
# CONFIG_BLK_DEV_VIA82CXXX is not set
# CONFIG_IDE_ARM is not set
CONFIG_BLK_DEV_IDEDMA=y
# CONFIG_IDEDMA_IVB is not set
CONFIG_IDEDMA_AUTO=y
# CONFIG_BLK_DEV_HD is not set

#
# SCSI device support
#
CONFIG_SCSI=m
CONFIG_SCSI_PROC_FS=y

#
# SCSI support type (disk, tape, CD-ROM)
#
CONFIG_BLK_DEV_SD=m
# CONFIG_CHR_DEV_ST is not set
# CONFIG_CHR_DEV_OSST is not set
CONFIG_BLK_DEV_SR=m
# CONFIG_BLK_DEV_SR_VENDOR is not set
CONFIG_CHR_DEV_SG=m

#
# Some SCSI devices (e.g. CD jukebox) support multiple LUNs
#
# CONFIG_SCSI_MULTI_LUN is not set
CONFIG_SCSI_CONSTANTS=y
# CONFIG_SCSI_LOGGING is not set

#
# SCSI Transport Attributes
#
# CONFIG_SCSI_SPI_ATTRS is not set
# CONFIG_SCSI_FC_ATTRS is not set

#
# SCSI low-level drivers
#
# CONFIG_BLK_DEV_3W_XXXX_RAID is not set
# CONFIG_SCSI_3W_9XXX is not set
# CONFIG_SCSI_ACARD is not set
# CONFIG_SCSI_AACRAID is not set
CONFIG_SCSI_AIC7XXX=m
CONFIG_AIC7XXX_CMDS_PER_DEVICE=32
CONFIG_AIC7XXX_RESET_DELAY_MS=15000
# CONFIG_AIC7XXX_DEBUG_ENABLE is not set
CONFIG_AIC7XXX_DEBUG_MASK=0
# CONFIG_AIC7XXX_REG_PRETTY_PRINT is not set
# CONFIG_SCSI_AIC7XXX_OLD is not set
# CONFIG_SCSI_AIC79XX is not set
# CONFIG_SCSI_DPT_I2O is not set
# CONFIG_MEGARAID_NEWGEN is not set
# CONFIG_MEGARAID_LEGACY is not set
# CONFIG_SCSI_SATA is not set
# CONFIG_SCSI_BUSLOGIC is not set
# CONFIG_SCSI_DMX3191D is not set
# CONFIG_SCSI_EATA is not set
# CONFIG_SCSI_EATA_PIO is not set
# CONFIG_SCSI_FUTURE_DOMAIN is not set
# CONFIG_SCSI_GDTH is not set
# CONFIG_SCSI_IPS is not set
# CONFIG_SCSI_INITIO is not set
# CONFIG_SCSI_INIA100 is not set
# CONFIG_SCSI_SYM53C8XX_2 is not set
# CONFIG_SCSI_IPR is not set
# CONFIG_SCSI_QLOGIC_ISP is not set
# CONFIG_SCSI_QLOGIC_FC is not set
# CONFIG_SCSI_QLOGIC_1280 is not set
# CONFIG_SCSI_QLOGIC_1280_1040 is not set
CONFIG_SCSI_QLA2XXX=m
# CONFIG_SCSI_QLA21XX is not set
# CONFIG_SCSI_QLA22XX is not set
# CONFIG_SCSI_QLA2300 is not set
# CONFIG_SCSI_QLA2322 is not set
# CONFIG_SCSI_QLA6312 is not set
# CONFIG_SCSI_QLA6322 is not set
# CONFIG_SCSI_DC395x is not set
# CONFIG_SCSI_DC390T is not set
# CONFIG_SCSI_NSP32 is not set
# CONFIG_SCSI_DEBUG is not set

#
# Multi-device support (RAID and LVM)
#
# CONFIG_MD is not set

#
# Fusion MPT device support
#
# CONFIG_FUSION is not set

#
# IEEE 1394 (FireWire) support
#
# CONFIG_IEEE1394 is not set

#
# I2O device support
#
# CONFIG_I2O is not set

#
# Networking support
#
CONFIG_NET=y

#
# Networking options
#
CONFIG_PACKET=y
# CONFIG_PACKET_MMAP is not set
CONFIG_NETLINK_DEV=y
CONFIG_UNIX=y
# CONFIG_NET_KEY is not set
CONFIG_INET=y
CONFIG_IP_MULTICAST=y
CONFIG_IP_ADVANCED_ROUTER=y
# CONFIG_IP_MULTIPLE_TABLES is not set
# CONFIG_IP_ROUTE_MULTIPATH is not set
# CONFIG_IP_ROUTE_VERBOSE is not set
# CONFIG_IP_PNP is not set
# CONFIG_NET_IPIP is not set
# CONFIG_NET_IPGRE is not set
# CONFIG_IP_MROUTE is not set
# CONFIG_ARPD is not set
# CONFIG_SYN_COOKIES is not set
# CONFIG_INET_AH is not set
# CONFIG_INET_ESP is not set
# CONFIG_INET_IPCOMP is not set
# CONFIG_INET_TUNNEL is not set

#
# IP: Virtual Server Configuration
#
# CONFIG_IP_VS is not set
# CONFIG_IPV6 is not set
CONFIG_NETFILTER=y
# CONFIG_NETFILTER_DEBUG is not set

#
# IP: Netfilter Configuration
#
CONFIG_IP_NF_CONNTRACK=m
# CONFIG_IP_NF_CT_ACCT is not set
# CONFIG_IP_NF_CT_PROTO_SCTP is not set
# CONFIG_IP_NF_FTP is not set
# CONFIG_IP_NF_IRC is not set
# CONFIG_IP_NF_TFTP is not set
# CONFIG_IP_NF_AMANDA is not set
# CONFIG_IP_NF_QUEUE is not set
CONFIG_IP_NF_IPTABLES=m
CONFIG_IP_NF_MATCH_LIMIT=m
CONFIG_IP_NF_MATCH_IPRANGE=m
CONFIG_IP_NF_MATCH_MAC=m
CONFIG_IP_NF_MATCH_PKTTYPE=m
CONFIG_IP_NF_MATCH_MARK=m
CONFIG_IP_NF_MATCH_MULTIPORT=m
CONFIG_IP_NF_MATCH_TOS=m
CONFIG_IP_NF_MATCH_RECENT=m
CONFIG_IP_NF_MATCH_ECN=m
CONFIG_IP_NF_MATCH_DSCP=m
CONFIG_IP_NF_MATCH_AH_ESP=m
CONFIG_IP_NF_MATCH_LENGTH=m
CONFIG_IP_NF_MATCH_TTL=m
CONFIG_IP_NF_MATCH_TCPMSS=m
CONFIG_IP_NF_MATCH_HELPER=m
CONFIG_IP_NF_MATCH_STATE=m
CONFIG_IP_NF_MATCH_CONNTRACK=m
CONFIG_IP_NF_MATCH_OWNER=m
CONFIG_IP_NF_MATCH_ADDRTYPE=m
CONFIG_IP_NF_MATCH_REALM=m
# CONFIG_IP_NF_MATCH_SCTP is not set
# CONFIG_IP_NF_MATCH_COMMENT is not set
CONFIG_IP_NF_FILTER=m
CONFIG_IP_NF_TARGET_REJECT=m
CONFIG_IP_NF_TARGET_LOG=m
CONFIG_IP_NF_TARGET_ULOG=m
CONFIG_IP_NF_TARGET_TCPMSS=m
CONFIG_IP_NF_NAT=m
CONFIG_IP_NF_NAT_NEEDED=y
CONFIG_IP_NF_TARGET_MASQUERADE=m
CONFIG_IP_NF_TARGET_REDIRECT=m
CONFIG_IP_NF_TARGET_NETMAP=m
CONFIG_IP_NF_TARGET_SAME=m
# CONFIG_IP_NF_NAT_LOCAL is not set
# CONFIG_IP_NF_NAT_SNMP_BASIC is not set
CONFIG_IP_NF_MANGLE=m
CONFIG_IP_NF_TARGET_TOS=m
CONFIG_IP_NF_TARGET_ECN=m
CONFIG_IP_NF_TARGET_DSCP=m
CONFIG_IP_NF_TARGET_MARK=m
CONFIG_IP_NF_TARGET_CLASSIFY=m
# CONFIG_IP_NF_RAW is not set
CONFIG_IP_NF_ARPTABLES=m
CONFIG_IP_NF_ARPFILTER=m
CONFIG_IP_NF_ARP_MANGLE=m
# CONFIG_IP_NF_COMPAT_IPCHAINS is not set
# CONFIG_IP_NF_COMPAT_IPFWADM is not set

#
# SCTP Configuration (EXPERIMENTAL)
#
# CONFIG_IP_SCTP is not set
# CONFIG_ATM is not set
# CONFIG_BRIDGE is not set
# CONFIG_VLAN_8021Q is not set
# CONFIG_DECNET is not set
# CONFIG_LLC2 is not set
# CONFIG_IPX is not set
# CONFIG_ATALK is not set
# CONFIG_X25 is not set
# CONFIG_LAPB is not set
# CONFIG_NET_DIVERT is not set
# CONFIG_ECONET is not set
# CONFIG_WAN_ROUTER is not set
# CONFIG_NET_HW_FLOWCONTROL is not set

#
# QoS and/or fair queueing
#
CONFIG_NET_SCHED=y
CONFIG_NET_SCH_CLK_JIFFIES=y
# CONFIG_NET_SCH_CLK_GETTIMEOFDAY is not set
# CONFIG_NET_SCH_CLK_CPU is not set
CONFIG_NET_SCH_CBQ=m
CONFIG_NET_SCH_HTB=m
# CONFIG_NET_SCH_HFSC is not set
CONFIG_NET_SCH_PRIO=m
CONFIG_NET_SCH_RED=m
CONFIG_NET_SCH_SFQ=m
CONFIG_NET_SCH_TEQL=m
CONFIG_NET_SCH_TBF=m
CONFIG_NET_SCH_GRED=m
CONFIG_NET_SCH_DSMARK=m
# CONFIG_NET_SCH_NETEM is not set
CONFIG_NET_SCH_INGRESS=m
CONFIG_NET_QOS=y
CONFIG_NET_ESTIMATOR=y
CONFIG_NET_CLS=y
CONFIG_NET_CLS_TCINDEX=m
CONFIG_NET_CLS_ROUTE4=m
CONFIG_NET_CLS_ROUTE=y
CONFIG_NET_CLS_FW=m
CONFIG_NET_CLS_U32=m
# CONFIG_CLS_U32_PERF is not set
# CONFIG_NET_CLS_IND is not set
CONFIG_NET_CLS_RSVP=m
CONFIG_NET_CLS_RSVP6=m
# CONFIG_NET_CLS_ACT is not set
CONFIG_NET_CLS_POLICE=y

#
# Network testing
#
# CONFIG_NET_PKTGEN is not set
# CONFIG_KGDBOE is not set
# CONFIG_NETPOLL is not set
# CONFIG_NETPOLL_RX is not set
# CONFIG_NETPOLL_TRAP is not set
# CONFIG_NET_POLL_CONTROLLER is not set
# CONFIG_HAMRADIO is not set
# CONFIG_IRDA is not set
# CONFIG_BT is not set
CONFIG_NETDEVICES=y
CONFIG_DUMMY=m
# CONFIG_BONDING is not set
# CONFIG_EQUALIZER is not set
# CONFIG_TUN is not set
# CONFIG_ETHERTAP is not set

#
# ARCnet devices
#
# CONFIG_ARCNET is not set

#
# Ethernet (10 or 100Mbit)
#
CONFIG_NET_ETHERNET=y
CONFIG_MII=m
# CONFIG_HAPPYMEAL is not set
# CONFIG_SUNGEM is not set
# CONFIG_NET_VENDOR_3COM is not set

#
# Tulip family network device support
#
# CONFIG_NET_TULIP is not set
# CONFIG_HP100 is not set
CONFIG_NET_PCI=y
# CONFIG_PCNET32 is not set
# CONFIG_AMD8111_ETH is not set
# CONFIG_ADAPTEC_STARFIRE is not set
# CONFIG_B44 is not set
# CONFIG_FORCEDETH is not set
# CONFIG_DGRS is not set
# CONFIG_EEPRO100 is not set
# CONFIG_E100 is not set
# CONFIG_FEALNX is not set
# CONFIG_NATSEMI is not set
# CONFIG_NE2K_PCI is not set
# CONFIG_8139CP is not set
# CONFIG_8139TOO is not set
CONFIG_SIS900=m
# CONFIG_EPIC100 is not set
# CONFIG_SUNDANCE is not set
# CONFIG_TLAN is not set
# CONFIG_VIA_RHINE is not set

#
# Ethernet (1000 Mbit)
#
# CONFIG_ACENIC is not set
# CONFIG_DL2K is not set
# CONFIG_E1000 is not set
# CONFIG_NS83820 is not set
# CONFIG_HAMACHI is not set
# CONFIG_YELLOWFIN is not set
# CONFIG_R8169 is not set
# CONFIG_SK98LIN is not set
# CONFIG_VIA_VELOCITY is not set
# CONFIG_TIGON3 is not set

#
# Ethernet (10000 Mbit)
#
# CONFIG_IXGB is not set
# CONFIG_S2IO is not set

#
# Token Ring devices
#
# CONFIG_TR is not set

#
# Wireless LAN (non-hamradio)
#
# CONFIG_NET_RADIO is not set

#
# Wan interfaces
#
# CONFIG_WAN is not set
# CONFIG_FDDI is not set
# CONFIG_HIPPI is not set
CONFIG_PPP=m
CONFIG_PPP_MULTILINK=y
CONFIG_PPP_FILTER=y
CONFIG_PPP_ASYNC=m
CONFIG_PPP_SYNC_TTY=m
CONFIG_PPP_DEFLATE=m
CONFIG_PPP_BSDCOMP=m
CONFIG_PPPOE=m
# CONFIG_SLIP is not set
# CONFIG_NET_FC is not set
# CONFIG_SHAPER is not set
# CONFIG_NETCONSOLE is not set

#
# ISDN subsystem
#
# CONFIG_ISDN is not set

#
# Telephony Support
#
# CONFIG_PHONE is not set

#
# Input device support
#
CONFIG_INPUT=y

#
# Userland interfaces
#
CONFIG_INPUT_MOUSEDEV=y
CONFIG_INPUT_MOUSEDEV_PSAUX=y
CONFIG_INPUT_MOUSEDEV_SCREEN_X=1024
CONFIG_INPUT_MOUSEDEV_SCREEN_Y=768
CONFIG_INPUT_JOYDEV=m
# CONFIG_INPUT_TSDEV is not set
# CONFIG_INPUT_EVDEV is not set
# CONFIG_INPUT_EVBUG is not set

#
# Input I/O drivers
#
CONFIG_GAMEPORT=m
CONFIG_SOUND_GAMEPORT=m
# CONFIG_GAMEPORT_NS558 is not set
# CONFIG_GAMEPORT_L4 is not set
# CONFIG_GAMEPORT_EMU10K1 is not set
# CONFIG_GAMEPORT_VORTEX is not set
# CONFIG_GAMEPORT_FM801 is not set
# CONFIG_GAMEPORT_CS461x is not set
CONFIG_SERIO=y
CONFIG_SERIO_I8042=y
# CONFIG_SERIO_SERPORT is not set
# CONFIG_SERIO_CT82C710 is not set
CONFIG_SERIO_PCIPS2=m
CONFIG_SERIO_LIBPS2=y
# CONFIG_SERIO_RAW is not set

#
# Input Device Drivers
#
CONFIG_INPUT_KEYBOARD=y
CONFIG_KEYBOARD_ATKBD=y
# CONFIG_KEYBOARD_SUNKBD is not set
# CONFIG_KEYBOARD_LKKBD is not set
# CONFIG_KEYBOARD_XTKBD is not set
# CONFIG_KEYBOARD_NEWTON is not set
CONFIG_INPUT_MOUSE=y
CONFIG_MOUSE_PS2=y
# CONFIG_MOUSE_SERIAL is not set
# CONFIG_MOUSE_VSXXXAA is not set
# CONFIG_INPUT_JOYSTICK is not set
# CONFIG_INPUT_TOUCHSCREEN is not set
CONFIG_INPUT_MISC=y
CONFIG_INPUT_PCSPKR=y
# CONFIG_INPUT_UINPUT is not set

#
# Character devices
#
CONFIG_VT=y
CONFIG_VT_CONSOLE=y
CONFIG_HW_CONSOLE=y
# CONFIG_SERIAL_NONSTANDARD is not set

#
# Serial drivers
#
CONFIG_SERIAL_8250=y
# CONFIG_SERIAL_8250_CONSOLE is not set
CONFIG_SERIAL_8250_NR_UARTS=4
# CONFIG_SERIAL_8250_EXTENDED is not set

#
# Non-8250 serial port support
#
CONFIG_SERIAL_CORE=y
CONFIG_UNIX98_PTYS=y
CONFIG_LEGACY_PTYS=y
CONFIG_LEGACY_PTY_COUNT=256

#
# IPMI
#
# CONFIG_IPMI_HANDLER is not set

#
# Watchdog Cards
#
# CONFIG_WATCHDOG is not set
# CONFIG_HW_RANDOM is not set
CONFIG_NVRAM=y
CONFIG_RTC=y
# CONFIG_DTLK is not set
# CONFIG_R3964 is not set
# CONFIG_APPLICOM is not set
# CONFIG_SONYPI is not set

#
# Ftape, the floppy tape device driver
#
# CONFIG_FTAPE is not set
CONFIG_AGP=m
# CONFIG_AGP_ALI is not set
# CONFIG_AGP_ATI is not set
# CONFIG_AGP_AMD is not set
# CONFIG_AGP_AMD64 is not set
# CONFIG_AGP_INTEL is not set
# CONFIG_AGP_INTEL_MCH is not set
# CONFIG_AGP_NVIDIA is not set
CONFIG_AGP_SIS=m
# CONFIG_AGP_SWORKS is not set
# CONFIG_AGP_VIA is not set
# CONFIG_AGP_EFFICEON is not set
# CONFIG_DRM is not set
# CONFIG_MWAVE is not set
# CONFIG_RAW_DRIVER is not set
CONFIG_HANGCHECK_TIMER=m

#
# I2C support
#
# CONFIG_I2C is not set

#
# Dallas's 1-wire bus
#
# CONFIG_W1 is not set

#
# Misc devices
#
# CONFIG_IBM_ASM is not set

#
# Multimedia devices
#
# CONFIG_VIDEO_DEV is not set

#
# Digital Video Broadcasting Devices
#
# CONFIG_DVB is not set

#
# Graphics support
#
# CONFIG_FB is not set
CONFIG_VIDEO_SELECT=y

#
# Console display driver support
#
CONFIG_VGA_CONSOLE=y
CONFIG_DUMMY_CONSOLE=y

#
# Sound
#
CONFIG_SOUND=m

#
# Advanced Linux Sound Architecture
#
CONFIG_SND=m
CONFIG_SND_TIMER=m
CONFIG_SND_PCM=m
CONFIG_SND_RAWMIDI=m
CONFIG_SND_SEQUENCER=m
CONFIG_SND_SEQ_DUMMY=m
CONFIG_SND_OSSEMUL=y
CONFIG_SND_MIXER_OSS=m
CONFIG_SND_PCM_OSS=m
CONFIG_SND_SEQUENCER_OSS=y
CONFIG_SND_RTCTIMER=m
# CONFIG_SND_VERBOSE_PRINTK is not set
CONFIG_SND_DEBUG=y
# CONFIG_SND_DEBUG_MEMORY is not set
# CONFIG_SND_DEBUG_DETECT is not set

#
# Generic devices
#
CONFIG_SND_DUMMY=m
# CONFIG_SND_VIRMIDI is not set
# CONFIG_SND_MTPAV is not set
# CONFIG_SND_SERIAL_U16550 is not set
# CONFIG_SND_MPU401 is not set

#
# PCI devices
#
CONFIG_SND_AC97_CODEC=m
# CONFIG_SND_ALI5451 is not set
# CONFIG_SND_ATIIXP is not set
# CONFIG_SND_ATIIXP_MODEM is not set
# CONFIG_SND_AU8810 is not set
# CONFIG_SND_AU8820 is not set
# CONFIG_SND_AU8830 is not set
# CONFIG_SND_AZT3328 is not set
# CONFIG_SND_BT87X is not set
CONFIG_SND_CS46XX=m
CONFIG_SND_CS46XX_NEW_DSP=y
# CONFIG_SND_CS4281 is not set
# CONFIG_SND_EMU10K1 is not set
# CONFIG_SND_KORG1212 is not set
# CONFIG_SND_MIXART is not set
# CONFIG_SND_NM256 is not set
# CONFIG_SND_RME32 is not set
# CONFIG_SND_RME96 is not set
# CONFIG_SND_RME9652 is not set
# CONFIG_SND_HDSP is not set
# CONFIG_SND_TRIDENT is not set
# CONFIG_SND_YMFPCI is not set
# CONFIG_SND_ALS4000 is not set
# CONFIG_SND_CMIPCI is not set
# CONFIG_SND_ENS1370 is not set
# CONFIG_SND_ENS1371 is not set
# CONFIG_SND_ES1938 is not set
# CONFIG_SND_ES1968 is not set
# CONFIG_SND_MAESTRO3 is not set
# CONFIG_SND_FM801 is not set
# CONFIG_SND_ICE1712 is not set
# CONFIG_SND_ICE1724 is not set
CONFIG_SND_INTEL8X0=m
# CONFIG_SND_INTEL8X0M is not set
# CONFIG_SND_SONICVIBES is not set
# CONFIG_SND_VIA82XX is not set
# CONFIG_SND_VX222 is not set

#
# Open Sound System
#
# CONFIG_SOUND_PRIME is not set

#
# USB support
#
# CONFIG_USB is not set

#
# USB Gadget Support
#
# CONFIG_USB_GADGET is not set

#
# File systems
#
CONFIG_EXT2_FS=y
CONFIG_EXT2_FS_XATTR=y
# CONFIG_EXT2_FS_POSIX_ACL is not set
# CONFIG_EXT2_FS_SECURITY is not set
CONFIG_EXT3_FS=y
CONFIG_EXT3_FS_XATTR=y
# CONFIG_EXT3_FS_POSIX_ACL is not set
# CONFIG_EXT3_FS_SECURITY is not set
CONFIG_JBD=y
# CONFIG_JBD_DEBUG is not set
CONFIG_FS_MBCACHE=y
# CONFIG_REISERFS_FS is not set
# CONFIG_JFS_FS is not set
# CONFIG_XFS_FS is not set
# CONFIG_MINIX_FS is not set
CONFIG_ROMFS_FS=y
# CONFIG_QUOTA is not set
# CONFIG_AUTOFS_FS is not set
CONFIG_AUTOFS4_FS=y

#
# Caches
#
# CONFIG_FSCACHE is not set

#
# CD-ROM/DVD Filesystems
#
CONFIG_ISO9660_FS=y
CONFIG_JOLIET=y
CONFIG_ZISOFS=y
CONFIG_ZISOFS_FS=y
CONFIG_UDF_FS=y
CONFIG_UDF_NLS=y

#
# DOS/FAT/NT Filesystems
#
CONFIG_FAT_FS=y
CONFIG_MSDOS_FS=y
CONFIG_VFAT_FS=y
CONFIG_FAT_DEFAULT_CODEPAGE=437
CONFIG_FAT_DEFAULT_IOCHARSET="iso8859-1"
CONFIG_NTFS_FS=m
# CONFIG_NTFS_DEBUG is not set
# CONFIG_NTFS_RW is not set

#
# Pseudo filesystems
#
CONFIG_PROC_FS=y
CONFIG_PROC_KCORE=y
CONFIG_SYSFS=y
# CONFIG_DEVFS_FS is not set
CONFIG_DEVPTS_FS_XATTR=y
# CONFIG_DEVPTS_FS_SECURITY is not set
CONFIG_TMPFS=y
# CONFIG_TMPFS_XATTR is not set
# CONFIG_HUGETLBFS is not set
# CONFIG_HUGETLB_PAGE is not set
CONFIG_RAMFS=y

#
# Miscellaneous filesystems
#
# CONFIG_ADFS_FS is not set
# CONFIG_AFFS_FS is not set
# CONFIG_HFS_FS is not set
# CONFIG_HFSPLUS_FS is not set
# CONFIG_BEFS_FS is not set
# CONFIG_BFS_FS is not set
# CONFIG_EFS_FS is not set
CONFIG_CRAMFS=m
# CONFIG_VXFS_FS is not set
# CONFIG_HPFS_FS is not set
# CONFIG_QNX4FS_FS is not set
# CONFIG_SYSV_FS is not set
# CONFIG_UFS_FS is not set

#
# Network File Systems
#
# CONFIG_NFS_FS is not set
# CONFIG_NFSD is not set
# CONFIG_EXPORTFS is not set
# CONFIG_SMB_FS is not set
# CONFIG_CIFS is not set
# CONFIG_NCP_FS is not set
# CONFIG_CODA_FS is not set
CONFIG_AFS_FS=m
CONFIG_RXRPC=m

#
# Partition Types
#
# CONFIG_PARTITION_ADVANCED is not set
CONFIG_MSDOS_PARTITION=y

#
# Native Language Support
#
CONFIG_NLS=y
CONFIG_NLS_DEFAULT="iso8859-1"
CONFIG_NLS_CODEPAGE_437=y
# CONFIG_NLS_CODEPAGE_737 is not set
# CONFIG_NLS_CODEPAGE_775 is not set
CONFIG_NLS_CODEPAGE_850=y
# CONFIG_NLS_CODEPAGE_852 is not set
# CONFIG_NLS_CODEPAGE_855 is not set
# CONFIG_NLS_CODEPAGE_857 is not set
# CONFIG_NLS_CODEPAGE_860 is not set
# CONFIG_NLS_CODEPAGE_861 is not set
# CONFIG_NLS_CODEPAGE_862 is not set
# CONFIG_NLS_CODEPAGE_863 is not set
# CONFIG_NLS_CODEPAGE_864 is not set
# CONFIG_NLS_CODEPAGE_865 is not set
# CONFIG_NLS_CODEPAGE_866 is not set
# CONFIG_NLS_CODEPAGE_869 is not set
# CONFIG_NLS_CODEPAGE_936 is not set
# CONFIG_NLS_CODEPAGE_950 is not set
# CONFIG_NLS_CODEPAGE_932 is not set
# CONFIG_NLS_CODEPAGE_949 is not set
# CONFIG_NLS_CODEPAGE_874 is not set
# CONFIG_NLS_ISO8859_8 is not set
CONFIG_NLS_CODEPAGE_1250=y
# CONFIG_NLS_CODEPAGE_1251 is not set
# CONFIG_NLS_ASCII is not set
CONFIG_NLS_ISO8859_1=y
# CONFIG_NLS_ISO8859_2 is not set
# CONFIG_NLS_ISO8859_3 is not set
# CONFIG_NLS_ISO8859_4 is not set
# CONFIG_NLS_ISO8859_5 is not set
# CONFIG_NLS_ISO8859_6 is not set
# CONFIG_NLS_ISO8859_7 is not set
# CONFIG_NLS_ISO8859_9 is not set
# CONFIG_NLS_ISO8859_13 is not set
# CONFIG_NLS_ISO8859_14 is not set
CONFIG_NLS_ISO8859_15=y
# CONFIG_NLS_KOI8_R is not set
# CONFIG_NLS_KOI8_U is not set
# CONFIG_NLS_UTF8 is not set

#
# Profiling support
#
# CONFIG_PROFILING is not set

#
# Kernel hacking
#
CONFIG_DEBUG_KERNEL=y
CONFIG_MAGIC_SYSRQ=y
# CONFIG_DEBUG_SLAB is not set
CONFIG_DEBUG_PREEMPT=y
CONFIG_PREEMPT_TIMING=y
CONFIG_PREEMPT_TRACE=y
CONFIG_LATENCY_TRACE=y
CONFIG_MCOUNT=y
CONFIG_RWSEM_DEADLOCK_DETECT=y
CONFIG_RWSEM_MAX_OWNERS=64
# CONFIG_DEBUG_INFO is not set
CONFIG_EARLY_PRINTK=y
# CONFIG_DEBUG_STACKOVERFLOW is not set
# CONFIG_KPROBES is not set
# CONFIG_DEBUG_STACK_USAGE is not set
# CONFIG_DEBUG_PAGEALLOC is not set
CONFIG_4KSTACKS=y
# CONFIG_SCHEDSTATS is not set
# CONFIG_KGDB is not set

#
# Security options
#
# CONFIG_KEYS is not set
CONFIG_SECURITY=y
# CONFIG_SECURITY_NETWORK is not set
CONFIG_SECURITY_CAPABILITIES=m
# CONFIG_SECURITY_SECLVL is not set
# CONFIG_SECURITY_SELINUX is not set

#
# Cryptographic options
#
CONFIG_CRYPTO=y
# CONFIG_CRYPTO_HMAC is not set
# CONFIG_CRYPTO_NULL is not set
# CONFIG_CRYPTO_MD4 is not set
# CONFIG_CRYPTO_MD5 is not set
# CONFIG_CRYPTO_SHA1 is not set
# CONFIG_CRYPTO_SHA256 is not set
# CONFIG_CRYPTO_SHA512 is not set
# CONFIG_CRYPTO_WP512 is not set
# CONFIG_CRYPTO_DES is not set
# CONFIG_CRYPTO_BLOWFISH is not set
# CONFIG_CRYPTO_TWOFISH is not set
# CONFIG_CRYPTO_SERPENT is not set
# CONFIG_CRYPTO_AES_586 is not set
# CONFIG_CRYPTO_CAST5 is not set
# CONFIG_CRYPTO_CAST6 is not set
# CONFIG_CRYPTO_TEA is not set
# CONFIG_CRYPTO_ARC4 is not set
# CONFIG_CRYPTO_KHAZAD is not set
# CONFIG_CRYPTO_DEFLATE is not set
# CONFIG_CRYPTO_MICHAEL_MIC is not set
# CONFIG_CRYPTO_CRC32C is not set
# CONFIG_CRYPTO_TEST is not set

#
# Library routines
#
CONFIG_CRC_CCITT=m
CONFIG_CRC32=m
CONFIG_LIBCRC32C=m
CONFIG_ZLIB_INFLATE=y
CONFIG_ZLIB_DEFLATE=m
CONFIG_GENERIC_HARDIRQS=y
CONFIG_X86_BIOS_REBOOT=y
CONFIG_PC=y

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U6

[Ingo Molnar]

* Florian Schmidt <mista.tapas@gmx.net> wrote:

> I don't get any oopses or panics, but i can observer a rather
> interesting behaviour. When i enable the latency traces via
> 
> echo 1 > /proc/sys/kernel/trace_enabled
> 
> my machine starts to make little pauses of ca 3-4 secs. X "hangs" for
> this duration and so does aplay when playing a .wav file. "hangs"
> means that the X display seems to be locked. Interestingly enough all
> keystrokes i entered during the "hang" seem to arrive fine after the
> hang has ended. aplay experiences an xrun.

do you get the same pauses if you do 'dmesg -n 1'? Also, are you using
preempt_thresh or the maximum-searching variant? preempt_thresh can
generate _tons_ of messages with a low threshold, freezing the system in
essence for long periods of time.

but this trace is weird:

> preemption latency trace v1.0.7 on 2.6.9-rc4-mm1-RT-U6
> -------------------------------------------------------
>  latency: 1841 us, entries: 4000 (12990)   |   [VP:1 KP:1 SP:1 HP:1 #CPUS:1]
>     -----------------
>     | task: aplay/2160, uid:1000 nice:0 policy:0 rt_prio:0
>     -----------------
>  => started at: __schedule+0x3b/0x5d0 <c02a767b>
>  => ended at:   finish_task_switch+0x43/0xb0 <c0114ae3>
> =======>
> 00000001 0.000ms (+0.000ms): __schedule (ksoftirqd)
> 00000001 0.000ms (+0.000ms): sched_clock (__schedule)
> 00000002 0.000ms (+0.000ms): deactivate_task (__schedule)
> 00000002 0.000ms (+0.000ms): dequeue_task (deactivate_task)
> 04000002 0.000ms (+0.000ms): __switch_to (__schedule)
> 04000002 0.001ms (+0.000ms): finish_task_switch (__schedule)
> 04000000 0.001ms (+0.000ms): schedule (down_write)
> 04000000 0.001ms (+0.000ms): __schedule (down_write)
> 04000001 0.001ms (+0.000ms): sched_clock (__schedule)
> 04000000 0.001ms (+0.000ms): schedule (down_write)
> 04000000 0.001ms (+0.000ms): __schedule (down_write)
> 04000001 0.002ms (+0.000ms): sched_clock (__schedule)
> 04000000 0.002ms (+0.000ms): schedule (down_write)

this doesnt seem like normal behavior. It seems two tasks are
ping-pong-ing a semaphore but are unable to make any progress. The whole
thing is non-preemptible because this semaphore was taken while in a 
PREEMPT_ACTIVE section.

(i'd say this is the BKL semaphore - it is quite special in that
regard.)

	Ingo

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U6

[Florian Schmidt]

On Tue, 19 Oct 2004 18:56:46 +0200
Ingo Molnar <mingo@elte.hu> wrote:

> do you get the same pauses if you do 'dmesg -n 1'? Also, are you using
> preempt_thresh or the maximum-searching variant? preempt_thresh can
> generate _tons_ of messages with a low threshold, freezing the system in
> essence for long periods of time.

afaik i use the maximum search:

mango:~# cat /proc/sys/kernel/preempt_thresh 
0
mango:~# cat /proc/sys/kernel/preempt_max_latency 
1841

I'll compile a kernel w/o preempt-timing and tracing. But i will get to it
tomorrow the earliest.

> but this trace is weird:

 [snip]
 
> this doesnt seem like normal behavior. It seems two tasks are
> ping-pong-ing a semaphore but are unable to make any progress. The whole
> thing is non-preemptible because this semaphore was taken while in a 
> PREEMPT_ACTIVE section.
> 
> (i'd say this is the BKL semaphore - it is quite special in that
> regard.)

btw: afaics these long critical sections reports do not correlate to the
pauses X makes (not sure though). I have anther long one. This is from
syslog as i haven't had the tracing enabled at that time:

(IRQ 3/117/CPU#0): new 1385 us maximum-latency critical section.
 => started at timestamp 2293619762: <call_console_drivers+0x76/0x140>
 =>   ended at timestamp 2293621147: <finish_task_switch+0x43/0xb0>
 [<c012f630>] sub_preempt_count+0x60/0x90
 [<c012f31e>] check_preempt_timing+0x15e/0x270
 [<c0114ae3>] finish_task_switch+0x43/0xb0
 [<c012f630>] sub_preempt_count+0x60/0x90
 [<c0114ae3>] finish_task_switch+0x43/0xb0
 [<c0114ae3>] finish_task_switch+0x43/0xb0
 [<c02a7917>] __schedule+0x2d7/0x5d0
 [<c0136faa>] do_irqd+0x5a/0x80
 [<c0112440>] mcount+0x14/0x18
 [<c0136faa>] do_irqd+0x5a/0x80
 [<c012d82a>] kthread+0xaa/0xb0
 [<c0136f50>] do_irqd+0x0/0x80
 [<c012d780>] kthread+0x0/0xb0
 [<c0104099>] kernel_thread_helper+0x5/0xc
preempt count: 00000002
. 2-level deep critical section nesting:
.. entry 1: __schedule+0x3b/0x5d0 / (do_irqd+0x5a/0x80)
.. entry 2: print_traces+0x1d/0x80 / (dump_stack+0x23/0x30)

 =>   dump-end timestamp 2293621634



Here's a similar (to the one from my last mail) shorter one:

preemption latency trace v1.0.7 on 2.6.9-rc4-mm1-RT-U6
-------------------------------------------------------
 latency: 471 us, entries: 2562 (2562)   |   [VP:1 KP:1 SP:1 HP:1 #CPUS:1]
    -----------------
    | task: xterm/3155, uid:1000 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: cond_resched+0x23/0x80 <c02a82b3>
 => ended at:   finish_task_switch+0x43/0xb0 <c0114ae3>
=======>
04000001 0.000ms (+0.000ms): __rwsem_deadlock (down_write)
04000000 0.000ms (+0.000ms): schedule (down_write)
04000000 0.000ms (+0.000ms): __schedule (down_write)
04000001 0.000ms (+0.000ms): sched_clock (__schedule)
04000000 0.000ms (+0.000ms): schedule (down_write)
04000000 0.000ms (+0.000ms): __schedule (down_write)
04000001 0.000ms (+0.000ms): sched_clock (__schedule)
04000000 0.001ms (+0.000ms): schedule (down_write)
04000000 0.001ms (+0.000ms): __schedule (down_write)
04000001 0.001ms (+0.000ms): sched_clock (__schedule)
04000000 0.001ms (+0.000ms): schedule (down_write)
04000000 0.001ms (+0.000ms): __schedule (down_write)
04000001 0.001ms (+0.000ms): sched_clock (__schedule)
04000000 0.002ms (+0.000ms): schedule (down_write)
04000000 0.002ms (+0.000ms): __schedule (down_write)
04000001 0.002ms (+0.000ms): sched_clock (__schedule)
04000000 0.002ms (+0.000ms): schedule (down_write)
04000000 0.002ms (+0.000ms): __schedule (down_write)
04000001 0.002ms (+0.000ms): sched_clock (__schedule)
04000000 0.002ms (+0.000ms): schedule (down_write)
04000000 0.002ms (+0.000ms): __schedule (down_write)
04000001 0.003ms (+0.000ms): sched_clock (__schedule)
04000000 0.003ms (+0.000ms): schedule (down_write)
04000000 0.003ms (+0.000ms): __schedule (down_write)
04000001 0.003ms (+0.000ms): sched_clock (__schedule)
04000000 0.003ms (+0.000ms): schedule (down_write)

[many many more]

04000000 0.445ms (+0.000ms): __schedule (down_write)
04000001 0.445ms (+0.000ms): sched_clock (__schedule)
04000000 0.446ms (+0.000ms): schedule (down_write)
04000000 0.446ms (+0.000ms): __schedule (down_write)
04000001 0.446ms (+0.000ms): sched_clock (__schedule)
04000000 0.446ms (+0.000ms): schedule (down_write)
04000000 0.446ms (+0.000ms): __schedule (down_write)
04000001 0.447ms (+0.000ms): sched_clock (__schedule)
04000000 0.447ms (+0.000ms): schedule (down_write)
04000000 0.447ms (+0.000ms): __schedule (down_write)
04000001 0.447ms (+0.000ms): sched_clock (__schedule)
04000000 0.447ms (+0.000ms): schedule (down_write)
04000000 0.447ms (+0.000ms): __schedule (down_write)
04000001 0.448ms (+0.000ms): sched_clock (__schedule)
04000000 0.448ms (+0.000ms): schedule (down_write)
04000000 0.448ms (+0.000ms): __schedule (down_write)
04000001 0.448ms (+0.000ms): sched_clock (__schedule)
04000000 0.448ms (+0.000ms): schedule (down_write)
04000000 0.449ms (+0.000ms): __schedule (down_write)
04000001 0.449ms (+0.000ms): sched_clock (__schedule)
04000000 0.449ms (+0.000ms): schedule (down_write)
04000000 0.449ms (+0.000ms): __schedule (down_write)
04000001 0.449ms (+0.000ms): sched_clock (__schedule)
04000000 0.449ms (+0.000ms): schedule (down_write)
04000000 0.450ms (+0.000ms): __schedule (down_write)
04000001 0.450ms (+0.000ms): sched_clock (__schedule)
04000000 0.450ms (+0.000ms): schedule (down_write)
04000000 0.450ms (+0.000ms): __schedule (down_write)
04000001 0.450ms (+0.000ms): sched_clock (__schedule)
04000000 0.450ms (+0.000ms): schedule (down_write)
04000000 0.451ms (+0.000ms): __schedule (down_write)
04000001 0.451ms (+0.000ms): sched_clock (__schedule)
04000000 0.451ms (+0.000ms): schedule (down_write)
04000000 0.451ms (+0.000ms): __schedule (down_write)
04000001 0.451ms (+0.000ms): sched_clock (__schedule)
04000000 0.452ms (+0.000ms): schedule (down_write)
04000000 0.452ms (+0.000ms): __schedule (down_write)
04000001 0.452ms (+0.000ms): sched_clock (__schedule)
04000000 0.452ms (+0.000ms): schedule (down_write)
04000000 0.452ms (+0.000ms): __schedule (down_write)
04000001 0.452ms (+0.000ms): sched_clock (__schedule)
04000000 0.453ms (+0.000ms): schedule (down_write)
04000000 0.453ms (+0.000ms): __schedule (down_write)
04000001 0.453ms (+0.000ms): sched_clock (__schedule)
04000000 0.453ms (+0.000ms): schedule (down_write)
04000000 0.453ms (+0.000ms): __schedule (down_write)
04000001 0.453ms (+0.000ms): sched_clock (__schedule)
04000000 0.454ms (+0.000ms): schedule (down_write)
04000000 0.454ms (+0.000ms): __schedule (down_write)
04000001 0.454ms (+0.000ms): sched_clock (__schedule)
04000000 0.454ms (+0.000ms): schedule (down_write)
04000000 0.454ms (+0.001ms): __schedule (down_write)
04010000 0.455ms (+0.000ms): do_IRQ (add_preempt_count)
04010000 0.455ms (+0.000ms): do_IRQ (<00000000>)
00010001 0.456ms (+0.001ms): mask_and_ack_8259A (__do_IRQ)
00010001 0.458ms (+0.000ms): redirect_hardirq (__do_IRQ)
00010000 0.458ms (+0.000ms): handle_IRQ_event (__do_IRQ)
00010000 0.458ms (+0.000ms): timer_interrupt (handle_IRQ_event)
00010001 0.458ms (+0.006ms): mark_offset_tsc (timer_interrupt)
00010001 0.464ms (+0.000ms): do_timer (timer_interrupt)
00010001 0.465ms (+0.000ms): update_wall_time (do_timer)
00010001 0.465ms (+0.000ms): update_wall_time_one_tick (update_wall_time)
00010001 0.465ms (+0.000ms): update_process_times (timer_interrupt)
00010001 0.465ms (+0.000ms): update_one_process (update_process_times)
00010001 0.465ms (+0.000ms): run_local_timers (update_process_times)
00010001 0.466ms (+0.000ms): raise_softirq (update_process_times)
00010001 0.466ms (+0.000ms): scheduler_tick (update_process_times)
00010001 0.466ms (+0.000ms): sched_clock (scheduler_tick)
00010002 0.466ms (+0.000ms): task_timeslice (scheduler_tick)
00010002 0.467ms (+0.000ms): dequeue_task (scheduler_tick)
00010002 0.467ms (+0.000ms): effective_prio (scheduler_tick)
00010002 0.467ms (+0.000ms): enqueue_task (scheduler_tick)
00010001 0.468ms (+0.000ms): note_interrupt (__do_IRQ)
00010001 0.468ms (+0.000ms): end_8259A_irq (__do_IRQ)
00010001 0.468ms (+0.000ms): enable_8259A_irq (__do_IRQ)
04010000 0.469ms (+0.000ms): irq_exit (do_IRQ)
04000001 0.469ms (+0.000ms): sched_clock (__schedule)
00000002 0.470ms (+0.000ms): __switch_to (__schedule)
00000002 0.470ms (+0.000ms): finish_task_switch (__schedule)












one more:

preemption latency trace v1.0.7 on 2.6.9-rc4-mm1-RT-U6
-------------------------------------------------------
 latency: 2363 us, entries: 4000 (15429)   |   [VP:1 KP:1 SP:1 HP:1 #CPUS:1]
    -----------------
    | task: xterm/3155, uid:1000 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: cond_resched+0x23/0x80 <c02a82b3>
 => ended at:   finish_task_switch+0x43/0xb0 <c0114ae3>
=======>
04000001 0.000ms (+0.000ms): __rwsem_deadlock (down_write)
04000000 0.000ms (+0.000ms): schedule (down_write)
04000000 0.000ms (+0.000ms): __schedule (down_write)
04000001 0.000ms (+0.000ms): sched_clock (__schedule)
04000000 0.000ms (+0.000ms): schedule (down_write)
04000000 0.000ms (+0.000ms): __schedule (down_write)

[more]

04000000 0.347ms (+0.000ms): schedule (down_write)
04000000 0.348ms (+0.000ms): __schedule (down_write)
04000001 0.348ms (+0.000ms): sched_clock (__schedule)
04000000 0.348ms (+0.000ms): schedule (down_write)
04000000 0.348ms (+0.000ms): __schedule (down_write)
04000001 0.348ms (+0.000ms): sched_clock (__schedule)
04000000 0.349ms (+0.000ms): schedule (down_write)
04000000 0.349ms (+0.000ms): __schedule (down_write)
04000001 0.349ms (+0.000ms): sched_clock (__schedule)
04000000 0.349ms (+0.000ms): schedule (down_write)
04000000 0.349ms (+0.000ms): __schedule (down_write)
04000001 0.349ms (+0.000ms): sched_clock (__schedule)
04000000 0.350ms (+0.000ms): schedule (down_write)
04000000 0.350ms (+0.000ms): __schedule (down_write)
04000001 0.350ms (+0.000ms): sched_clock (__schedule)
04000000 0.350ms (+0.000ms): schedule (down_write)
04000000 0.350ms (+0.000ms): __schedule (down_write)
04000001 0.351ms (+0.000ms): sched_clock (__schedule)
04000000 0.351ms (+0.000ms): schedule (down_write)
04000000 0.351ms (+0.000ms): __schedule (down_write)
04000001 0.351ms (+0.000ms): sched_clock (__schedule)
04000000 0.352ms (+0.000ms): schedule (down_write)
04000000 0.352ms (+0.000ms): __schedule (down_write)
04010001 0.352ms (+0.000ms): do_IRQ (add_preempt_count)
04010001 0.353ms (+0.000ms): do_IRQ (<00000000>)
00010001 0.353ms (+0.001ms): mask_and_ack_8259A (__do_IRQ)
00010001 0.355ms (+0.000ms): redirect_hardirq (__do_IRQ)
00010000 0.355ms (+0.000ms): handle_IRQ_event (__do_IRQ)
00010000 0.355ms (+0.000ms): timer_interrupt (handle_IRQ_event)
00010001 0.356ms (+0.006ms): mark_offset_tsc (timer_interrupt)
00010001 0.362ms (+0.000ms): do_timer (timer_interrupt)
00010001 0.363ms (+0.000ms): update_wall_time (do_timer)
00010001 0.363ms (+0.000ms): update_wall_time_one_tick (update_wall_time)
00010001 0.363ms (+0.000ms): update_process_times (timer_interrupt)
00010001 0.363ms (+0.000ms): update_one_process (update_process_times)
00010001 0.363ms (+0.000ms): run_local_timers (update_process_times)
00010001 0.363ms (+0.000ms): raise_softirq (update_process_times)
00010001 0.364ms (+0.000ms): scheduler_tick (update_process_times)
00010001 0.364ms (+0.000ms): sched_clock (scheduler_tick)
00010002 0.364ms (+0.000ms): task_timeslice (scheduler_tick)
00010001 0.365ms (+0.000ms): note_interrupt (__do_IRQ)
00010001 0.365ms (+0.000ms): end_8259A_irq (__do_IRQ)
00010001 0.365ms (+0.000ms): enable_8259A_irq (__do_IRQ)
04010001 0.366ms (+0.000ms): irq_exit (do_IRQ)
04000001 0.367ms (+0.000ms): sched_clock (__schedule)
04000000 0.367ms (+0.000ms): schedule (down_write)
04000000 0.367ms (+0.000ms): __schedule (down_write)
04000001 0.367ms (+0.000ms): sched_clock (__schedule)
04000000 0.368ms (+0.000ms): schedule (down_write)
04000000 0.368ms (+0.000ms): __schedule (down_write)
04000001 0.368ms (+0.000ms): sched_clock (__schedule)
04000000 0.368ms (+0.000ms): schedule (down_write)
04000000 0.368ms (+0.000ms): __schedule (down_write)
04000001 0.369ms (+0.000ms): sched_clock (__schedule)
04000000 0.369ms (+0.000ms): schedule (down_write)
04000000 0.369ms (+0.000ms): __schedule (down_write)
04000001 0.369ms (+0.000ms): sched_clock (__schedule)
04000000 0.370ms (+0.000ms): schedule (down_write)
04000000 0.370ms (+0.000ms): __schedule (down_write)
04000001 0.370ms (+0.000ms): sched_clock (__schedule)
04000000 0.370ms (+0.000ms): schedule (down_write)

[more]

04000000 0.797ms (+0.000ms): schedule (down_write)
04000000 0.797ms (+0.000ms): __schedule (down_write)
04000001 0.797ms (+0.000ms): sched_clock (__schedule)
04000000 0.797ms (+0.000ms): schedule (down_write)
04000000 0.798ms (+0.000ms): __schedule (down_write)
04000001 0.798ms (+0.000ms): sched_clock (__schedule)
04000000 0.798ms (+0.000ms): schedule (down_write)
04000000 0.798ms (+0.000ms): __schedule (down_write)
04000001 0.798ms (+0.000ms): sched_clock (__schedule)
04000000 0.799ms (+0.000ms): schedule (down_write)
04000000 0.799ms (+0.000ms): __schedule (down_write)
04000001 0.799ms (+0.000ms): sched_clock (__schedule)
04000000 0.799ms (+0.000ms): schedule (down_write)
04000000 0.799ms (+0.000ms): __schedule (down_write)
04000001 0.800ms (+0.000ms): sched_clock (__schedule)
04000000 0.800ms (+0.000ms): schedule (down_write)
04000000 0.800ms (+0.000ms): __schedule (down_write)
04000001 0.800ms (+877840.005ms): sched_clock (__schedule)



fio

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U6

[Thomas Gleixner]

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

On Tue, 2004-10-19 at 16:46, Ingo Molnar wrote:
> * Ingo Molnar <mingo@elte.hu> wrote:
> i've re-released the patch because shortly after releasing it i found a
> false-positive in the deadlock-detector that was triggering in oowriter. 

Hit and converted another one. There are more, but they need more
modifications as they don't have a condition to wait for and therefor
must be converted to use the completion API, which must be extended to
provide completion_timemout() first.

tglx




[-- Attachment #2: clnt.c.diff --]
[-- Type: text/x-patch, Size: 534 bytes --]

diff --exclude='*~' -urN 2.6.9-rc4-mm1-RT-U6/net/sunrpc/clnt.c 2.6.9-rc4-mm1-VP-U4-LRT1/net/sunrpc/clnt.c
--- 2.6.9-rc4-mm1-RT-U6/net/sunrpc/clnt.c	2004-10-12 09:32:23.000000000 +0200
+++ 2.6.9-rc4-mm1-VP-U4-LRT1/net/sunrpc/clnt.c	2004-10-19 16:16:29.000000000 +0200
@@ -231,7 +231,8 @@
 		clnt->cl_oneshot = 0;
 		clnt->cl_dead = 0;
 		rpc_killall_tasks(clnt);
-		sleep_on_timeout(&destroy_wait, 1*HZ);
+		wait_event_timeout(destroy_wait, 
+			atomic_read(&clnt->cl_users) > 0, 1*HZ);
 	}
 
 	if (atomic_read(&clnt->cl_users) < 0) {

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U6

[Ingo Molnar]

* Thomas Gleixner <tglx@linutronix.de> wrote:

> On Tue, 2004-10-19 at 16:46, Ingo Molnar wrote:
> > * Ingo Molnar <mingo@elte.hu> wrote:
> > i've re-released the patch because shortly after releasing it i found a
> > false-positive in the deadlock-detector that was triggering in oowriter. 
> 
> Hit and converted another one. There are more, but they need more
> modifications as they don't have a condition to wait for and therefor
> must be converted to use the completion API, which must be extended to
> provide completion_timemout() first.

thanks, i've applied your patch to my tree. Find below an untested
implementation of wait_for_completion_timeout().

	Ingo

--- linux/kernel/sched.c.orig
+++ linux/kernel/sched.c
@@ -3070,6 +3148,31 @@ void fastcall __sched wait_for_completio
 }
 EXPORT_SYMBOL(wait_for_completion);
 
+unsigned long fastcall __sched
+wait_for_completion_timeout(struct completion *x, unsigned long timeout)
+{
+	might_sleep();
+	spin_lock_irq(&x->wait.lock);
+	if (!x->done) {
+		DECLARE_WAITQUEUE(wait, current);
+
+		wait.flags |= WQ_FLAG_EXCLUSIVE;
+		__add_wait_queue_tail(&x->wait, &wait);
+		do {
+			__set_current_state(TASK_UNINTERRUPTIBLE);
+			spin_unlock_irq(&x->wait.lock);
+			timeout = schedule_timeout(timeout);
+			spin_lock_irq(&x->wait.lock);
+		} while (!x->done);
+		__remove_wait_queue(&x->wait, &wait);
+	}
+	x->done--;
+	spin_unlock_irq(&x->wait.lock);
+
+	return timeout;
+}
+EXPORT_SYMBOL(wait_for_completion_timeout);
+
 #define	SLEEP_ON_VAR					\
 	unsigned long flags;				\
 	wait_queue_t wait;				\
--- linux/include/linux/completion.h.orig
+++ linux/include/linux/completion.h
@@ -28,6 +28,8 @@ static inline void init_completion(struc
 }
 
 extern void FASTCALL(wait_for_completion(struct completion *));
+extern unsigned long FASTCALL(wait_for_completion_timeout(struct completion *,
+							  unsigned long));
 extern void FASTCALL(complete(struct completion *));
 extern void FASTCALL(complete_all(struct completion *));
 

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U6

[Thomas Gleixner]

On Tue, 2004-10-19 at 18:26, Ingo Molnar wrote:
> thanks, i've applied your patch to my tree. Find below an untested
> implementation of wait_for_completion_timeout().

Will give it a try.

Found another exterm ugly one. In scsi_error_handler a mutex is
initialized locked and then it is acquired again with
down_interruptible()

I have no fix yet. Somebody else ?

tglx


PCI: Found IRQ 10 for device 0000:00:02.0
sym0: <875> rev 0x4 at pci 0000:00:02.0 irq 10
BUG: semaphore recursion deadlock detected!
.. current task scsi_eh_0/730 is already holding cfed3ed8.
00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
       00000000 c025a590 00000000 c0104115 cfed7800 00000000 00000000
Call Trace:
 [<c025a590>] scsi_error_handler+0x0/0x100
 [<c0104115>] kernel_thread_helper+0x5/0x10
------------[ cut here ]------------
kernel BUG at lib/rwsem-generic.c:472!
invalid operand: 0000 [#1]
PREEMPT
Modules linked in:
CPU:    0
EIP:    0060:[<c0307bb5>]    Not tainted VLI
EFLAGS: 00010046   (2.6.9-rc4-mm1-RT-U6)
EIP is at __down_write_interruptible+0xd5/0x296
eax: 00000001   ebx: 00000000   ecx: c036222c   edx: 00000001
esi: cfed3ed8   edi: cfd04070   ebp: 00000001   esp: cfed3e8c
ds: 007b   es: 007b   ss: 0068   preempt: 00000003
Process scsi_eh_0 (pid: 730, threadinfo=cfed2000 task=cfd04070)
Stack: cfed3ed8 00000000 00000000 cfed3edc cfed3edc cfd04070 00000002
cfed2000
       cfed3ed8 cfed3ed8 00000000 c01c6ae4 cfed3ed8 cfd04070 cfed7800
00000000
       c025a617 c032a106 00000000 ffffffff cfed3e98 cfed3e98 00000001
cfd04070
Call Trace:
 [<c01c6ae4>] down_write_interruptible+0x44/0x70
 [<c025a617>] scsi_error_handler+0x87/0x100
 [<c025a590>] scsi_error_handler+0x0/0x100
 [<c0104115>] kernel_thread_helper+0x5/0x10
Code: 08 89 44 24 10 89 34 24 e8 29 e7 eb ff 89 34 24 e8 d1 e7 eb ff 85
c0 74 1a 8b 2d 20 b6 36 c0 85 ed 74 10 31 db 89 1d 2
 <6>note: scsi_eh_0[730] exited with preempt_count 2

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U6

[Adam Heath]

On Tue, 19 Oct 2004, Ingo Molnar wrote:

>
> i have released the -U6 Real-Time Preemption patch:
>
>   http://redhat.com/~mingo/realtime-preempt/realtime-preempt-2.6.9-rc4-mm1-U6
>
> this is a fixes-only release.
>
> found and fixed the 'big bug' that was probably the one causing
> stability problems for a number of people. There was a small window for
> a task double-free race to occur, causing all sorts of crashes later on.
> This bug could trigger on UP and SMP systems alike, on SMP being a bit
> more frequent.

I am still having the same bug(repeatable by running liquidwar) as I reported
with -U5(see my earlier email).

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U6

[Ingo Molnar]

* Adam Heath <doogie@debian.org> wrote:

> I am still having the same bug(repeatable by running liquidwar) as I
> reported with -U5(see my earlier email).

ok, this seems to be some questionable code in OSS. It really has no
business up()-ing the inode semaphore - nobody down()-ed it before! This
could be either a bad workaround for a bug/hang someone saw, or an old
VFS assumption that doesnt hold anymore. In any case, could you try the
patch below, does it fix liquidwar?

	Ingo

--- linux/sound/core/oss/pcm_oss.c.orig
+++ linux/sound/core/oss/pcm_oss.c
@@ -2120,9 +2120,7 @@ static ssize_t snd_pcm_oss_write(struct 
 	substream = pcm_oss_file->streams[SNDRV_PCM_STREAM_PLAYBACK];
 	if (substream == NULL)
 		return -ENXIO;
-	up(&file->f_dentry->d_inode->i_sem);
 	result = snd_pcm_oss_write1(substream, buf, count);
-	down(&file->f_dentry->d_inode->i_sem);
 #ifdef OSS_DEBUG
 	printk("pcm_oss: write %li bytes (wrote %li bytes)\n", (long)count, (long)result);
 #endif

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U6

[Adam Heath]

On Tue, 19 Oct 2004, Ingo Molnar wrote:

>
> * Adam Heath <doogie@debian.org> wrote:
>
> > I am still having the same bug(repeatable by running liquidwar) as I
> > reported with -U5(see my earlier email).
>
> ok, this seems to be some questionable code in OSS. It really has no
> business up()-ing the inode semaphore - nobody down()-ed it before! This
> could be either a bad workaround for a bug/hang someone saw, or an old
> VFS assumption that doesnt hold anymore. In any case, could you try the
> patch below, does it fix liquidwar?

Yup, the below fixes it.  However, this problem *only* started occuring in
-U5.  I've been running liquidwar on all versions(it's my current
game-to-play-when-I-feel-stupid program).

>
> 	Ingo
>
> --- linux/sound/core/oss/pcm_oss.c.orig
> +++ linux/sound/core/oss/pcm_oss.c
> @@ -2120,9 +2120,7 @@ static ssize_t snd_pcm_oss_write(struct
>  	substream = pcm_oss_file->streams[SNDRV_PCM_STREAM_PLAYBACK];
>  	if (substream == NULL)
>  		return -ENXIO;
> -	up(&file->f_dentry->d_inode->i_sem);
>  	result = snd_pcm_oss_write1(substream, buf, count);
> -	down(&file->f_dentry->d_inode->i_sem);
>  #ifdef OSS_DEBUG
>  	printk("pcm_oss: write %li bytes (wrote %li bytes)\n", (long)count, (long)result);
>  #endif
> -
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/
>

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U6

[Lee Revell]

On Tue, 2004-10-19 at 14:52, Adam Heath wrote:
> On Tue, 19 Oct 2004, Ingo Molnar wrote:
> 
> >
> > * Adam Heath <doogie@debian.org> wrote:
> >
> > > I am still having the same bug(repeatable by running liquidwar) as I
> > > reported with -U5(see my earlier email).
> >
> > ok, this seems to be some questionable code in OSS. It really has no
> > business up()-ing the inode semaphore - nobody down()-ed it before! This
> > could be either a bad workaround for a bug/hang someone saw, or an old
> > VFS assumption that doesnt hold anymore. In any case, could you try the
> > patch below, does it fix liquidwar?
> 
> Yup, the below fixes it.  However, this problem *only* started occuring in
> -U5.  I've been running liquidwar on all versions(it's my current
> game-to-play-when-I-feel-stupid program).

The real fix is to use ALSA. :-)

Lee

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U6

[Adam Heath]

On Tue, 19 Oct 2004, Ingo Molnar wrote:

> i have released the -U6 Real-Time Preemption patch:

(xterm/1219/CPU#0): new 39188 us maximum-latency critical section.
 => started at timestamp 71898423: <call_console_drivers+0x76/0x140>
 =>   ended at timestamp 71937611: <finish_task_switch+0x43/0xb0>
 [<c01327f0>] sub_preempt_count+0x60/0x90
 [<c01324de>] check_preempt_timing+0x15e/0x270
 [<c0117ca3>] finish_task_switch+0x43/0xb0
 [<c01327f0>] sub_preempt_count+0x60/0x90
 [<c0117ca3>] finish_task_switch+0x43/0xb0
 [<c0117ca3>] finish_task_switch+0x43/0xb0
 [<c02a5717>] __sched_text_start+0x2d7/0x5d0
 [<c02a684f>] down_write+0x12f/0x1e0
 [<c0113104>] mcount+0x14/0x18
 [<c02a684f>] down_write+0x12f/0x1e0
 [<c014dd45>] remove_vm_struct+0x45/0xb0
 [<c014fde2>] exit_mmap+0xf2/0x120
 [<c0119b96>] mmput+0x46/0xf0
 [<c0166d8f>] exec_mmap+0xaf/0x140
 [<c0166ffd>] flush_old_exec+0xfd/0x7f0
 [<c015b917>] vfs_read+0xe7/0x140
 [<c0113104>] mcount+0x14/0x18
 [<c0185d7f>] load_elf_binary+0x30f/0xbd0
 [<c01327f0>] sub_preempt_count+0x60/0x90
 [<c01db739>] up_read+0xf9/0x140
 [<c01323d8>] check_preempt_timing+0x58/0x270
 [<c01327f0>] sub_preempt_count+0x60/0x90
 [<c0131c6d>] __mcount+0x1d/0x20
 [<c0185a70>] load_elf_binary+0x0/0xbd0
 [<c0167aba>] search_binary_handler+0x19a/0x2e0
 [<c0167dac>] do_execve+0x1ac/0x260
 [<c0104b07>] sys_execve+0x47/0xd0
 [<c0106013>] syscall_call+0x7/0xb
preempt count: 00000002
. 2-level deep critical section nesting:
.. entry 1: __sched_text_start+0x3b/0x5d0 / (down_write+0x12f/0x1e0)
.. entry 2: print_traces+0x1d/0x80 / (dump_stack+0x23/0x30)

 =>   dump-end timestamp 71938197

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U6

[Michal Schmidt]

Ingo Molnar wrote:
> i have released the -U6 Real-Time Preemption patch:
>  
>   http://redhat.com/~mingo/realtime-preempt/realtime-preempt-2.6.9-rc4-mm1-U6
> 
>   [...]
> - deadlock bug: fix networking deadlock reported by Matthew L Foster.
>   Restructured the way the RT-RCU locking of ptype_lock is done - it's
>   cleaner and more obvious now (besides being correct). This could also
>   fix the deadlock reported by Michal Schmidt.

Yes, this fixed the deadlock for me.
I'm now going to try -U7.

Michal

Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U6

[Adam Heath]

On Tue, 19 Oct 2004, Ingo Molnar wrote:

>
> i have released the -U6 Real-Time Preemption patch:
>
>   http://redhat.com/~mingo/realtime-preempt/realtime-preempt-2.6.9-rc4-mm1-U6

Got these high-latency values during the night on U6(haven't booted U8 yet).

IRQ 5/431/CPU#0): 612 us critical section violates 100 us threshold.
 => started at timestamp 4167601478: <call_console_drivers+0x76/0x140>
 =>   ended at timestamp 4167602090: <finish_task_switch+0x43/0xb0>
 [<c01327f0>] sub_preempt_count+0x60/0x90
 [<c01324de>] check_preempt_timing+0x15e/0x270
 [<c0117ca3>] finish_task_switch+0x43/0xb0
 [<c01327f0>] sub_preempt_count+0x60/0x90
 [<c0117ca3>] finish_task_switch+0x43/0xb0
 [<c0117ca3>] finish_task_switch+0x43/0xb0
 [<c02a5717>] __sched_text_start+0x2d7/0x5d0
 [<c0113104>] mcount+0x14/0x18
 [<c013bdfa>] do_irqd+0x5a/0x80
 [<c01309ea>] kthread+0xaa/0xb0
 [<c013bda0>] do_irqd+0x0/0x80
 [<c0130940>] kthread+0x0/0xb0
 [<c0104099>] kernel_thread_helper+0x5/0xc
preempt count: 00000002
. 2-level deep critical section nesting:
.. entry 1: __sched_text_start+0x3b/0x5d0 / (do_irqd+0x5a/0x80)
.. entry 2: print_traces+0x1d/0x80 / (dump_stack+0x23/0x30)

 =>   dump-end timestamp 4167602447

(IRQ 5/431/CPU#0): 34875 us critical section violates 100 us threshold.
 => started at timestamp 4167608224: <call_console_drivers+0x76/0x140>
 =>   ended at timestamp 4167643099: <finish_task_switch+0x43/0xb0>
 [<c01327f0>] sub_preempt_count+0x60/0x90
 [<c01324de>] check_preempt_timing+0x15e/0x270
 [<c0117ca3>] finish_task_switch+0x43/0xb0
 [<c01327f0>] sub_preempt_count+0x60/0x90
 [<c0117ca3>] finish_task_switch+0x43/0xb0
 [<c0117ca3>] finish_task_switch+0x43/0xb0
 [<c02a5717>] __sched_text_start+0x2d7/0x5d0
 [<c0113104>] mcount+0x14/0x18
 [<c013bdfa>] do_irqd+0x5a/0x80
 [<c01309ea>] kthread+0xaa/0xb0
 [<c013bda0>] do_irqd+0x0/0x80
 [<c0130940>] kthread+0x0/0xb0
 [<c0104099>] kernel_thread_helper+0x5/0xc
preempt count: 00000002
. 2-level deep critical section nesting:
.. entry 1: __sched_text_start+0x3b/0x5d0 / (do_irqd+0x5a/0x80)
.. entry 2: print_traces+0x1d/0x80 / (dump_stack+0x23/0x30)

 =>   dump-end timestamp 4167643459

(IRQ 1/18/CPU#0): 30560 us critical section violates 100 us threshold.
 => started at timestamp 4167647182: <call_console_drivers+0x76/0x140>
 =>   ended at timestamp 4167677742: <finish_task_switch+0x43/0xb0>
 [<c01327f0>] sub_preempt_count+0x60/0x90
 [<c01324de>] check_preempt_timing+0x15e/0x270
 [<c0117ca3>] finish_task_switch+0x43/0xb0
 [<c01327f0>] sub_preempt_count+0x60/0x90
 [<c0117ca3>] finish_task_switch+0x43/0xb0
 [<c0117ca3>] finish_task_switch+0x43/0xb0
 [<c02a5717>] __sched_text_start+0x2d7/0x5d0
 [<c0113104>] mcount+0x14/0x18
 [<c013bdfa>] do_irqd+0x5a/0x80
 [<c01309ea>] kthread+0xaa/0xb0
 [<c013bda0>] do_irqd+0x0/0x80
 [<c0130940>] kthread+0x0/0xb0
 [<c0104099>] kernel_thread_helper+0x5/0xc
preempt count: 00000002
. 2-level deep critical section nesting:
.. entry 1: __sched_text_start+0x3b/0x5d0 / (do_irqd+0x5a/0x80)
.. entry 2: print_traces+0x1d/0x80 / (dump_stack+0x23/0x30)

 =>   dump-end timestamp 4167678099

(bash/10595/CPU#0): 33546 us critical section violates 100 us threshold.
 => started at timestamp 4167681248: <call_console_drivers+0x76/0x140>
 =>   ended at timestamp 4167714794: <finish_task_switch+0x43/0xb0>
 [<c01327f0>] sub_preempt_count+0x60/0x90
 [<c01324de>] check_preempt_timing+0x15e/0x270
 [<c0117ca3>] finish_task_switch+0x43/0xb0
 [<c01327f0>] sub_preempt_count+0x60/0x90
 [<c0117ca3>] finish_task_switch+0x43/0xb0
 [<c0117ca3>] finish_task_switch+0x43/0xb0
 [<c02a5717>] __sched_text_start+0x2d7/0x5d0
 [<c02a684f>] down_write+0x12f/0x1e0
 [<c0113104>] mcount+0x14/0x18
 [<c02a684f>] down_write+0x12f/0x1e0
 [<c01182bb>] lock_kernel+0x2b/0x40
 [<c016f122>] sys_ioctl+0x52/0x230
 [<c0106013>] syscall_call+0x7/0xb
preempt count: 00000002
. 2-level deep critical section nesting:
.. entry 1: __sched_text_start+0x3b/0x5d0 / (down_write+0x12f/0x1e0)
.. entry 2: print_traces+0x1d/0x80 / (dump_stack+0x23/0x30)

 =>   dump-end timestamp 4167715168