Re: [Bug #12650] Strange load average and ksoftirqd behavior with 2.6.29-rc2-git1

Damien Wyart
2009-02-16T11:56:42Z

* Ingo Molnar <mingo@elte.hu> [090216 10:50]:
> hm, we need a trace with both abstime and process information included:

> echo funcgraph-proc > trace_options
> echo funcgraph-abstime > trace_options

> Also, at 140 msecs the duration is a bit short - could you please make a
> 1-2 seconds capture? You can do that by increasing the number in
> buffer_size_kb 10-fold:

> echo 14100 > buffer_size_kb

Ok, I've redone a trace with these options enabled. The file is here:
http://damien.wyart.free.fr/ksoftirqd_pb/trace_tip_2009.02.16_ksoftirqd_pb_abstime_proc.txt.gz

> Hm ... even with this limited trace, there's an unusually high amount of
> RCU activities. Each activity goes like this:

> 457.680976 | 1) | do_softirq() {
> 457.680976 | 1) | __do_softirq() {
> 457.680977 | 1) | rcu_process_callbacks() {
> 457.680977 | 1) | __rcu_process_callbacks() {
> 4 457.680978 | 1) 0.478 us | force_quiescent_state();
> 457.680979 | 1) 1.591 us | }
> 457.680979 | 1) | __rcu_process_callbacks() {
> 457.680980 | 1) 0.478 us | force_quiescent_state();
> 457.680981 | 1) | cpu_quiet() {
> 457.680981 | 1) 0.506 us | _spin_lock_irqsave();
> 457.680982 | 1) 0.496 us | _spin_unlock_irqrestore();
> 457.680983 | 1) 2.545 us | }
> 457.680984 | 1) 4.626 us | }
> 457.680985 | 1) 7.823 us | }
> 457.680985 | 1) 0.496 us | _local_bh_enable();
> 457.680986 | 1) 9.845 us | }
> 457.680987 | 1) + 10.962 us | }

> I've Cc:-ed Paul, as you have tree-RCU enabled, which is a new feature
> in v2.6.29:

> #
> # RCU Subsystem
> #
> # CONFIG_CLASSIC_RCU is not set
> CONFIG_TREE_RCU=y
> # CONFIG_PREEMPT_RCU is not set
> # CONFIG_RCU_TRACE is not set
> CONFIG_RCU_FANOUT=32
> # CONFIG_RCU_FANOUT_EXACT is not set
> # CONFIG_TREE_RCU_TRACE is not set
> # CONFIG_PREEMPT_RCU_TRACE is not set

> Damien, as an experiment, if you change your config to
> CONFIG_CLASSIC_RCU=y, does the ksoftirqd problem go away?

Yes, in that case the problem completely goes away. Nice catch!

> On the other hand ... the softirq processing there looks anomalous in
> itself, and might be due to some compiler bug perhaps. Could you try
> the debug patch below please (you'll get it automatically if you
> update to latest -tip), and redo the trace - the ftrace_printk() info
> should now be embedded in the trace. The expected result would be for
> the printed ot value to be non-zero at the #1 point, and zero at the
> #2 point.

> Note: if it's a compiler optimization bug then this patch might make the
> whole problem go away.

> Ingo

> ------------------>
> >From 2d7cf65eec92937bff1073311f6843aa7189bff2 Mon Sep 17 00:00:00 2001
> From: Ingo Molnar <mingo@elte.hu>
> Date: Mon, 16 Feb 2009 10:48:37 +0100
> Subject: [PATCH] softirq: debug

> Signed-off-by: Ingo Molnar <mingo@elte.hu>
> ---
> kernel/softirq.c | 2 ++
> 1 files changed, 2 insertions(+), 0 deletions(-)

> diff --git a/kernel/softirq.c b/kernel/softirq.c
> index 3dd0d13..110cad0 100644
> --- a/kernel/softirq.c
> +++ b/kernel/softirq.c
> @@ -196,7 +196,9 @@ asmlinkage void __do_softirq(void)
> cpu = smp_processor_id();
> restart:
> /* Reset the pending bitmask before enabling irqs */
> + ftrace_printk("#1 softirq pending: %08x\n", local_softirq_pending());
> set_softirq_pending(0);
> + ftrace_printk("#2 softirq pending: %08x\n", local_softirq_pending());

> local_irq_enable();

I've done my new trace after recompiling very latest tip, so this should
have been taken into account.

So this seems RCU-related... If more tests are needed, do not hesitate
to ask. Btw, on the laptop which also shows ksoftirqd problems, I also
have CONFIG_TREE_RCU=y.

--
Damien