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: 101+ 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-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 an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.