lkml.org 
[lkml]   [2009]   [Feb]   [16]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    Patch in this message
    /
    Date
    From
    SubjectRe: [Bug #12650] Strange load average and ksoftirqd behavior with 2.6.29-rc2-git1

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

    > Hello,
    >
    > Ok, I've redone the tests under tip from this morning (Paris time).
    > Everything is in http://damien.wyart.free.fr/ksoftirqd_pb/
    >
    > * Ingo Molnar <mingo@elte.hu> [2009-02-15 20:31]:
    > > Yes, an abstime trace would be useful.
    >
    > The corresponding file is trace_tip_2009.02.16_ksoftirqd_pb_abstime.txt.gz
    > and there is also a trace without abstime:
    > trace_tip_2009.02.16_ksoftirqd_pb.txt.gz

    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

    (your defaults might be different)

    You can see the duration of the trace by looking at the first timestamp
    and the last one:

    310.846260 | 0) 2.380 us | }
    [...]
    457.712729 | 1) | dequeue_task() {

    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?

    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();


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