Message-ID: <AANLkTimtKP9ypNzf4ZpLK-CvGnqY+UigJaALHbFzUwg+@mail.gmail.com>
Date:	Mon, 28 Mar 2011 18:46:48 +0200
From:	Sedat Dilek <sedat.dilek@...glemail.com>
To:	paulmck@...ux.vnet.ibm.com
Cc:	Josh Triplett <josh@...htriplett.org>,
	linux-next <linux-next@...r.kernel.org>,
	LKML <linux-kernel@...r.kernel.org>,
	Stephen Rothwell <sfr@...b.auug.org.au>,
	Randy Dunlap <randy.dunlap@...cle.com>,
	"Theodore Ts'o" <tytso@....edu>, Jens Axboe <axboe@...nel.dk>,
	Tejun Heo <tj@...nel.org>, Al Viro <viro@...iv.linux.org.uk>,
	Nick Piggin <npiggin@...nel.dk>
Subject: Re: linux-next: Tree for March 25 (Call trace: RCU|workqueues|block|VFS|ext4
 related?)

On Mon, Mar 28, 2011 at 6:38 PM, Sedat Dilek <sedat.dilek@...glemail.com> wrote:
> On Mon, Mar 28, 2011 at 5:11 PM, Paul E. McKenney
> <paulmck@...ux.vnet.ibm.com> wrote:
>> On Mon, Mar 28, 2011 at 06:24:36AM -0700, Paul E. McKenney wrote:
>>> On Mon, Mar 28, 2011 at 02:33:36PM +0200, Sedat Dilek wrote:
>>> > On Mon, Mar 28, 2011 at 6:08 AM, Paul E. McKenney
>>> > <paulmck@...ux.vnet.ibm.com> wrote:
>>> > > On Sun, Mar 27, 2011 at 11:48:30PM +0200, Sedat Dilek wrote:
>>> > >> On Sun, Mar 27, 2011 at 11:32 PM, Paul E. McKenney
>>> > >> <paulmck@...ux.vnet.ibm.com> wrote:
>>> > >> > On Sun, Mar 27, 2011 at 02:26:15PM +0200, Sedat Dilek wrote:
>>> > >> >> On Sun, Mar 27, 2011 at 7:07 AM, Paul E. McKenney
>>> > >> >> <paulmck@...ux.vnet.ibm.com> wrote:
>>> > >> >> > On Sat, Mar 26, 2011 at 08:25:29PM -0700, Paul E. McKenney wrote:
>>> > >> >> >> On Sun, Mar 27, 2011 at 03:30:34AM +0200, Sedat Dilek wrote:
>>> > >> >> >> > On Sun, Mar 27, 2011 at 1:09 AM, Paul E. McKenney
>>> > >> >> >> > <paulmck@...ux.vnet.ibm.com> wrote:
>>> > >> >> >> > > On Sat, Mar 26, 2011 at 11:15:22PM +0100, Sedat Dilek wrote:
>>> > >> >> >
>>> > >> >> > [ . . . ]
>>> > >> >> >
>>> > >> >> >> > >> But then came RCU :-(.
>>> > >> >> >> > >
>>> > >> >> >> > > Well, if it turns out to be a problem in RCU I will certainly apologize.
>>> > >> >> >> > >
>>> > >> >> >> >
>>> > >> >> >> > No, that's not so dramatic.
>>> > >> >> >> > Dealing with this RCU issue has nice side-effects: I remembered (and
>>> > >> >> >> > finally did) to use a reduced kernel-config set.
>>> > >> >> >> > The base for it I created with 'make localmodconfig' and did some
>>> > >> >> >> > manual fine-tuning afterwards (throw out media, rc, dvd, unneeded FSs,
>>> > >> >> >> > etc.).
>>> > >> >> >> > Also, I can use fresh gcc-4.6 (4.6.0-1) from the official Debian repos.
>>> > >> >> >> >
>>> > >> >> >> > So, I started building with
>>> > >> >> >> > "revert-rcu-patches/0001-Revert-rcu-introduce-kfree_rcu.patch".
>>> > >> >> >> > I will let you know.
>>> > >> >> >>
>>> > >> >> >> And please also check for tasks consuming all available CPU.
>>> > >> >> >
>>> > >> >> > And I still cannot reproduce with the full RCU stack (but based off of
>>> > >> >> > 2.6.38 rather than -next).  Nevertheless, if you would like to try a
>>> > >> >> > speculative patch, here you go.
>>> > >> >>
>>> > >> >> You are right and my strategy on handling the (possible RCU?) issue is wrong.
>>> > >> >> Surely, you tested your RCU stuff in your own repo and everything
>>> > >> >> might be OK on top of stable 2.6.38.
>>> > >> >> Linux-next gets daily updates from a lot of different trees, so there
>>> > >> >> might be interferences with other stuff.
>>> > >> >> Please, understand I am interested in finding out what is the cause
>>> > >> >> for my issues, my aim is not to blame you.
>>> > >> >
>>> > >> > I am not worried about blame, but rather getting the bug fixed.  The
>>> > >> > bug might be in RCU, it might be elsewhere, or it might be a combination
>>> > >> > of problems in RCU and elsewhere.
>>> > >> >
>>> > >> > So the first priority is locating the bug.
>>> > >> >
>>> > >> > And that is why I have been asking you over and over to PLEASE take
>>> > >> > a look at what tasks are consuming CPU while the problem is occuring.
>>> > >> > The reason that I have been asking over and over is that the symptoms
>>> > >> > you describe are likely caused by a loop in some kernel code.  Yes,
>>> > >> > there might be other causes, but this is the most likely.  Given that
>>> > >> > TREE_PREEMPT_RCU behaves better than TREE_RCU, it is likely that this
>>> > >> > loop is in preemptible code with irqs enabled.  Therefore, the process
>>> > >> > accounting code is likely to be able to see the CPU consumption, and
>>> > >> > you should be able to see it via the "top" or "ps" commands -- or via
>>> > >> > any number of other tools.
>>> > >> >
>>> > >> > For example, if the problem is confined to RCU, you would likely see
>>> > >> > the "rcuc0" or "rcun0" tasks consuming lots of CPU.  This would narrow
>>> > >> > the problem down to a few tens of lines of code.  If the problem was
>>> > >> > in some other kthread, then identifying the kthread would very likely
>>> > >> > narrow things down as well.
>>> > >> >
>>> > >> > So, please do take a look to see what taks consuming CPU.
>>> > >> >
>>> > >> >> As I was wrong and want to be 99.9% sure it is RCU stuff, I reverted
>>> > >> >> all (18) RCU patches from linux-next (next-20110325) by keeping the
>>> > >> >> RCU|PREEMPT|HZ settings from last working next-20110323.
>>> > >> >
>>> > >> > Makes sense.
>>> > >> >
>>> > >> >> $ egrep 'RCU|PREEMPT|_HZ' /boot/config-2.6.38-next20110325-7-686-iniza
>>> > >> >> # RCU Subsystem
>>> > >> >> 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_RCU_FAST_NO_HZ=y
>>> > >> >> # CONFIG_TREE_RCU_TRACE is not set
>>> > >> >> CONFIG_PREEMPT_NOTIFIERS=y
>>> > >> >> CONFIG_NO_HZ=y
>>> > >> >> # CONFIG_PREEMPT_NONE is not set
>>> > >> >> CONFIG_PREEMPT_VOLUNTARY=y
>>> > >> >> # CONFIG_PREEMPT is not set
>>> > >> >> # CONFIG_HZ_100 is not set
>>> > >> >> CONFIG_HZ_250=y
>>> > >> >> # CONFIG_HZ_300 is not set
>>> > >> >> # CONFIG_HZ_1000 is not set
>>> > >> >> CONFIG_HZ=250
>>> > >> >> # CONFIG_SPARSE_RCU_POINTER is not set
>>> > >> >> # CONFIG_RCU_TORTURE_TEST is not set
>>> > >> >> # CONFIG_RCU_CPU_STALL_DETECTOR is not set
>>> > >> >>
>>> > >> >> I will work and stress this kernel before doing any step-by-step
>>> > >> >> revert of RCU stuff.
>>> > >> >>
>>> > >> >> Thanks for your patch, I applied it on top of "naked" next-20110325,
>>> > >> >> but I still see call-traces.
>>> > >> >
>>> > >> > Thank you very much for testing it!
>>> > >> >
>>> > >> > I intend to keep that patch, as it should increase robustness in other
>>> > >> > situations.
>>> > >> >
>>> > >> >                                                        Thanx, Paul
>>> > >> >
>>> > >> >> - Sedat -
>>> > >> >>
>>> > >> >>
>>> > >> >>
>>> > >> >> >                                                        Thanx, Paul
>>> > >> >> >
>>> > >> >> > ------------------------------------------------------------------------
>>> > >> >> >
>>> > >> >> > rcu: further lower priority in rcu_yield()
>>> > >> >> >
>>> > >> >> > Although rcu_yield() dropped from real-time to normal priority, there
>>> > >> >> > is always the possibility that the competing tasks have been niced.
>>> > >> >> > So nice to 19 in rcu_yield() to help ensure that other tasks have a
>>> > >> >> > better chance of running.
>>> > >> >> >
>>> > >> >> >    Signed-off-by: Paul E. McKenney <paulmck@...ux.vnet.ibm.com>
>>> > >> >> >
>>> > >> >> > diff --git a/kernel/rcutree.c b/kernel/rcutree.c
>>> > >> >> > index 759f54b..5477764 100644
>>> > >> >> > --- a/kernel/rcutree.c
>>> > >> >> > +++ b/kernel/rcutree.c
>>> > >> >> > @@ -1492,6 +1492,7 @@ static void rcu_yield(void (*f)(unsigned long), unsigned long arg)
>>> > >> >> >        mod_timer(&yield_timer, jiffies + 2);
>>> > >> >> >        sp.sched_priority = 0;
>>> > >> >> >        sched_setscheduler_nocheck(current, SCHED_NORMAL, &sp);
>>> > >> >> > +       set_user_nice(current, 19);
>>> > >> >> >        schedule();
>>> > >> >> >        sp.sched_priority = RCU_KTHREAD_PRIO;
>>> > >> >> >        sched_setscheduler_nocheck(current, SCHED_FIFO, &sp);
>>> > >>
>>> > >> Sorry, my attempt was to identify and isolate the culprit commit.
>>> > >>
>>> > >> Reverting all RCU patches resulted in a stable system, the following 8
>>> > >> kernels with reduced k-config setup where all built using this kernel.
>>> > >>
>>> > >> All kernels used TREE_RCU (see above), I did not change it (no
>>> > >> mixing/switching to PREEMPT and TREE_PREEMPT_RCU).
>>> > >> ( I doubt that TREE_PREEMPT_RCU was some kind of more stable here. )
>>> > >>
>>> > >> The culprit commit is bc56163ebd4580199ac7e63f5e160bf139ba0dd6 (from
>>> > >> rcu/next GIT tree):
>>> > >> "rcu: move TREE_RCU from softirq to kthread"
>>> > >
>>> >
>>> > Hi Paul,
>>> >
>>> > > OK, please accept my apologies for your lost weekend.  And thank you for
>>> > > testing this.
>>> > >
>>> >
>>> > No worries, it was mostly a rainy day.
>>> > The only thing I did @ 16:30 was to go to regional election (the new
>>> > (regional) prime minister will be the 1st from The German Green
>>> > party).
>>>
>>> ;-)
>>>
>>> > But back to RCU :-):
>>> > The reduced kernel-config setup decreased the build-time from approx.
>>> > 2hrs (full, generic build) down to approx. 35mins.
>>>
>>> Very good!
>>>
>>> > >> I can do parallelly a tar job, open 20 tabs in firefox and run a flash
>>> > >> video in one of them (I did this several times).
>>> > >
>>> > > How many files in the tar job?  Is this creating a tar archive, expanding
>>> > > it, or both?
>>> >
>>> > I am doing a simple tar (filesize: 1.6G for full and 1.0G for reduced build):
>>> >
>>> > $ tar -cf $archivedir-on-external-usbhdd/$tarfile $kernel-build-dir
>>>
>>> OK, I was extracting a tarball and then removing the resulting source
>>> tree.  I will try this.  Though it does seem strange -- I can understand
>>> how removing a file tree would stress RCU, but not creating a tarball.
>>> Ah, well, if I fully understood it, there would not be a bug.
>>>
>>> > ...plus parallelly opening 20 tabs in firefox.
>>> > That's normally enough to get my system freaky and see RCU related
>>> > messages in the logs.
>>>
>>> Hmmm...  My normal test systems don't have X -- I will need to set
>>> this up.
>>>
>>> > > Do you have a script for this?  Are all of these running at normal
>>> > > priority, or are some of them running at real-time priority?
>>> > >
>>> >
>>> > Nothing special.
>>>
>>> OK.
>>>
>>> > >> [ setup.log ]
>>> > >> ...
>>> > >>   (+) OK   revert-rcu-patches/0001-Revert-rcu-introduce-kfree_rcu.patch
>>> > >>   (+) OK   revert-rcu-patches/0002-Revert-rcu-fix-spelling.patch
>>> > >>   (+) OK   revert-rcu-patches/0003-Revert-rcu-fix-rcu_cpu_kthread_task-synchronization.patch
>>> > >>   (+) OK   revert-rcu-patches/0004-Revert-rcu-call-__rcu_read_unlock-in-exit_rcu-for-tr.patch
>>> > >>   (+) OK   revert-rcu-patches/0005-Revert-rcu-Converge-TINY_RCU-expedited-and-normal-bo.patch
>>> > >>   (+) OK   revert-rcu-patches/0006-Revert-rcu-remove-useless-boosted_this_gp-field.patch
>>> > >>   (+) OK   revert-rcu-patches/0007-Revert-rcu-code-cleanups-in-TINY_RCU-priority-boosti.patch
>>> > >>   (+) OK   revert-rcu-patches/0008-Revert-rcu-Switch-to-this_cpu-primitives.patch
>>> > >>   (+) OK   revert-rcu-patches/0009-Revert-rcu-Use-WARN_ON_ONCE-for-DEBUG_OBJECTS_RCU_HE.patch
>>> > >>   (+) OK   revert-rcu-patches/0010-Revert-rcu-Enable-DEBUG_OBJECTS_RCU_HEAD-from-PREEMP.patch
>>> > >>   (+) OK   revert-rcu-patches/0011-Revert-rcu-Add-boosting-to-TREE_PREEMPT_RCU-tracing.patch
>>> > >>   (+) OK   revert-rcu-patches/0012-Revert-rcu-eliminate-unused-boosting-statistics.patch
>>> > >>   (+) OK   revert-rcu-patches/0013-Revert-rcu-priority-boosting-for-TREE_PREEMPT_RCU.patch
>>> > >>   (+) OK   revert-rcu-patches/0014-Revert-rcu-move-TREE_RCU-from-softirq-to-kthread.patch
>>> > >> ...
>>> > >>
>>> > >> Hope this helps to narrow down the problem.
>>> > >>
>>> > >> As I kept all kernels I can have a look at the tasks consuming high
>>> > >> CPU usage tomorrow.
>>> > >
>>> > > Could you please?
>>> >
>>> > I recalled (as you say I requested over and over again from you :-)) I
>>> > looked with top, htop and 'ps axu', but there was nothing special.
>>> > Sometimes the system got frozen - at this point (or short before) I
>>> > did not see anything suspicious with top.
>>>
>>> OK, thank you for the info.
>>>
>>> > > Also, could you please mount debugfs and list out the files in the
>>> > > "rcu" directory?  The "ql=" value from the "rcu/rcudata" file is of
>>> > > particular interest.
>>> > >
>>> >
>>> > Ah, before I forget...
>>> >
>>> > I used TREE_RCU (was the default before noticing RCU issue) for
>>> > finding the culprit commit.
>>> > If it is from your POV more helpful to switch to PREEMPT + PREEMPT_RCU
>>> > + RCU_BOOST, please let me *now* know.
>>> > ( Both RCU setups freaks up the system. )
>>>
>>> If TREE_RCU hits problems faster, it is probably best to stay with
>>> TREE_RCU.
>>
>> And of course, one exception to this advice is if TREE_RCU hangs so hard
>> and fast that you don't have time to get any diagnostics.  If this is the
>> case, then TREE_PREEMPT_RCU might be more productive.
>>
>
> OK, that would somehow explain why I could not really get some debug
> infos when doing "my stress-test" and checking via:
>
> $ LC_ALL=C tail -f /sys/kernel/debug/rcu/rcudata
>
> Then I remembered I saw a snippet for a RCU torture script mentionned
> in the kernel-docs (see Documentation/RCU/torture.txt).
>
> 189 The following script may be used to torture RCU:
> 190
> 191         #!/bin/sh
> 192
> 193         modprobe rcutorture
> 194         sleep 100
> 195         rmmod rcutorture
> 196         dmesg | grep torture:
>
> So, I recompiled a new TREE_RC-based kernel and build with
> CONFIG_RCU_TORTURE_TEST=m.
>
> Unfortunately, the rmmod (I prefer modprobe -r -v) hangs... the
> messages in the logs look promising.
>
> - Sedat -
>

Wrong attachment, correct attached.

- Sedat -

>
>
>>                                                        Thanx, Paul
>>
>>> > I think top & Co. are not enough to track the problem down.
>>> > I have seen tracing and debugging facililities for RCU.
>>> >
>>> > Some questions to debug and trace setup:
>>> >
>>> > Case #1: TREE_RCU
>>> >
>>> > CONFIG_RCU_TRACE=y
>>> > CONFIG_TREE_RCU_TRACE=y
>>>
>>> Yep.
>>>
>>> > Case #2: PREEMPT + PREEMPT_RCU + RCU_BOOST
>>> >
>>> > CONFIG_RCU_TRACE=y
>>> > CONFIG_TREE_RCU_TRACE=y
>>> > CONFIG_DEBUG_PREEMPT=y <--- Helpful?
>>> > CONFIG_PREEMPT_TRACER=y <--- Helpful?
>>> >
>>> > Any other recommends for useful/helpful trace and/or debug options?
>>> >
>>> > Any other intructions for debugging/tracing?
>>>
>>> Not at the moment.  I will be looking at diagnostics will going
>>> through the code, so might have something later.
>>>
>>> > BTW, today's linux-next (next-20110328) is still freaky, I applied the
>>> > revert-rcu-patches patchset and all is fine.
>>>
>>> I reverted back to the commit preceding the one you pointed out last night
>>> my time, so the upcoming -next should be less freaky.
>>>
>>> > - Sedat -
>>> >
>>> > P.S.: Note to myself
>>> >
>>> > # mount -t debugfs none /sys/kernel/debug/
>>> > # ln -s /sys/kernel/debug /debug
>>> >
>>> > # find /debug -name rcu
>>>
>>> Or:
>>>
>>> # cd /debug/rcu
>>>
>>> then dump out everything except for the .csv file (which is the same
>>> as the non-.csv equivalent, but in spreadsheet format -- intended
>>> for systems with 100s or 1000s of CPUs).
>>>
>>>                                                       Thanx, Paul
>>
>

View attachment "msg_rcu-torture_correct.txt" of type "text/plain" (39880 bytes)

Powered by blists - more mailing lists