When a caller writes heavily to the kernel log (e.g. writing to
/dev/kmsg in a loop) while another panics, there's currently a high
likelihood of a deadlock (see patch 2 for the full description of this
deadlock).
The principle fix is to disable the optimistic spin once panic_cpu is
set, so the panic CPU doesn't spin waiting for a halted CPU to hand over
the console_sem.
However, this exposed us to a livelock situation, where the panic CPU
holds the console_sem, and another CPU could fill up the log buffer
faster than the consoles could drain it, preventing the panic from
progressing and halting the other CPUs. To avoid this, patch 3 adds a
mechanism to suppress printk (from non-panic-CPU) during panic, if we
reach a threshold of dropped messages.
A major goal with all of these patches is to try to decrease the
likelihood that another CPU is holding the console_sem when we halt it
in panic(). This reduces the odds of needing to break locks and
potentially encountering further deadlocks with the console drivers.
To test, I use the following script, kmsg_panic.sh:
#!/bin/bash
date
# 991 chars (based on log buffer size):
chars="$(printf 'a%.0s' {1..991})"
while :; do
echo $chars > /dev/kmsg
done &
echo c > /proc/sysrq-trigger &
date
exit
I defined a hang as any time the system did not reboot to a login prompt
on the serial console within 60 seconds. Here are the statistics on
hangs using this script, before and after the patch.
before: 776 hangs / 1484 trials - 52.3%
after : 0 hangs / 15k trials - 0.0%
v4: Moved panic_in_progress() out of #define CONFIG_PRINTK
v3:
Some mild style changes, none of which affect testing (which has run
continuously and is now over 15 thousand trials without a hang!)
v2:
Each patch has minor updates from code reviews. I've re-done testing
and updated the above statistics. Exact changes are in each patch.
Stephen Brennan (4):
printk: Add panic_in_progress helper
printk: disable optimistic spin during panic
printk: Avoid livelock with heavy printk during panic
printk: Drop console_sem during panic
kernel/printk/printk.c | 55 +++++++++++++++++++++++++++++++++++++++++-
1 file changed, 54 insertions(+), 1 deletion(-)
--
2.30.2
On 2/10/22 01:22, Petr Mladek wrote:
> On Wed 2022-02-02 09:18:17, Stephen Brennan wrote:
>> When a caller writes heavily to the kernel log (e.g. writing to
>> /dev/kmsg in a loop) while another panics, there's currently a high
>> likelihood of a deadlock (see patch 2 for the full description of this
>> deadlock).
>>
>> The principle fix is to disable the optimistic spin once panic_cpu is
>> set, so the panic CPU doesn't spin waiting for a halted CPU to hand over
>> the console_sem.
>>
>> However, this exposed us to a livelock situation, where the panic CPU
>> holds the console_sem, and another CPU could fill up the log buffer
>> faster than the consoles could drain it, preventing the panic from
>> progressing and halting the other CPUs. To avoid this, patch 3 adds a
>> mechanism to suppress printk (from non-panic-CPU) during panic, if we
>> reach a threshold of dropped messages.
>>
>> A major goal with all of these patches is to try to decrease the
>> likelihood that another CPU is holding the console_sem when we halt it
>> in panic(). This reduces the odds of needing to break locks and
>> potentially encountering further deadlocks with the console drivers.
>>
>> To test, I use the following script, kmsg_panic.sh:
>>
>> #!/bin/bash
>> date
>> # 991 chars (based on log buffer size):
>> chars="$(printf 'a%.0s' {1..991})"
>> while :; do
>> echo $chars > /dev/kmsg
>> done &
>> echo c > /proc/sysrq-trigger &
>> date
>> exit
>>
>> I defined a hang as any time the system did not reboot to a login prompt
>> on the serial console within 60 seconds. Here are the statistics on
>> hangs using this script, before and after the patch.
>>
>> before: 776 hangs / 1484 trials - 52.3%
>> after : 0 hangs / 15k trials - 0.0%
>>
>> Stephen Brennan (4):
>> printk: Add panic_in_progress helper
>> printk: disable optimistic spin during panic
>> printk: Avoid livelock with heavy printk during panic
>> printk: Drop console_sem during panic
>>
>> kernel/printk/printk.c | 55 +++++++++++++++++++++++++++++++++++++++++-
>> 1 file changed, 54 insertions(+), 1 deletion(-)
>
> For the entire patchset:
>
> Reviewed-by: Petr Mladek <[email protected]>
>
> It looks ready for linux-next from my POV. I am going to push it early
> next week unless anyone complains in the meantime.
Thank you Petr! It occurs to me that some of this could be
stable-worthy, depending on your feelings on it. Patches 1-3 resolve
real bugs on customer systems, and they'd apply back a decent way. 1-2
apply all the way back to 4.14, and 3 would apply with some minor
changes. I suppose the question is whether they are simple enough. Patch
4 is useful but I don't have a real reproducer for a bug it fixes, so I
wouldn't say it's stable worthy.
Of course we have the logbuf_lock in 5.10 and previous, and if a CPU is
halted holding that lock, then printk hangs even before the optimistic
spinning. I have patches which reinitialize those locks after the CPUs
are halted if necessary. I think they are reasonable for stable - printk
is guaranteed to hang without doing this, so in the worst case you trade
a hang during a panic, with some other sort of printk log buffer bug
during a panic. But in the common case, you eliminate the hang. I can
send that patch to linux-stable as well.
What do you think about these patches and stable?
Thanks again,
Stephen
>
> Best Regards,
> Petr Mladek
On Wed 2022-02-02 09:18:17, Stephen Brennan wrote:
> When a caller writes heavily to the kernel log (e.g. writing to
> /dev/kmsg in a loop) while another panics, there's currently a high
> likelihood of a deadlock (see patch 2 for the full description of this
> deadlock).
>
> The principle fix is to disable the optimistic spin once panic_cpu is
> set, so the panic CPU doesn't spin waiting for a halted CPU to hand over
> the console_sem.
>
> However, this exposed us to a livelock situation, where the panic CPU
> holds the console_sem, and another CPU could fill up the log buffer
> faster than the consoles could drain it, preventing the panic from
> progressing and halting the other CPUs. To avoid this, patch 3 adds a
> mechanism to suppress printk (from non-panic-CPU) during panic, if we
> reach a threshold of dropped messages.
>
> A major goal with all of these patches is to try to decrease the
> likelihood that another CPU is holding the console_sem when we halt it
> in panic(). This reduces the odds of needing to break locks and
> potentially encountering further deadlocks with the console drivers.
>
> To test, I use the following script, kmsg_panic.sh:
>
> #!/bin/bash
> date
> # 991 chars (based on log buffer size):
> chars="$(printf 'a%.0s' {1..991})"
> while :; do
> echo $chars > /dev/kmsg
> done &
> echo c > /proc/sysrq-trigger &
> date
> exit
>
> I defined a hang as any time the system did not reboot to a login prompt
> on the serial console within 60 seconds. Here are the statistics on
> hangs using this script, before and after the patch.
>
> before: 776 hangs / 1484 trials - 52.3%
> after : 0 hangs / 15k trials - 0.0%
>
> Stephen Brennan (4):
> printk: Add panic_in_progress helper
> printk: disable optimistic spin during panic
> printk: Avoid livelock with heavy printk during panic
> printk: Drop console_sem during panic
>
> kernel/printk/printk.c | 55 +++++++++++++++++++++++++++++++++++++++++-
> 1 file changed, 54 insertions(+), 1 deletion(-)
For the entire patchset:
Reviewed-by: Petr Mladek <[email protected]>
It looks ready for linux-next from my POV. I am going to push it early
next week unless anyone complains in the meantime.
Best Regards,
Petr Mladek
On (22/02/10 10:22), Petr Mladek wrote:
>
> For the entire patchset:
>
> Reviewed-by: Petr Mladek <[email protected]>
FWIW
Reviewed-by: Sergey Senozhatsky <[email protected]>
On Thu 2022-02-10 12:06:44, Stephen Brennan wrote:
> On 2/10/22 01:22, Petr Mladek wrote:
> > On Wed 2022-02-02 09:18:17, Stephen Brennan wrote:
> > > When a caller writes heavily to the kernel log (e.g. writing to
> > > /dev/kmsg in a loop) while another panics, there's currently a high
> > > likelihood of a deadlock (see patch 2 for the full description of this
> > > deadlock).
> > >
> > > The principle fix is to disable the optimistic spin once panic_cpu is
> > > set, so the panic CPU doesn't spin waiting for a halted CPU to hand over
> > > the console_sem.
> > >
> > > However, this exposed us to a livelock situation, where the panic CPU
> > > holds the console_sem, and another CPU could fill up the log buffer
> > > faster than the consoles could drain it, preventing the panic from
> > > progressing and halting the other CPUs. To avoid this, patch 3 adds a
> > > mechanism to suppress printk (from non-panic-CPU) during panic, if we
> > > reach a threshold of dropped messages.
> > >
> > > A major goal with all of these patches is to try to decrease the
> > > likelihood that another CPU is holding the console_sem when we halt it
> > > in panic(). This reduces the odds of needing to break locks and
> > > potentially encountering further deadlocks with the console drivers.
> > >
> > > To test, I use the following script, kmsg_panic.sh:
> > >
> > > #!/bin/bash
> > > date
> > > # 991 chars (based on log buffer size):
> > > chars="$(printf 'a%.0s' {1..991})"
> > > while :; do
> > > echo $chars > /dev/kmsg
> > > done &
> > > echo c > /proc/sysrq-trigger &
> > > date
> > > exit
> > >
> > > I defined a hang as any time the system did not reboot to a login prompt
> > > on the serial console within 60 seconds. Here are the statistics on
> > > hangs using this script, before and after the patch.
> > >
> > > before: 776 hangs / 1484 trials - 52.3%
> > > after : 0 hangs / 15k trials - 0.0%
> > >
> > > Stephen Brennan (4):
> > > printk: Add panic_in_progress helper
> > > printk: disable optimistic spin during panic
> > > printk: Avoid livelock with heavy printk during panic
> > > printk: Drop console_sem during panic
> > >
> > > kernel/printk/printk.c | 55 +++++++++++++++++++++++++++++++++++++++++-
> > > 1 file changed, 54 insertions(+), 1 deletion(-)
> >
> > For the entire patchset:
> >
> > Reviewed-by: Petr Mladek <[email protected]>
> >
> > It looks ready for linux-next from my POV. I am going to push it early
> > next week unless anyone complains in the meantime.
The patchset is committed in printk/linux.git, branch for-5.18-panic-deadlocks.
> Thank you Petr! It occurs to me that some of this could be stable-worthy,
> depending on your feelings on it. Patches 1-3 resolve real bugs on customer
> systems, and they'd apply back a decent way. 1-2 apply all the way back to
> 4.14, and 3 would apply with some minor changes. I suppose the question is
> whether they are simple enough. Patch 4 is useful but I don't have a real
> reproducer for a bug it fixes, so I wouldn't say it's stable worthy.
Good question. If you saw these deadlocks on customer systems in
the real life then it might be worth it.
I newer saw them. But they hard to debug and report. Also they are
visible only when CPUs are stopped by NMI. And the default
smp_send_stop() tries to stop CPUs using normal IRQ first.
Anyway, the patches 1,2,4 are pretty straightforward and should be
safe. Feel free to send them to stable.
3rd patch is a heuristic. It tries to prevent livelock and the cost
is a possible loss of information. I am not 100% sure that it will
do the right thing in all situations. I would wait one or two release
cycles before we backport it to older stable releases.
> Of course we have the logbuf_lock in 5.10 and previous, and if a CPU is
> halted holding that lock, then printk hangs even before the optimistic
> spinning. I have patches which reinitialize those locks after the CPUs are
> halted if necessary. I think they are reasonable for stable - printk is
> guaranteed to hang without doing this, so in the worst case you trade a hang
> during a panic, with some other sort of printk log buffer bug during a
> panic. But in the common case, you eliminate the hang. I can send that patch
> to linux-stable as well.
The main problem is that the locks can be safely re-initialized only
when the other CPUs were stopped using NMI. Otherwise, there is
a risk of double unlock. Such a patch would need to be arch-dependent.
Also stable people do not like much solutions that were not used
in the mainline. So, it might be a waste of time.
Best Regards,
Petr
On 2/14/22 05:54, Petr Mladek wrote:
> On Thu 2022-02-10 12:06:44, Stephen Brennan wrote:
>> On 2/10/22 01:22, Petr Mladek wrote:
>>> On Wed 2022-02-02 09:18:17, Stephen Brennan wrote:
>>>> When a caller writes heavily to the kernel log (e.g. writing to
>>>> /dev/kmsg in a loop) while another panics, there's currently a high
>>>> likelihood of a deadlock (see patch 2 for the full description of this
>>>> deadlock).
>>>>
>>>> The principle fix is to disable the optimistic spin once panic_cpu is
>>>> set, so the panic CPU doesn't spin waiting for a halted CPU to hand over
>>>> the console_sem.
>>>>
>>>> However, this exposed us to a livelock situation, where the panic CPU
>>>> holds the console_sem, and another CPU could fill up the log buffer
>>>> faster than the consoles could drain it, preventing the panic from
>>>> progressing and halting the other CPUs. To avoid this, patch 3 adds a
>>>> mechanism to suppress printk (from non-panic-CPU) during panic, if we
>>>> reach a threshold of dropped messages.
>>>>
>>>> A major goal with all of these patches is to try to decrease the
>>>> likelihood that another CPU is holding the console_sem when we halt it
>>>> in panic(). This reduces the odds of needing to break locks and
>>>> potentially encountering further deadlocks with the console drivers.
>>>>
>>>> To test, I use the following script, kmsg_panic.sh:
>>>>
>>>> #!/bin/bash
>>>> date
>>>> # 991 chars (based on log buffer size):
>>>> chars="$(printf 'a%.0s' {1..991})"
>>>> while :; do
>>>> echo $chars > /dev/kmsg
>>>> done &
>>>> echo c > /proc/sysrq-trigger &
>>>> date
>>>> exit
>>>>
>>>> I defined a hang as any time the system did not reboot to a login prompt
>>>> on the serial console within 60 seconds. Here are the statistics on
>>>> hangs using this script, before and after the patch.
>>>>
>>>> before: 776 hangs / 1484 trials - 52.3%
>>>> after : 0 hangs / 15k trials - 0.0%
>>>>
>>>> Stephen Brennan (4):
>>>> printk: Add panic_in_progress helper
>>>> printk: disable optimistic spin during panic
>>>> printk: Avoid livelock with heavy printk during panic
>>>> printk: Drop console_sem during panic
>>>>
>>>> kernel/printk/printk.c | 55 +++++++++++++++++++++++++++++++++++++++++-
>>>> 1 file changed, 54 insertions(+), 1 deletion(-)
>>>
>>> For the entire patchset:
>>>
>>> Reviewed-by: Petr Mladek <[email protected]>
>>>
>>> It looks ready for linux-next from my POV. I am going to push it early
>>> next week unless anyone complains in the meantime.
>
> The patchset is committed in printk/linux.git, branch for-5.18-panic-deadlocks.
Thank you!
>
>> Thank you Petr! It occurs to me that some of this could be stable-worthy,
>> depending on your feelings on it. Patches 1-3 resolve real bugs on customer
>> systems, and they'd apply back a decent way. 1-2 apply all the way back to
>> 4.14, and 3 would apply with some minor changes. I suppose the question is
>> whether they are simple enough. Patch 4 is useful but I don't have a real
>> reproducer for a bug it fixes, so I wouldn't say it's stable worthy.
>
> Good question. If you saw these deadlocks on customer systems in
> the real life then it might be worth it.
>
> I newer saw them. But they hard to debug and report. Also they are
> visible only when CPUs are stopped by NMI. And the default
> smp_send_stop() tries to stop CPUs using normal IRQ first.
Some of our default configurations like to ship with
crash_kexec_post_notifiers=1, so I see the aggressive
crash_smp_send_stop() code path a lot internally.
And interestingly, Hyper-V enables crash_kexec_post_notifiers in certain
cases, without so much as a peep in the kernel log, even if kdump is not
enabled... So folks running on Azure or otherwise running Hyper-V guests
would be exposed to this. I actually just saw some patches related to
this which you reviewed, so I guess you're aware of that :)
https://lore.kernel.org/lkml/YgDZX4PYwhrA1+Ct@MiWiFi-R3L-srv/
As somebody who mainly browses subsystem-focused mailing lists I didn't
see this at all, as these printk/panic related patches only seem to go
to LKML. I guess I need to check out the new lore+lei system so I can
keep track of relevant work.
>
> Anyway, the patches 1,2,4 are pretty straightforward and should be
> safe. Feel free to send them to stable.
Very reasonable. The customer systems experiencing the issue would be
resolved by patches 1-2 alone. I did not have a customer experiencing
any sort of livelock (and it would be a pretty ridiculous situation,
most printk dies down quickly). I see the value of patch 4 for
architectures without these NMI so I can send it too.
>
> 3rd patch is a heuristic. It tries to prevent livelock and the cost
> is a possible loss of information. I am not 100% sure that it will
> do the right thing in all situations. I would wait one or two release
> cycles before we backport it to older stable releases.
Fair enough!
>
>> Of course we have the logbuf_lock in 5.10 and previous, and if a CPU is
>> halted holding that lock, then printk hangs even before the optimistic
>> spinning. I have patches which reinitialize those locks after the CPUs are
>> halted if necessary. I think they are reasonable for stable - printk is
>> guaranteed to hang without doing this, so in the worst case you trade a hang
>> during a panic, with some other sort of printk log buffer bug during a
>> panic. But in the common case, you eliminate the hang. I can send that patch
>> to linux-stable as well.
>
> The main problem is that the locks can be safely re-initialized only
> when the other CPUs were stopped using NMI. Otherwise, there is
> a risk of double unlock. Such a patch would need to be arch-dependent.
That's a very good point, thank you for mentioning it.
>
> Also stable people do not like much solutions that were not used
> in the mainline. So, it might be a waste of time.
True. I may try my hand at it simply because I would much rather see
work be done for all via -stable rather than in vendor-specific trees.
Thanks,
Stephen
>
> Best Regards,
> Petr