| Message ID | 20160713054507.GA563@swordfish (mailing list archive) |
|---|---|
| State | Not Applicable, archived |
| Headers | show |
On 13-07-16, 14:45, Sergey Senozhatsky wrote: > On (07/12/16 16:19), Viresh Kumar wrote: > [..] > > Okay, we have tracked this BUG and its really interesting. > > good find! > > > I hacked the platform's serial driver to implement a putchar() routine > > that simply writes to the FIFO in polling mode, that helped us in > > tracing on where we are going wrong. > > > > The problem is that we are running asynchronous printks and we call > > wake_up_process() from the last running CPU which has disabled > > interrupts. That takes us to: try_to_wake_up(). > > > > In our case the CPU gets deadlocked on this line in try_to_wake_up(). > > > > raw_spin_lock_irqsave(&p->pi_lock, flags); > > yeah, printk() can't handle these types of recursion. it can prevent > printk() calls issued from within the logbuf_lock spinlock section, > with some limitations: > > if (unlikely(logbuf_cpu == smp_processor_id())) { > recursion_bug = true; > return; > } > > raw_spin_lock(&logbuf_lock); > logbuf_cpu = this_cpu; > ... > logbuf_cpu = UINT_MAX; > raw_spin_unlock(&logbuf_lock); > > so should, for instance, raw_spin_unlock() generate spin_dump(), printk() > will blow up (both sync and async), because logbuf_cpu is already reset. I see. > it may look that async printk added another source of recursion - wake_up(). > but, apparently, this is not exactly correct. because there is already a > wake_up() call in console_unlock() - up(). > > printk() > if (logbuf_cpu == smp_processor_id()) > return; > > raw_spin_lock(&logbuf_lock); > logbuf_cpu = this_cpu; > ... > logbuf_cpu = UINT_MAX; > raw_spin_unlock(&logbuf_lock); > > console_trylock() > raw_spin_lock_irqsave(&sem->lock) << *** > raw_spin_unlock_irqsave(&sem->lock) << *** > > console_unlock() > up() > raw_spin_lock_irqsave(&sem->lock) << *** > __up() > wake_up_process() > try_to_wake_up() << *** in may places > > > *** a printk() call from here will kill the system. either it will > recurse printk(), or spin forever in 'nested' printk() on one of > the already taken spin locks. So, in case you are asked for similar issues (system hang), we should first doubt on recursive prints from somewhere :) :) > I had an idea of waking up a printk_kthread under logbuf_lock, > so `logbuf_cpu == smp_processor_id()' test would help here. But > it turned out to introduce a regression in printk() behaviour. > apart from that, it didn't fix any of the existing recursion > printks. > > there is printk_deferred() printk that is supposed to be used for > printing under scheduler locks, but it won't help in all of the cases. > > printk() has many issues. Yeah, that's why we are all here :) > right. adding only (num_online_cpus() > 1) check to can_printk_async() > *in theory* can break some cases. for example, SMP system, with only > one online CPU, active rt_sched throttling (not necessarily because of > printk kthread, any other task will do), and some of interrupts services > by CPU0 keep calling printk(), so deferred printk IRQ will stay busy: Right. > echo 0 > /sys/..../cpu{1..NR_CPUS}/online # only CPU0 is active > > CPU0 > sched() > printk_deferred() > IRQ > wake_up_klogd_work_func() > console_trylock() > console_unlock() > > IRQ > printk() > > IRQ > printk() > .... > IRQ > printk() > ... > > console_sem_up() > return > > with async printk here we can offload printing from IRQ. > > the warning that you see is WARN_ON(timekeeping_suspended), so we have > timekeeping_suspended Right. > checking for irqs_disabled() is a _bit_ non-intuitive, > I think, but in the existing scheme of things can work (at least tick_suspend() > comment suggests so). correct me if I'm wrong. > > > so... I think we can switch to sync printk mode in suspend_console() and > enable async printk from resume_console(). IOW, suspend/kexec are now > executed under sync printk mode. > > we already call console_unlock() during suspend, which is synchronous, > many times (e.g. console_cpu_notify()). > > > something like below, perhaps. will this work for you? Maybe not, as this can still lead to the original bug we were all chasing. This may hog some other CPU if we are doing excessive printing in suspend :( suspend_console() is called quite early, so for example in my case we do lots of printing during suspend (not from the suspend thread, but an IRQ handled by the USB subsystem, which removes a bus with help of some other thread probably). That is why my Hacky patch tried to do it after devices are removed and irqs are disabled, but before syscore users are suspended (and timekeeping is one of them). And so it fixes it for me completely. IOW, we should switch back to synchronous printing after disabling interrupts on the last running CPU. And I of course agree with Rafael that we would need something similar in Hibernation code path as well, if we choose to fix it my way.
On Wed, Jul 13, 2016 at 5:39 PM, Viresh Kumar <viresh.kumar@linaro.org> wrote: > On 13-07-16, 14:45, Sergey Senozhatsky wrote: >> On (07/12/16 16:19), Viresh Kumar wrote: [cut] >> >> something like below, perhaps. will this work for you? > > Maybe not, as this can still lead to the original bug we were all > chasing. This may hog some other CPU if we are doing excessive > printing in suspend :( How can it hog that CPU, exactly? > suspend_console() is called quite early, so for example in my case we > do lots of printing during suspend (not from the suspend thread, but > an IRQ handled by the USB subsystem, which removes a bus with help of > some other thread probably). Why doing a lot of printing from an IRQ is not regarded as a bug? Are all of those messages printed actually useful? > That is why my Hacky patch tried to do it after devices are removed > and irqs are disabled, but before syscore users are suspended (and > timekeeping is one of them). And so it fixes it for me completely. > > IOW, we should switch back to synchronous printing after disabling > interrupts on the last running CPU. > > And I of course agree with Rafael that we would need something similar > in Hibernation code path as well, if we choose to fix it my way. Well, the patch proposed by Sergey is sufficient to fix the deadlock issue and it is not clear that anything more needs to be done. My suggestion, then, would be to use this patch to start with and see if things really go worse then. Thanks, Rafael -- 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
On 14-07-16, 01:08, Rafael J. Wysocki wrote: > On Wed, Jul 13, 2016 at 5:39 PM, Viresh Kumar <viresh.kumar@linaro.org> wrote: > > Maybe not, as this can still lead to the original bug we were all > > chasing. This may hog some other CPU if we are doing excessive > > printing in suspend :( > > How can it hog that CPU, exactly? Not *that* CPU, but any of the CPUs. Because we are moving back to synchronous printing, any CPU which is doing a lot of printing, may end up spending all its time in the print-loop (as the original problem we had). > > suspend_console() is called quite early, so for example in my case we > > do lots of printing during suspend (not from the suspend thread, but > > an IRQ handled by the USB subsystem, which removes a bus with help of > > some other thread probably). > > Why doing a lot of printing from an IRQ is not regarded as a bug? We aren't doing it in Interrupt Context or with interrupts disabled, but perhaps in the kthread managed by usb hub core. But, I am not only talking about my platform's printing issues, but the idea behind the patches that Sergey and Jan are working on. If we move back to synchronous printing before starting to suspend the devices, we may have the same problem again that we were trying to solve. > Are all of those messages printed actually useful? Hmm, maybe not. But that's not the point I was trying to raise, as I earlier mentioned :) We have a problem with asynchronous printing after disabling interrupts on the last running CPU, and we are trying to disable that from suspend_console(), because we already have a function to call this from. > > That is why my Hacky patch tried to do it after devices are removed > > and irqs are disabled, but before syscore users are suspended (and > > timekeeping is one of them). And so it fixes it for me completely. > > > > IOW, we should switch back to synchronous printing after disabling > > interrupts on the last running CPU. > > > > And I of course agree with Rafael that we would need something similar > > in Hibernation code path as well, if we choose to fix it my way. > > Well, the patch proposed by Sergey is sufficient to fix the deadlock > issue and it is not clear that anything more needs to be done. > > My suggestion, then, would be to use this patch to start with and see > if things really go worse then. Sure, I am just saying that theoretically, we can still have the CPU hog problem that we all started with :)
On Wed, Jul 13, 2016 at 04:18:58PM -0700, Viresh Kumar wrote: > > Are all of those messages printed actually useful? > > Hmm, maybe not. But that's not the point I was trying to raise, as I > earlier mentioned :) > > We have a problem with asynchronous printing after disabling > interrupts on the last running CPU, and we are trying to disable that > from suspend_console(), because we already have a function to call > this from. Note, this problem has also been seen in "the wild" in a number of 3.10-based systems where a printk message happens right when suspend is happening. If we are unlucky, it hits, causing a watchdog to trigger and the system is reset. My personal phone happens to be one of those "unlucky" ones and is reset every other day or so due to this bug :( So yes, lots of printk() messages will cause this to be hit more often, like in the system that Viresh is working on here. But it will also trigger on "normal" systems as well, just much more infrequently. thanks, greg k-h -- 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
Hello, On (07/13/16 08:39), Viresh Kumar wrote: [..] > Maybe not, as this can still lead to the original bug we were all > chasing. This may hog some other CPU if we are doing excessive > printing in suspend :( excessive printing is just part of the problem here. if we cab cond_resched() in console_unlock() (IOW, we execute console_unlock() with preemption and interrupts enabled) then everything must be ok, and *from printing POV* there is no difference whether it's printk_kthread or anything else in this case. the difference jumps in when original console_unlock() is executed with preemption/irq disabled, then offloading it to schedulable printk_kthread is the right thing. > suspend_console() is called quite early, so for example in my case we > do lots of printing during suspend (not from the suspend thread, but > an IRQ handled by the USB subsystem, which removes a bus with help of > some other thread probably). a silly question -- can we suspend consoles later? part of suspend/hibernation is cpu_down(), which lands in console_cpu_notify(), that does synchronous printing for every CPU taken down: static int console_cpu_notify(struct notifier_block *self, unsigned long action, void *hcpu) { switch (action) { case CPU_ONLINE: case CPU_DEAD: case CPU_DOWN_FAILED: case CPU_UP_CANCELED: console_lock(); console_unlock(); ^^^^^^^^^^^^^^ } return NOTIFY_OK; } console_unlock() is synchronous (I posted a very early draft patch that makes it asynchronous, but that's a future work). so if there is a ton of printk()-s, then console_unlock() will print it, 100% guaranteed. even if printk_kthread is doing the printing job at the moment, cpu down path will wait for it to stop, lock the console semaphore, and got to console_unlock() printing loop. in printk that you have posted, that will happen not only for CPU_DEAD, but for CPU_DYING as well (possibly, there is a /* invoked with preemption disabled, so defer */ comment, so may be you never endup doing direct printk there, but then you schedule a console_unlock() work). > That is why my Hacky patch tried to do it after devices are removed > and irqs are disabled, but before syscore users are suspended (and > timekeeping is one of them). And so it fixes it for me completely. > > IOW, we should switch back to synchronous printing after disabling > interrupts on the last running CPU. > > And I of course agree with Rafael that we would need something similar > in Hibernation code path as well, if we choose to fix it my way. suspend/hibernation/kexec - all covered by this patch. -ss -- 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
On Thu, Jul 14, 2016 at 2:55 AM, Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote: > Hello, > > On (07/13/16 08:39), Viresh Kumar wrote: > [..] >> Maybe not, as this can still lead to the original bug we were all >> chasing. This may hog some other CPU if we are doing excessive >> printing in suspend :( > > excessive printing is just part of the problem here. if we cab cond_resched() > in console_unlock() (IOW, we execute console_unlock() with preemption and > interrupts enabled) then everything must be ok, and *from printing POV* there > is no difference whether it's printk_kthread or anything else in this case. > the difference jumps in when original console_unlock() is executed with > preemption/irq disabled, then offloading it to schedulable printk_kthread is > the right thing. > >> suspend_console() is called quite early, so for example in my case we >> do lots of printing during suspend (not from the suspend thread, but >> an IRQ handled by the USB subsystem, which removes a bus with help of >> some other thread probably). > > a silly question -- can we suspend consoles later? Not really and I'm not sure how that would help? -- 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
On (07/14/16 03:09), Rafael J. Wysocki wrote: > On Thu, Jul 14, 2016 at 2:55 AM, Sergey Senozhatsky > <sergey.senozhatsky.work@gmail.com> wrote: > > Hello, > > > > On (07/13/16 08:39), Viresh Kumar wrote: > > [..] > >> Maybe not, as this can still lead to the original bug we were all > >> chasing. This may hog some other CPU if we are doing excessive > >> printing in suspend :( > > > > excessive printing is just part of the problem here. if we cab cond_resched() > > in console_unlock() (IOW, we execute console_unlock() with preemption and > > interrupts enabled) then everything must be ok, and *from printing POV* there > > is no difference whether it's printk_kthread or anything else in this case. > > the difference jumps in when original console_unlock() is executed with > > preemption/irq disabled, then offloading it to schedulable printk_kthread is > > the right thing. > > > >> suspend_console() is called quite early, so for example in my case we > >> do lots of printing during suspend (not from the suspend thread, but > >> an IRQ handled by the USB subsystem, which removes a bus with help of > >> some other thread probably). > > > > a silly question -- can we suspend consoles later? > > Not really and I'm not sure how that would help? it wouldn't really, this silly question was not directly related to the deadlock we are discussing here but to Viresh's argument that later stages of suspending/hibernation seem to printk many messages in sync mode. so I thought that there might be a small benefit in suspending consoles later, as far as I understand, Viresh has `no_console_suspend' anyway. other than that, I tend to stick to the approach of switching to sync mode from suspend_console(). thanks for your late night reply! -ss -- 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
On Wed 13-07-16 14:45:07, Sergey Senozhatsky wrote: > Cc Petr Mladek. > > On (07/12/16 16:19), Viresh Kumar wrote: > [..] > > Okay, we have tracked this BUG and its really interesting. > > good find! > > > I hacked the platform's serial driver to implement a putchar() routine > > that simply writes to the FIFO in polling mode, that helped us in > > tracing on where we are going wrong. > > > > The problem is that we are running asynchronous printks and we call > > wake_up_process() from the last running CPU which has disabled > > interrupts. That takes us to: try_to_wake_up(). > > > > In our case the CPU gets deadlocked on this line in try_to_wake_up(). > > > > raw_spin_lock_irqsave(&p->pi_lock, flags); > > yeah, printk() can't handle these types of recursion. it can prevent > printk() calls issued from within the logbuf_lock spinlock section, > with some limitations: > > if (unlikely(logbuf_cpu == smp_processor_id())) { > recursion_bug = true; > return; > } > > raw_spin_lock(&logbuf_lock); > logbuf_cpu = this_cpu; > ... > logbuf_cpu = UINT_MAX; > raw_spin_unlock(&logbuf_lock); > > so should, for instance, raw_spin_unlock() generate spin_dump(), printk() > will blow up (both sync and async), because logbuf_cpu is already reset. > it may look that async printk added another source of recursion - wake_up(). > but, apparently, this is not exactly correct. because there is already a > wake_up() call in console_unlock() - up(). > > printk() > if (logbuf_cpu == smp_processor_id()) > return; > > raw_spin_lock(&logbuf_lock); > logbuf_cpu = this_cpu; > ... > logbuf_cpu = UINT_MAX; > raw_spin_unlock(&logbuf_lock); > > console_trylock() > raw_spin_lock_irqsave(&sem->lock) << *** > raw_spin_unlock_irqsave(&sem->lock) << *** > > console_unlock() > up() > raw_spin_lock_irqsave(&sem->lock) << *** > __up() > wake_up_process() > try_to_wake_up() << *** in may places > > > *** a printk() call from here will kill the system. either it will > recurse printk(), or spin forever in 'nested' printk() on one of > the already taken spin locks. Exactly. Calling printk() from certain parts of the kernel (like scheduler code or timer code) has been always unsafe because printk itself uses these parts and so it can lead to deadlocks. That's why printk_deffered() has been introduced as you mention below. And with sync printk the above deadlock doesn't trigger only by chance - if there happened to be a waiter on console_sem while we suspend, the same deadlock would trigger because up(&console_sem) will try to wake him up and the warning in timekeeping code will cause recursive printk. So I think your patch doesn't really address the real issue - it only works around the particular WARN_ON(timekeeping_enabled) warning but if there was a different warning in timekeeping code which would trigger, it has a potential for causing recursive printk deadlock (and indeed we had such issues previously - see e.g. 504d58745c9c "timer: Fix lock inversion between hrtimer_bases.lock and scheduler locks"). So there are IMHO two issues here worth looking at: 1) I didn't find how a wakeup would would lead to calling to ktime_get() in the current upstream kernel or even current RT kernel. Maybe this is a problem specific to the 3.10 kernel you are using? If yes, we don't have to do anything for current upstream AFAIU. If I just missed how wakeup can call into ktime_get() in current upstream, there is another question: 2) Is it OK that printk calls wakeup so late during suspend? I believe it is but I'm neither scheduler nor suspend expert. If it is OK, and wakeup can lead to ktime_get() in current upstream, then this contradicts the check WARN_ON(timekeeping_suspended) in ktime_get() and something is wrong. Adding Thomas to CC as timer / RT expert... Honza > so... I think we can switch to sync printk mode in suspend_console() and > enable async printk from resume_console(). IOW, suspend/kexec are now > executed under sync printk mode. > > we already call console_unlock() during suspend, which is synchronous, > many times (e.g. console_cpu_notify()). > > > something like below, perhaps. will this work for you? > > --- > kernel/printk/printk.c | 12 +++++++++++- > 1 file changed, 11 insertions(+), 1 deletion(-) > > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c > index bbb4180..786690e 100644 > --- a/kernel/printk/printk.c > +++ b/kernel/printk/printk.c > @@ -288,6 +288,11 @@ static u32 log_buf_len = __LOG_BUF_LEN; > > /* Control whether printing to console must be synchronous. */ > static bool __read_mostly printk_sync = true; > +/* > + * Force sync printk mode during suspend/kexec, regardless whether > + * console_suspend_enabled permits console suspend. > + */ > +static bool __read_mostly force_printk_sync; > /* Printing kthread for async printk */ > static struct task_struct *printk_kthread; > /* When `true' printing thread has messages to print */ > @@ -295,7 +300,7 @@ static bool printk_kthread_need_flush_console; > > static inline bool can_printk_async(void) > { > - return !printk_sync && printk_kthread; > + return !printk_sync && printk_kthread && !force_printk_sync; > } > > /* Return log buffer address */ > @@ -2027,6 +2032,7 @@ static bool suppress_message_printing(int level) { return false; } > > /* Still needs to be defined for users */ > DEFINE_PER_CPU(printk_func_t, printk_func); > +static bool __read_mostly force_printk_sync; > > #endif /* CONFIG_PRINTK */ > > @@ -2163,6 +2169,8 @@ MODULE_PARM_DESC(console_suspend, "suspend console during suspend" > */ > void suspend_console(void) > { > + force_printk_sync = true; > + > if (!console_suspend_enabled) > return; > printk("Suspending console(s) (use no_console_suspend to debug)\n"); > @@ -2173,6 +2181,8 @@ void suspend_console(void) > > void resume_console(void) > { > + force_printk_sync = false; > + > if (!console_suspend_enabled) > return; > down_console_sem(); > -- > 2.9.0.rc1 >
On Thursday, July 14, 2016 04:12:16 PM Jan Kara wrote: > On Wed 13-07-16 14:45:07, Sergey Senozhatsky wrote: > > Cc Petr Mladek. > > > > On (07/12/16 16:19), Viresh Kumar wrote: > > [..] > > > Okay, we have tracked this BUG and its really interesting. > > > > good find! > > > > > I hacked the platform's serial driver to implement a putchar() routine > > > that simply writes to the FIFO in polling mode, that helped us in > > > tracing on where we are going wrong. > > > > > > The problem is that we are running asynchronous printks and we call > > > wake_up_process() from the last running CPU which has disabled > > > interrupts. That takes us to: try_to_wake_up(). > > > > > > In our case the CPU gets deadlocked on this line in try_to_wake_up(). > > > > > > raw_spin_lock_irqsave(&p->pi_lock, flags); > > > > yeah, printk() can't handle these types of recursion. it can prevent > > printk() calls issued from within the logbuf_lock spinlock section, > > with some limitations: > > > > if (unlikely(logbuf_cpu == smp_processor_id())) { > > recursion_bug = true; > > return; > > } > > > > raw_spin_lock(&logbuf_lock); > > logbuf_cpu = this_cpu; > > ... > > logbuf_cpu = UINT_MAX; > > raw_spin_unlock(&logbuf_lock); > > > > so should, for instance, raw_spin_unlock() generate spin_dump(), printk() > > will blow up (both sync and async), because logbuf_cpu is already reset. > > it may look that async printk added another source of recursion - wake_up(). > > but, apparently, this is not exactly correct. because there is already a > > wake_up() call in console_unlock() - up(). > > > > printk() > > if (logbuf_cpu == smp_processor_id()) > > return; > > > > raw_spin_lock(&logbuf_lock); > > logbuf_cpu = this_cpu; > > ... > > logbuf_cpu = UINT_MAX; > > raw_spin_unlock(&logbuf_lock); > > > > console_trylock() > > raw_spin_lock_irqsave(&sem->lock) << *** > > raw_spin_unlock_irqsave(&sem->lock) << *** > > > > console_unlock() > > up() > > raw_spin_lock_irqsave(&sem->lock) << *** > > __up() > > wake_up_process() > > try_to_wake_up() << *** in may places > > > > > > *** a printk() call from here will kill the system. either it will > > recurse printk(), or spin forever in 'nested' printk() on one of > > the already taken spin locks. > > Exactly. Calling printk() from certain parts of the kernel (like scheduler > code or timer code) has been always unsafe because printk itself uses these > parts and so it can lead to deadlocks. That's why printk_deffered() has > been introduced as you mention below. > > And with sync printk the above deadlock doesn't trigger only by chance - if > there happened to be a waiter on console_sem while we suspend, the same > deadlock would trigger because up(&console_sem) will try to wake him up and > the warning in timekeeping code will cause recursive printk. > > So I think your patch doesn't really address the real issue - it only > works around the particular WARN_ON(timekeeping_enabled) warning but if > there was a different warning in timekeeping code which would trigger, it > has a potential for causing recursive printk deadlock (and indeed we had > such issues previously - see e.g. 504d58745c9c "timer: Fix lock inversion > between hrtimer_bases.lock and scheduler locks"). > > So there are IMHO two issues here worth looking at: > > 1) I didn't find how a wakeup would would lead to calling to ktime_get() in > the current upstream kernel or even current RT kernel. Maybe this is a > problem specific to the 3.10 kernel you are using? If yes, we don't have to > do anything for current upstream AFAIU. > > If I just missed how wakeup can call into ktime_get() in current upstream, > there is another question: > > 2) Is it OK that printk calls wakeup so late during suspend? I believe it > is but I'm neither scheduler nor suspend expert. I don't think it really is OK. Nothing will wake up for sure at this point, so why to do that in the first place? > If it is OK, and wakeup can lead to ktime_get() in current upstream, then > this contradicts the check WARN_ON(timekeeping_suspended) in ktime_get() and > something is wrong. Thanks, Rafael -- 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
Hello Jan, On (07/14/16 16:12), Jan Kara wrote: [..] > > *** a printk() call from here will kill the system. either it will > > recurse printk(), or spin forever in 'nested' printk() on one of > > the already taken spin locks. [..] > And with sync printk the above deadlock doesn't trigger only by chance - if > there happened to be a waiter on console_sem while we suspend, the same > deadlock would trigger because up(&console_sem) will try to wake him up and > the warning in timekeeping code will cause recursive printk. > > So I think your patch doesn't really address the real issue - it only > works around the particular WARN_ON(timekeeping_enabled) warning but if > there was a different warning in timekeeping code which would trigger, it > has a potential for causing recursive printk deadlock (and indeed we had > such issues previously - see e.g. 504d58745c9c "timer: Fix lock inversion > between hrtimer_bases.lock and scheduler locks"). we switch to sync printk in suspend_console(), that is happening long before we start bringing cpu downs suspend_devices_and_enter() suspend_console() ... suspend_enter() ... dpm_suspend_late ... disable_nonboot_cpus and cpu_down() in printk does static int console_cpu_notify(struct notifier_block *self, unsigned long action, void *hcpu) { switch (action) { case CPU_ONLINE: case CPU_DEAD: case CPU_DOWN_FAILED: case CPU_UP_CANCELED: console_lock(); console_unlock(); } return NOTIFY_OK; } so I think this console_lock() sort of guarantees that there should be no sleeping tasks in console semaphore wait list. or am I missing something? > So there are IMHO two issues here worth looking at: > > 1) I didn't find how a wakeup would would lead to calling to ktime_get() in > the current upstream kernel or even current RT kernel. Maybe this is a > problem specific to the 3.10 kernel you are using? If yes, we don't have to > do anything for current upstream AFAIU. I personally suspect it's an in-hose (custom) code. -ss > If I just missed how wakeup can call into ktime_get() in current upstream, > there is another question: > > 2) Is it OK that printk calls wakeup so late during suspend? I believe it > is but I'm neither scheduler nor suspend expert. If it is OK, and wakeup > can lead to ktime_get() in current upstream, then this contradicts the > check WARN_ON(timekeeping_suspended) in ktime_get() and something is wrong. > > Adding Thomas to CC as timer / RT expert... > > Honza > > > so... I think we can switch to sync printk mode in suspend_console() and > > enable async printk from resume_console(). IOW, suspend/kexec are now > > executed under sync printk mode. > > > > we already call console_unlock() during suspend, which is synchronous, > > many times (e.g. console_cpu_notify()). > > > > > > something like below, perhaps. will this work for you? > > > > --- > > kernel/printk/printk.c | 12 +++++++++++- > > 1 file changed, 11 insertions(+), 1 deletion(-) > > > > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c > > index bbb4180..786690e 100644 > > --- a/kernel/printk/printk.c > > +++ b/kernel/printk/printk.c > > @@ -288,6 +288,11 @@ static u32 log_buf_len = __LOG_BUF_LEN; > > > > /* Control whether printing to console must be synchronous. */ > > static bool __read_mostly printk_sync = true; > > +/* > > + * Force sync printk mode during suspend/kexec, regardless whether > > + * console_suspend_enabled permits console suspend. > > + */ > > +static bool __read_mostly force_printk_sync; > > /* Printing kthread for async printk */ > > static struct task_struct *printk_kthread; > > /* When `true' printing thread has messages to print */ > > @@ -295,7 +300,7 @@ static bool printk_kthread_need_flush_console; > > > > static inline bool can_printk_async(void) > > { > > - return !printk_sync && printk_kthread; > > + return !printk_sync && printk_kthread && !force_printk_sync; > > } > > > > /* Return log buffer address */ > > @@ -2027,6 +2032,7 @@ static bool suppress_message_printing(int level) { return false; } > > > > /* Still needs to be defined for users */ > > DEFINE_PER_CPU(printk_func_t, printk_func); > > +static bool __read_mostly force_printk_sync; > > > > #endif /* CONFIG_PRINTK */ > > > > @@ -2163,6 +2169,8 @@ MODULE_PARM_DESC(console_suspend, "suspend console during suspend" > > */ > > void suspend_console(void) > > { > > + force_printk_sync = true; > > + > > if (!console_suspend_enabled) > > return; > > printk("Suspending console(s) (use no_console_suspend to debug)\n"); > > @@ -2173,6 +2181,8 @@ void suspend_console(void) > > > > void resume_console(void) > > { > > + force_printk_sync = false; > > + > > if (!console_suspend_enabled) > > return; > > down_console_sem(); > > -- > > 2.9.0.rc1 > > > -- > Jan Kara <jack@suse.com> > SUSE Labs, CR > -- 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
On Thu 14-07-16 16:33:38, Rafael J. Wysocki wrote: > On Thursday, July 14, 2016 04:12:16 PM Jan Kara wrote: > > On Wed 13-07-16 14:45:07, Sergey Senozhatsky wrote: > > > Cc Petr Mladek. > > > > > > On (07/12/16 16:19), Viresh Kumar wrote: > > > [..] > > > > Okay, we have tracked this BUG and its really interesting. > > > > > > good find! > > > > > > > I hacked the platform's serial driver to implement a putchar() routine > > > > that simply writes to the FIFO in polling mode, that helped us in > > > > tracing on where we are going wrong. > > > > > > > > The problem is that we are running asynchronous printks and we call > > > > wake_up_process() from the last running CPU which has disabled > > > > interrupts. That takes us to: try_to_wake_up(). > > > > > > > > In our case the CPU gets deadlocked on this line in try_to_wake_up(). > > > > > > > > raw_spin_lock_irqsave(&p->pi_lock, flags); > > > > > > yeah, printk() can't handle these types of recursion. it can prevent > > > printk() calls issued from within the logbuf_lock spinlock section, > > > with some limitations: > > > > > > if (unlikely(logbuf_cpu == smp_processor_id())) { > > > recursion_bug = true; > > > return; > > > } > > > > > > raw_spin_lock(&logbuf_lock); > > > logbuf_cpu = this_cpu; > > > ... > > > logbuf_cpu = UINT_MAX; > > > raw_spin_unlock(&logbuf_lock); > > > > > > so should, for instance, raw_spin_unlock() generate spin_dump(), printk() > > > will blow up (both sync and async), because logbuf_cpu is already reset. > > > it may look that async printk added another source of recursion - wake_up(). > > > but, apparently, this is not exactly correct. because there is already a > > > wake_up() call in console_unlock() - up(). > > > > > > printk() > > > if (logbuf_cpu == smp_processor_id()) > > > return; > > > > > > raw_spin_lock(&logbuf_lock); > > > logbuf_cpu = this_cpu; > > > ... > > > logbuf_cpu = UINT_MAX; > > > raw_spin_unlock(&logbuf_lock); > > > > > > console_trylock() > > > raw_spin_lock_irqsave(&sem->lock) << *** > > > raw_spin_unlock_irqsave(&sem->lock) << *** > > > > > > console_unlock() > > > up() > > > raw_spin_lock_irqsave(&sem->lock) << *** > > > __up() > > > wake_up_process() > > > try_to_wake_up() << *** in may places > > > > > > > > > *** a printk() call from here will kill the system. either it will > > > recurse printk(), or spin forever in 'nested' printk() on one of > > > the already taken spin locks. > > > > Exactly. Calling printk() from certain parts of the kernel (like scheduler > > code or timer code) has been always unsafe because printk itself uses these > > parts and so it can lead to deadlocks. That's why printk_deffered() has > > been introduced as you mention below. > > > > And with sync printk the above deadlock doesn't trigger only by chance - if > > there happened to be a waiter on console_sem while we suspend, the same > > deadlock would trigger because up(&console_sem) will try to wake him up and > > the warning in timekeeping code will cause recursive printk. > > > > So I think your patch doesn't really address the real issue - it only > > works around the particular WARN_ON(timekeeping_enabled) warning but if > > there was a different warning in timekeeping code which would trigger, it > > has a potential for causing recursive printk deadlock (and indeed we had > > such issues previously - see e.g. 504d58745c9c "timer: Fix lock inversion > > between hrtimer_bases.lock and scheduler locks"). > > > > So there are IMHO two issues here worth looking at: > > > > 1) I didn't find how a wakeup would would lead to calling to ktime_get() in > > the current upstream kernel or even current RT kernel. Maybe this is a > > problem specific to the 3.10 kernel you are using? If yes, we don't have to > > do anything for current upstream AFAIU. > > > > If I just missed how wakeup can call into ktime_get() in current upstream, > > there is another question: > > > > 2) Is it OK that printk calls wakeup so late during suspend? I believe it > > is but I'm neither scheduler nor suspend expert. > > I don't think it really is OK. Nothing will wake up for sure at this point, > so why to do that in the first place? So that the process is put into a runnable state (currently it is in uninterruptible sleep) and may run after the system resumes? Honza
On Thursday, July 14, 2016 04:39:39 PM Jan Kara wrote: > On Thu 14-07-16 16:33:38, Rafael J. Wysocki wrote: > > On Thursday, July 14, 2016 04:12:16 PM Jan Kara wrote: > > > On Wed 13-07-16 14:45:07, Sergey Senozhatsky wrote: > > > > Cc Petr Mladek. > > > > > > > > On (07/12/16 16:19), Viresh Kumar wrote: > > > > [..] > > > > > Okay, we have tracked this BUG and its really interesting. > > > > > > > > good find! > > > > > > > > > I hacked the platform's serial driver to implement a putchar() routine > > > > > that simply writes to the FIFO in polling mode, that helped us in > > > > > tracing on where we are going wrong. > > > > > > > > > > The problem is that we are running asynchronous printks and we call > > > > > wake_up_process() from the last running CPU which has disabled > > > > > interrupts. That takes us to: try_to_wake_up(). > > > > > > > > > > In our case the CPU gets deadlocked on this line in try_to_wake_up(). > > > > > > > > > > raw_spin_lock_irqsave(&p->pi_lock, flags); > > > > > > > > yeah, printk() can't handle these types of recursion. it can prevent > > > > printk() calls issued from within the logbuf_lock spinlock section, > > > > with some limitations: > > > > > > > > if (unlikely(logbuf_cpu == smp_processor_id())) { > > > > recursion_bug = true; > > > > return; > > > > } > > > > > > > > raw_spin_lock(&logbuf_lock); > > > > logbuf_cpu = this_cpu; > > > > ... > > > > logbuf_cpu = UINT_MAX; > > > > raw_spin_unlock(&logbuf_lock); > > > > > > > > so should, for instance, raw_spin_unlock() generate spin_dump(), printk() > > > > will blow up (both sync and async), because logbuf_cpu is already reset. > > > > it may look that async printk added another source of recursion - wake_up(). > > > > but, apparently, this is not exactly correct. because there is already a > > > > wake_up() call in console_unlock() - up(). > > > > > > > > printk() > > > > if (logbuf_cpu == smp_processor_id()) > > > > return; > > > > > > > > raw_spin_lock(&logbuf_lock); > > > > logbuf_cpu = this_cpu; > > > > ... > > > > logbuf_cpu = UINT_MAX; > > > > raw_spin_unlock(&logbuf_lock); > > > > > > > > console_trylock() > > > > raw_spin_lock_irqsave(&sem->lock) << *** > > > > raw_spin_unlock_irqsave(&sem->lock) << *** > > > > > > > > console_unlock() > > > > up() > > > > raw_spin_lock_irqsave(&sem->lock) << *** > > > > __up() > > > > wake_up_process() > > > > try_to_wake_up() << *** in may places > > > > > > > > > > > > *** a printk() call from here will kill the system. either it will > > > > recurse printk(), or spin forever in 'nested' printk() on one of > > > > the already taken spin locks. > > > > > > Exactly. Calling printk() from certain parts of the kernel (like scheduler > > > code or timer code) has been always unsafe because printk itself uses these > > > parts and so it can lead to deadlocks. That's why printk_deffered() has > > > been introduced as you mention below. > > > > > > And with sync printk the above deadlock doesn't trigger only by chance - if > > > there happened to be a waiter on console_sem while we suspend, the same > > > deadlock would trigger because up(&console_sem) will try to wake him up and > > > the warning in timekeeping code will cause recursive printk. > > > > > > So I think your patch doesn't really address the real issue - it only > > > works around the particular WARN_ON(timekeeping_enabled) warning but if > > > there was a different warning in timekeeping code which would trigger, it > > > has a potential for causing recursive printk deadlock (and indeed we had > > > such issues previously - see e.g. 504d58745c9c "timer: Fix lock inversion > > > between hrtimer_bases.lock and scheduler locks"). > > > > > > So there are IMHO two issues here worth looking at: > > > > > > 1) I didn't find how a wakeup would would lead to calling to ktime_get() in > > > the current upstream kernel or even current RT kernel. Maybe this is a > > > problem specific to the 3.10 kernel you are using? If yes, we don't have to > > > do anything for current upstream AFAIU. > > > > > > If I just missed how wakeup can call into ktime_get() in current upstream, > > > there is another question: > > > > > > 2) Is it OK that printk calls wakeup so late during suspend? I believe it > > > is but I'm neither scheduler nor suspend expert. > > > > I don't think it really is OK. Nothing will wake up for sure at this point, > > so why to do that in the first place? > > So that the process is put into a runnable state (currently it is in > uninterruptible sleep) and may run after the system resumes? Fair enough. But calling ktime_get() with suspended timekeeping is dumb at best which is why the warning is there. Thanks, Rafael -- 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
On Thu 14-07-16 16:47:11, Rafael J. Wysocki wrote: > On Thursday, July 14, 2016 04:39:39 PM Jan Kara wrote: > > On Thu 14-07-16 16:33:38, Rafael J. Wysocki wrote: > > > On Thursday, July 14, 2016 04:12:16 PM Jan Kara wrote: > > > > On Wed 13-07-16 14:45:07, Sergey Senozhatsky wrote: > > > > > Cc Petr Mladek. > > > > > > > > > > On (07/12/16 16:19), Viresh Kumar wrote: > > > > > [..] > > > > > > Okay, we have tracked this BUG and its really interesting. > > > > > > > > > > good find! > > > > > > > > > > > I hacked the platform's serial driver to implement a putchar() routine > > > > > > that simply writes to the FIFO in polling mode, that helped us in > > > > > > tracing on where we are going wrong. > > > > > > > > > > > > The problem is that we are running asynchronous printks and we call > > > > > > wake_up_process() from the last running CPU which has disabled > > > > > > interrupts. That takes us to: try_to_wake_up(). > > > > > > > > > > > > In our case the CPU gets deadlocked on this line in try_to_wake_up(). > > > > > > > > > > > > raw_spin_lock_irqsave(&p->pi_lock, flags); > > > > > > > > > > yeah, printk() can't handle these types of recursion. it can prevent > > > > > printk() calls issued from within the logbuf_lock spinlock section, > > > > > with some limitations: > > > > > > > > > > if (unlikely(logbuf_cpu == smp_processor_id())) { > > > > > recursion_bug = true; > > > > > return; > > > > > } > > > > > > > > > > raw_spin_lock(&logbuf_lock); > > > > > logbuf_cpu = this_cpu; > > > > > ... > > > > > logbuf_cpu = UINT_MAX; > > > > > raw_spin_unlock(&logbuf_lock); > > > > > > > > > > so should, for instance, raw_spin_unlock() generate spin_dump(), printk() > > > > > will blow up (both sync and async), because logbuf_cpu is already reset. > > > > > it may look that async printk added another source of recursion - wake_up(). > > > > > but, apparently, this is not exactly correct. because there is already a > > > > > wake_up() call in console_unlock() - up(). > > > > > > > > > > printk() > > > > > if (logbuf_cpu == smp_processor_id()) > > > > > return; > > > > > > > > > > raw_spin_lock(&logbuf_lock); > > > > > logbuf_cpu = this_cpu; > > > > > ... > > > > > logbuf_cpu = UINT_MAX; > > > > > raw_spin_unlock(&logbuf_lock); > > > > > > > > > > console_trylock() > > > > > raw_spin_lock_irqsave(&sem->lock) << *** > > > > > raw_spin_unlock_irqsave(&sem->lock) << *** > > > > > > > > > > console_unlock() > > > > > up() > > > > > raw_spin_lock_irqsave(&sem->lock) << *** > > > > > __up() > > > > > wake_up_process() > > > > > try_to_wake_up() << *** in may places > > > > > > > > > > > > > > > *** a printk() call from here will kill the system. either it will > > > > > recurse printk(), or spin forever in 'nested' printk() on one of > > > > > the already taken spin locks. > > > > > > > > Exactly. Calling printk() from certain parts of the kernel (like scheduler > > > > code or timer code) has been always unsafe because printk itself uses these > > > > parts and so it can lead to deadlocks. That's why printk_deffered() has > > > > been introduced as you mention below. > > > > > > > > And with sync printk the above deadlock doesn't trigger only by chance - if > > > > there happened to be a waiter on console_sem while we suspend, the same > > > > deadlock would trigger because up(&console_sem) will try to wake him up and > > > > the warning in timekeeping code will cause recursive printk. > > > > > > > > So I think your patch doesn't really address the real issue - it only > > > > works around the particular WARN_ON(timekeeping_enabled) warning but if > > > > there was a different warning in timekeeping code which would trigger, it > > > > has a potential for causing recursive printk deadlock (and indeed we had > > > > such issues previously - see e.g. 504d58745c9c "timer: Fix lock inversion > > > > between hrtimer_bases.lock and scheduler locks"). > > > > > > > > So there are IMHO two issues here worth looking at: > > > > > > > > 1) I didn't find how a wakeup would would lead to calling to ktime_get() in > > > > the current upstream kernel or even current RT kernel. Maybe this is a > > > > problem specific to the 3.10 kernel you are using? If yes, we don't have to > > > > do anything for current upstream AFAIU. > > > > > > > > If I just missed how wakeup can call into ktime_get() in current upstream, > > > > there is another question: > > > > > > > > 2) Is it OK that printk calls wakeup so late during suspend? I believe it > > > > is but I'm neither scheduler nor suspend expert. > > > > > > I don't think it really is OK. Nothing will wake up for sure at this point, > > > so why to do that in the first place? > > > > So that the process is put into a runnable state (currently it is in > > uninterruptible sleep) and may run after the system resumes? > > Fair enough. > > But calling ktime_get() with suspended timekeeping is dumb at best which > is why the warning is there. Agree on that - but that seems to be a problem of a particular wakeup implementation of the 3.10 kernel Viresh is using, not a problem of the upstream kernel. Honza
On Thu 14-07-16 23:34:50, Sergey Senozhatsky wrote: > Hello Jan, > > On (07/14/16 16:12), Jan Kara wrote: > [..] > > > *** a printk() call from here will kill the system. either it will > > > recurse printk(), or spin forever in 'nested' printk() on one of > > > the already taken spin locks. > [..] > > And with sync printk the above deadlock doesn't trigger only by chance - if > > there happened to be a waiter on console_sem while we suspend, the same > > deadlock would trigger because up(&console_sem) will try to wake him up and > > the warning in timekeeping code will cause recursive printk. > > > > So I think your patch doesn't really address the real issue - it only > > works around the particular WARN_ON(timekeeping_enabled) warning but if > > there was a different warning in timekeeping code which would trigger, it > > has a potential for causing recursive printk deadlock (and indeed we had > > such issues previously - see e.g. 504d58745c9c "timer: Fix lock inversion > > between hrtimer_bases.lock and scheduler locks"). > > we switch to sync printk in suspend_console(), that is happening > long before we start bringing cpu downs > > suspend_devices_and_enter() > suspend_console() > ... > suspend_enter() > ... > dpm_suspend_late > ... > disable_nonboot_cpus > > > > and cpu_down() in printk does > > static int console_cpu_notify(struct notifier_block *self, > unsigned long action, void *hcpu) > { > switch (action) { > case CPU_ONLINE: > case CPU_DEAD: > case CPU_DOWN_FAILED: > case CPU_UP_CANCELED: > console_lock(); > console_unlock(); > } > return NOTIFY_OK; > } > > so I think this console_lock() sort of guarantees that there should be > no sleeping tasks in console semaphore wait list. or am I missing something? No, probably you're right - unless there would be a CPU notifier executed after console_cpu_notify() which would try to acquire console_sem for some reason. But that is a wild speculation and I tend to agree that in synchronous printk case and current code the wakeup cannot happen. But my point really is that I don't see why changing process state (which is what wakeup actually is) should be problematic even this late during suspend... Honza
On 14-07-16, 09:55, Sergey Senozhatsky wrote: > excessive printing is just part of the problem here. if we cab cond_resched() > part of suspend/hibernation is cpu_down(), which lands in console_cpu_notify(), > that does synchronous printing for every CPU taken down: > > static int console_cpu_notify(struct notifier_block *self, > unsigned long action, void *hcpu) > { > switch (action) { > case CPU_ONLINE: > case CPU_DEAD: > case CPU_DOWN_FAILED: > case CPU_UP_CANCELED: > console_lock(); > console_unlock(); > ^^^^^^^^^^^^^^ > } > return NOTIFY_OK; > } > > console_unlock() is synchronous (I posted a very early draft patch that makes > it asynchronous, but that's a future work). so if there is a ton of printk()-s, > then console_unlock() will print it, 100% guaranteed. even if printk_kthread > is doing the printing job at the moment, cpu down path will wait for it to > stop, lock the console semaphore, and got to console_unlock() printing loop. Hmm... > in printk that you have posted, that will happen not only for CPU_DEAD, It doesn't happen for CPU_DEAD right now as CONFIG_CONSOLE_FLUSH_ON_HOTPLUG isn't enabled in my setup. > but for CPU_DYING as well (possibly, there is a /* invoked with preemption > disabled, so defer */ comment, so may be you never endup doing direct > printk there, but then you schedule a console_unlock() work).
On 14-07-16, 10:32, Sergey Senozhatsky wrote: > it wouldn't really, this silly question was not directly related to the > deadlock we are discussing here but to Viresh's argument that later stages > of suspending/hibernation seem to printk many messages in sync mode. so I > thought that there might be a small benefit in suspending consoles later, > as far as I understand, Viresh has `no_console_suspend' anyway. other That option is enabled only for testing though :) > than that, I tend to stick to the approach of switching to sync mode from > suspend_console(). I actually need to test it out as well :)
On 14-07-16, 16:12, Jan Kara wrote: > Exactly. Calling printk() from certain parts of the kernel (like scheduler > code or timer code) has been always unsafe because printk itself uses these > parts and so it can lead to deadlocks. That's why printk_deffered() has > been introduced as you mention below. > > And with sync printk the above deadlock doesn't trigger only by chance - if > there happened to be a waiter on console_sem while we suspend, the same > deadlock would trigger because up(&console_sem) will try to wake him up and > the warning in timekeeping code will cause recursive printk. > > So I think your patch doesn't really address the real issue - it only > works around the particular WARN_ON(timekeeping_enabled) warning but if > there was a different warning in timekeeping code which would trigger, it > has a potential for causing recursive printk deadlock (and indeed we had > such issues previously - see e.g. 504d58745c9c "timer: Fix lock inversion > between hrtimer_bases.lock and scheduler locks"). > > So there are IMHO two issues here worth looking at: > > 1) I didn't find how a wakeup would would lead to calling to ktime_get() in > the current upstream kernel or even current RT kernel. Maybe this is a > problem specific to the 3.10 kernel you are using? If yes, we don't have to > do anything for current upstream AFAIU. I haven't checked that earlier, but I see the path in both 3.10 and mainline. vprintk_emit -> wake_up_process -> try_to_wake_up -> ttwu_queue -> ttwu_do_activate -> ttwu_activate -> activate_task -> enqueue_task (sched/core.c) -> enqueue_task_rt (rt.c) -> enqueue_rt_entity -> __enqueue_rt_entity -> inc_rt_tasks -> inc_rt_group -> start_rt_bandwidth -> start_bandwidth_timer -> __hrtimer_start_range_ns -> ktime_get() > If I just missed how wakeup can call into ktime_get() in current upstream, > there is another question: > > 2) Is it OK that printk calls wakeup so late during suspend? To clarify again to everybody, we are talking about the place where all non-boot CPUs are already hot-unplugged and the last running one has disabled interrupts. I believe that we can't do migration at all now, right? What will we get by calling wake_up_process() now anyway ? > I believe it > is but I'm neither scheduler nor suspend expert. If it is OK, and wakeup > can lead to ktime_get() in current upstream, then this contradicts the > check WARN_ON(timekeeping_suspended) in ktime_get() and something is wrong. > > Adding Thomas to CC as timer / RT expert... Thanks.
On 14-07-16, 16:55, Jan Kara wrote: > Agree on that - but that seems to be a problem of a particular wakeup > implementation of the 3.10 kernel Viresh is using, not a problem of the > upstream kernel. I think we can get it to trigger on mainline as well. Also to mention that I also don't see it on every suspend. Probably hrtimer_active() call returns true in the sequence somewhere earlier, and we don't have to go activate a hrtimer.
On Thu 14-07-16 15:12:51, Viresh Kumar wrote: > On 14-07-16, 16:12, Jan Kara wrote: > > Exactly. Calling printk() from certain parts of the kernel (like scheduler > > code or timer code) has been always unsafe because printk itself uses these > > parts and so it can lead to deadlocks. That's why printk_deffered() has > > been introduced as you mention below. > > > > And with sync printk the above deadlock doesn't trigger only by chance - if > > there happened to be a waiter on console_sem while we suspend, the same > > deadlock would trigger because up(&console_sem) will try to wake him up and > > the warning in timekeeping code will cause recursive printk. > > > > So I think your patch doesn't really address the real issue - it only > > works around the particular WARN_ON(timekeeping_enabled) warning but if > > there was a different warning in timekeeping code which would trigger, it > > has a potential for causing recursive printk deadlock (and indeed we had > > such issues previously - see e.g. 504d58745c9c "timer: Fix lock inversion > > between hrtimer_bases.lock and scheduler locks"). > > > > So there are IMHO two issues here worth looking at: > > > > 1) I didn't find how a wakeup would would lead to calling to ktime_get() in > > the current upstream kernel or even current RT kernel. Maybe this is a > > problem specific to the 3.10 kernel you are using? If yes, we don't have to > > do anything for current upstream AFAIU. > > I haven't checked that earlier, but I see the path in both 3.10 and mainline. > > vprintk_emit > -> wake_up_process > -> try_to_wake_up > -> ttwu_queue > -> ttwu_do_activate > -> ttwu_activate > -> activate_task > -> enqueue_task (sched/core.c) > -> enqueue_task_rt (rt.c) > -> enqueue_rt_entity > -> __enqueue_rt_entity > -> inc_rt_tasks > -> inc_rt_group > -> start_rt_bandwidth > -> start_bandwidth_timer > -> __hrtimer_start_range_ns > -> ktime_get() Yeah, you are right. > > If I just missed how wakeup can call into ktime_get() in current upstream, > > there is another question: > > > > 2) Is it OK that printk calls wakeup so late during suspend? > > To clarify again to everybody, we are talking about the place where all > non-boot CPUs are already hot-unplugged and the last running one has > disabled interrupts. > > I believe that we can't do migration at all now, right? What will we get by > calling wake_up_process() now anyway ? As I already wrote to Rafael, wake_up_process() will change the process state to TASK_RUNNING so that it can run after we resume from suspend. But seeing that the same problem is in upstream I guess what Sergey did makes more sense if it works for you. If Sergey's fix does not work for you due to too many messages being printed during device suspend, then we will have to try something else... Honza
On Monday, July 18, 2016 01:01:34 PM Jan Kara wrote: > On Thu 14-07-16 15:12:51, Viresh Kumar wrote: > > On 14-07-16, 16:12, Jan Kara wrote: > > > Exactly. Calling printk() from certain parts of the kernel (like scheduler > > > code or timer code) has been always unsafe because printk itself uses these > > > parts and so it can lead to deadlocks. That's why printk_deffered() has > > > been introduced as you mention below. > > > > > > And with sync printk the above deadlock doesn't trigger only by chance - if > > > there happened to be a waiter on console_sem while we suspend, the same > > > deadlock would trigger because up(&console_sem) will try to wake him up and > > > the warning in timekeeping code will cause recursive printk. > > > > > > So I think your patch doesn't really address the real issue - it only > > > works around the particular WARN_ON(timekeeping_enabled) warning but if > > > there was a different warning in timekeeping code which would trigger, it > > > has a potential for causing recursive printk deadlock (and indeed we had > > > such issues previously - see e.g. 504d58745c9c "timer: Fix lock inversion > > > between hrtimer_bases.lock and scheduler locks"). > > > > > > So there are IMHO two issues here worth looking at: > > > > > > 1) I didn't find how a wakeup would would lead to calling to ktime_get() in > > > the current upstream kernel or even current RT kernel. Maybe this is a > > > problem specific to the 3.10 kernel you are using? If yes, we don't have to > > > do anything for current upstream AFAIU. > > > > I haven't checked that earlier, but I see the path in both 3.10 and mainline. > > > > vprintk_emit > > -> wake_up_process > > -> try_to_wake_up > > -> ttwu_queue > > -> ttwu_do_activate > > -> ttwu_activate > > -> activate_task > > -> enqueue_task (sched/core.c) > > -> enqueue_task_rt (rt.c) > > -> enqueue_rt_entity > > -> __enqueue_rt_entity > > -> inc_rt_tasks > > -> inc_rt_group > > -> start_rt_bandwidth > > -> start_bandwidth_timer > > -> __hrtimer_start_range_ns > > -> ktime_get() > > Yeah, you are right. > > > > If I just missed how wakeup can call into ktime_get() in current upstream, > > > there is another question: > > > > > > 2) Is it OK that printk calls wakeup so late during suspend? > > > > To clarify again to everybody, we are talking about the place where all > > non-boot CPUs are already hot-unplugged and the last running one has > > disabled interrupts. > > > > I believe that we can't do migration at all now, right? What will we get by > > calling wake_up_process() now anyway ? > > As I already wrote to Rafael, wake_up_process() will change the process > state to TASK_RUNNING so that it can run after we resume from suspend. > > But seeing that the same problem is in upstream I guess what Sergey did > makes more sense if it works for you. If Sergey's fix does not work for you > due to too many messages being printed during device suspend, then we will > have to try something else... Which is exactly my point. :-) Thanks, Rafael -- 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
On 13-07-16, 14:45, Sergey Senozhatsky wrote: > something like below, perhaps. will this work for you? > > --- > kernel/printk/printk.c | 12 +++++++++++- > 1 file changed, 11 insertions(+), 1 deletion(-) > > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c > index bbb4180..786690e 100644 > --- a/kernel/printk/printk.c > +++ b/kernel/printk/printk.c > @@ -288,6 +288,11 @@ static u32 log_buf_len = __LOG_BUF_LEN; > > /* Control whether printing to console must be synchronous. */ > static bool __read_mostly printk_sync = true; > +/* > + * Force sync printk mode during suspend/kexec, regardless whether > + * console_suspend_enabled permits console suspend. > + */ > +static bool __read_mostly force_printk_sync; > /* Printing kthread for async printk */ > static struct task_struct *printk_kthread; > /* When `true' printing thread has messages to print */ > @@ -295,7 +300,7 @@ static bool printk_kthread_need_flush_console; > > static inline bool can_printk_async(void) > { > - return !printk_sync && printk_kthread; > + return !printk_sync && printk_kthread && !force_printk_sync; > } > > /* Return log buffer address */ > @@ -2027,6 +2032,7 @@ static bool suppress_message_printing(int level) { return false; } > > /* Still needs to be defined for users */ > DEFINE_PER_CPU(printk_func_t, printk_func); > +static bool __read_mostly force_printk_sync; > > #endif /* CONFIG_PRINTK */ > > @@ -2163,6 +2169,8 @@ MODULE_PARM_DESC(console_suspend, "suspend console during suspend" > */ > void suspend_console(void) > { > + force_printk_sync = true; > + > if (!console_suspend_enabled) > return; > printk("Suspending console(s) (use no_console_suspend to debug)\n"); > @@ -2173,6 +2181,8 @@ void suspend_console(void) > > void resume_console(void) > { > + force_printk_sync = false; > + > if (!console_suspend_enabled) > return; > down_console_sem(); I haven't seen any issues with it yet and it works just fine. Please feel free to add below for the entire series including this hunk. Tested-by: Viresh Kumar <viresh.kumar@linaro.org>
On (07/29/16 13:42), Viresh Kumar wrote: [..] > I haven't seen any issues with it yet and it works just fine. Please feel free > to add below for the entire series including this hunk. > > Tested-by: Viresh Kumar <viresh.kumar@linaro.org> Thanks a lot! will refresh the series next week. sorry, haven't gotten many chances to investigate the sched throttling so far. -ss -- 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
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index bbb4180..786690e 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -288,6 +288,11 @@ static u32 log_buf_len = __LOG_BUF_LEN; /* Control whether printing to console must be synchronous. */ static bool __read_mostly printk_sync = true; +/* + * Force sync printk mode during suspend/kexec, regardless whether + * console_suspend_enabled permits console suspend. + */ +static bool __read_mostly force_printk_sync; /* Printing kthread for async printk */ static struct task_struct *printk_kthread; /* When `true' printing thread has messages to print */ @@ -295,7 +300,7 @@ static bool printk_kthread_need_flush_console; static inline bool can_printk_async(void) { - return !printk_sync && printk_kthread; + return !printk_sync && printk_kthread && !force_printk_sync; } /* Return log buffer address */ @@ -2027,6 +2032,7 @@ static bool suppress_message_printing(int level) { return false; } /* Still needs to be defined for users */ DEFINE_PER_CPU(printk_func_t, printk_func); +static bool __read_mostly force_printk_sync; #endif /* CONFIG_PRINTK */ @@ -2163,6 +2169,8 @@ MODULE_PARM_DESC(console_suspend, "suspend console during suspend" */ void suspend_console(void) { + force_printk_sync = true; + if (!console_suspend_enabled) return; printk("Suspending console(s) (use no_console_suspend to debug)\n"); @@ -2173,6 +2181,8 @@ void suspend_console(void) void resume_console(void) { + force_printk_sync = false; + if (!console_suspend_enabled) return; down_console_sem();