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

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

[Ingo Molnar]

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

> (right now it's not possible to do wakeup-timing without
> LATENCY_TRACE, i'll fix that.)

i've fixed this in -RT-V0.5.2. Also, the trace_enabled=4 method is
deprecated now and the new mechanism is to use:

    /proc/sys/kernel/preempt_wakeup_timing

this flag is default-enabled. So starting at -RT-V0.5.2 to activate
wakeup timing it's enough to enable PREEMPT_TIMING and reset the max
after bootup:

    echo 0 > /proc/sys/kernel/preempt_max_latency

this will switch back to critical-section timing/tracing:

    echo 0 > /proc/sys/kernel/preempt_wakeup_timing

	Ingo

Re: [patch] Real-Time Preemption, -RT-2.6.9-mm1-V0.5.2

[DaMouse]

On Thu, 28 Oct 2004 15:57:06 +0200, Ingo Molnar <mingo@elte.hu> wrote:
> 
> * Ingo Molnar <mingo@elte.hu> wrote:
> 
> > (right now it's not possible to do wakeup-timing without
> > LATENCY_TRACE, i'll fix that.)
> 
> i've fixed this in -RT-V0.5.2. Also, the trace_enabled=4 method is
> deprecated now and the new mechanism is to use:
> 
>     /proc/sys/kernel/preempt_wakeup_timing
> 
> this flag is default-enabled. So starting at -RT-V0.5.2 to activate
> wakeup timing it's enough to enable PREEMPT_TIMING and reset the max
> after bootup:
> 
>     echo 0 > /proc/sys/kernel/preempt_max_latency
> 
> this will switch back to critical-section timing/tracing:
> 
>     echo 0 > /proc/sys/kernel/preempt_wakeup_timing

What kind of benchmarking tools about from the inkernel timing/tracing
do you use for testing REALTIME_PREEMPT?

> 
>         Ingo

-DaMouse

-- 
I know I broke SOMETHING but its their fault for not fixing it before me

Re: [patch] Real-Time Preemption, -RT-2.6.9-mm1-V0.5.2

[Ingo Molnar]

* DaMouse <damouse@gmail.com> wrote:

> >     echo 0 > /proc/sys/kernel/preempt_max_latency
> > 
> > this will switch back to critical-section timing/tracing:
> > 
> >     echo 0 > /proc/sys/kernel/preempt_wakeup_timing
> 
> What kind of benchmarking tools about from the inkernel timing/tracing
> do you use for testing REALTIME_PREEMPT?

amlat's 'realfeel' with the patch i posted yesterday.

	Ingo

Re: [patch] Real-Time Preemption, -RT-2.6.9-mm1-V0.5.2

[Mark_H_Johnson]

I built with V0.5.1 and on a relatively idle system saw a number
of traces with > 4000 entries, with a wide range of latencies.
For example:

lt001.v1k1/lt.00: latency: 98910 us, entries: 4000 (24040)   |   [VP:0 KP:1
SP:1 HP:1 #CPUS:2]
lt001.v1k1/lt.01: latency: 4021 us, entries: 4000 (11139)   |   [VP:0 KP:1
SP:1 HP:1 #CPUS:2]
lt001.v1k1/lt.02: latency: 6597 us, entries: 4000 (13361)   |   [VP:0 KP:1
SP:1 HP:1 #CPUS:2]
lt001.v1k1/lt.03: latency: 8873 us, entries: 4000 (16109)   |   [VP:0 KP:1
SP:1 HP:1 #CPUS:2]
lt001.v1k1/lt.04: latency: 9092 us, entries: 4000 (17525)   |   [VP:0 KP:1
SP:1 HP:1 #CPUS:2]
lt001.v1k1/lt.05: latency: 10079 us, entries: 4000 (22351)   |   [VP:0 KP:1
SP:1 HP:1 #CPUS:2]
lt001.v1k1/lt.06: latency: 1976 us, entries: 2148 (2148)   |   [VP:0 KP:1
SP:1 HP:1 #CPUS:2]
lt001.v1k1/lt.07: latency: 50675 us, entries: 4000 (12102)   |   [VP:0 KP:1
SP:1 HP:1 #CPUS:2]
lt001.v1k1/lt.08: latency: 2822 us, entries: 4000 (7318)   |   [VP:0 KP:1
SP:1 HP:1 #CPUS:2]
lt001.v1k1/lt.09: latency: 5817 us, entries: 4000 (9574)   |   [VP:0 KP:1
SP:1 HP:1 #CPUS:2]
lt001.v1k1/lt.10: latency: 10811 us, entries: 4000 (26175)   |   [VP:0 KP:1
SP:1 HP:1 #CPUS:2]
lt001.v1k1/lt.11: latency: 2511 us, entries: 4000 (6204)   |   [VP:0 KP:1
SP:1 HP:1 #CPUS:2]
lt001.v1k1/lt.12: latency: 9194 us, entries: 4000 (28039)   |   [VP:0 KP:1
SP:1 HP:1 #CPUS:2]
lt001.v1k1/lt.13: latency: 12068 us, entries: 4000 (37143)   |   [VP:0 KP:1
SP:1 HP:1 #CPUS:2]
lt001.v1k1/lt.14: latency: 36768 us, entries: 4000 (101483)   |   [VP:0
KP:1 SP:1 HP:1 #CPUS:2]
lt001.v1k1/lt.15: latency: 96154 us, entries: 4000 (21364)   |   [VP:0 KP:1
SP:1 HP:1 #CPUS:2]
lt001.v1k1/lt.16: latency: 2759 us, entries: 4000 (7153)   |   [VP:0 KP:1
SP:1 HP:1 #CPUS:2]
lt001.v1k1/lt.17: latency: 6653 us, entries: 4000 (15161)   |   [VP:0 KP:1
SP:1 HP:1 #CPUS:2]
lt001.v1k1/lt.18: latency: 7322 us, entries: 4000 (12684)   |   [VP:0 KP:1
SP:1 HP:1 #CPUS:2]
lt001.v1k1/lt.19: latency: 7440 us, entries: 4000 (15368)   |   [VP:0 KP:1
SP:1 HP:1 #CPUS:2]
lt001.v1k1/lt.20: latency: 13838 us, entries: 4000 (30923)   |   [VP:0 KP:1
SP:1 HP:1 #CPUS:2]

It did not take long to collect this information. These may be false
positives, here is the start of one example (note 00000000 for preempt
count in some of the lines).

preemption latency trace v1.0.7 on 2.6.9-mm1-RT-V0.5.1
-------------------------------------------------------
 latency: 1976 us, entries: 2148 (2148)   |   [VP:0 KP:1 SP:1 HP:1 #CPUS:2]
    -----------------
    | task: get_ltrace.sh/3673, uid:0 nice:0 policy:1 rt_prio:50
    -----------------
 => started at: try_to_wake_up+0x1cc/0x330 <c011c1cc>
 => ended at:   finish_task_switch+0x41/0xc0 <c011c7e1>
=======>
80000000 0.000ms (+0.000ms): _spin_unlock (try_to_wake_up)
80000000 0.000ms (+0.000ms): (105) ((140))
80000000 0.000ms (+0.000ms): (6) ((0))
80000000 0.000ms (+0.000ms): resched_task (try_to_wake_up)
80000000 0.001ms (+0.000ms): _spin_unlock_irqrestore (try_to_wake_up)
80000000 0.001ms (+0.000ms): preempt_schedule (try_to_wake_up)
00000000 0.001ms (+0.000ms): preempt_schedule (cpu_idle)
80000000 0.002ms (+0.000ms): __sched_text_start (preempt_schedule)
80000000 0.002ms (+0.000ms): sched_clock (__sched_text_start)
80000000 0.002ms (+0.000ms): _spin_lock_irq (__sched_text_start)
80000000 0.003ms (+0.000ms): _spin_lock_irqsave (__sched_text_start)
80000000 0.003ms (+0.000ms): dequeue_task (__sched_text_start)
80000000 0.004ms (+0.000ms): recalc_task_prio (__sched_text_start)
80000000 0.004ms (+0.000ms): effective_prio (recalc_task_prio)
80000000 0.004ms (+0.000ms): enqueue_task (__sched_text_start)
80000000 0.005ms (+0.000ms): __switch_to (__sched_text_start)
80000000 0.005ms (+0.000ms): (0) ((6))
80000000 0.005ms (+0.000ms): (140) ((105))
80000000 0.006ms (+0.000ms): finish_task_switch (__sched_text_start)
80000000 0.006ms (+0.000ms): trace_stop_sched_switched (finish_task_switch)
80000000 0.006ms (+0.000ms): (6) ((105))
80000000 0.006ms (+0.000ms): _spin_lock (trace_stop_sched_switched)
80000000 0.007ms (+0.000ms): _spin_unlock (finish_task_switch)
80000000 0.007ms (+0.000ms): _spin_unlock_irq (finish_task_switch)
00000000 0.008ms (+0.000ms): _do_softirq (ksoftirqd)
80000000 0.008ms (+0.000ms): ___do_softirq (_do_softirq)
00000000 0.008ms (+0.000ms): run_timer_softirq (___do_softirq)
... ends like this ...
80000000 1.856ms (+0.000ms): rwsem_owner_del (__up_write)
80000000 1.857ms (+0.000ms): _spin_unlock (__up_write)
80000000 1.857ms (+0.000ms): _spin_unlock (__up_write)
00000000 1.858ms (+0.000ms): up (real_lookup)
00000000 1.858ms (+0.000ms): _up_write (up)
00000000 1.858ms (+0.000ms): __up_write (_up_write)
80000000 1.859ms (+0.000ms): _spin_lock (__up_write)
80000000 1.859ms (+0.000ms): _spin_lock (__up_write)
80000000 1.860ms (+0.000ms): rwsem_owner_del (__up_write)
80000000 1.861ms (+0.000ms): _spin_unlock (__up_write)
80000000 1.861ms (+0.000ms): _spin_unlock (__up_write)
00000000 1.862ms (+0.001ms): follow_mount (link_path_walk)
00000000 1.863ms (+33179.004ms): dput (link_path_walk)

I haven't run the stress tests yet but will send the system log
and these traces in a separate message so you can see what I'm seeing.

  --Mark

Re: [patch] Real-Time Preemption, -RT-2.6.9-mm1-V0.5.2

[Ingo Molnar]

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

> It did not take long to collect this information. These may be false
> positives, here is the start of one example (note 00000000 for preempt
> count in some of the lines).
> 
> preemption latency trace v1.0.7 on 2.6.9-mm1-RT-V0.5.1
> -------------------------------------------------------
>  latency: 1976 us, entries: 2148 (2148)   |   [VP:0 KP:1 SP:1 HP:1 #CPUS:2]
>     -----------------
>     | task: get_ltrace.sh/3673, uid:0 nice:0 policy:1 rt_prio:50
>     -----------------
>  => started at: try_to_wake_up+0x1cc/0x330 <c011c1cc>
>  => ended at:   finish_task_switch+0x41/0xc0 <c011c7e1>
> =======>
> 80000000 0.000ms (+0.000ms): _spin_unlock (try_to_wake_up)
> 80000000 0.000ms (+0.000ms): (105) ((140))
> 80000000 0.000ms (+0.000ms): (6) ((0))

here pid 6 got woken up and it's about to preempt pid 0 [the idle task].

> 80000000 0.000ms (+0.000ms): resched_task (try_to_wake_up)
> 80000000 0.001ms (+0.000ms): _spin_unlock_irqrestore (try_to_wake_up)
> 80000000 0.001ms (+0.000ms): preempt_schedule (try_to_wake_up)
> 00000000 0.001ms (+0.000ms): preempt_schedule (cpu_idle)
> 80000000 0.002ms (+0.000ms): __sched_text_start (preempt_schedule)
> 80000000 0.002ms (+0.000ms): sched_clock (__sched_text_start)
> 80000000 0.002ms (+0.000ms): _spin_lock_irq (__sched_text_start)
> 80000000 0.003ms (+0.000ms): _spin_lock_irqsave (__sched_text_start)
> 80000000 0.003ms (+0.000ms): dequeue_task (__sched_text_start)
> 80000000 0.004ms (+0.000ms): recalc_task_prio (__sched_text_start)
> 80000000 0.004ms (+0.000ms): effective_prio (recalc_task_prio)
> 80000000 0.004ms (+0.000ms): enqueue_task (__sched_text_start)
> 80000000 0.005ms (+0.000ms): __switch_to (__sched_text_start)
> 80000000 0.005ms (+0.000ms): (0) ((6))
> 80000000 0.005ms (+0.000ms): (140) ((105))
> 80000000 0.006ms (+0.000ms): finish_task_switch (__sched_text_start)
> 80000000 0.006ms (+0.000ms): trace_stop_sched_switched (finish_task_switch)
> 80000000 0.006ms (+0.000ms): (6) ((105))
> 80000000 0.006ms (+0.000ms): _spin_lock (trace_stop_sched_switched)

the trace should have stopped here! We just successfully switched from
pid 0 to pid 6 and called trace_stop_sched_switched() - the tracer
should really have noticed it. But the trace goes on for eternity:

> 00000000 1.862ms (+0.001ms): follow_mount (link_path_walk)
> 00000000 1.863ms (+33179.004ms): dput (link_path_walk)

which is just wrong.

i think the tracer is more broken on SMP systems than i thought. If we
start tracing on one CPU and it goes over to another CPU [which might
have happened in the above case - another task on another CPU took
precedence over pid 6 on this CPU] ... but the tracing timestamp is
per-CPU.

what needs to happen is some sort of 'handover' whenever the
highest-prio task is migrated from one CPU to another. Until this is
fixed i'd not suggest to use the wakeup latency tracer on SMP :-|

	Ingo

Re: [patch] Real-Time Preemption, -RT-2.6.9-mm1-V0.5.2

[Mark_H_Johnson]

Today's run with -V0.5.11.

In short, the tracing appears to be broken on SMP systems and
may have caused the crash in the first attempt. In the second
attempt (no tracing), the system ran but the something is not
quite right in the scheduler (or in marking tasks "ready to run"
since it appears that my cpu burner (a nice'd task) is getting
run when the system should run the X server & other applications.

Will be sending system logs and serial console output separately.
  --Mark

-----

First attempt.

[1] Build / boot to X server OK. Only unusual message is the one
with the atomic counter underflow (in system log, not on console output).

[2] Set IRQ priorities & ran my "get_ltrace" script which looks for
changes in the latency trace output & dumps them out. Had one trace
and then soon after, the machine locked up. No console output for
several seconds, then finally a stream of errors.

The serial console messages appear to be incomplete at the beginning
(not sure why). Looks something like this

Starting system message bus: [  OK  ]^M
(kdeinit/3196/CPU#0): new 1204 us maximum-latency wakeup.
(X/2832/CPU#1): new 68008 us maximum-latency wakeup.
(get_ltrace.sh/3482/CPU#1): new 3814 us maximum-latency wakeup.
(get_ltrace.sh/3530/CPU#1): new 3963 us maximum-latency wakeup.
(artsd/2965/CPU#1): new 78620 us maximum-latency wakeup.

  (124)
 [<c012454b>] profile_task_exit+0x1b/0x50 (24)
 [<c012691f>] do_exit+0x1f/0x5c0 (40)

[note how the prologue data is missing & the output starts in
the middle of a line]

The critical section nesting was "unique" and looks like

| preempt count: 00010005 ]
| 5-level deep critical section nesting:
----------------------------------------
.. [<c03257cf>] .... _spin_lock+0x1f/0x70
.....[<c01e217a>] ..   ( <= __up_write+0x26a/0x2a0)
.. [<c03257cf>] .... _spin_lock+0x1f/0x70
.....[<c01e1f65>] ..   ( <= __up_write+0x55/0x2a0)
.. [<c0325817>] .... _spin_lock+0x67/0x70
.....[<c011b54d>] ..   ( <= task_rq_lock+0x3d/0x70)
.. [<c03257cf>] .... _spin_lock+0x1f/0x70
.....[<c0115f47>] ..   ( <= nmi_watchdog_tick+0x127/0x140)
.. [<c013d5bd>] .... print_traces+0x1d/0x60
.....[<c0105bec>] ..   ( <= show_regs+0x14c/0x174)

The script then exits with preempt count of 3 and an atomic counter
underflow BUG message. This is followed right after with

BUG: Unable to handle kernel NULL pointer dereference at virtual address
00000
020

and the appropriate dump messages. The cycle of script failure and
kernel BUG repeats a few cycles and then stops.

Let's reboot and not look at the latency traces.

Second attempt.

Boots OK and started the stress test.

[1] Got through about 80% of the X11perf stress test before the system
"live locked" again. The audio continued to come out but the display
stopped updating. I found that Alt-Sysrq-L and Alt-Sysrq-T seemed to
work so I did both while waiting for the audio test to stop on its own.

[2] Running the second test, a similar symptom occurred where the
display froze during the top test, but it finished as well.

[3] Running the third test (network output), I got a number of error
messages on the X display (but not on the serial console) indicating
segmentation violation for the command
  sudo -u me rcp file remote-system
I was able to manipulate the display at this point.

[4] It then ran the fourth test (network input), and the symptom of
locking up the display repeated (still no serial console messages).

[5] Disk write test had the same display lockup (audio OK).
Did Alt-Sysrq-L and -T to see what the status of tasks was.
Noticed that the cpu_burn program (nice'd) was still the active
task even though I had higher priority jobs (e.g., the X server)
that should have been ready to run.

[6] Disk copy & read tests, same symptoms, though it unfroze sometime
later in the test (and then froze again...). Something is not
quite consistent in how the system runs under these stress tests.

Application level charts are "interesting". All of them show very
little overhead to the CPU task with a few glitches. The audio
loop is consistently getting done "early". The yellow line showing
the nominal audio cycle time is well above the white line showing
the actual duration. To recap, in latencytest, we have a loop like
this...

  capture T1
  CPU burn 80% of nominal audio duration
  capture T2
  write next audio segment
  capture T3

where T2-T1 is the CPU time and T3-T1 is the audio time. Some of the
delays were extremely long, but I assume that was due to the occasional
use of Alt-Sysrq keys. Some may also be due to that scheduling problem
I described above as well.

Re: [patch] Real-Time Preemption, -RT-2.6.9-mm1-V0.5.2

[Ingo Molnar]

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

> The critical section nesting was "unique" and looks like
> 
> | preempt count: 00010005 ]
> | 5-level deep critical section nesting:
> ----------------------------------------
> .. [<c03257cf>] .... _spin_lock+0x1f/0x70
> .....[<c01e217a>] ..   ( <= __up_write+0x26a/0x2a0)
> .. [<c03257cf>] .... _spin_lock+0x1f/0x70
> .....[<c01e1f65>] ..   ( <= __up_write+0x55/0x2a0)
> .. [<c0325817>] .... _spin_lock+0x67/0x70
> .....[<c011b54d>] ..   ( <= task_rq_lock+0x3d/0x70)
> .. [<c03257cf>] .... _spin_lock+0x1f/0x70
> .....[<c0115f47>] ..   ( <= nmi_watchdog_tick+0x127/0x140)
> .. [<c013d5bd>] .... print_traces+0x1d/0x60
> .....[<c0105bec>] ..   ( <= show_regs+0x14c/0x174)

this might as well have been the NMI watchdog interacting. Could you
turn off the NMI watchdog to see whether that stabilizes things?

> The script then exits with preempt count of 3 and an atomic counter
> underflow BUG message. This is followed right after with
> 
> BUG: Unable to handle kernel NULL pointer dereference at virtual address
> 00000
> 020

these are then probably just followup-errors. Will take a look at the
logs.

	Ingo

Re: [patch] Real-Time Preemption, -RT-2.6.9-mm1-V0.5.2

[John Gilbert]

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

Hello all, Ingo,
Here's a few bugs on boot with V0.5.2, and a question: what's needed to 
get back to the verbose latency messages of previous preempt patches 
(see the terse second log)?
Thanks.
John Gilbert
jgilbert@biomail.ucsd.edu

[-- Attachment #2: v05log01 --]
[-- Type: text/plain, Size: 21284 bytes --]

Linux version 2.6.9-mm1-RT-V0.5.11-pleiades (root@pleiades) (gcc version 3.4.2) #1 Fri Oct 29 10:19:50 PDT 2004
BIOS-provided physical RAM map:
 BIOS-e820: 0000000000000000 - 000000000009fc00 (usable)
 BIOS-e820: 000000000009fc00 - 00000000000a0000 (reserved)
 BIOS-e820: 0000000000100000 - 000000001ffea800 (usable)
 BIOS-e820: 000000001ffea800 - 0000000020000000 (reserved)
 BIOS-e820: 00000000feea0000 - 00000000fef00000 (reserved)
 BIOS-e820: 00000000ffb80000 - 0000000100000000 (reserved)
511MB LOWMEM available.
On node 0 totalpages: 131050
  DMA zone: 4096 pages, LIFO batch:1
  Normal zone: 126954 pages, LIFO batch:16
  HighMem zone: 0 pages, LIFO batch:1
DMI 2.3 present.
ACPI: RSDP (v000 DELL                                  ) @ 0x000fde50
ACPI: RSDT (v001 DELL    CPi R   0x27d30303 ASL  0x00000061) @ 0x000fde64
ACPI: FADT (v001 DELL    CPi R   0x27d30303 ASL  0x00000061) @ 0x000fde90
ACPI: BOOT (v001 DELL    CPi R   0x27d30303 ASL  0x00000061) @ 0x000fdf04
ACPI: DSDT (v001 INT430 SYSFexxx 0x00001001 MSFT 0x0100000e) @ 0x00000000
Built 1 zonelists
Initializing CPU#0
Kernel command line: BOOT_IMAGE=2.6.9-HRT ro root=301 hdb=ide-cd
ide_setup: hdb=ide-cd
PID hash table entries: 2048 (order: 11, 32768 bytes)
Detected 1196.303 MHz processor.
Using tsc 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: 514344k/524200k available (2931k kernel code, 9468k reserved, 984k data, 168k init, 0k highmem)
Checking if this processor honours the WP bit even in supervisor mode... Ok.
Calibrating delay loop... 2367.48 BogoMIPS (lpj=1183744)
Mount-cache hash table entries: 512 (order: 0, 4096 bytes)
CPU: After generic identify, caps: 0383f9ff 00000000 00000000 00000000
CPU: After vendor identify, caps:  0383f9ff 00000000 00000000 00000000
CPU: L1 I cache: 16K, L1 D cache: 16K
CPU: L2 cache: 512K
CPU: After all inits, caps:        0383f9ff 00000000 00000000 00000040
Intel machine check architecture supported.
Intel machine check reporting enabled on CPU#0.
CPU: Intel(R) Pentium(R) III Mobile CPU      1200MHz stepping 01
Enabling fast FPU save and restore... done.
Enabling unmasked SIMD FPU exception support... done.
Checking 'hlt' instruction... OK.
ACPI: IRQ9 SCI: Edge set to Level Trigger.
spawn_desched_task(00000000)
desched cpu_callback 3/00000000
ksoftirqd started up.
softirq RT prio: 24.
desched cpu_callback 2/00000000
desched thread 0 started up.
NET: Registered protocol family 16
PCI: PCI BIOS revision 2.10 entry at 0xfc06e, last bus=2
PCI: Using configuration type 1
mtrr: v2.0 (20020519)
ACPI: Subsystem revision 20040816
ACPI: Interpreter enabled
ACPI: Using PIC for interrupt routing
ACPI: PCI Root Bridge [PCI0] (00:00)
PCI: Probing PCI hardware (bus 00)
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)
ACPI: PCI Interrupt Link [LNKC] (IRQs 9 10 11) *0, disabled.
ACPI: PCI Interrupt Link [LNKD] (IRQs 5 7 *10 11)
ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.AGP_._PRT]
ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.PCIE._PRT]
ACPI: Power Resource [PADA] (on)
Linux Plug and Play Support v0.97 (c) Adam Belay
Dell laptop SMM driver v1.13 14/05/2002 Massimo Dal Zotto (dz@debian.org)
Linux Kernel Card Services
  options:  [pci] [cardbus] [pm]
usbcore: registered new driver usbfs
usbcore: registered new driver hub
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: the driver 'system' has been registered
Simple Boot Flag at 0x79 set to 0x1
Machine check exception polling timer started.
IA-32 Microcode Update Driver: v1.14 <tigran@veritas.com>
audit: initializing netlink socket (disabled)
audit(1099046576.850:0): initialized
Installing knfsd (copyright (C) 1996 okir@monad.swb.de).
radeonfb_pci_register BEGIN
ACPI: PCI Interrupt Link [LNKA] enabled at IRQ 11
PCI: setting IRQ 11 as level-triggered
ACPI: PCI interrupt 0000:01:00.0[A] -> GSI 11 (level, low) -> IRQ 11
radeonfb: probed DDR SGRAM 65536k videoram
radeonfb: mapped 16384k videoram
radeonfb: Retreived PLL infos from BIOS
radeonfb: Reference=27.00 MHz (RefDiv=12) Memory=260.00 Mhz, System=183.00 MHz
radeonfb: PLL min 12000 max 40000
i2c_adapter i2c-0: registered as adapter #0
i2c_adapter i2c-1: registered as adapter #1
i2c_adapter i2c-2: registered as adapter #2
i2c_adapter i2c-3: registered as adapter #3
1 chips in connector info
 - chip 1 has 1 connectors
  * connector 0 of type 2 (CRT) : 2300
Starting monitor auto detection...
radeonfb: I2C (port 1) ... not found
i2c_adapter i2c-1: master_xfer: with 2 msgs.
i2c_adapter i2c-1: master_xfer: with 2 msgs.
i2c_adapter i2c-1: master_xfer: with 2 msgs.
radeonfb: I2C (port 2) ... not found
i2c_adapter i2c-2: master_xfer: with 2 msgs.
i2c_adapter i2c-2: master_xfer: with 2 msgs.
i2c_adapter i2c-2: master_xfer: with 2 msgs.
radeonfb: I2C (port 3) ... not found
i2c_adapter i2c-3: master_xfer: with 2 msgs.
i2c_adapter i2c-3: master_xfer: with 2 msgs.
i2c_adapter i2c-3: master_xfer: with 2 msgs.
radeonfb: I2C (port 4) ... not found
i2c_adapter i2c-1: master_xfer: with 2 msgs.
i2c_adapter i2c-1: master_xfer: with 2 msgs.
i2c_adapter i2c-1: master_xfer: with 2 msgs.
radeonfb: I2C (port 2) ... not found
i2c_adapter i2c-3: master_xfer: with 2 msgs.
i2c_adapter i2c-3: master_xfer: with 2 msgs.
i2c_adapter i2c-3: master_xfer: with 2 msgs.
radeonfb: I2C (port 4) ... not found
Non-DDC laptop panel detected
i2c_adapter i2c-2: master_xfer: with 2 msgs.
i2c_adapter i2c-2: master_xfer: with 2 msgs.
i2c_adapter i2c-2: master_xfer: with 2 msgs.
radeonfb: I2C (port 3) ... not found
i2c_adapter i2c-3: master_xfer: with 2 msgs.
i2c_adapter i2c-3: master_xfer: with 2 msgs.
i2c_adapter i2c-3: master_xfer: with 2 msgs.
radeonfb: I2C (port 4) ... not found
radeonfb: Monitor 1 type LCD found
radeonfb: Monitor 2 type no found
radeonfb: panel ID string: LCD LTM15C166
          
radeonfb: detected LVDS panel size from BIOS: 1600x1200
BIOS provided panel power delay: 1000
radeondb: BIOS provided dividers will be used
ref_divider = 2
post_divider = 1
fbk_divider = 18
Scanning BIOS table ...
 320 x 350
 320 x 400
 320 x 400
 320 x 480
 400 x 600
 512 x 384
 640 x 350
 640 x 400
 640 x 475
 640 x 480
 720 x 480
 720 x 576
 800 x 600
 848 x 480
 1024 x 768
 1280 x 1024
 1600 x 1200
Found panel in BIOS table:
  hblank: 560
  hOver_plus: 56
  hSync_width: 192
  vblank: 50
  vOver_plus: 1
  vSync_width: 3
  clock: 16200
Setting up default mode based on panel info
radeonfb: Power Management enabled for Mobility chipsets
hStart = 1656, hEnd = 1848, hTotal = 2160
vStart = 1201, vEnd = 1204, vTotal = 1250
h_total_disp = 0xc7010d	   hsync_strt_wid = 0x180672
v_total_disp = 0x4af04e1	   vsync_strt_wid = 0x304b0
pixclock = 6172
freq = 16202
Console: switching to colour frame buffer device 200x150
radeonfb: ATI Radeon LW  DDR SGRAM 64 MB
radeonfb_pci_register END
ACPI: AC Adapter [AC] (on-line)
ACPI: Battery Slot [BAT0] (battery absent)
ACPI: Battery Slot [BAT1] (battery present)
ACPI: Lid Switch [LID]
ACPI: Power Button (CM) [PBTN]
ACPI: Sleep Button (CM) [SBTN]
ACPI: Processor [CPU0] (supports C1 C2)
ACPI: Thermal Zone [THM] (70 C)
lp: driver loaded but no devices found
Real Time Clock Driver v1.12
Non-volatile memory driver v1.2
Linux agpgart interface v0.100 (c) Dave Jones
agpgart: Detected an Intel i815 Chipset.
agpgart: Maximum main memory to use for agp memory: 439M
agpgart: AGP aperture is 64M @ 0xe8000000
ACPI: PCI interrupt 0000:01:00.0[A] -> GSI 11 (level, low) -> IRQ 11
[drm] Initialized radeon 1.11.0 20020828 on minor 0: ATI Technologies Inc Radeon Mobility M7 LW [Radeon Mobility 7500]
Hangcheck: starting hangcheck timer 0.5.0 (tick is 180 seconds, margin is 60 seconds).
ACPI: PS/2 Keyboard Controller [KBC] at I/O 0x60, 0x64, irq 1
ACPI: PS/2 Mouse Controller [PS2M] at irq 12
serio: i8042 AUX port at 0x60,0x64 irq 12
serio: i8042 KBD port at 0x60,0x64 irq 1
Serial: 8250/16550 driver $Revision: 1.90 $ 8 ports, IRQ sharing disabled
ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
ttyS1 at I/O 0x2f8 (irq = 3) is a 16550A
pnp: the driver 'serial' has been registered
pnp: the driver 'parport_pc' has been registered
parport0: PC-style at 0x378 (0x778) [PCSPP(,...)]
parport0: irq 7 detected
lp0: using parport0 (polling).
io scheduler noop registered
io scheduler anticipatory registered
io scheduler deadline registered
io scheduler cfq registered
ACPI: Floppy Controller [FDC0] at I/O 0x3f2-0x3f5, 0x3f7 irq 6 dma channel 2
elevator: using anticipatory as default io scheduler
Floppy drive(s): fd0 is 1.44M
IRQ#6 thread RT prio: 49.
FDC 0 is a post-1991 82077
loop: loaded (max 8 devices)
ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 10
PCI: setting IRQ 10 as level-triggered
ACPI: PCI interrupt 0000:02:06.0[A] -> GSI 10 (level, low) -> IRQ 10
3c59x: Donald Becker and others. www.scyld.com/network/vortex.html
0000:02:06.0: 3Com PCI 3c556 Laptop Tornado at 0xe800. Vers LK1.1.19
Uniform Multi-Platform E-IDE driver Revision: 7.00alpha2
ide: Assuming 33MHz system bus speed for PIO modes; override with idebus=xx
ICH2M: IDE controller at PCI slot 0000:00:1f.1
ICH2M: chipset revision 3
ICH2M: not 100% native mode: will probe irqs later
    ide0: BM-DMA at 0xbfa0-0xbfa7, BIOS settings: hda:DMA, hdb:DMA
    ide1: BM-DMA at 0xbfa8-0xbfaf, BIOS settings: hdc:pio, hdd:pio
Probing IDE interface ide0...
hda: TOSHIBA MK4018GAP, ATA DISK drive
hdb: HL-DT-STCD-RW/DVD-ROM GCC-4240N, ATAPI CD/DVD-ROM drive
ide0 at 0x1f0-0x1f7,0x3f6 on irq 14
Probing IDE interface ide1...
Probing IDE interface ide1...
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 !
hda: max request size: 128KiB
IRQ#14 thread RT prio: 48.
hda: 78140160 sectors (40007 MB), CHS=65535/16/63, UDMA(100)
hda: cache flushes supported
 hda: hda1 hda2 hda3
hdb: ATAPI 24X DVD-ROM CD-R/RW drive, 2048kB Cache, UDMA(33)
Uniform CD-ROM driver Revision: 3.20
PCI: Enabling device 0000:02:0f.0 (0000 -> 0002)
ACPI: PCI interrupt 0000:02:0f.0[A] -> GSI 10 (level, low) -> IRQ 10
Yenta: CardBus bridge found at 0000:02:0f.0 [1028:00e6]
Yenta: Using CSCINT to route CSC interrupts to PCI
Yenta: Routing CardBus interrupts to PCI
Yenta TI: socket 0000:02:0f.0, mfunc 0x05033002, devctl 0x64
IRQ#10 thread RT prio: 47.
Yenta: ISA IRQ mask 0x0098, PCI irq 10
Socket status: 30000010
PCI: Enabling device 0000:02:0f.1 (0000 -> 0002)
ACPI: PCI interrupt 0000:02:0f.1[A] -> GSI 10 (level, low) -> IRQ 10
Yenta: CardBus bridge found at 0000:02:0f.1 [1028:00e6]
Yenta: Using CSCINT to route CSC interrupts to PCI
Yenta: Routing CardBus interrupts to PCI
Yenta TI: socket 0000:02:0f.1, mfunc 0x05033002, devctl 0x64
Yenta: ISA IRQ mask 0x0098, PCI irq 10
Socket status: 30000010
USB Universal Host Controller Interface driver v2.2
ACPI: PCI interrupt 0000:00:1f.2[D] -> GSI 10 (level, low) -> IRQ 10
uhci_hcd 0000:00:1f.2: Intel Corp. 82801BA/BAM USB (Hub #1)
PCI: Setting latency timer of device 0000:00:1f.2 to 64
uhci_hcd 0000:00:1f.2: irq 10, io base 0xdce0
uhci_hcd 0000:00:1f.2: new USB bus registered, assigned bus number 1
hub 1-0:1.0: USB hub found
hub 1-0:1.0: 2 ports detected
usbcore: registered new driver usbhid
drivers/usb/input/hid-core.c: v2.0:USB HID core driver
mice: PS/2 mouse device common for all mice
IRQ#12 thread RT prio: 46.
IRQ#1 thread RT prio: 45.
input: AT Translated Set 2 keyboard on isa0060/serio0
usb 1-1: new full speed USB device using address 2
hub 1-1:1.0: USB hub found
hub 1-1:1.0: 4 ports detected
usb 1-1.1: new low speed USB device using address 3
input: USB HID v1.10 Mouse [Logitech USB-PS/2 Optical Mouse] on usb-0000:00:1f.2-1.1
usb 1-1.2: new low speed USB device using address 4
input: USB HID v1.10 Mouse [Logitech USB-PS/2 Optical Mouse] on usb-0000:00:1f.2-1.2
Synaptics Touchpad, model: 1
 Firmware: 5.7
 180 degree mounted touchpad
 Sensor: 1
 new absolute packet format
 Touchpad has extended capability bits
 -> multifinger detection
 -> palm detection
 -> pass-through port
input: SynPS/2 Synaptics TouchPad on isa0060/serio1
serio: Synaptics pass-through port at isa0060/serio1/input0
input: PS/2 Generic Mouse on synaptics-pt/serio0
Please email the following PERFCTR INIT lines to mikpe@csd.uu.se
To remove this message, rebuild the driver with CONFIG_PERFCTR_INIT_TESTS=n
PERFCTR INIT: vendor 0, family 6, model 11, stepping 1, clock 1196303 kHz
PERFCTR INIT: NITER == 64
PERFCTR INIT: loop overhead is 386 cycles
PERFCTR INIT: rdtsc cost is 34.6 cycles (2604 total)
PERFCTR INIT: rdpmc cost is 36.0 cycles (2694 total)
PERFCTR INIT: rdmsr (counter) cost is 90.5 cycles (6179 total)
PERFCTR INIT: rdmsr (evntsel) cost is 71.9 cycles (4991 total)
PERFCTR INIT: wrmsr (counter) cost is 100.7 cycles (6837 total)
PERFCTR INIT: wrmsr (evntsel) cost is 96.2 cycles (6548 total)
PERFCTR INIT: read cr4 cost is 1.8 cycles (507 total)
PERFCTR INIT: write cr4 cost is 42.3 cycles (3095 total)
PERFCTR INIT: sync_core cost is 147.4 cycles (9825 total)
perfctr: driver 2.7.5, cpu type Intel P6 at 1196303 kHz
NET: Registered protocol family 2
IP: routing cache hash table of 512 buckets, 28Kbytes
TCP: Hash tables configured (established 4096 bind 5041)
ip_conntrack version 2.1 (4095 buckets, 32760 max) - 348 bytes per conntrack
ip_tables: (C) 2000-2002 Netfilter core team
ipt_recent v0.3.1: Stephen Frost <sfrost@snowman.net>.  http://snowman.net/projects/ipt_recent/
arp_tables: (C) 2002 David S. Miller
NET: Registered protocol family 1
NET: Registered protocol family 17
ACPI: (supports S0 S1 S3 S4 S4bios S5)
ACPI wakeup devices: 
 LID PBTN PCI0 UAR1 USB0 PCIE MPCI 
ReiserFS: hda1: found reiserfs format "3.6" with standard journal
ReiserFS: hda1: using ordered data mode
ReiserFS: hda1: journal params: device hda1, size 8192, journal first block 18, max trans len 1024, max batch 900, max commit age 30, max trans age 30
ReiserFS: hda1: checking transaction log (hda1)
ReiserFS: hda1: Using r5 hash to sort names
VFS: Mounted root (reiserfs filesystem) readonly.
Freeing unused kernel memory: 168k freed
IRQ#8 thread RT prio: 44.
BUG: sleeping function called from invalid context IRQ 8(788) at kernel/mutex.c:30
in_atomic():0 [00000000], irqs_disabled():1
 [<c0105963>] dump_stack+0x23/0x30 (20)
 [<c01187fc>] __might_sleep+0xbc/0xd0 (36)
 [<c0132f69>] __mutex_lock+0x39/0x60 (24)
 [<c0132fad>] _mutex_lock+0x1d/0x20 (16)
 [<c014a77d>] kmem_cache_alloc+0x3d/0x100 (32)
 [<c0247ea6>] soft_cursor+0x66/0x260 (80)
 [<c0242654>] bit_cursor+0x2e4/0x4c0 (160)
 [<c023de76>] fbcon_cursor+0x146/0x210 (56)
 [<c029faae>] hide_cursor+0x5e/0x70 (20)
 [<c02a35b6>] vt_console_print+0x2f6/0x340 (56)
 [<c011c079>] __call_console_drivers+0x59/0x70 (32)
 [<c011c1ed>] call_console_drivers+0xbd/0x180 (36)
 [<c011c61d>] release_console_sem+0x4d/0x110 (36)
 [<c011c4e0>] vprintk+0x130/0x180 (36)
 [<c011c3ad>] printk+0x1d/0x20 (16)
 [<c013ec91>] do_irqd+0x61/0xd0 (32)
 [<c01323f6>] kthread+0xa6/0xf0 (48)
 [<c0103315>] kernel_thread_helper+0x5/0x10 (1051148308)
---------------------------
| preempt count: 00000001 ]
| 1-level deep critical section nesting:
----------------------------------------
.. [<c0134bfb>] .... print_traces+0x1b/0x50
.....[<c0105963>] ..   ( <= dump_stack+0x23/0x30)

ReiserFS: hda3: found reiserfs format "3.6" with standard journal
BUG: sleeping function called from invalid context mount(1108) at kernel/mutex.c:30
in_atomic():0 [00000000], irqs_disabled():1
 [<c0105963>] dump_stack+0x23/0x30 (20)
 [<c01187fc>] __might_sleep+0xbc/0xd0 (36)
 [<c0132f69>] __mutex_lock+0x39/0x60 (24)
 [<c0132fad>] _mutex_lock+0x1d/0x20 (16)
 [<c014a77d>] kmem_cache_alloc+0x3d/0x100 (32)
 [<c0247ea6>] soft_cursor+0x66/0x260 (80)
 [<c0242654>] bit_cursor+0x2e4/0x4c0 (160)
 [<c023de76>] fbcon_cursor+0x146/0x210 (56)
 [<c029faae>] hide_cursor+0x5e/0x70 (20)
 [<c02a35b6>] vt_console_print+0x2f6/0x340 (56)
 [<c011c079>] __call_console_drivers+0x59/0x70 (32)
 [<c011c1ed>] call_console_drivers+0xbd/0x180 (36)
 [<c011c61d>] release_console_sem+0x4d/0x110 (36)
 [<c011c4e0>] vprintk+0x130/0x180 (36)
 [<c011c3ad>] printk+0x1d/0x20 (16)
 [<c01b8a64>] reiserfs_info+0x44/0x70 (24)
 [<c01b6ae3>] read_super_block+0x233/0x280 (80)
 [<c01b746d>] reiserfs_fill_super+0x27d/0x870 (180)
 [<c016a0dc>] get_sb_bdev+0xfc/0x160 (72)
 [<c01b7ae4>] get_super_block+0x34/0x40 (28)
 [<c016a35f>] do_kern_mount+0x5f/0x100 (40)
 [<c01823f2>] do_new_mount+0x92/0xe0 (48)
 [<c0182b53>] do_mount+0x183/0x1a0 (116)
 [<c0182fdc>] sys_mount+0x9c/0x100 (48)
 [<c010537f>] syscall_call+0x7/0xb (-8124)
---------------------------
| preempt count: 00000001 ]
| 1-level deep critical section nesting:
----------------------------------------
.. [<c0134bfb>] .... print_traces+0x1b/0x50
.....[<c0105963>] ..   ( <= dump_stack+0x23/0x30)

ReiserFS: hda3: using ordered data mode
BUG: sleeping function called from invalid context mount(1108) at kernel/mutex.c:30
in_atomic():0 [00000000], irqs_disabled():1
 [<c0105963>] dump_stack+0x23/0x30 (20)
 [<c01187fc>] __might_sleep+0xbc/0xd0 (36)
 [<c0132f69>] __mutex_lock+0x39/0x60 (24)
 [<c0132fad>] _mutex_lock+0x1d/0x20 (16)
 [<c014a77d>] kmem_cache_alloc+0x3d/0x100 (32)
 [<c0247ea6>] soft_cursor+0x66/0x260 (80)
 [<c0242654>] bit_cursor+0x2e4/0x4c0 (160)
 [<c023de76>] fbcon_cursor+0x146/0x210 (56)
 [<c029faae>] hide_cursor+0x5e/0x70 (20)
 [<c02a35b6>] vt_console_print+0x2f6/0x340 (56)
 [<c011c079>] __call_console_drivers+0x59/0x70 (32)
 [<c011c1ed>] call_console_drivers+0xbd/0x180 (36)
 [<c011c61d>] release_console_sem+0x4d/0x110 (36)
 [<c011c4e0>] vprintk+0x130/0x180 (36)
 [<c011c3ad>] printk+0x1d/0x20 (16)
 [<c01b8a64>] reiserfs_info+0x44/0x70 (24)
 [<c01b7508>] reiserfs_fill_super+0x318/0x870 (180)
 [<c016a0dc>] get_sb_bdev+0xfc/0x160 (72)
 [<c01b7ae4>] get_super_block+0x34/0x40 (28)
 [<c016a35f>] do_kern_mount+0x5f/0x100 (40)
 [<c01823f2>] do_new_mount+0x92/0xe0 (48)
 [<c0182b53>] do_mount+0x183/0x1a0 (116)
 [<c0182fdc>] sys_mount+0x9c/0x100 (48)
 [<c010537f>] syscall_call+0x7/0xb (-8124)
---------------------------
| preempt count: 00000001 ]
| 1-level deep critical section nesting:
----------------------------------------
.. [<c0134bfb>] .... print_traces+0x1b/0x50
.....[<c0105963>] ..   ( <= dump_stack+0x23/0x30)

ReiserFS: hda3: journal params: device hda3, size 8192, journal first block 18, max trans len 1024, max batch 900, max commit age 30, max trans age 30
BUG: sleeping function called from invalid context mount(1108) at kernel/mutex.c:30
in_atomic():0 [00000000], irqs_disabled():1
 [<c0105963>] dump_stack+0x23/0x30 (20)
 [<c01187fc>] __might_sleep+0xbc/0xd0 (36)
 [<c0132f69>] __mutex_lock+0x39/0x60 (24)
 [<c0132fad>] _mutex_lock+0x1d/0x20 (16)
 [<c014a77d>] kmem_cache_alloc+0x3d/0x100 (32)
 [<c0247ea6>] soft_cursor+0x66/0x260 (80)
 [<c0242654>] bit_cursor+0x2e4/0x4c0 (160)
 [<c023de76>] fbcon_cursor+0x146/0x210 (56)
 [<c029faae>] hide_cursor+0x5e/0x70 (20)
 [<c02a35b6>] vt_console_print+0x2f6/0x340 (56)
 [<c011c079>] __call_console_drivers+0x59/0x70 (32)
 [<c011c1ed>] call_console_drivers+0xbd/0x180 (36)
 [<c011c61d>] release_console_sem+0x4d/0x110 (36)
 [<c011c4e0>] vprintk+0x130/0x180 (36)
 [<c011c3ad>] printk+0x1d/0x20 (16)
 [<c01b8a64>] reiserfs_info+0x44/0x70 (24)
 [<c01c8c9e>] journal_init+0x34e/0x6f0 (104)
 [<c01b7538>] reiserfs_fill_super+0x348/0x870 (180)
 [<c016a0dc>] get_sb_bdev+0xfc/0x160 (72)
 [<c01b7ae4>] get_super_block+0x34/0x40 (28)
 [<c016a35f>] do_kern_mount+0x5f/0x100 (40)
 [<c01823f2>] do_new_mount+0x92/0xe0 (48)
 [<c0182b53>] do_mount+0x183/0x1a0 (116)
 [<c0182fdc>] sys_mount+0x9c/0x100 (48)
 [<c010537f>] syscall_call+0x7/0xb (-8124)
---------------------------
| preempt count: 00000001 ]
| 1-level deep critical section nesting:
----------------------------------------
.. [<c0134bfb>] .... print_traces+0x1b/0x50
.....[<c0105963>] ..   ( <= dump_stack+0x23/0x30)

ReiserFS: hda3: checking transaction log (hda3)
ReiserFS: hda3: Using r5 hash to sort names
cs: IO port probe 0x0c00-0x0cff: clean.
cs: IO port probe 0x0820-0x08ff: excluding 0x8c0-0x8cf
cs: IO port probe 0x0800-0x080f: clean.
cs: IO port probe 0x03e0-0x04ff: excluding 0x4d0-0x4d7
cs: IO port probe 0x0100-0x03af: excluding 0x170-0x177 0x280-0x287 0x370-0x37f
cs: IO port probe 0x0a00-0x0aff: clean.
cs: memory probe 0xa0000000-0xa0ffffff: clean.
ttyS2 at I/O 0x3e8 (irq = 3) is a 16550A
ACPI: PCI interrupt 0000:02:06.0[A] -> GSI 10 (level, low) -> IRQ 10
ACPI: PCI Interrupt Link [LNKB] enabled at IRQ 5
PCI: setting IRQ 5 as level-triggered
ACPI: PCI interrupt 0000:02:03.0[A] -> GSI 5 (level, low) -> IRQ 5
maestro3: enabled hack for 'Dell Inspiron 8100'
i8xx TCO timer: initialized (0x0860). heartbeat=30 sec (nowayout=0)

[-- Attachment #3: v05log02 --]
[-- Type: text/plain, Size: 515 bytes --]

(ksoftirqd/0/2/CPU#0): new 4 us maximum-latency wakeup.
(primert/2474/CPU#0): new 13 us maximum-latency wakeup.
(startx/2484/CPU#0): new 14 us maximum-latency wakeup.
(hotplug/2501/CPU#0): new 34 us maximum-latency wakeup.
agpgart: Found an AGP 2.0 compliant device at 0000:00:00.0.
agpgart: Putting AGP V2 device at 0000:00:00.0 into 4x mode
agpgart: Putting AGP V2 device at 0000:01:00.0 into 4x mode
IRQ#11 thread RT prio: 43.
IRQ#5 thread RT prio: 42.
(ksoftirqd/0/2/CPU#0): new 1003 us maximum-latency wakeup.

Re: [patch] Real-Time Preemption, -RT-2.6.9-mm1-V0.5.2

[Ingo Molnar]

* John Gilbert <jgilbert@biomail.ucsd.edu> wrote:

> Hello all, Ingo,
> Here's a few bugs on boot with V0.5.2, and a question: what's needed to 
> get back to the verbose latency messages of previous preempt patches 
> (see the terse second log)?

> (ksoftirqd/0/2/CPU#0): new 1003 us maximum-latency wakeup.

if you have LATENCY_TRACING enabled then the wakeup trace of the last 
wakeup will be in /proc/latency_trace.

the reason that the messages are less verbose is that by default we are
not measuring critical sections anymore, but 'wakeup latency'. Wakeup 
latency is measured from the point of wakeup to the point where the task 
runs - so it makes no sense to dump the stack (which is why the previous 
tracing output was more verbose) - a stackdump would always show the 
scheduler codepath where we stop measuring.

you can switch back to critical section timing though, via:

	echo 0 > /proc/sys/kernel/preempt_wakeup_timing

this will also turn the stackdumps back on. (those make sense in this
case because we measure 'start of critical section' to 'end of critical
section', in which case both a stackdump and the symbolic printout of
the start and end address is useful - because it's variable.

	Ingo

Re: [patch] Real-Time Preemption, -RT-2.6.9-mm1-V0.5.2

[Lee Revell]

On Fri, 2004-10-29 at 10:52 -0700, John Gilbert wrote:
> Hello all, Ingo,
> Here's a few bugs on boot with V0.5.2, and a question: what's needed to 
> get back to the verbose latency messages of previous preempt patches 
> (see the terse second log)?

There is a setting in /proc/sys/kernel for this, don't remember what
it's called but should be pretty clear.

Lee