lkml.org 
[lkml]   [2009]   [Feb]   [16]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    Date
    From
    SubjectRe: [Bug #12650] Strange load average and ksoftirqd behavior with 2.6.29-rc2-git1
    On Mon, Feb 16, 2009 at 02:39:44PM -0800, Paul E. McKenney wrote:
    > On Mon, Feb 16, 2009 at 09:09:23PM +0100, Ingo Molnar wrote:
    > >
    > > * Paul E. McKenney <paulmck@linux.vnet.ibm.com> wrote:
    > >
    > > > Here the calls to rcu_process_callbacks() are only 75
    > > > microseconds apart, so that this function is consuming more
    > > > than 10% of a CPU. The strange thing is that I don't see a
    > > > raise_softirq() in between, though perhaps it gets inlined or
    > > > something that makes it invisible to ftrace.
    > >
    > > look at the latest trace please, that has even the most inline
    > > raise-softirq method instrumented, so all the raising is
    > > visible.
    >
    > Ah, my apologies! This time looking at:
    >
    > http://damien.wyart.free.fr/ksoftirqd_pb/trace_tip_2009.02.16_ksoftirqd_pb_abstime_proc.txt.gz
    >
    >
    > 799.521187 | 1) <idle>-0 | | rcu_check_callbacks() {
    > 799.521371 | 1) <idle>-0 | | rcu_check_callbacks() {
    > 799.521555 | 1) <idle>-0 | | rcu_check_callbacks() {
    > 799.521738 | 1) <idle>-0 | | rcu_check_callbacks() {
    > 799.521934 | 1) <idle>-0 | | rcu_check_callbacks() {
    > 799.522068 | 1) ksoftir-2324 | | rcu_check_callbacks() {
    > 799.522208 | 1) <idle>-0 | | rcu_check_callbacks() {
    > 799.522392 | 1) <idle>-0 | | rcu_check_callbacks() {
    > 799.522575 | 1) <idle>-0 | | rcu_check_callbacks() {
    > 799.522759 | 1) <idle>-0 | | rcu_check_callbacks() {
    > 799.522956 | 1) <idle>-0 | | rcu_check_callbacks() {
    > 799.523074 | 1) ksoftir-2324 | | rcu_check_callbacks() {
    > 799.523214 | 1) <idle>-0 | | rcu_check_callbacks() {
    > 799.523397 | 1) <idle>-0 | | rcu_check_callbacks() {
    > 799.523579 | 1) <idle>-0 | | rcu_check_callbacks() {
    > 799.523762 | 1) <idle>-0 | | rcu_check_callbacks() {
    > 799.523960 | 1) <idle>-0 | | rcu_check_callbacks() {
    > 799.524079 | 1) ksoftir-2324 | | rcu_check_callbacks() {
    > 799.524220 | 1) <idle>-0 | | rcu_check_callbacks() {
    > 799.524403 | 1) <idle>-0 | | rcu_check_callbacks() {
    > 799.524587 | 1) <idle>-0 | | rcu_check_callbacks() {
    > 799.524770 | 1) <idle>-0 | | rcu_check_callbacks() {
    > [ . . . ]
    >
    > Yikes!!!
    >
    > Why is rcu_check_callbacks() being invoked so often? It should be called
    > but once per jiffy, and here it is called no less than 22 times in about
    > 3.5 milliseconds, meaning one call every 160 microseconds or so.

    BTW, the other question I have is "why do we need to call rcu_pending()
    and rcu_check_callbacks() from the idle loop of 32-bit x86, especially
    given that no other architecture does this?". Don't get me wrong, it
    would be good to get rcutree's rcu_pending() to avoid spuriously saying
    that rcu_check_callbacks() should be invoked, so I would still like the
    trace with my patch, but...

    Thanx, Paul

    > Hmmm...
    >
    > Looks like we never return from:
    >
    > 799.521142 | 1) <idle>-0 | | tick_nohz_stop_sched_tick() {
    >
    > Perhaps we are taking an interrupt immediately after the
    > local_irq_restore()? And at 799.521209 deciding to exit nohz mode.
    > And then deciding to go back into nohz mode at 799.521326, 117
    > microseconds later, after which we re-invoke rcu_check_callbacks(),
    > which again raises RCU's softirq.
    >
    > And the reason we are invoking rcu_check_callbacks() so often appears
    > to be in in arch/x86/kernel/process_32.c cpu_idle() near line 107,
    > which explains my failure to reproduce on a 64-bit system:
    >
    > void cpu_idle(void)
    > {
    > int cpu = smp_processor_id();
    >
    > current_thread_info()->status |= TS_POLLING;
    >
    > /* endless idle loop with no priority at all */
    > while (1) {
    > tick_nohz_stop_sched_tick(1);
    > while (!need_resched()) {
    >
    > check_pgt_cache();
    > rmb();
    >
    > if (rcu_pending(cpu))
    > rcu_check_callbacks(cpu, 0);
    >
    > if (cpu_is_offline(cpu))
    > play_dead();
    >
    > local_irq_disable();
    > __get_cpu_var(irq_stat).idle_timestamp = jiffies;
    > /* Don't trace irqs off for idle */
    > stop_critical_timings();
    > pm_idle();
    > start_critical_timings();
    > }
    > tick_nohz_restart_sched_tick();
    > preempt_enable_no_resched();
    > schedule();
    > preempt_disable();
    > }
    > }
    >
    > If we go in and out of nohz mode quickly, we will invoke rcu_pending()
    > each time. I would expect rcu_pending() to return 0 most of the time,
    > but that apparently isn't the case with treercu...
    >
    > What is the easiest way for me to make it easy to trace the return path
    > from __rcu_pending()? Make each return path call an empty function
    > located off where the compiler cannot see it, I guess... Diagnostic
    > patch along these lines below. Frederic, Damien, could you please give
    > it a go? (And of course please let me know if something else is
    > needed.)
    >
    > Signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
    > ---
    >
    > rcupdate.c | 23 +++++++++++++++++++++++
    > rcutree.c | 31 +++++++++++++++++++++++++------
    > 2 files changed, 48 insertions(+), 6 deletions(-)
    >
    > diff --git a/kernel/rcupdate.c b/kernel/rcupdate.c
    > index d92a76a..42bbf03 100644
    > --- a/kernel/rcupdate.c
    > +++ b/kernel/rcupdate.c
    > @@ -175,3 +175,26 @@ void __init rcu_init(void)
    > __rcu_init();
    > }
    >
    > +void __rcu_pending_qs_pending(void)
    > +{
    > +}
    > +
    > +void __rcu_pending_callbacks_ready(void)
    > +{
    > +}
    > +
    > +void __rcu_pending_needs_gp(void)
    > +{
    > +}
    > +
    > +void __rcu_pending_new_completed(void)
    > +{
    > +}
    > +
    > +void __rcu_pending_new_gp(void)
    > +{
    > +}
    > +
    > +void __rcu_pending_fqs(void)
    > +{
    > +}
    > diff --git a/kernel/rcutree.c b/kernel/rcutree.c
    > index b2fd602..e2d72c3 100644
    > --- a/kernel/rcutree.c
    > +++ b/kernel/rcutree.c
    > @@ -1234,6 +1234,13 @@ void call_rcu_bh(struct rcu_head *head, void (*func)(struct rcu_head *rcu))
    > }
    > EXPORT_SYMBOL_GPL(call_rcu_bh);
    >
    > +extern void __rcu_pending_qs_pending(void);
    > +extern void __rcu_pending_callbacks_ready(void);
    > +extern void __rcu_pending_needs_gp(void);
    > +extern void __rcu_pending_new_completed(void);
    > +extern void __rcu_pending_new_gp(void);
    > +extern void __rcu_pending_fqs(void);
    > +
    > /*
    > * Check to see if there is any immediate RCU-related work to be done
    > * by the current CPU, for the specified type of RCU, returning 1 if so.
    > @@ -1249,30 +1256,42 @@ static int __rcu_pending(struct rcu_state *rsp, struct rcu_data *rdp)
    > check_cpu_stall(rsp, rdp);
    >
    > /* Is the RCU core waiting for a quiescent state from this CPU? */
    > - if (rdp->qs_pending)
    > + if (rdp->qs_pending) {
    > + __rcu_pending_qs_pending();
    > return 1;
    > + }
    >
    > /* Does this CPU have callbacks ready to invoke? */
    > - if (cpu_has_callbacks_ready_to_invoke(rdp))
    > + if (cpu_has_callbacks_ready_to_invoke(rdp)) {
    > + __rcu_pending_callbacks_ready();
    > return 1;
    > + }
    >
    > /* Has RCU gone idle with this CPU needing another grace period? */
    > - if (cpu_needs_another_gp(rsp, rdp))
    > + if (cpu_needs_another_gp(rsp, rdp)) {
    > + __rcu_pending_needs_gp();
    > return 1;
    > + }
    >
    > /* Has another RCU grace period completed? */
    > - if (ACCESS_ONCE(rsp->completed) != rdp->completed) /* outside of lock */
    > + if (ACCESS_ONCE(rsp->completed) != rdp->completed) /* outside of lock */ {
    > + __rcu_pending_new_completed();
    > return 1;
    > + }
    >
    > /* Has a new RCU grace period started? */
    > - if (ACCESS_ONCE(rsp->gpnum) != rdp->gpnum) /* outside of lock */
    > + if (ACCESS_ONCE(rsp->gpnum) != rdp->gpnum) /* outside of lock */ {
    > + __rcu_pending_new_gp();
    > return 1;
    > + }
    >
    > /* Has an RCU GP gone long enough to send resched IPIs &c? */
    > if (ACCESS_ONCE(rsp->completed) != ACCESS_ONCE(rsp->gpnum) &&
    > ((long)(ACCESS_ONCE(rsp->jiffies_force_qs) - jiffies) < 0 ||
    > - (rdp->n_rcu_pending_force_qs - rdp->n_rcu_pending) < 0))
    > + (rdp->n_rcu_pending_force_qs - rdp->n_rcu_pending) < 0)) {
    > + __rcu_pending_fqs();
    > return 1;
    > + }
    >
    > /* nothing to do */
    > return 0;


    \
     
     \ /
      Last update: 2009-02-18 12:23    [W:0.058 / U:15.148 seconds]
    ©2003-2017 Jasper Spaans. hosted at Digital OceanAdvertise on this site