RE: Latency traces I cannot interpret (sa1100, 2.6.15-rc7-rt1)

[kus Kusche Klaus]

> From: Ingo Molnar
> there seem to be leaked preempt counts:
> 
>   <idle>-0     0.n.1 8974us : touch_critical_timing (cpu_idle)
> 
> we should never have preemption disabled in cpu_idle(). To 
> debug leaked 
> preemption counts, enable CONFIG_DEBUG_PREEMPT.

Something really fishy is going on here: 
That 9 ms latency seems to be really *idle* time!

* If the box is idle, I get that trace almost immediately, and
almost always with close to 9 ms (system clock is 100 Hz, 
i.e. 10 ms tick period).

* If the box is 100 % loaded, I don't get that trace. I get
different traces from different processes, mostly shorter than
9 ms.

* If I load the box with work at regular intervals 
and idle time in between, I get traces
identical to the 9 ms idle trace, but consistently shorter.
If I throw a flood ping with 1000 pkt/s against my box, the idle
trace shows up with 800 or 900 microseconds, i.e. the idle time
between packets.

Now, is the tracer wrong, or has the idle time a wrong status?

By the way, I had one trace today where the cat /proc/latency_trace
itself showed up:

      \   /    |||||   \   |   /           
     cat-3129  0D...    1us!: preempt_schedule_irq (svc_preempt)
     cat-3129  0.... 5502us+: rt_up (l_start)
     cat-3129  0D..1 5511us+: check_raw_flags (rt_up)
     cat-3129  0...1 5514us+: rt_up (l_start)
     cat-3129  0...1 5518us : sub_preempt_count_ti (rt_up)

What's happening in those 5 ms?

-- 
Klaus Kusche                 (Software Development - Control Systems)
KEBA AG             Gewerbepark Urfahr, A-4041 Linz, Austria (Europe)
Tel: +43 / 732 / 7090-3120                 Fax: +43 / 732 / 7090-6301
E-Mail: kus@xxxxxxxx                                WWW: www.keba.com
-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/