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

From: K.R. Foley
Date: Thu Dec 09 2004 - 18:22:07 EST

Next message: Tigran Aivazian: "[patch-2.6.x] fix for make clean and make mrproper"
Previous message: john cooper: "Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-12"
In reply to: Ingo Molnar: "Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-6"
Next in thread: K.R. Foley: "Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-6"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

Ingo Molnar wrote:

* K.R. Foley <kr@xxxxxxxxxx> wrote:

running realfeel with rtc histogram generates > 100 usec entries in
the histogram but none of these are ever caught by the wakeup tracing.

can you reproduce this with rtc_wakeup:

http://www.affenbande.org/~tapas/wiki/index.php?rtc_wakeup

?

Yes. See attached files. When I ran rtc_wakeup the priorities were
IRQ 8= 97
IRQ 0= 96
Dropping IRQ 8 (down to 86) below rtc_wakeup kept rtc_wakeup from completing any runs.

I think I know why we don't get traces from this. TIF_NEED_RESCHED is
not set for IRQ 8 at the time that it wakes up realfeel so
_need_resched fails and trace_start_sched_wakeup doesn't actually call
__trace_start_sched_wakeup(p)???

here's the code:

+static inline void trace_start_sched_wakeup(task_t *p, runqueue_t *rq)
+{
+ if (TASK_PREEMPTS_CURR(p, rq) && (p != rq->curr) && _need_resched())
+ __trace_start_sched_wakeup(p);
+}

I know. I MUST KEEP MY MOUTH SHUT. I MUST KEEP MY MOUTH SHUT. I just didn't see how it was possible that either of the other two conditions could ever be false in this case and I missed the call to resched_task

indeed this only triggers if the woken up task has a higher priority
than the waker... hm. Could you try to reverse the priorities of realfeel and IRQ8, does that produce traces?

I did this and latencies in the histogram dropped drastically. The highest latency in the histogram is 33 usecs and thus never gets high enough to trigger the tracing???

IRQ 8 = 97
IRQ 0 = 96
realfeel = 98

Ingo

preemption latency trace v1.1.4 on 2.6.10-rc2-mm3-V0.7.32-12
--------------------------------------------------------------------
latency: 46 us, #83/83 | (M:rt VP:0, KP:1, SP:1 HP:1 #P:2)
-----------------
| task: su-5646 (uid:500 nice:0 policy:0 rt_prio:0)
-----------------

_------=> CPU#
/ _-----=> irqs-off
| / _----=> hardirq
|| / _---=> softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
bash-5650 0-h.2 0µs : __trace_start_sched_wakeup (try_to_wake_up)
bash-5650 0-h.2 0µs : _raw_spin_unlock (try_to_wake_up)
bash-5650 0-h.1 0µs : preempt_schedule (try_to_wake_up)
bash-5650 0 1µs : __wake_up_common <su-5646> (74 75):
bash-5650 0-h.1 1µs : try_to_wake_up (__wake_up_common)
bash-5650 0-h.1 1µs : _raw_spin_unlock (try_to_wake_up)
bash-5650 0-h.. 2µs : preempt_schedule (try_to_wake_up)
bash-5650 0.h.. 2µs : _spin_unlock_irqrestore (__wake_up_sync)
bash-5650 0.h.. 2µs : up_mutex (__wake_up_sync)
bash-5650 0.h.. 2µs : __up_mutex (up_mutex)
bash-5650 0-h.. 3µs : _raw_spin_lock (__up_mutex)
bash-5650 0-h.1 3µs : _raw_spin_lock (__up_mutex)
bash-5650 0-h.2 3µs : _raw_spin_lock (__up_mutex)
bash-5650 0-h.3 3µs : mutex_getprio (__up_mutex)
bash-5650 0 4µs : __up_mutex <bash-5650> (75 75):
bash-5650 0-h.3 4µs : _raw_spin_unlock (__up_mutex)
bash-5650 0-h.2 4µs : preempt_schedule (__up_mutex)
bash-5650 0-h.2 4µs : _raw_spin_unlock (__up_mutex)
bash-5650 0-h.1 5µs : preempt_schedule (__up_mutex)
bash-5650 0-h.1 5µs : _raw_spin_unlock (__up_mutex)
bash-5650 0-h.. 5µs : preempt_schedule (__up_mutex)
bash-5650 0.h.. 5µs : next_thread (__wake_up_parent)
bash-5650 0.h.. 6µs : _spin_is_locked (next_thread)
bash-5650 0.h.. 6µs : rt_mutex_is_locked (next_thread)
bash-5650 0.h.. 6µs : _spin_unlock_irqrestore (do_notify_parent)
bash-5650 0.h.. 6µs : up_mutex (do_notify_parent)
bash-5650 0.h.. 7µs : __up_mutex (up_mutex)
bash-5650 0-h.. 7µs : _raw_spin_lock (__up_mutex)
bash-5650 0-h.1 7µs : _raw_spin_lock (__up_mutex)
bash-5650 0-h.2 7µs : _raw_spin_lock (__up_mutex)
bash-5650 0-h.3 8µs : mutex_getprio (__up_mutex)
bash-5650 0 8µs : __up_mutex <bash-5650> (75 75):
bash-5650 0-h.3 8µs : _raw_spin_unlock (__up_mutex)
bash-5650 0-h.2 8µs : preempt_schedule (__up_mutex)
bash-5650 0-h.2 9µs : _raw_spin_unlock (__up_mutex)
bash-5650 0-h.1 9µs : preempt_schedule (__up_mutex)
bash-5650 0-h.1 9µs : _raw_spin_unlock (__up_mutex)
bash-5650 0-h.. 10µs : preempt_schedule (__up_mutex)
bash-5650 0.h.. 10µs : _write_unlock_irq (exit_notify)
bash-5650 0.h.. 10µs : up_write_mutex (exit_notify)
bash-5650 0.h.. 11µs : __up_mutex (up_write_mutex)
bash-5650 0-h.. 11µs : _raw_spin_lock (__up_mutex)
bash-5650 0-h.1 11µs : _raw_spin_lock (__up_mutex)
bash-5650 0-h.2 12µs : _raw_spin_lock (__up_mutex)
bash-5650 0-h.3 12µs : mutex_getprio (__up_mutex)
bash-5650 0 12µs : __up_mutex <bash-5650> (75 75):
bash-5650 0-h.3 12µs : _raw_spin_unlock (__up_mutex)
bash-5650 0-h.2 13µs : preempt_schedule (__up_mutex)
bash-5650 0-h.2 13µs : _raw_spin_unlock (__up_mutex)
bash-5650 0-h.1 13µs : preempt_schedule (__up_mutex)
bash-5650 0-h.1 14µs : _raw_spin_unlock (__up_mutex)
bash-5650 0-h.. 14µs : preempt_schedule (__up_mutex)
bash-5650 0.h.. 14µs : check_no_held_locks (do_exit)
bash-5650 0-h.. 15µs+: _raw_spin_lock (check_no_held_locks)
bash-5650 0-h.1 22µs : _raw_spin_lock (check_no_held_locks)
bash-5650 0-h.2 23µs : _raw_spin_unlock (check_no_held_locks)
bash-5650 0-h.1 23µs : preempt_schedule (check_no_held_locks)
bash-5650 0-h.1 24µs : _raw_spin_unlock (check_no_held_locks)
bash-5650 0-h.. 24µs : preempt_schedule (check_no_held_locks)
bash-5650 0.h.. 24µs : preempt_schedule (do_exit)
bash-5650 0-h.. 25µs : __schedule (preempt_schedule)
bash-5650 0-h.1 25µs : sched_clock (__schedule)
bash-5650 0-h.1 26µs : _raw_spin_lock_irq (__schedule)
bash-5650 0-h.1 26µs : _raw_spin_lock_irqsave (__schedule)
bash-5650 0-h.2 27µs : dequeue_task (__schedule)
bash-5650 0-h.2 27µs : recalc_task_prio (__schedule)
bash-5650 0-h.2 28µs : effective_prio (recalc_task_prio)
bash-5650 0-h.2 28µs : enqueue_task (__schedule)
bash-5650 0-..2 29µs+: trace_array (__schedule)
bash-5650 0 33µs : __schedule <su-5646> (74 78):
bash-5650 0 33µs : __schedule <bash-5650> (75 78):
bash-5650 0-..2 34µs+: trace_array (__schedule)
su-5646 0-..2 41µs : __switch_to (__schedule)
su-5646 0 42µs : schedule <bash-5650> (75 74):
su-5646 0-..2 42µs : finish_task_switch (__schedule)
su-5646 0-..2 43µs : _raw_spin_unlock (finish_task_switch)
su-5646 0-..1 43µs : trace_stop_sched_switched (finish_task_switch)
su-5646 0 44µs : finish_task_switch <su-5646> (74 0):
su-5646 0-..1 44µs : _raw_spin_lock_irqsave (trace_stop_sched_switched)
su-5646 0-..2 45µs : trace_stop_sched_switched (finish_task_switch)

vim:ft=help
`IRQ 8'[677] is being piggy. need_resched=0, cpu=0
Read missed before next interrupt
`IRQ 8'[677] is being piggy. need_resched=0, cpu=0
Read missed before next interrupt
`IRQ 8'[677] is being piggy. need_resched=0, cpu=0
Read missed before next interrupt
`IRQ 8'[677] is being piggy. need_resched=0, cpu=0
Read missed before next interrupt
`IRQ 8'[677] is being piggy. need_resched=0, cpu=0
Read missed before next interrupt
`IRQ 8'[677] is being piggy. need_resched=0, cpu=0
Read missed before next interrupt
`IRQ 8'[677] is being piggy. need_resched=0, cpu=0
Read missed before next interrupt
`IRQ 8'[677] is being piggy. need_resched=0, cpu=1
Read missed before next interrupt
`IRQ 8'[677] is being piggy. need_resched=0, cpu=1
Read missed before next interrupt
`IRQ 8'[677] is being piggy. need_resched=0, cpu=1
Read missed before next interrupt
`IRQ 8'[677] is being piggy. need_resched=0, cpu=1
Read missed before next interrupt
`IRQ 8'[677] is being piggy. need_resched=0, cpu=1
Read missed before next interrupt
`IRQ 8'[677] is being piggy. need_resched=0, cpu=1
Read missed before next interrupt
`IRQ 8'[677] is being piggy. need_resched=0, cpu=1
Read missed before next interrupt
`IRQ 8'[677] is being piggy. need_resched=0, cpu=1
Read missed before next interrupt
`IRQ 8'[677] is being piggy. need_resched=0, cpu=1
Read missed before next interrupt
`IRQ 8'[677] is being piggy. need_resched=0, cpu=1
Read missed before next interrupt
`IRQ 8'[677] is being piggy. need_resched=0, cpu=1
Read missed before next interrupt
`IRQ 8'[677] is being piggy. need_resched=0, cpu=1
Read missed before next interrupt
`IRQ 8'[677] is being piggy. need_resched=0, cpu=0
Read missed before next interrupt
`IRQ 8'[677] is being piggy. need_resched=0, cpu=0
Read missed before next interrupt
`IRQ 8'[677] is being piggy. need_resched=0, cpu=0
Read missed before next interrupt
`IRQ 8'[677] is being piggy. need_resched=0, cpu=0
Read missed before next interrupt
`IRQ 8'[677] is being piggy. need_resched=0, cpu=0
Read missed before next interrupt
`IRQ 8'[677] is being piggy. need_resched=0, cpu=0
Read missed before next interrupt
`IRQ 8'[677] is being piggy. need_resched=0, cpu=1
Read missed before next interrupt
`IRQ 8'[677] is being piggy. need_resched=0, cpu=1
Read missed before next interrupt
bug in rtc_read(): called in state S_IDLE!
`IRQ 8'[677] is being piggy. need_resched=0, cpu=1
Read missed before next interrupt

rtc latency histogram of {rtc_wakeup/5775, 320346 samples}:
10 179572
11 98009
12 11054
13 19555
14 5171
15 928
16 1257
17 610
18 638
19 317
20 255
21 585
22 1108
23 375
24 220
25 138
26 113
27 201
28 92
29 19
30 21
31 4
32 3
33 3
34 1
36 2
40 2
41 3
42 2
44 1
45 1
46 1
48 14
49 16
50 9
51 5
52 4
53 1
54 2
56 1
58 1
60 2
62 1
65 1
67 1
147 1
157 1
158 5
159 3
160 6
161 1
162 2
165 1
167 2
168 1
169 1
170 1
172 1
174 1
rtc_wakeup - press ctrl-c to stop - use -h to get help
freq: 8192
max # of irqs: 0 (run until stopped)
jitter threshold: 100000% (122070 usec)
output filename: /dev/null
rt priority: 90(91)
aquiring rt privs
getting cpu speed
929730325.422 Hz (929.730 MHz)
# of cycles for "perfect" period: 113492 (122 usec)
setting up ringbuffer
setting up consumer thread
setting up /dev/rtc
locking memory
turning irq on
beginning measurement
missed 1 irq(s) - not timing last period
new max. jitter: 1.3% (1 usec)
new max. jitter: 2.7% (3 usec)
new max. jitter: 6.4% (7 usec)
new max. jitter: 8.0% (9 usec)
new max. jitter: 9.8% (11 usec)
new max. jitter: 18.8% (22 usec)
new max. jitter: 46.2% (56 usec)
new max. jitter: 68.4% (83 usec)
new max. jitter: 91.0% (111 usec)
new max. jitter: 102.2% (124 usec)
done.
total # of irqs: 320362
missed irqs: 1
threshold violations: 0
max jitter: 102.2% (124 usec)

Next message: Tigran Aivazian: "[patch-2.6.x] fix for make clean and make mrproper"
Previous message: john cooper: "Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-12"
In reply to: Ingo Molnar: "Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-6"
Next in thread: K.R. Foley: "Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-6"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]