Hi, everyone.
This series was inspired by the need to modernize and display more
informative messages about unhandled signals.
The "unhandled signal NN" is not very informative. We thought it would
be helpful adding a human-readable message describing what the signal
number means, printing the VMA address, and dumping the instructions.
We can add more informative messages, like informing what each code of a
SIGSEGV signal means. We are open to suggestions.
I have collected some early feedback from Michael Ellerman about this
series and would love to hear more feedback from you all.
Before this series:
Jul 24 13:01:07 localhost kernel: pandafault[5989]: unhandled signal 11 at 00000000100007d0 nip 000000001000061c lr 00003fff85a75100 code 2
After this series:
Jul 24 13:08:01 localhost kernel: pandafault[10758]: segfault (11) at 00000000100007d0 nip 000000001000061c lr 00007fffabc85100 code 2 in pandafault[10000000+10000]
Jul 24 13:08:01 localhost kernel: Instruction dump:
Jul 24 13:08:01 localhost kernel: 4bfffeec 4bfffee8 3c401002 38427f00 fbe1fff8 f821ffc1 7c3f0b78 3d22fffe
Jul 24 13:08:01 localhost kernel: 392988d0 f93f0020 e93f0020 39400048 <99490000> 39200000 7d234b78 383f0040
Cheers
Murilo
Murilo Opsfelder Araujo (7):
powerpc/traps: Print unhandled signals in a separate function
powerpc/traps: Return early in show_signal_msg()
powerpc/reg: Add REG_FMT definition
powerpc/traps: Use REG_FMT in show_signal_msg()
powerpc/traps: Print VMA for unhandled signals
powerpc/traps: Print signal name for unhandled signals
powerpc/traps: Show instructions on exceptions
arch/powerpc/include/asm/reg.h | 6 +++
arch/powerpc/include/asm/stacktrace.h | 7 +++
arch/powerpc/kernel/process.c | 28 +++++-----
arch/powerpc/kernel/traps.c | 73 +++++++++++++++++++++++----
4 files changed, 89 insertions(+), 25 deletions(-)
create mode 100644 arch/powerpc/include/asm/stacktrace.h
--
2.17.1
Make REG definition, in arch/powerpc/kernel/process.c, generic enough by
renaming it to REG_FMT and placing it in arch/powerpc/include/asm/reg.h to be
used elsewhere.
Replace occurrences of REG by REG_FMT in arch/powerpc/kernel/process.c.
Signed-off-by: Murilo Opsfelder Araujo <redacted>
---
arch/powerpc/include/asm/reg.h | 6 ++++++
arch/powerpc/kernel/process.c | 22 ++++++++++------------
2 files changed, 16 insertions(+), 12 deletions(-)
Simplify the message format by using REG_FMT as the register format. This
avoids having two different formats and avoids checking for MSR_64BIT.
Signed-off-by: Murilo Opsfelder Araujo <redacted>
---
arch/powerpc/kernel/traps.c | 12 ++++--------
1 file changed, 4 insertions(+), 8 deletions(-)
This adds VMA address in the message printed for unhandled signals, similarly to
what other architectures, like x86, print.
Before this patch, a page fault looked like:
Jul 11 15:56:25 localhost kernel: pandafault[61470]: unhandled signal 11 at 00000000100007d0 nip 000000001000061c lr 00007fff8d185100 code 2
After this patch, a page fault looks like:
Jul 11 16:04:11 localhost kernel: pandafault[6303]: unhandled signal 11 at 00000000100007d0 nip 000000001000061c lr 00007fff93c55100 code 2 in pandafault[10000000+10000]
Signed-off-by: Murilo Opsfelder Araujo <redacted>
---
arch/powerpc/kernel/traps.c | 6 +++++-
1 file changed, 5 insertions(+), 1 deletion(-)
This adds a human-readable name in the unhandled signal message.
Before this patch, a page fault looked like:
Jul 11 16:04:11 localhost kernel: pandafault[6303]: unhandled signal 11 at 00000000100007d0 nip 000000001000061c lr 00007fff93c55100 code 2 in pandafault[10000000+10000]
After this patch, a page fault looks like:
Jul 11 18:14:48 localhost kernel: pandafault[6352]: segfault (11) at 000000013a2a09f8 nip 000000013a2a086c lr 00007fffb63e5100 code 2 in pandafault[13a2a0000+10000]
Signed-off-by: Murilo Opsfelder Araujo <redacted>
---
arch/powerpc/kernel/traps.c | 43 +++++++++++++++++++++++++++++++++----
1 file changed, 39 insertions(+), 4 deletions(-)
From: Michael Neuling <hidden> Date: 2018-07-25 07:00:30
On Tue, 2018-07-24 at 16:27 -0300, Murilo Opsfelder Araujo wrote:
Hi, everyone.
=20
This series was inspired by the need to modernize and display more
informative messages about unhandled signals.
=20
The "unhandled signal NN" is not very informative. We thought it would
be helpful adding a human-readable message describing what the signal
number means, printing the VMA address, and dumping the instructions.
=20
We can add more informative messages, like informing what each code of a
SIGSEGV signal means. We are open to suggestions.
=20
I have collected some early feedback from Michael Ellerman about this
series and would love to hear more feedback from you all.
Nice.. the instruction dump would have been very handy when debugging the P=
CR
init issue I had a month or so back.
Before this series:
=20
Jul 24 13:01:07 localhost kernel: pandafault[5989]: unhandled signal =
11 at 00000000100007d0 nip 000000001000061c lr 00003fff85a75100 code 2
=20
After this series:
=20
Jul 24 13:08:01 localhost kernel: pandafault[10758]: segfault (11) at=
00000000100007d0 nip 000000001000061c lr 00007fffabc85100 code 2 in pandaf=
ault[10000000+10000]
<99490000> 39200000 7d234b78 383f0040
What happens if we get a sudden flood of these from different processes tha=
t
overlap their output? Are we going to be able to match up the process with
instruction dump?
Should we prefix every line with the PID to avoid this?
Mikey
Hi Murilo,
LGTM.
Just a comment:
On 07/24/2018 04:27 PM, Murilo Opsfelder Araujo wrote:
This adds a human-readable name in the unhandled signal message.
Before this patch, a page fault looked like:
Jul 11 16:04:11 localhost kernel: pandafault[6303]: unhandled signal 11 at 00000000100007d0 nip 000000001000061c lr 00007fff93c55100 code 2 in pandafault[10000000+10000]
After this patch, a page fault looks like:
Jul 11 18:14:48 localhost kernel: pandafault[6352]: segfault (11) at 000000013a2a09f8 nip 000000013a2a086c lr 00007fffb63e5100 code 2 in pandafault[13a2a0000+10000]
I _really_ don't want to bikeshed here, but I vouch for keeping the
"unhandled" word before the signal name, like:
[...] pandafault[6352]: unhandled segfault (11) at 000000013a2a09f8 nip [...]
because the issue reported here is really that we got a segfault _and_
there was no handler to catch it.
But feel free to wait for additional comments to decide it.
Cheers,
Gustavo
Murilo Opsfelder Araujo [off-list ref] a =C3=A9crit=C2=A0:
Modify logic of show_signal_msg() to return early, if possible. Replace
printk_ratelimited() by printk() and a default rate limit burst to limit
displaying unhandled signals messages.
Can you explain more the benefits of this change ?
Christophe
Murilo Opsfelder Araujo [off-list ref] a =C3=A9crit=C2=A0:
quoted hunk
This adds a human-readable name in the unhandled signal message.
Before this patch, a page fault looked like:
Jul 11 16:04:11 localhost kernel: pandafault[6303]: unhandled=20=20
=20signal 11 at 00000000100007d0 nip 000000001000061c lr=20=20
=2000007fff93c55100 code 2 in pandafault[10000000+10000]
After this patch, a page fault looks like:
Jul 11 18:14:48 localhost kernel: pandafault[6352]: segfault=20=20
=20(11) at 000000013a2a09f8 nip 000000013a2a086c lr 00007fffb63e5100=20=20
=20code 2 in pandafault[13a2a0000+10000]
Signed-off-by: Murilo Opsfelder Araujo <redacted>
---
arch/powerpc/kernel/traps.c | 43 +++++++++++++++++++++++++++++++++----
1 file changed, 39 insertions(+), 4 deletions(-)
Murilo Opsfelder Araujo [off-list ref] a =C3=A9crit=C2=A0:
Move show_instructions() declaration to arch/powerpc/include/asm/stacktra=
ce.h
and include asm/stracktrace.h in arch/powerpc/kernel/process.c,=20=20
=20which contains
the implementation.
Modify show_instructions() not to call __kernel_text_address(), allowing
userspace instruction dump. probe_kernel_address(), which returns -EFAUL=
T if
something goes wrong, is still being called.
Call show_instructions() in arch/powerpc/kernel/traps.c to dump=20=20
=20instructions at
faulty location, useful to debugging.
Shouldn't this part be in a second patch ?
Wouldn't it be better to also see regs in addition if we want to use=20=20
this=20to understand what happened ?
So you could call show_regs() instead of show_instructions() ?
Christophe
quoted hunk
Before this patch, an unhandled signal message looked like:
Jul 24 09:57:00 localhost kernel: pandafault[10524]: segfault=20=20
=20(11) at 00000000100007d0 nip 000000001000061c lr 00007fffbd295100=20=20
=20code 2 in pandafault[10000000+10000]
After this patch, it looks like:
Jul 24 09:57:00 localhost kernel: pandafault[10524]: segfault=20=20
=20(11) at 00000000100007d0 nip 000000001000061c lr 00007fffbd295100=20=20
=20code 2 in pandafault[10000000+10000]
Jul 24 09:57:00 localhost kernel: Instruction dump:
Jul 24 09:57:00 localhost kernel: 4bfffeec 4bfffee8 3c401002=20=20
=2038427f00 fbe1fff8 f821ffc1 7c3f0b78 3d22fffe
Jul 24 09:57:00 localhost kernel: 392988d0 f93f0020 e93f0020=20=20
=2039400048 <99490000> 39200000 7d234b78 383f0040
Signed-off-by: Murilo Opsfelder Araujo <redacted>
---
arch/powerpc/include/asm/stacktrace.h | 7 +++++++
arch/powerpc/kernel/process.c | 6 +++---
arch/powerpc/kernel/traps.c | 3 +++
3 files changed, 13 insertions(+), 3 deletions(-)
create mode 100644 arch/powerpc/include/asm/stacktrace.h
Hi, Mikey.
On Wed, Jul 25, 2018 at 05:00:21PM +1000, Michael Neuling wrote:
On Tue, 2018-07-24 at 16:27 -0300, Murilo Opsfelder Araujo wrote:
quoted
Hi, everyone.
This series was inspired by the need to modernize and display more
informative messages about unhandled signals.
The "unhandled signal NN" is not very informative. We thought it would
be helpful adding a human-readable message describing what the signal
number means, printing the VMA address, and dumping the instructions.
We can add more informative messages, like informing what each code of a
SIGSEGV signal means. We are open to suggestions.
I have collected some early feedback from Michael Ellerman about this
series and would love to hear more feedback from you all.
Nice.. the instruction dump would have been very handy when debugging the PCR
init issue I had a month or so back.
quoted
Before this series:
Jul 24 13:01:07 localhost kernel: pandafault[5989]: unhandled signal 11 at 00000000100007d0 nip 000000001000061c lr 00003fff85a75100 code 2
After this series:
Jul 24 13:08:01 localhost kernel: pandafault[10758]: segfault (11) at 00000000100007d0 nip 000000001000061c lr 00007fffabc85100 code 2 in pandafault[10000000+10000]
Jul 24 13:08:01 localhost kernel: Instruction dump:
Jul 24 13:08:01 localhost kernel: 4bfffeec 4bfffee8 3c401002 38427f00 fbe1fff8 f821ffc1 7c3f0b78 3d22fffe
Jul 24 13:08:01 localhost kernel: 392988d0 f93f0020 e93f0020 39400048 <99490000> 39200000 7d234b78 383f0040
What happens if we get a sudden flood of these from different processes that
overlap their output? Are we going to be able to match up the process with
instruction dump?
As to the flood of messages, ___ratelimit() makes me think that we'll
likely see some warn messages informing how many show_signal_msg()
callbacks were suppressed, instead of interleaved messages and
instruction dumps.
As to matching process with instruction dump, I believe we'd need more
information to glue them together.
What if we modify show_instructions() to accept a string prefix to be
printed along with each line?
Should we prefix every line with the PID to avoid this?
That's possible. An alternative would be prefixing each line with the
process name and its PID, as in the first line. For example:
pandafault[10758]: segfault (11) at 00000000100007d0 nip 000000001000061c lr 00007fffabc85100 code 2 in pandafault[10000000+10000]
pandafault[10758]: Instruction dump:
pandafault[10758]: 4bfffeec 4bfffee8 3c401002 38427f00 fbe1fff8 f821ffc1 7c3f0b78 3d22fffe
pandafault[10758]: 392988d0 f93f0020 e93f0020 39400048 <99490000> 39200000 7d234b78 383f0040
The above can be interleaved with other messages and we'll still be able
to match process and its corresponding instruction dump.
Cheers
Murilo
Hi, Gustavo.
On Wed, Jul 25, 2018 at 12:19:00PM -0300, Gustavo Romero wrote:
Hi Murilo,
LGTM.
Just a comment:
On 07/24/2018 04:27 PM, Murilo Opsfelder Araujo wrote:
quoted
This adds a human-readable name in the unhandled signal message.
Before this patch, a page fault looked like:
Jul 11 16:04:11 localhost kernel: pandafault[6303]: unhandled signal 11 at 00000000100007d0 nip 000000001000061c lr 00007fff93c55100 code 2 in pandafault[10000000+10000]
After this patch, a page fault looks like:
Jul 11 18:14:48 localhost kernel: pandafault[6352]: segfault (11) at 000000013a2a09f8 nip 000000013a2a086c lr 00007fffb63e5100 code 2 in pandafault[13a2a0000+10000]
I _really_ don't want to bikeshed here, but I vouch for keeping the
"unhandled" word before the signal name, like:
[...] pandafault[6352]: unhandled segfault (11) at 000000013a2a09f8 nip [...]
because the issue reported here is really that we got a segfault _and_
there was no handler to catch it.
Either way works for me.
But feel free to wait for additional comments to decide it.
Sure. I intend to wait a couple of weeks to respin the series based on
community feedback.
Cheers
Murilo
Hi, Christophe.
On Wed, Jul 25, 2018 at 05:49:27PM +0200, LEROY Christophe wrote:
Murilo Opsfelder Araujo [off-list ref] a écrit :
quoted
This adds a human-readable name in the unhandled signal message.
Before this patch, a page fault looked like:
Jul 11 16:04:11 localhost kernel: pandafault[6303]: unhandled signal
11 at 00000000100007d0 nip 000000001000061c lr 00007fff93c55100 code 2
in pandafault[10000000+10000]
After this patch, a page fault looks like:
Jul 11 18:14:48 localhost kernel: pandafault[6352]: segfault (11) at
000000013a2a09f8 nip 000000013a2a086c lr 00007fffb63e5100 code 2 in
pandafault[13a2a0000+10000]
Signed-off-by: Murilo Opsfelder Araujo <redacted>
---
arch/powerpc/kernel/traps.c | 43 +++++++++++++++++++++++++++++++++----
1 file changed, 39 insertions(+), 4 deletions(-)
pt_regs *regs, int code,
if (!unhandled_signal(current, signr))
return;
- pr_info("%s[%d]: unhandled signal %d at "REG_FMT \
- " nip "REG_FMT" lr "REG_FMT" code %x",
- current->comm, current->pid, signr, addr,
- regs->nip, regs->link, code);
+ pr_info("%s[%d]: %s (%d) at "REG_FMT" nip "REG_FMT \
+ " lr "REG_FMT" code %x",
+ current->comm, current->pid, signames[signr],
+ signr, addr, regs->nip, regs->link, code);
Are we sure that signr is always within the limits of the table ?
Looking at the code, we only pass the following signals:
SIGBUS
SIGFPE
SIGILL
SIGSEGV
SIGTRAP
All of them are within the limits of the table. We've added other
signals for completeness.
Cheers
Murilo
Hi, Christophe.
On Wed, Jul 25, 2018 at 05:42:28PM +0200, LEROY Christophe wrote:
Murilo Opsfelder Araujo [off-list ref] a écrit :
quoted
Modify logic of show_signal_msg() to return early, if possible. Replace
printk_ratelimited() by printk() and a default rate limit burst to limit
displaying unhandled signals messages.
Can you explain more the benefits of this change ?
Mainly is to improve readability of the function.
The conditions to display the message were coupled together in one
single `if` statement.
Besides that, patch 5/7 adds a call to print_vma_addr(), which is not
aware of any rate limit - it simply calls printk().
So splitting out the rate limit check outside show_signal_msg() makes it
easier to the caller decide if it wants to respect a printk rate limit
or not.
Cheers
Murilo
Hi, Christophe.
On Wed, Jul 25, 2018 at 06:01:34PM +0200, LEROY Christophe wrote:
Murilo Opsfelder Araujo [off-list ref] a écrit :
quoted
Move show_instructions() declaration to arch/powerpc/include/asm/stacktrace.h
and include asm/stracktrace.h in arch/powerpc/kernel/process.c, which
contains
the implementation.
Modify show_instructions() not to call __kernel_text_address(), allowing
userspace instruction dump. probe_kernel_address(), which returns -EFAULT if
something goes wrong, is still being called.
Call show_instructions() in arch/powerpc/kernel/traps.c to dump
instructions at
faulty location, useful to debugging.
Shouldn't this part be in a second patch ?
Makes sense. Perhaps I should split this patch in two: one to remove
__kernel_text_address() check in show_instructions(), and another to
call show_instructions() in show_signal_msg().
Wouldn't it be better to also see regs in addition if we want to use this to
understand what happened ?
So you could call show_regs() instead of show_instructions() ?
I see that show_regs() prints more information and calls
show_instructions() at the end if in privileged state.
I'm not sure about which situations we might want to call show_regs() -
and display a bunch of information - or just dump instructions for some
signals.
Isn't calling show_regs() in this case considered overkill?
Cheers
Murilo
From: Michael Neuling <hidden> Date: 2018-07-26 02:12:01
quoted
Should we prefix every line with the PID to avoid this?
=20
That's possible. An alternative would be prefixing each line with the
process name and its PID, as in the first line. For example:
=20
pandafault[10758]: segfault (11) at 00000000100007d0 nip 000000001000=
061c lr 00007fffabc85100 code 2 in pandafault[10000000+10000]
From: Michael Ellerman <mpe@ellerman.id.au> Date: 2018-07-26 02:21:05
Murilo Opsfelder Araujo [off-list ref] writes:
On Wed, Jul 25, 2018 at 05:00:21PM +1000, Michael Neuling wrote:
quoted
On Tue, 2018-07-24 at 16:27 -0300, Murilo Opsfelder Araujo wrote:
quoted
This series was inspired by the need to modernize and display more
informative messages about unhandled signals.
...
quoted
Nice.. the instruction dump would have been very handy when debugging the PCR
init issue I had a month or so back.
These things may be related :)
quoted
What happens if we get a sudden flood of these from different processes that
overlap their output? Are we going to be able to match up the process with
instruction dump?
As to the flood of messages, ___ratelimit() makes me think that we'll
likely see some warn messages informing how many show_signal_msg()
callbacks were suppressed, instead of interleaved messages and
instruction dumps.
As to matching process with instruction dump, I believe we'd need more
information to glue them together.
What if we modify show_instructions() to accept a string prefix to be
printed along with each line?
quoted
Should we prefix every line with the PID to avoid this?
That's possible. An alternative would be prefixing each line with the
process name and its PID, as in the first line. For example:
pandafault[10758]: segfault (11) at 00000000100007d0 nip 000000001000061c lr 00007fffabc85100 code 2 in pandafault[10000000+10000]
pandafault[10758]: Instruction dump:
pandafault[10758]: 4bfffeec 4bfffee8 3c401002 38427f00 fbe1fff8 f821ffc1 7c3f0b78 3d22fffe
pandafault[10758]: 392988d0 f93f0020 e93f0020 39400048 <99490000> 39200000 7d234b78 383f0040
The above can be interleaved with other messages and we'll still be able
to match process and its corresponding instruction dump.
Yeah prefixing with the comm and pid is nice.
Also the "Instruction dump:" line is a waste of space.
I prefer the x86 format, where it's prefixed with "code:", eg:
pandafault[10758]: segfault (11) at 00000000100007d0 nip 000000001000061c lr 00007fffabc85100 code 2 in pandafault[10000000+10000]
pandafault[10758]: code: 4bfffeec 4bfffee8 3c401002 38427f00 fbe1fff8 f821ffc1 7c3f0b78 3d22fffe
pandafault[10758]: code: 392988d0 f93f0020 e93f0020 39400048 <99490000> 39200000 7d234b78 383f0040
cheers