From: Thomas Charbonnel <thomas@undata.org>
To: Ingo Molnar <mingo@elte.hu>
Cc: Lee Revell <rlrevell@joe-job.com>,
Free Ekanayaka <free@agnula.org>,
Eric St-Laurent <ericstl34@sympatico.ca>,
linux-kernel <linux-kernel@vger.kernel.org>,
"K.R. Foley" <kr@cybsft.com>,
Felipe Alfaro Solana <lkml@felipe-alfaro.com>,
Daniel Schmitt <pnambic@unu.nu>,
Mark_H_Johnson@raytheon.com,
"P.O. Gaillard" <pierre-olivier.gaillard@fr.thalesgroup.com>,
nando@ccrma.stanford.edu, luke@audioslack.com, free78@tin.it
Subject: Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-R1
Date: Fri, 03 Sep 2004 18:14:20 +0200 [thread overview]
Message-ID: <1094228060.5492.8.camel@localhost> (raw)
In-Reply-To: <20040903114949.GA29493@elte.hu>
Ingo Molnar wrote :
> this is a pretty weird one. First it shows an apparently non-monotonic
> RDTSC: the jump forward and backward in time around profile_hit. I
> suspect the real RDTSC value was lower than the previous one and caused
> an underflow. What is your cpu_khz in /proc/cpuinfo?
>
> the other weird one is the +0.595 usec entry at notifier_call_chain().
> That code is just a couple of instructions, so no real for any overhead
> there.
>
> could you try the attached robust-get-cycles.patch ontop of your current
> tree and see whether it impacts these weirdnesses? The patch makes sure
> that the cycle counter is sane: two subsequent readings of it were
> monotonic and less than 1000 cycles apart.
>
> this patch probably wont remove the +0.595 msec latency though - the
> RDTSC value jumped forward there permanently. Maybe the RDTSC value is
> somehow corrupted by NMIs - could you turn off the NMI watchdog to
> check?
Here are more traces with robust-get-cycles applied. So far no
non-monotonic issue.
preemption latency trace v1.0.5 on 2.6.9-rc1-VP-R1
--------------------------------------------------
latency: 626 us, entries: 25 (25)
-----------------
| task: ksoftirqd/0/2, uid:0 nice:-10 policy:0 rt_prio:0
-----------------
=> started at: preempt_schedule+0x3b/0x60
=> ended at: schedule+0x2e4/0x570
=======>
04000000 0.000ms (+0.000ms): preempt_schedule (need_resched)
04000000 0.000ms (+0.000ms): schedule (preempt_schedule)
04000001 0.000ms (+0.620ms): sched_clock (schedule)
04010001 0.620ms (+0.000ms): do_nmi (sched_clock)
04010001 0.621ms (+0.000ms): profile_tick (nmi_watchdog_tick)
04010001 0.622ms (+0.000ms): profile_hook (profile_tick)
04010002 0.622ms (+0.000ms): notifier_call_chain (profile_hook)
04010001 0.622ms (+0.000ms): preempt_schedule (profile_tick)
04010001 0.622ms (+0.000ms): profile_hit (nmi_watchdog_tick)
04000001 0.623ms (+0.000ms): smp_apic_timer_interrupt (sched_clock)
04010001 0.623ms (+0.000ms): profile_tick (smp_apic_timer_interrupt)
04010001 0.623ms (+0.000ms): profile_hook (profile_tick)
04010002 0.623ms (+0.000ms): notifier_call_chain (profile_hook)
04010001 0.624ms (+0.000ms): preempt_schedule (profile_tick)
04010001 0.624ms (+0.000ms): profile_hit (smp_apic_timer_interrupt)
04000002 0.624ms (+0.000ms): do_softirq (smp_apic_timer_interrupt)
04000002 0.624ms (+0.000ms): __do_softirq (do_softirq)
04000002 0.625ms (+0.000ms): dequeue_task (schedule)
04000002 0.625ms (+0.000ms): recalc_task_prio (schedule)
04000002 0.625ms (+0.000ms): effective_prio (recalc_task_prio)
04000002 0.625ms (+0.000ms): enqueue_task (schedule)
00000002 0.626ms (+0.000ms): __switch_to (schedule)
00000002 0.626ms (+0.000ms): finish_task_switch (schedule)
00000001 0.626ms (+0.000ms): sub_preempt_count (schedule)
00000001 0.627ms (+0.000ms): update_max_trace (check_preempt_timing)
preemption latency trace v1.0.5 on 2.6.9-rc1-VP-R1
--------------------------------------------------
latency: 460 us, entries: 38 (38)
-----------------
| task: swapper/0, uid:0 nice:0 policy:0 rt_prio:0
-----------------
=> started at: do_IRQ+0x19/0x190
=> ended at: do_IRQ+0x14a/0x190
=======>
00010000 0.000ms (+0.000ms): do_IRQ (common_interrupt)
00010000 0.000ms (+0.000ms): do_IRQ (default_idle)
00010000 0.000ms (+0.000ms): do_IRQ (<00000000>)
00010001 0.000ms (+0.444ms): mask_and_ack_8259A (do_IRQ)
00020002 0.444ms (+0.000ms): do_nmi (mask_and_ack_8259A)
00020002 0.445ms (+0.000ms): profile_tick (nmi_watchdog_tick)
00020002 0.446ms (+0.000ms): profile_hook (profile_tick)
00020003 0.446ms (+0.000ms): notifier_call_chain (profile_hook)
00020002 0.446ms (+0.001ms): profile_hit (nmi_watchdog_tick)
00010001 0.448ms (+0.000ms): generic_redirect_hardirq (do_IRQ)
00010000 0.448ms (+0.000ms): generic_handle_IRQ_event (do_IRQ)
00010000 0.448ms (+0.000ms): timer_interrupt (generic_handle_IRQ_event)
00010001 0.448ms (+0.005ms): mark_offset_tsc (timer_interrupt)
00010001 0.454ms (+0.000ms): do_timer (timer_interrupt)
00010001 0.454ms (+0.000ms): update_process_times (do_timer)
00010001 0.454ms (+0.000ms): update_one_process (update_process_times)
00010001 0.455ms (+0.000ms): run_local_timers (update_process_times)
00010001 0.455ms (+0.000ms): raise_softirq (update_process_times)
00010001 0.455ms (+0.000ms): scheduler_tick (update_process_times)
00010001 0.455ms (+0.000ms): sched_clock (scheduler_tick)
00010001 0.456ms (+0.000ms): update_wall_time (do_timer)
00010001 0.456ms (+0.000ms): update_wall_time_one_tick
(update_wall_time)
00010001 0.456ms (+0.000ms): generic_note_interrupt (do_IRQ)
00010001 0.456ms (+0.000ms): end_8259A_irq (do_IRQ)
00010001 0.457ms (+0.001ms): enable_8259A_irq (do_IRQ)
00000001 0.458ms (+0.000ms): do_softirq (do_IRQ)
00000001 0.458ms (+0.000ms): __do_softirq (do_softirq)
00000001 0.458ms (+0.000ms): wake_up_process (do_softirq)
00000001 0.458ms (+0.000ms): try_to_wake_up (wake_up_process)
00000001 0.458ms (+0.000ms): task_rq_lock (try_to_wake_up)
00000002 0.459ms (+0.000ms): activate_task (try_to_wake_up)
00000002 0.459ms (+0.000ms): sched_clock (activate_task)
00000002 0.459ms (+0.000ms): recalc_task_prio (activate_task)
00000002 0.459ms (+0.000ms): effective_prio (recalc_task_prio)
00000002 0.459ms (+0.000ms): enqueue_task (activate_task)
00000001 0.460ms (+0.000ms): preempt_schedule (try_to_wake_up)
00000001 0.460ms (+0.000ms): sub_preempt_count (do_IRQ)
00000001 0.460ms (+0.000ms): update_max_trace (check_preempt_timing)
preemption latency trace v1.0.5 on 2.6.9-rc1-VP-R1
--------------------------------------------------
latency: 557 us, entries: 39 (39)
-----------------
| task: evolution-1.4/5492, uid:1000 nice:0 policy:0 rt_prio:0
-----------------
=> started at: fget+0x32/0x80
=> ended at: fget+0x58/0x80
=======>
00000001 0.000ms (+0.537ms): fget (do_pollfd)
00010001 0.537ms (+0.000ms): do_nmi (sub_preempt_count)
00010001 0.538ms (+0.000ms): profile_tick (nmi_watchdog_tick)
00010001 0.538ms (+0.000ms): profile_hook (profile_tick)
00010002 0.539ms (+0.000ms): notifier_call_chain (profile_hook)
00010001 0.539ms (+0.001ms): profile_hit (nmi_watchdog_tick)
00010001 0.540ms (+0.000ms): do_IRQ (sub_preempt_count)
00010001 0.540ms (+0.000ms): do_IRQ (<00000000>)
00010002 0.541ms (+0.002ms): mask_and_ack_8259A (do_IRQ)
00010002 0.543ms (+0.000ms): generic_redirect_hardirq (do_IRQ)
00010001 0.543ms (+0.000ms): generic_handle_IRQ_event (do_IRQ)
00010001 0.543ms (+0.000ms): timer_interrupt (generic_handle_IRQ_event)
00010002 0.544ms (+0.005ms): mark_offset_tsc (timer_interrupt)
00010002 0.549ms (+0.000ms): do_timer (timer_interrupt)
00010002 0.550ms (+0.000ms): update_process_times (do_timer)
00010002 0.550ms (+0.000ms): update_one_process (update_process_times)
00010002 0.550ms (+0.000ms): run_local_timers (update_process_times)
00010002 0.550ms (+0.000ms): raise_softirq (update_process_times)
00010002 0.551ms (+0.000ms): scheduler_tick (update_process_times)
00010002 0.551ms (+0.000ms): sched_clock (scheduler_tick)
00010003 0.551ms (+0.000ms): task_timeslice (scheduler_tick)
00010002 0.552ms (+0.000ms): update_wall_time (do_timer)
00010002 0.552ms (+0.000ms): update_wall_time_one_tick
(update_wall_time)
00010002 0.552ms (+0.000ms): generic_note_interrupt (do_IRQ)
00010002 0.553ms (+0.000ms): end_8259A_irq (do_IRQ)
00010002 0.553ms (+0.001ms): enable_8259A_irq (do_IRQ)
00000002 0.554ms (+0.000ms): do_softirq (do_IRQ)
00000002 0.554ms (+0.000ms): __do_softirq (do_softirq)
00000002 0.554ms (+0.000ms): wake_up_process (do_softirq)
00000002 0.555ms (+0.000ms): try_to_wake_up (wake_up_process)
00000002 0.555ms (+0.000ms): task_rq_lock (try_to_wake_up)
00000003 0.555ms (+0.000ms): activate_task (try_to_wake_up)
00000003 0.555ms (+0.000ms): sched_clock (activate_task)
00000003 0.555ms (+0.000ms): recalc_task_prio (activate_task)
00000003 0.556ms (+0.000ms): effective_prio (recalc_task_prio)
00000003 0.556ms (+0.000ms): enqueue_task (activate_task)
00000002 0.556ms (+0.000ms): preempt_schedule (try_to_wake_up)
00000001 0.557ms (+0.000ms): sub_preempt_count (fget)
00000001 0.557ms (+0.000ms): update_max_trace (check_preempt_timing)
I had similar problems affecting apparently random code paths before
enabling nmi_watchdog, but if you feel it can be useful, I can do some
more tests with robust-get-cycles and without nmi.
Thomas
next prev parent reply other threads:[~2004-09-03 16:14 UTC|newest]
Thread overview: 100+ messages / expand[flat|nested] mbox.gz Atom feed top
2004-08-30 19:13 [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5 Mark_H_Johnson
2004-08-30 19:21 ` Ingo Molnar
2004-09-01 12:31 ` [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5 - netdev_max_back_log is too small P.O. Gaillard
2004-09-01 13:05 ` Ingo Molnar
2004-09-02 11:24 ` [patch] voluntary-preempt-2.6.9-rc1-bk4-Q6 - network is no longer smooth P.O. Gaillard
2004-09-02 11:28 ` Ingo Molnar
2004-09-02 15:26 ` P.O. Gaillard
2004-08-31 8:49 ` [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5 Ingo Molnar
2004-09-02 6:33 ` Ingo Molnar
2004-09-02 6:55 ` [patch] voluntary-preempt-2.6.9-rc1-bk4-Q8 Ingo Molnar
2004-09-02 7:04 ` Lee Revell
2004-09-02 7:15 ` Ingo Molnar
2004-09-02 7:31 ` Lee Revell
2004-09-02 7:46 ` Ingo Molnar
2004-09-03 1:10 ` Rusty Russell
2004-09-02 23:25 ` Lee Revell
2004-09-02 23:28 ` Ingo Molnar
2004-09-02 23:32 ` Lee Revell
2004-09-02 7:17 ` Ingo Molnar
2004-09-02 8:23 ` Ingo Molnar
2004-09-02 11:10 ` [patch] voluntary-preempt-2.6.9-rc1-bk4-Q9 Ingo Molnar
2004-09-02 12:14 ` Thomas Charbonnel
2004-09-02 13:16 ` Thomas Charbonnel
2004-09-02 13:23 ` Ingo Molnar
2004-09-02 14:38 ` Thomas Charbonnel
2004-09-02 21:57 ` [patch] voluntary-preempt-2.6.9-rc1-bk4-R0 Ingo Molnar
2004-09-02 22:06 ` Lee Revell
2004-09-02 22:14 ` Ingo Molnar
2004-09-02 22:15 ` Lee Revell
2004-09-03 0:24 ` Lee Revell
2004-09-03 3:17 ` Eric St-Laurent
2004-09-03 6:26 ` Lee Revell
2004-09-03 6:36 ` Ingo Molnar
2004-09-03 6:49 ` Lee Revell
2004-09-03 7:01 ` Ingo Molnar
2004-09-03 7:05 ` Ingo Molnar
2004-09-03 7:40 ` Lee Revell
2004-09-03 7:50 ` Free Ekanayaka
2004-09-03 8:05 ` Lee Revell
2004-09-03 9:05 ` Free Ekanayaka
2004-09-03 9:25 ` [patch] voluntary-preempt-2.6.9-rc1-bk4-R1 Ingo Molnar
2004-09-03 9:50 ` Luke Yelavich
2004-09-03 10:29 ` Ingo Molnar
2004-09-03 10:43 ` Luke Yelavich
2004-09-03 11:33 ` Thomas Charbonnel
2004-09-03 11:49 ` Ingo Molnar
2004-09-03 12:05 ` Thomas Charbonnel
2004-09-03 16:14 ` Thomas Charbonnel [this message]
2004-09-03 17:36 ` Thomas Charbonnel
2004-09-03 11:36 ` [patch] voluntary-preempt-2.6.9-rc1-bk4-R2 Ingo Molnar
2004-09-03 8:09 ` [patch] voluntary-preempt-2.6.9-rc1-bk4-R0 Luke Yelavich
2004-09-03 8:13 ` Lee Revell
2004-09-03 8:21 ` Luke Yelavich
2004-09-03 12:52 ` Luke Yelavich
2004-09-03 18:09 ` K.R. Foley
2004-09-03 11:04 ` K.R. Foley
2004-09-03 17:02 ` K.R. Foley
2004-09-03 20:40 ` Lee Revell
2004-09-03 17:10 ` K.R. Foley
2004-09-03 18:17 ` Ingo Molnar
2004-09-03 18:36 ` K.R. Foley
2004-09-03 19:30 ` [patch] voluntary-preempt-2.6.9-rc1-bk4-R3 Ingo Molnar
2004-09-03 19:49 ` K.R. Foley
2004-09-04 3:39 ` K.R. Foley
2004-09-04 3:43 ` K.R. Foley
2004-09-04 6:41 ` Ingo Molnar
2004-09-04 12:28 ` K.R. Foley
2004-09-04 8:57 ` Ingo Molnar
2004-09-04 10:16 ` Lee Revell
2004-09-04 14:35 ` K.R. Foley
2004-09-04 20:05 ` Ingo Molnar
2004-09-03 18:39 ` [patch] voluntary-preempt-2.6.9-rc1-bk4-R0 Ingo Molnar
2004-09-03 18:41 ` K.R. Foley
-- strict thread matches above, loose matches on Subject: below --
2004-09-07 16:54 [patch] voluntary-preempt-2.6.9-rc1-bk4-R1 Mark_H_Johnson
2004-09-08 18:42 ` Ingo Molnar
2004-09-10 2:31 ` K.R. Foley
2004-09-10 17:56 ` K.R. Foley
2004-09-10 19:26 ` Ingo Molnar
2004-09-10 19:28 ` K.R. Foley
2004-09-09 16:02 ` Ingo Molnar
2004-09-08 20:33 Mark_H_Johnson
2004-09-08 22:31 ` Alan Cox
2004-09-09 16:44 ` Thomas Charbonnel
2004-09-09 6:27 ` Ingo Molnar
2004-09-09 15:12 ` Ingo Molnar
2004-09-09 15:33 ` Ingo Molnar
2004-09-09 18:31 Mark_H_Johnson
2004-09-09 19:23 Mark_H_Johnson
2004-09-09 19:47 ` Ingo Molnar
2004-09-09 19:02 ` Alan Cox
2004-09-09 22:41 Mark_H_Johnson
2004-09-09 22:56 Mark_H_Johnson
2004-09-10 12:42 ` Ingo Molnar
2004-09-10 12:57 Mark_H_Johnson
2004-09-10 13:10 ` Ingo Molnar
2004-09-10 14:28 Mark_H_Johnson
2004-09-10 19:29 ` Ingo Molnar
2004-09-13 14:44 Mark_H_Johnson
2004-09-14 18:32 ` Ingo Molnar
2004-09-15 15:26 ` Stephen Smalley
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=1094228060.5492.8.camel@localhost \
--to=thomas@undata.org \
--cc=Mark_H_Johnson@raytheon.com \
--cc=ericstl34@sympatico.ca \
--cc=free78@tin.it \
--cc=free@agnula.org \
--cc=kr@cybsft.com \
--cc=linux-kernel@vger.kernel.org \
--cc=lkml@felipe-alfaro.com \
--cc=luke@audioslack.com \
--cc=mingo@elte.hu \
--cc=nando@ccrma.stanford.edu \
--cc=pierre-olivier.gaillard@fr.thalesgroup.com \
--cc=pnambic@unu.nu \
--cc=rlrevell@joe-job.com \
/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