From: "K.R. Foley" <kr@cybsft.com>
To: Ingo Molnar <mingo@elte.hu>
Cc: Mark_H_Johnson@raytheon.com, Amit Shah <amit.shah@codito.com>,
Karsten Wiese <annabellesgarden@yahoo.de>,
Bill Huey <bhuey@lnxw.com>, Adam Heath <doogie@debian.org>,
emann@mrv.com, Gunther Persoons <gunther_persoons@spymac.com>,
linux-kernel@vger.kernel.org,
Florian Schmidt <mista.tapas@gmx.net>,
Fernando Pablo Lopez-Lezcano <nando@ccrma.Stanford.EDU>,
Lee Revell <rlrevell@joe-job.com>,
Rui Nuno Capela <rncbc@rncbc.org>,
Shane Shrybman <shrybman@aei.ca>,
Esben Nielsen <simlo@phys.au.dk>,
Thomas Gleixner <tglx@linutronix.de>,
Michal Schmidt <xschmi00@stud.feec.vutbr.cz>
Subject: Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-6
Date: Thu, 09 Dec 2004 17:16:15 -0600 [thread overview]
Message-ID: <41B8DCBF.6070504@cybsft.com> (raw)
In-Reply-To: <20041209220632.GE14194@elte.hu>
[-- Attachment #1: Type: text/plain, Size: 1621 bytes --]
Ingo Molnar wrote:
> * K.R. Foley <kr@cybsft.com> 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
>
[-- Attachment #2: latency_trace.out1 --]
[-- Type: text/plain, Size: 5638 bytes --]
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
[-- Attachment #3: log.out1 --]
[-- Type: text/plain, Size: 2846 bytes --]
`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
[-- Attachment #4: rtc.out1 --]
[-- Type: text/plain, Size: 940 bytes --]
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 prev parent reply other threads:[~2004-12-09 23:21 UTC|newest]
Thread overview: 72+ messages / expand[flat|nested] mbox.gz Atom feed top
2004-12-09 17:22 [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-6 Mark_H_Johnson
2004-12-09 17:31 ` Ingo Molnar
2004-12-09 20:34 ` K.R. Foley
2004-12-09 22:06 ` Ingo Molnar
2004-12-09 23:16 ` K.R. Foley [this message]
2004-12-10 4:26 ` K.R. Foley
2004-12-10 11:22 ` Ingo Molnar
2004-12-10 15:26 ` K.R. Foley
-- strict thread matches above, loose matches on Subject: below --
2004-12-13 14:10 Mark_H_Johnson
2004-12-09 21:58 Mark_H_Johnson
2004-12-09 22:55 ` Ingo Molnar
2004-12-09 20:49 Mark_H_Johnson
2004-12-09 21:56 ` Ingo Molnar
2004-12-09 20:38 Mark_H_Johnson
2004-12-09 19:54 Mark_H_Johnson
2004-12-09 19:23 Mark_H_Johnson
2004-12-09 20:04 ` Ingo Molnar
2004-12-10 5:01 ` Bill Huey
2004-12-10 5:14 ` Steven Rostedt
2004-12-10 5:58 ` Bill Huey
2004-12-09 18:15 Mark_H_Johnson
2004-12-09 20:11 ` Ingo Molnar
2004-12-09 18:10 Mark_H_Johnson
2004-12-09 19:40 ` Ingo Molnar
2004-12-09 19:58 ` Ingo Molnar
2004-12-10 23:42 ` Steven Rostedt
2004-12-11 16:59 ` john cooper
2004-12-12 4:36 ` Steven Rostedt
2004-12-13 23:45 ` john cooper
2004-12-14 13:01 ` Steven Rostedt
2004-12-14 14:28 ` john cooper
2004-12-14 16:53 ` Steven Rostedt
2004-12-11 17:59 ` Esben Nielsen
2004-12-11 18:59 ` Steven Rostedt
2004-12-11 19:50 ` Esben Nielsen
2004-12-11 22:34 ` Steven Rostedt
2004-12-13 21:55 ` Bill Huey
2004-12-13 22:15 ` Steven Rostedt
2004-12-13 22:20 ` Ingo Molnar
2004-12-13 22:31 ` Ingo Molnar
2004-12-09 16:56 Mark_H_Johnson
2004-12-09 17:28 ` Ingo Molnar
2004-12-09 17:41 ` Ingo Molnar
2004-12-09 18:26 ` Ingo Molnar
2004-12-09 19:04 ` Esben Nielsen
2004-12-09 19:58 ` john cooper
2004-12-09 20:16 ` Lee Revell
2004-12-09 15:16 Mark_H_Johnson
2004-12-09 16:17 ` Florian Schmidt
2004-12-09 17:13 ` Ingo Molnar
2004-12-09 14:46 Mark_H_Johnson
2004-12-09 14:14 Mark_H_Johnson
2004-12-07 21:41 Mark_H_Johnson
2004-11-16 13:09 [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm1-V0.7.27-1 Ingo Molnar
2004-11-16 13:40 ` [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm1-V0.7.27-3 Ingo Molnar
2004-11-17 12:42 ` [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm1-V0.7.28-0 Ingo Molnar
2004-11-18 12:35 ` [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm1-V0.7.28-1 Ingo Molnar
2004-11-18 16:46 ` [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm2-V0.7.29-0 Ingo Molnar
2004-11-22 0:54 ` [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm2-V0.7.30-2 Ingo Molnar
2004-11-23 17:58 ` [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm2-V0.7.30-9 Ingo Molnar
2004-11-24 10:16 ` [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm2-V0.7.30-10 Ingo Molnar
2004-12-03 20:58 ` [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm2-V0.7.32-0 Ingo Molnar
2004-12-07 13:29 ` [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-4 Ingo Molnar
2004-12-07 14:11 ` [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-6 Ingo Molnar
2004-12-08 4:31 ` K.R. Foley
2004-12-08 8:34 ` Ingo Molnar
2004-12-08 16:07 ` K.R. Foley
2004-12-08 16:18 ` Lee Revell
2004-12-08 16:52 ` K.R. Foley
2004-12-08 16:58 ` Lee Revell
2004-12-09 9:02 ` Ingo Molnar
2004-12-09 2:45 ` K.R. Foley
2004-12-09 12:11 ` Ingo Molnar
2004-12-09 14:50 ` K.R. Foley
2004-12-08 17:13 ` Steven Rostedt
2004-12-08 18:14 ` Rui Nuno Capela
2004-12-08 19:03 ` Steven Rostedt
2004-12-08 21:39 ` Rui Nuno Capela
2004-12-08 22:11 ` Steven Rostedt
2004-12-09 9:32 ` Ingo Molnar
2004-12-09 13:36 ` Steven Rostedt
2004-12-09 9:06 ` Ingo Molnar
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=41B8DCBF.6070504@cybsft.com \
--to=kr@cybsft.com \
--cc=Mark_H_Johnson@raytheon.com \
--cc=amit.shah@codito.com \
--cc=annabellesgarden@yahoo.de \
--cc=bhuey@lnxw.com \
--cc=doogie@debian.org \
--cc=emann@mrv.com \
--cc=gunther_persoons@spymac.com \
--cc=linux-kernel@vger.kernel.org \
--cc=mingo@elte.hu \
--cc=mista.tapas@gmx.net \
--cc=nando@ccrma.Stanford.EDU \
--cc=rlrevell@joe-job.com \
--cc=rncbc@rncbc.org \
--cc=shrybman@aei.ca \
--cc=simlo@phys.au.dk \
--cc=tglx@linutronix.de \
--cc=xschmi00@stud.feec.vutbr.cz \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).