From: Lee Revell <rlrevell@joe-job.com>
To: Ingo Molnar <mingo@elte.hu>
Cc: Dave Jones <davej@redhat.com>, Hugh Dickins <hugh@veritas.com>,
linux-kernel <linux-kernel@vger.kernel.org>,
Linus Torvalds <torvalds@osdl.org>
Subject: Re: [patch] latency tracer, 2.6.15-rc7
Date: Fri, 30 Dec 2005 19:51:09 -0500 [thread overview]
Message-ID: <1135990270.31111.46.camel@mindpipe> (raw)
In-Reply-To: <20051230080032.GA26152@elte.hu>
On Fri, 2005-12-30 at 09:00 +0100, Ingo Molnar wrote:
> * Lee Revell <rlrevell@joe-job.com> wrote:
>
> > It seems that debug_smp_processor_id is being called a lot, even
> > though I have a UP config, which I didn't see with the -rt kernel:
>
> do you have CONFIG_DEBUG_PREEMPT enabled? (if yes then disable it)
>
> > Was this optimized out on UP before?
>
> no, because smp_processor_id() debugging is useful on UP too: it checks
> whether smp_processor_id() is every called with preemption enabled, and
> reports such bugs.
It seems that the networking code's use of RCU can cause 10ms+
latencies:
preemption latency trace v1.1.5 on 2.6.15-rc7
--------------------------------------------------------------------
latency: 10437 us, #12080/12080, CPU#0 | (M:rt VP:0, KP:0, SP:0 HP:0)
-----------------
| task: gam_server-21330 (uid:1000 nice:0 policy:0 rt_prio:0)
-----------------
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
<idle>-0 0d.s2 1us : __trace_start_sched_wakeup (try_to_wake_up)
<idle>-0 0d.s2 1us : __trace_start_sched_wakeup <<...>-21330> (73 0)
<idle>-0 0d.s. 2us : wake_up_process (process_timeout)
<idle>-0 0d.s. 3us : tasklet_action (__do_softirq)
<idle>-0 0d.s. 4us : rcu_process_callbacks (tasklet_action)
<idle>-0 0d.s. 5us : __rcu_process_callbacks (rcu_process_callbacks)
<idle>-0 0d.s. 5us : rcu_check_quiescent_state (__rcu_process_callbacks)
<idle>-0 0d.s. 6us : __rcu_process_callbacks (rcu_process_callbacks)
<idle>-0 0d.s. 7us : rcu_check_quiescent_state (__rcu_process_callbacks)
<idle>-0 0d.s. 7us : rcu_do_batch (__rcu_process_callbacks)
<idle>-0 0d.s. 8us : dst_rcu_free (rcu_do_batch)
<idle>-0 0d.s. 9us : dst_destroy (dst_rcu_free)
<idle>-0 0d.s. 11us : ipv4_dst_destroy (dst_destroy)
<idle>-0 0d.s. 12us : kmem_cache_free (dst_destroy)
<idle>-0 0d.s. 13us+: debug_smp_processor_id (kmem_cache_free)
<idle>-0 0d.s. 15us : dst_rcu_free (rcu_do_batch)
<idle>-0 0d.s. 16us : dst_destroy (dst_rcu_free)
<idle>-0 0d.s. 16us : ipv4_dst_destroy (dst_destroy)
<idle>-0 0d.s. 18us : kmem_cache_free (dst_destroy)
<idle>-0 0d.s. 18us : debug_smp_processor_id (kmem_cache_free)
<idle>-0 0d.s. 19us : dst_rcu_free (rcu_do_batch)
<idle>-0 0d.s. 20us : dst_destroy (dst_rcu_free)
[last 5 lines repeat ~2000 times]
<idle>-0 0d.s. 10368us : ipv4_dst_destroy (dst_destroy)
<idle>-0 0d.s. 10369us : kmem_cache_free (dst_destroy)
<idle>-0 0d.s. 10370us : debug_smp_processor_id (kmem_cache_free)
<idle>-0 0d.s. 10371us : dst_rcu_free (rcu_do_batch)
<idle>-0 0d.s. 10371us : dst_destroy (dst_rcu_free)
<idle>-0 0d.s. 10372us : ipv4_dst_destroy (dst_destroy)
<idle>-0 0d.s. 10373us : kmem_cache_free (dst_destroy)
<idle>-0 0d.s. 10373us : debug_smp_processor_id (kmem_cache_free)
<idle>-0 0d.s. 10375us : debug_smp_processor_id (__do_softirq)
<idle>-0 0d.s. 10375us : debug_smp_processor_id (__do_softirq)
<idle>-0 0d.s. 10376us+: run_timer_softirq (__do_softirq)
<idle>-0 0d.s. 10378us : rh_timer_func (run_timer_softirq)
<idle>-0 0d.s. 10379us : usb_hcd_poll_rh_status (rh_timer_func)
<idle>-0 0d.s. 10380us : uhci_hub_status_data (usb_hcd_poll_rh_status)
<idle>-0 0d.s1 10381us : uhci_scan_schedule (uhci_hub_status_data)
<idle>-0 0d.s1 10382us : uhci_get_current_frame_number (uhci_scan_schedule)
<idle>-0 0d.s1 10384us : uhci_free_pending_qhs (uhci_scan_schedule)
<idle>-0 0d.s1 10384us : uhci_free_pending_tds (uhci_scan_schedule)
<idle>-0 0d.s1 10385us : uhci_remove_pending_urbps (uhci_scan_schedule)
<idle>-0 0d.s1 10387us : uhci_transfer_result (uhci_scan_schedule)
<idle>-0 0d.s2 10388us : uhci_result_common (uhci_transfer_result)
<idle>-0 0d.s1 10390us : uhci_finish_completion (uhci_scan_schedule)
<idle>-0 0d.s1 10391us : __wake_up (uhci_scan_schedule)
<idle>-0 0d.s2 10391us : __wake_up_common (__wake_up)
<idle>-0 0d.s1 10392us : check_fsbr (uhci_hub_status_data)
<idle>-0 0d.s1 10394us+: uhci_check_ports (uhci_hub_status_data)
<idle>-0 0d.s1 10398us : any_ports_active (uhci_hub_status_data)
<idle>-0 0d.s. 10399us : mod_timer (usb_hcd_poll_rh_status)
<idle>-0 0d.s. 10400us : __mod_timer (mod_timer)
<idle>-0 0d.s. 10401us : lock_timer_base (__mod_timer)
<idle>-0 0d.s1 10402us : internal_add_timer (__mod_timer)
<idle>-0 0d.s. 10403us : i8042_timer_func (run_timer_softirq)
<idle>-0 0d.s. 10404us : i8042_interrupt (i8042_timer_func)
<idle>-0 0d.s. 10405us : mod_timer (i8042_interrupt)
<idle>-0 0d.s. 10405us : __mod_timer (mod_timer)
<idle>-0 0d.s. 10406us : lock_timer_base (__mod_timer)
<idle>-0 0d.s1 10407us+: internal_add_timer (__mod_timer)
<idle>-0 0d.s. 10411us : tasklet_action (__do_softirq)
<idle>-0 0d.s. 10412us : rcu_process_callbacks (tasklet_action)
<idle>-0 0d.s. 10412us : __rcu_process_callbacks (rcu_process_callbacks)
<idle>-0 0d.s. 10413us : rcu_check_quiescent_state (__rcu_process_callbacks)
<idle>-0 0d.s. 10414us : __rcu_process_callbacks (rcu_process_callbacks)
<idle>-0 0d.s. 10414us : rcu_check_quiescent_state (__rcu_process_callbacks)
<idle>-0 0d.s. 10415us+: debug_smp_processor_id (__do_softirq)
<idle>-0 0dn.1 10417us < (2097760)
<idle>-0 0dn.. 10418us : schedule (cpu_idle)
<idle>-0 0dn.. 10419us : stop_trace (schedule)
<idle>-0 0dn.. 10420us : profile_hit (schedule)
<idle>-0 0dn.1 10421us : sched_clock (schedule)
<idle>-0 0dn.2 10422us : debug_smp_processor_id (schedule)
<idle>-0 0dn.2 10423us : recalc_task_prio (schedule)
<idle>-0 0dn.2 10424us : effective_prio (recalc_task_prio)
<idle>-0 0dn.2 10425us : requeue_task (schedule)
<idle>-0 0d..2 10426us : debug_smp_processor_id (schedule)
<...>-21330 0d..2 10430us : __switch_to (schedule)
<...>-21330 0d..2 10431us+: debug_smp_processor_id (__switch_to)
<...>-21330 0d..2 10433us : schedule <<idle>-0> (8c 73)
<...>-21330 0d..1 10434us : trace_stop_sched_switched (schedule)
<...>-21330 0d..2 10435us+: trace_stop_sched_switched <<...>-21330> (73 0)
<...>-21330 0d..2 10437us : trace_stop_sched_switched (schedule)
next prev parent reply other threads:[~2005-12-31 0:51 UTC|newest]
Thread overview: 52+ messages / expand[flat|nested] mbox.gz Atom feed top
2005-12-27 23:31 2.6.15-rc5: latency regression vs 2.6.14 in exit_mmap->free_pgtables Lee Revell
2005-12-28 2:46 ` Lee Revell
2005-12-28 22:59 ` Hugh Dickins
2005-12-29 0:00 ` Lee Revell
2005-12-29 8:22 ` [patch] latency tracer, 2.6.15-rc7 Ingo Molnar
2005-12-29 10:02 ` Dave Jones
2005-12-29 10:17 ` Ingo Molnar
2005-12-29 20:11 ` Lee Revell
2005-12-29 20:26 ` Lee Revell
2005-12-29 20:28 ` Ingo Molnar
2005-12-29 22:18 ` Lee Revell
2005-12-30 0:08 ` Grant Coady
2005-12-30 0:18 ` Lee Revell
2005-12-30 0:42 ` Grant Coady
2005-12-30 8:09 ` Ingo Molnar
2005-12-30 16:51 ` Linus Torvalds
2006-01-02 20:14 ` Ingo Molnar
2006-01-19 1:49 ` Lee Revell
2006-01-19 6:17 ` Lee Revell
2005-12-31 0:20 ` Grant Coady
2005-12-30 2:16 ` Lee Revell
2005-12-30 8:00 ` Ingo Molnar
2005-12-30 18:51 ` Lee Revell
2005-12-31 0:51 ` Lee Revell [this message]
2005-12-31 0:59 ` Mark Knecht
2005-12-31 1:16 ` Lee Revell
2005-12-31 1:30 ` Lee Revell
2005-12-31 1:02 ` Linus Torvalds
2005-12-31 1:15 ` Lee Revell
2005-12-31 1:39 ` Linus Torvalds
2005-12-31 3:54 ` Lee Revell
2005-12-31 4:00 ` Lee Revell
2005-12-31 4:29 ` Paul E. McKenney
2005-12-31 4:54 ` Lee Revell
2005-12-31 20:14 ` Paul E. McKenney
2006-01-01 5:46 ` Lee Revell
2006-01-01 18:56 ` Linus Torvalds
2006-01-01 19:02 ` Lee Revell
2006-01-01 19:06 ` Lee Revell
2006-01-03 11:12 ` Dipankar Sarma
2006-01-03 13:28 ` David Lang
2006-01-03 14:11 ` Dipankar Sarma
2006-01-03 14:09 ` Dipankar Sarma
2006-01-03 15:55 ` Paul E. McKenney
2005-12-31 4:48 ` Linus Torvalds
2006-01-01 8:32 ` Lee Revell
2006-01-06 20:28 ` Lee Revell
2005-12-29 0:54 ` 2.6.15-rc5: latency regression vs 2.6.14 in exit_mmap->free_pgtables Lee Revell
2006-01-19 1:42 ` Lee Revell
2006-01-19 7:29 ` Hugh Dickins
2006-01-19 7:32 ` Lee Revell
2006-01-19 7:35 ` Lee Revell
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=1135990270.31111.46.camel@mindpipe \
--to=rlrevell@joe-job.com \
--cc=davej@redhat.com \
--cc=hugh@veritas.com \
--cc=linux-kernel@vger.kernel.org \
--cc=mingo@elte.hu \
--cc=torvalds@osdl.org \
/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