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

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <20090216122632.GA3158@elte.hu>
Date:	Mon, 16 Feb 2009 13:26:32 +0100
From:	Ingo Molnar <mingo@...e.hu>
To:	Damien Wyart <damien.wyart@...e.fr>
Cc:	"Paul E. McKenney" <paulmck@...ibm.com>,
	Peter Zijlstra <a.p.zijlstra@...llo.nl>,
	Mike Galbraith <efault@....de>,
	Frédéric Weisbecker <fweisbec@...il.com>,
	"Rafael J. Wysocki" <rjw@...k.pl>,
	Linux Kernel Mailing List <linux-kernel@...r.kernel.org>,
	Kernel Testers List <kernel-testers@...r.kernel.org>
Subject: Re: [Bug #12650] Strange load average and ksoftirqd behavior with
	2.6.29-rc2-git1


* Damien Wyart <damien.wyart@...e.fr> wrote:

> * Ingo Molnar <mingo@...e.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

ok, here's the new annotated trace:

  799.555279 |   1)  ksoftir-2324  |               |  do_softirq() {
  799.555279 |   1)  ksoftir-2324  |               |    __do_softirq() {
  799.555280 |   1)  ksoftir-2324  |               |      /* #1 softirq pending: 00000100 */
  799.555281 |   1)  ksoftir-2324  |               |      /* #2 softirq pending: 00000000 */
  799.555282 |   1)  ksoftir-2324  |               |      rcu_process_callbacks() {
  799.555282 |   1)  ksoftir-2324  |               |        __rcu_process_callbacks() {
  799.555283 |   1)  ksoftir-2324  |   0.479 us    |          force_quiescent_state();
  799.555284 |   1)  ksoftir-2324  |   1.576 us    |        }
  799.555284 |   1)  ksoftir-2324  |               |        __rcu_process_callbacks() {
  799.555285 |   1)  ksoftir-2324  |               |          force_quiescent_state() {
  799.555286 |   1)  ksoftir-2324  |               |          cpu_quiet() {
  799.555286 |   1)  ksoftir-2324  |   0.518 us    |            _spin_lock_irqsave();
  799.555287 |   1)  ksoftir-2324  |   0.506 us    |            _spin_unlock_irqrestore();
  799.555288 |   1)  ksoftir-2324  |   2.563 us    |          }
  799.555289 |   1)  ksoftir-2324  |   4.624 us    |        }
  799.555289 |   1)  ksoftir-2324  |   7.836 us    |      }
  799.555290 |   1)  ksoftir-2324  |   0.495 us    |      _local_bh_enable();
  799.555291 |   1)  ksoftir-2324  | + 11.550 us   |    }
  799.555291 |   1)  ksoftir-2324  | + 12.713 us   |  }
  799.555292 |   1)  ksoftir-2324  |   0.524 us    |  _cond_resched();

We do get 0x100 which is 1 << RCU_SOFTIRQ, i.e. the RCU softirq. Paul, 
this indeed seems to be a CONFIG_TREE_RCU=y bug.

What is weird is that RCU_SOFTIRQ gets set again and again - but there's 
no raise_softirq() calls. Could you please do a two-CPU trace too via:

   echo 3 > /debug/tracing/tracing_cpumask

So that we can see what's happening on the other CPU?

Also, could you please apply the debug patch below (or update to the 
very latest -tip tree), so that we get trace entries of softirq triggers 
too?

Thanks,

	Ingo

-------------->

>From 6876d5d56716427f9bbe3af7e4e9c06cb760ae0c Mon Sep 17 00:00:00 2001
From: Ingo Molnar <mingo@...e.hu>
Date: Mon, 16 Feb 2009 13:23:36 +0100
Subject: [PATCH] softirq: debug #2

Signed-off-by: Ingo Molnar <mingo@...e.hu>
---
 include/linux/interrupt.h |    3 ++-
 kernel/softirq.c          |    7 +++++++
 2 files changed, 9 insertions(+), 1 deletions(-)

diff --git a/include/linux/interrupt.h b/include/linux/interrupt.h
index e7bcfd7..cc1f529 100644
--- a/include/linux/interrupt.h
+++ b/include/linux/interrupt.h
@@ -271,7 +271,8 @@ asmlinkage void do_softirq(void);
 asmlinkage void __do_softirq(void);
 extern void open_softirq(int nr, void (*action)(struct softirq_action *));
 extern void softirq_init(void);
-#define __raise_softirq_irqoff(nr) do { or_softirq_pending(1UL << (nr)); } while (0)
+#define ___raise_softirq_irqoff(nr) do { or_softirq_pending(1UL << (nr)); } while (0)
+extern void __raise_softirq_irqoff(unsigned int nr);
 extern void raise_softirq_irqoff(unsigned int nr);
 extern void raise_softirq(unsigned int nr);
 
diff --git a/kernel/softirq.c b/kernel/softirq.c
index 110cad0..431cb4f 100644
--- a/kernel/softirq.c
+++ b/kernel/softirq.c
@@ -302,6 +302,13 @@ void irq_exit(void)
 	preempt_enable_no_resched();
 }
 
+void __raise_softirq_irqoff(unsigned int nr)
+{
+	ftrace_printk("nr: %d\n", nr);
+	or_softirq_pending(1UL << nr);
+}
+EXPORT_SYMBOL_GPL(__raise_softirq_irqoff);
+
 /*
  * This function must run with irqs disabled!
  */
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/