| Message ID | 20170214160140.GA401@tigerII.localdomain (mailing list archive) |
|---|---|
| State | Not Applicable, archived |
| Headers | show |
On Wed, Feb 15, 2017 at 01:01:40AM +0900, Sergey Senozhatsky wrote: > > but I'm a bit confused by rt_b->rt_runtime_lock in this unsafe lock > scenario (so it's not ABBA, but ABAD) > > > lock(hrtimer_bases.lock); > > lock(&rt_b->rt_runtime_lock); > > lock(hrtimer_bases.lock); > > lock(tk_core); > > > > > > Chain exists of: > > > > tk_core --> &rt_b->rt_runtime_lock --> hrtimer_bases.lock > > > I'm lacking some knowledge here, sorry. where does the tk_core --> &rt_b->rt_runtime_lock > come from? rt_b->rt_runtime_lock is one of the scheduler locks, since we do printk() under tk_core, which does semaphore muck, which then includes the entire scheduler chain of locks. -- To unsubscribe from this list: send the line "unsubscribe linux-pm" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
* Sergey Senozhatsky <sergey.senozhatsky@gmail.com> [170214 08:03]: > Hello, > > Cc Rafael, just in case > > On (02/13/17 10:59), Tony Lindgren wrote: > > Looks like commit f975237b7682 ("printk: use printk_safe buffers in > > printk") causes "possible circular locking dependency detected " for > > me on the first suspend. > > thanks for the report. > > > Reverting the following four patches in next makes it go away: > > > > d9c23523ed98 ("printk: drop call_console_drivers() unused param") > > de6fcbdb68b2 ("printk: convert the rest to printk-safe") > > 8b1742c9c207 ("printk: remove zap_locks() function") > > f975237b7682 ("printk: use printk_safe buffers in printk") > > > these patches basically just enable locked where it previously was > forcibly turned off. no timekeeping/pm/sched/etc code was modified. > can you share the link where Peter pointed out that this might be > caused by printk() changes? Oh sorry I should have been more specific. Not much there to share, I got redirected over to Peter's department in a private email thread while chasing this issue. So that was just Peter's comment looking at the log output. > timekeeping_resume() > lock timekeeper_lock > lock tk_core > tk_debug_account_sleep_time() > printk() << lockdep was disabled here before > try_to_wake_up() > lock_hrtimer_base() ##hrtimer_bases.lock Yeah above seems describe what changed, so your patch makes sense. > shouldn't tk_debug_account_sleep_time() do printk_deferred() instead of > 'normal' printk()? > printk() calls from under timekeeping seqlock are not safe, aren't they? > and tk_debug_account_sleep_time() is under tk_core seq lock. > > IOW, replace pr_info() in tk_debug_account_sleep_time() with something > like this > > printk_deferred(KERN_INFO "Suspended for %lld.%03lu seconds\n", > (s64)t->tv_sec, t->tv_nsec / NSEC_PER_MSEC); Your patch below fixes the issue for me thanks. I had to apply it manually though as tabs got replaced by spaces probably by some mail daemons. Regards, Tony > --- > > diff --git a/kernel/time/timekeeping_debug.c b/kernel/time/timekeeping_debug.c > index ca9fb800336b..b8f7146c3538 100644 > --- a/kernel/time/timekeeping_debug.c > +++ b/kernel/time/timekeeping_debug.c > @@ -75,7 +75,8 @@ void tk_debug_account_sleep_time(struct timespec64 *t) > int bin = min(fls(t->tv_sec), NUM_BINS-1); > > sleep_time_bin[bin]++; > - pr_info("Suspended for %lld.%03lu seconds\n", (s64)t->tv_sec, > + printk_deferred(KERN_INFO "Suspended for %lld.%03lu seconds\n", > + (s64)t->tv_sec, > t->tv_nsec / NSEC_PER_MSEC); > } > > -- To unsubscribe from this list: send the line "unsubscribe linux-pm" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Hi, * Sergey Senozhatsky <sergey.senozhatsky@gmail.com> [170214 08:03]: > Hello, > > Cc Rafael, just in case Found another issue on booting ARM devices, so adding Russell too. > On (02/13/17 10:59), Tony Lindgren wrote: > > Looks like commit f975237b7682 ("printk: use printk_safe buffers in > > printk") causes "possible circular locking dependency detected " for > > me on the first suspend. > > thanks for the report. > > > Reverting the following four patches in next makes it go away: > > > > d9c23523ed98 ("printk: drop call_console_drivers() unused param") > > de6fcbdb68b2 ("printk: convert the rest to printk-safe") > > 8b1742c9c207 ("printk: remove zap_locks() function") > > f975237b7682 ("printk: use printk_safe buffers in printk") > > > these patches basically just enable locked where it previously was > forcibly turned off. no timekeeping/pm/sched/etc code was modified. Below is another issue I noticed caused by commit f975237b7682 that I noticed during booting. Regards, Tony 8< -------------------------- [ 2.581939] hw-breakpoint: Failed to enable monitor mode on CPU 0. [ 2.591613] hw-breakpoint: CPU 0 failed to disable vector catch [ 2.597686] [ 2.597717] =============================== [ 2.597717] [ ERR: suspicious RCU usage. ] [ 2.597717] 4.10.0-rc8-next-20170215+ #119 Not tainted [ 2.597717] ------------------------------- [ 2.597717] ./include/trace/events/printk.h:32 suspicious rcu_dereference_check() usage! [ 2.597717] [ 2.597717] other info that might help us debug this: [ 2.597717] [ 2.597717] [ 2.597717] RCU used illegally from idle CPU! [ 2.597717] rcu_scheduler_active = 2, debug_locks = 0 [ 2.597747] RCU used illegally from extended quiescent state! [ 2.597747] 2 locks held by swapper/0/0: [ 2.597747] #0: (cpu_pm_notifier_lock){......}, at: [<c0237e2c>] cpu_pm_exit+0x10/0x54 [ 2.597747] #1: (console_lock){+.+.+.}, at: [<c01ab350>] vprintk_emit+0x264/0x474 [ 2.597747] [ 2.597747] stack backtrace: [ 2.597778] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.10.0-rc8-next-20170215+ #119 [ 2.597778] Hardware name: Generic OMAP4 (Flattened Device Tree) [ 2.597778] [<c0110228>] (unwind_backtrace) from [<c010c224>] (show_stack+0x10/0x14) [ 2.597778] [<c010c224>] (show_stack) from [<c04ca8a0>] (dump_stack+0xac/0xe0) [ 2.597778] [<c04ca8a0>] (dump_stack) from [<c01ab084>] (console_unlock+0x5e8/0x650) [ 2.597778] [<c01ab084>] (console_unlock) from [<c01ab35c>] (vprintk_emit+0x270/0x474) [ 2.597778] [<c01ab35c>] (vprintk_emit) from [<c01ab6f0>] (vprintk_default+0x20/0x28) [ 2.597808] [<c01ab6f0>] (vprintk_default) from [<c0250c94>] (printk+0x20/0x30) [ 2.597808] [<c0250c94>] (printk) from [<c0111004>] (reset_ctrl_regs+0x108/0x288) [ 2.597808] [<c0111004>] (reset_ctrl_regs) from [<c0111220>] (dbg_cpu_pm_notify+0x28/0x30) [ 2.597808] [<c0111220>] (dbg_cpu_pm_notify) from [<c015f3ac>] (notifier_call_chain+0x44/0x80) [ 2.597808] [<c015f3ac>] (notifier_call_chain) from [<c0237e48>] (cpu_pm_exit+0x2c/0x54) [ 2.597808] [<c0237e48>] (cpu_pm_exit) from [<c0126ca0>] (omap_enter_idle_coupled+0x80/0x208) [ 2.597808] [<c0126ca0>] (omap_enter_idle_coupled) from [<c0680d80>] (cpuidle_enter_state+0x118/0x4ac) [ 2.597808] [<c0680d80>] (cpuidle_enter_state) from [<c0682e54>] (cpuidle_enter_state_coupled+0x3a8/0x40c) [ 2.597839] [<c0682e54>] (cpuidle_enter_state_coupled) from [<c0190c04>] (do_idle+0x1a4/0x218) [ 2.597839] [<c0190c04>] (do_idle) from [<c0190ffc>] (cpu_startup_entry+0x18/0x1c) [ 2.597839] [<c0190ffc>] (cpu_startup_entry) from [<c0c00c40>] (start_kernel+0x35c/0x3d4) [ 2.597839] [<c0c00c40>] (start_kernel) from [<8000807c>] (0x8000807c)
diff --git a/kernel/time/timekeeping_debug.c b/kernel/time/timekeeping_debug.c index ca9fb800336b..b8f7146c3538 100644 --- a/kernel/time/timekeeping_debug.c +++ b/kernel/time/timekeeping_debug.c @@ -75,7 +75,8 @@ void tk_debug_account_sleep_time(struct timespec64 *t) int bin = min(fls(t->tv_sec), NUM_BINS-1); sleep_time_bin[bin]++; - pr_info("Suspended for %lld.%03lu seconds\n", (s64)t->tv_sec, + printk_deferred(KERN_INFO "Suspended for %lld.%03lu seconds\n", + (s64)t->tv_sec, t->tv_nsec / NSEC_PER_MSEC); }