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

[Mark_H_Johnson]

This time, initial test results on -18PK (PREEMPT_DESKTOP, no IRQ
threading).

Again, results running cpu_delay and collecting user triggered traces.

[1] Similar symptoms where I do not get traces that span CPU's plus
the missing trace symptom.

# ./cpu_delay 0.000100
Delay limit set to 0.00010000 seconds
calibrating loop ....
time diff= 0.503365 or 397326229 loops/sec.
Trace activated with 0.000100 second delay.
Trace triggered with 0.000321 second delay. [not recorded]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000136 second delay. [not recorded]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000139 second delay. [00]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000130 second delay. [not recorded]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000240 second delay. [01]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000104 second delay. [02]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000130 second delay. [03]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000109 second delay. [04]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000109 second delay. [not recorded]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000155 second delay. [not recorded]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000100 second delay. [05]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000105 second delay. [not recorded]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000128 second delay. [06]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000123 second delay. [07]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000100 second delay. [08]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000113 second delay. [not recorded]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000136 second delay. [09]

# chrt -f 1 ./get_ltrace.sh 50
Current Maximum is 4965280, limit will be 50.
Resetting max latency from 4965280 to 50.
No new latency samples at Fri Dec 10 13:42:31 CST 2004.
No new latency samples at Fri Dec 10 13:42:41 CST 2004.
No new latency samples at Fri Dec 10 13:42:51 CST 2004.
No new latency samples at Fri Dec 10 13:43:01 CST 2004.
New trace 0 w/ 139 usec latency.
Resetting max latency from 139 to 50.
No new latency samples at Fri Dec 10 13:43:23 CST 2004.
New trace 1 w/ 241 usec latency.
Resetting max latency from 241 to 50.
No new latency samples at Fri Dec 10 13:43:44 CST 2004.
New trace 2 w/ 103 usec latency.
Resetting max latency from 103 to 50.
New trace 3 w/ 130 usec latency.
Resetting max latency from 130 to 50.
No new latency samples at Fri Dec 10 13:44:17 CST 2004.
No new latency samples at Fri Dec 10 13:44:27 CST 2004.
No new latency samples at Fri Dec 10 13:44:37 CST 2004.
New trace 4 w/ 109 usec latency.
Resetting max latency from 109 to 50.
No new latency samples at Fri Dec 10 13:44:58 CST 2004.
New trace 5 w/ 100 usec latency.
Resetting max latency from 100 to 50.
New trace 6 w/ 128 usec latency.
Resetting max latency from 128 to 50.
New trace 7 w/ 123 usec latency.
Resetting max latency from 123 to 50.
New trace 8 w/ 100 usec latency.
Resetting max latency from 100 to 50.
No new latency samples at Fri Dec 10 13:45:54 CST 2004.
New trace 9 w/ 135 usec latency.
Resetting max latency from 135 to 50.

I don't see a significant difference in failures to record when compared
with -18RT (7 vs. 8).

[2] I get no ksoftirqd activity (as expected).

[3] Long sequences of one CPU only was seen again. Though in looking
at these traces I find several incomplete ones like this:

preemption latency trace v1.1.4 on 2.6.10-rc2-mm3-V0.7.32-18PK
--------------------------------------------------------------------
 latency: 139 us, #55/55, CPU#1 | (M:preempt VP:0, KP:1, SP:0 HP:0 #P:2)
    -----------------
    | task: cpu_delay-3517 (uid:0 nice:0 policy:1 rt_prio:30)
    -----------------
 => started at: <00000000>
 => ended at:   <00000000>

                 _------=> CPU#
                / _-----=> irqs-off
               | / _----=> need-resched
               || / _---=> hardirq/softirq
               ||| / _--=> preempt-depth
               |||| /
               |||||     delay
   cmd     pid ||||| time  |   caller
      \   /    |||||   \   |   /
<unknown-0     0d.h1    0µs : do_nmi (default_idle)
<unknown-0     0d.h1    0µs : do_nmi (_raw_spin_lock_irqsave)
<unknown-3517  1d.H2    0µs : do_nmi (default_idle)
<unknown-0     0d.h1    0µs : do_nmi (<00200246>)
<unknown-3517  1d.H2    0µs+: do_nmi ((514))
<unknown-0     0...1    3µs : default_idle (cpu_idle)
<unknown-3517  1d.H2    3µs : do_IRQ (c013a0cc 0 0)
<unknown-3517  1d.H2    3µs : _raw_spin_lock (__do_IRQ)
<unknown-3517  1d.H3    4µs : ack_edge_ioapic_irq (__do_IRQ)
<unknown-3517  1d.H3    4µs : redirect_hardirq (__do_IRQ)
<unknown-3517  1d.H3    5µs : _raw_spin_unlock (__do_IRQ)
<unknown-3517  1d.H2    5µs : handle_IRQ_event (__do_IRQ)
<unknown-3517  1d.H2    5µs : timer_interrupt (handle_IRQ_event)
<unknown-3517  1d.H2    6µs : _raw_spin_lock (timer_interrupt)
<unknown-3517  1d.H3    6µs : mark_offset_tsc (timer_interrupt)
<unknown-3517  1d.H3    7µs : _raw_spin_lock (mark_offset_tsc)
<unknown-3517  1d.H4    7µs+: _raw_spin_lock_irqsave (mark_offset_tsc)
<unknown-3517  1d.H5   13µs : _raw_spin_unlock_irqrestore (mark_offset_tsc)
<unknown-3517  1d.H4   14µs : _raw_spin_unlock (mark_offset_tsc)
<unknown-3517  1d.H3   14µs+: _raw_spin_lock_irqsave (timer_interrupt)
<unknown-3517  1d.H4   18µs : _raw_spin_unlock_irqrestore (timer_interrupt)
<unknown-3517  1d.H3   18µs : do_timer (timer_interrupt)
<unknown-3517  1d.H3   19µs : _raw_spin_unlock (timer_interrupt)
<unknown-3517  1d.H2   19µs : _raw_spin_lock (__do_IRQ)
<unknown-3517  1d.H3   20µs : note_interrupt (__do_IRQ)
<unknown-3517  1d.H3   20µs : end_edge_ioapic_irq (__do_IRQ)
<unknown-3517  1d.H3   21µs : _raw_spin_unlock (__do_IRQ)
<unknown-3517  1d.H2   21µs : irq_exit (do_IRQ)
<unknown-3517  1d.s2   21µs < (0)
<unknown-3517  1..s1   22µs : mod_timer (rt_check_expire)
<unknown-3517  1..s1   23µs : __mod_timer (rt_check_expire)
<unknown-3517  1..s1   23µs : _raw_spin_lock_irqsave (__mod_timer)
<unknown-3517  1d.s2   24µs : _raw_spin_lock (__mod_timer)
<unknown-3517  1d.s3   24µs : internal_add_timer (__mod_timer)
<unknown-3517  1d.s3   25µs : _raw_spin_unlock (__mod_timer)
<unknown-3517  1d.s2   25µs : _raw_spin_unlock_irqrestore (__mod_timer)
<unknown-3517  1..s1   26µs : cond_resched_all (run_timer_softirq)
<unknown-3517  1..s1   26µs : cond_resched_softirq (run_timer_softirq)
<unknown-3517  1..s1   26µs : _raw_spin_lock_irq (run_timer_softirq)
<unknown-3517  1..s1   27µs : _raw_spin_lock_irqsave (run_timer_softirq)
<unknown-3517  1d.s2   28µs : _raw_spin_unlock_irq (run_timer_softirq)
<unknown-3517  1..s1   29µs : __wake_up (run_timer_softirq)
<unknown-3517  1..s1   29µs : _raw_spin_lock_irqsave (__wake_up)
<unknown-3517  1d.s2   29µs : __wake_up_common (__wake_up)
<unknown-3517  1d.s2   30µs : _raw_spin_unlock_irqrestore
(run_timer_softirq)
<unknown-3517  1..s1   30µs : cond_resched_all (___do_softirq)
<unknown-3517  1..s1   30µs : cond_resched_softirq (___do_softirq)
<unknown-3517  1d...   31µs < (0)
<unknown-3517  1d...   32µs+< (0)
<unknown-3517  1....   35µs > sys_gettimeofday (00000000 00000000 0000007b)
<unknown-3517  1....   35µs : sys_gettimeofday (sysenter_past_esp)
<unknown-3517  1....   35µs : user_trace_stop (sys_gettimeofday)
<unknown-3517  1...1   36µs : user_trace_stop (sys_gettimeofday)
<unknown-3517  1...1   36µs : _raw_spin_lock_irqsave (user_trace_stop)
<unknown-3517  1d..2   37µs : _raw_spin_unlock_irqrestore (user_trace_stop)

I assume that since it does not start with user_trace_start (or something
like that) that the missing portion is the first portion.

[4] Not sure if I can make the same comment on -18PK as I did for -18RT
on changing CPU's [since I understand we do not have the opportunity to
do so unless the IRQ's are threaded].

[5] The trace output cosmetic problems are on PREEMPT_DESKTOP as well.

Traces to come shortly in a separate message.
  --Mark

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