by Hugo Mills

[permalink] [raw]

Subject: Re: Linux 3.7-rc3

On Tue, Oct 30, 2012 at 01:10:32AM +0100, Rafael J. Wysocki wrote:
> On Sunday, October 28, 2012 12:59:49 PM Linus Torvalds wrote:
> > It's been a week, time for -rc3!
> >
> > Nothing particularly stands out here. Lots of small fixes, exemplified
> > by the series of memory leak fixes in usb serial drivers. Just a lot
> > of random stuff..
> >
> > Most of it is drivers (all over: drm, wireless, staging, usb, sound),
> > but there's a few filesystem updates (nfs, btrfs, ext4), arch updates
> > (arm, x86 and m68k) and just random stuff. Shortlog appended.
>
> Unfortunately, s2disk is broken with this one and previous -rc. In the
> majority of cases it just hangs the machine during hibernation, although
> sometimes it returns to user space reporting freezing problems, suspicions
> RCU usage and similar stuff, pretty much without any useful debug information.
>
> I'm quite confident that v3.6 was OK (and -stable based on that too), so
> it most likely is a recent regression. The in-kernel hibernation
> (ie. "echo disk > /sys/power/state") works no problem. So does suspend to
> RAM on my test boxes.
>
> So far I have been able to reproduce this 100% of the time on two machines
> with Intel CPUs and graphics driven by i915. I _suspect_ that this may be
> related to VT switching, because s2disk does some ugly things in that area
> which are not done by the in-kernel code. Dunno.

I've had this symptom on my laptop (Thinkpad Edge 13, Intel
graphics & CPU; I can get details when I get back home in about 8
hours), but only with 3.7-rc2. It was definitely working in 3.6, and
seems to be OK in 3.7-rc3, although I've only tried two cycles of that
last night.

When I did suspend to disk, I get a blank screen (but clearly with
backlight still on), and a blinking text-mode cursor in the top left.
I left it for half an hour once, and nothing changed, so I'm fairly
sure it was properly hung. I've not seen it return to user space with
errors at all -- just the hang.

> Anyway, it looks like nothing short of bisection is going to help debug this,
> but I'm afraid I won't have the time to bisect within the next two weeks, so if
> anyone can reproduce this issue and will be able to bisect it, please help
> (openSUSE/Tumbleweed users anyone?).

I can try to bisect the 3.6 -> 3.7-rc2 failure, if that helps? But
as I said, I've got it working on -rc3, so I may not have the same
problem.

Hugo.

--
=== Hugo Mills: hugo@... carfax.org.uk | darksatanic.net | lug.org.uk ===
PGP key: 515C238D from wwwkeys.eu.pgp.net or http://www.carfax.org.uk
--- UNIX: Spanish manufacturer of fire extinguishers. ---

Attachments:

(No filename) (2.60 kB)
signature.asc (828.00 B)
Digital signature Download all attachments

2012-10-30 12:53:15

On Wednesday, November 07, 2012 02:22:34 PM Paul E. McKenney wrote:
> On Fri, Nov 02, 2012 at 04:10:34PM -0700, Linus Torvalds wrote:
> > On Fri, Nov 2, 2012 at 3:43 PM, Rafael J. Wysocki <[email protected]> wrote:
> > >
> > > Well, not everything is rosy in the suspend land, though. This is a
> > > failure to freeze khubd during the second in a row attempt to suspend to
> > > RAM (your current tree):
> >
> > Ugh. So khubd is blocked in usb_start_wait_urb(), and apparently the
> > timeout for that block is longer than the freezing timeout.
> >
> > There's a comment about why khubd needs to be freezable, but I wonder
> > if that whole thing isn't doing something wrong. Causing the suspend
> > to fail is definitely always the wrong thing.
> >
> > Greg?
> >
> > > [ 125.780766] [ INFO: suspicious RCU usage. ]
> > > [ 125.780804] 3.7.0-rc3+ #988 Not tainted
> > > [ 125.780838] -------------------------------
> > > [ 125.780875] /home/rafael/src/linux/kernel/sched/core.c:4497 suspicious rcu_dereference_check() usage!
> >
> > Heh. The RCU usage is from the debug printout from sched_show_task(),
> > so it's "related", but it's a totally independent issue.
> >
> > It's apparently because we've not done a "rcu_read_lock()" around that
> > sequence, but I seriously doubt we care. But it's technically a real
> > bug - even if the fix might be to just not print out the parent pid
> > (or to just ignore the bug and turn the rcu dereference into an
> > ACCESS_ONCE() or something.
> >
> > Ingo, Peter, any comments about that sched/core.c:4497 RCU usage?
>
> Rafael, does the following patch fix that problem?

Well, the box I can reproduce that on is not with me now and it's
not readily reproducible anyway, so it may take some time to verify
I'm afraid.

Thanks,
Rafael

> ------------------------------------------------------------------------
>
> sched: Mark RCU reader in sched_show_task()
>
> When sched_show_task() is invoked from try_to_freeze_tasks(), there is
> no RCU read-side critical section, resulting in the following splat:
>
> [ 125.780730] ===============================
> [ 125.780766] [ INFO: suspicious RCU usage. ]
> [ 125.780804] 3.7.0-rc3+ #988 Not tainted
> [ 125.780838] -------------------------------
> [ 125.780875] /home/rafael/src/linux/kernel/sched/core.c:4497 suspicious rcu_dereference_check() usage!
> [ 125.780946]
> [ 125.780946] other info that might help us debug this:
> [ 125.780946]
> [ 125.781031]
> [ 125.781031] rcu_scheduler_active = 1, debug_locks = 0
> [ 125.781087] 4 locks held by s2ram/4211:
> [ 125.781120] #0: (&buffer->mutex){+.+.+.}, at: [<ffffffff811e2acf>] sysfs_write_file+0x3f/0x160
> [ 125.781233] #1: (s_active#94){.+.+.+}, at: [<ffffffff811e2b58>] sysfs_write_file+0xc8/0x160
> [ 125.781339] #2: (pm_mutex){+.+.+.}, at: [<ffffffff81090a81>] pm_suspend+0x81/0x230
> [ 125.781439] #3: (tasklist_lock){.?.?..}, at: [<ffffffff8108feed>] try_to_freeze_tasks+0x2cd/0x3f0
> [ 125.781543]
> [ 125.781543] stack backtrace:
> [ 125.781584] Pid: 4211, comm: s2ram Not tainted 3.7.0-rc3+ #988
> [ 125.781632] Call Trace:
> [ 125.781662] [<ffffffff810a3c73>] lockdep_rcu_suspicious+0x103/0x140
> [ 125.781719] [<ffffffff8107cf21>] sched_show_task+0x121/0x180
> [ 125.781770] [<ffffffff8108ffb4>] try_to_freeze_tasks+0x394/0x3f0
> [ 125.781823] [<ffffffff810903b5>] freeze_kernel_threads+0x25/0x80
> [ 125.781876] [<ffffffff81090b65>] pm_suspend+0x165/0x230
> [ 125.781924] [<ffffffff8108fa29>] state_store+0x99/0x100
> [ 125.781975] [<ffffffff812f5867>] kobj_attr_store+0x17/0x20
> [ 125.782038] [<ffffffff811e2b71>] sysfs_write_file+0xe1/0x160
> [ 125.782091] [<ffffffff811667a6>] vfs_write+0xc6/0x180
> [ 125.782138] [<ffffffff81166ada>] sys_write+0x5a/0xa0
> [ 125.782185] [<ffffffff812ff6ae>] ? trace_hardirqs_on_thunk+0x3a/0x3f
> [ 125.782242] [<ffffffff81669dd2>] system_call_fastpath+0x16/0x1b
>
> This commit therefore adds the needed RCU read-side critical section.
>
> Reported-by: "Rafael J. Wysocki" <[email protected]>
> Signed-off-by: Paul E. McKenney <[email protected]>
>
> diff --git a/kernel/sched/core.c b/kernel/sched/core.c
> index 6d4569e..36f2608 100644
> --- a/kernel/sched/core.c
> +++ b/kernel/sched/core.c
> @@ -4474,6 +4474,7 @@ static const char stat_nam[] = TASK_STATE_TO_CHAR_STR;
> void sched_show_task(struct task_struct *p)
> {
> unsigned long free = 0;
> + int ppid;
> unsigned state;
>
> state = p->state ? __ffs(p->state) + 1 : 0;
> @@ -4493,8 +4494,11 @@ void sched_show_task(struct task_struct *p)
> #ifdef CONFIG_DEBUG_STACK_USAGE
> free = stack_not_used(p);
> #endif
> + rcu_read_lock();
> + ppid = task_pid_nr(rcu_dereference(p->real_parent));
> + rcu_read_unlock();
> printk(KERN_CONT "%5lu %5d %6d 0x%08lx\n", free,
> - task_pid_nr(p), task_pid_nr(rcu_dereference(p->real_parent)),
> + task_pid_nr(p), ppid,
> (unsigned long)task_thread_info(p)->flags);
>
> show_stack(p, NULL);
>
>
--
I speak only for myself.
Rafael J. Wysocki, Intel Open Source Technology Center.