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 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.