2019-06-26 18:38:43

by Naveen N. Rao

[permalink] [raw]
Subject: [PATCH] recordmcount: Fix spurious mcount entries on powerpc

The recent change enabling HAVE_C_RECORDMCOUNT on powerpc started
showing the following issue:

# modprobe kprobe_example
ftrace-powerpc: Not expected bl: opcode is 3c4c0001
WARNING: CPU: 0 PID: 227 at kernel/trace/ftrace.c:2001 ftrace_bug+0x90/0x318
Modules linked in:
CPU: 0 PID: 227 Comm: modprobe Not tainted 5.2.0-rc6-00678-g1c329100b942 #2
NIP: c000000000264318 LR: c00000000025d694 CTR: c000000000f5cd30
REGS: c000000001f2b7b0 TRAP: 0700 Not tainted (5.2.0-rc6-00678-g1c329100b942)
MSR: 900000010282b033 <SF,HV,VEC,VSX,EE,FP,ME,IR,DR,RI,LE,TM[E]> CR: 28228222 XER: 00000000
CFAR: c0000000002642fc IRQMASK: 0
<snip>
NIP [c000000000264318] ftrace_bug+0x90/0x318
LR [c00000000025d694] ftrace_process_locs+0x4f4/0x5e0
Call Trace:
[c000000001f2ba40] [0000000000000004] 0x4 (unreliable)
[c000000001f2bad0] [c00000000025d694] ftrace_process_locs+0x4f4/0x5e0
[c000000001f2bb90] [c00000000020ff10] load_module+0x25b0/0x30c0
[c000000001f2bd00] [c000000000210cb0] sys_finit_module+0xc0/0x130
[c000000001f2be20] [c00000000000bda4] system_call+0x5c/0x70
Instruction dump:
419e0018 2f83ffff 419e00bc 2f83ffea 409e00cc 4800001c 0fe00000 3c62ff96
39000001 39400000 386386d0 480000c4 <0fe00000> 3ce20003 39000001 3c62ff96
---[ end trace 4c438d5cebf78381 ]---
ftrace failed to modify
[<c0080000012a0008>] 0xc0080000012a0008
actual: 01:00:4c:3c
Initializing ftrace call sites
ftrace record flags: 2000000
(0)
expected tramp: c00000000006af4c

Looking at the relocation records in __mcount_loc showed a few spurious
entries:
RELOCATION RECORDS FOR [__mcount_loc]:
OFFSET TYPE VALUE
0000000000000000 R_PPC64_ADDR64 .text.unlikely+0x0000000000000008
0000000000000008 R_PPC64_ADDR64 .text.unlikely+0x0000000000000014
0000000000000010 R_PPC64_ADDR64 .text.unlikely+0x0000000000000060
0000000000000018 R_PPC64_ADDR64 .text.unlikely+0x00000000000000b4
0000000000000020 R_PPC64_ADDR64 .init.text+0x0000000000000008
0000000000000028 R_PPC64_ADDR64 .init.text+0x0000000000000014

The first entry in each section is incorrect. Looking at the relocation
records, the spurious entries correspond to the R_PPC64_ENTRY records:
RELOCATION RECORDS FOR [.text.unlikely]:
OFFSET TYPE VALUE
0000000000000000 R_PPC64_REL64 .TOC.-0x0000000000000008
0000000000000008 R_PPC64_ENTRY *ABS*
0000000000000014 R_PPC64_REL24 _mcount
<snip>

The problem is that we are not validating the return value from
get_mcountsym() in sift_rel_mcount(). With this entry, mcountsym is 0,
but Elf_r_sym(relp) also ends up being 0. Fix this by ensuring mcountsym
is valid before processing the entry.

Fixes: c7d64b560ce80 ("powerpc/ftrace: Enable C Version of recordmcount")
Signed-off-by: Naveen N. Rao <[email protected]>
---
scripts/recordmcount.h | 3 ++-
1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/scripts/recordmcount.h b/scripts/recordmcount.h
index 13c5e6c8829c..47fca2c69a73 100644
--- a/scripts/recordmcount.h
+++ b/scripts/recordmcount.h
@@ -325,7 +325,8 @@ static uint_t *sift_rel_mcount(uint_t *mlocp,
if (!mcountsym)
mcountsym = get_mcountsym(sym0, relp, str0);

- if (mcountsym == Elf_r_sym(relp) && !is_fake_mcount(relp)) {
+ if (mcountsym && mcountsym == Elf_r_sym(relp) &&
+ !is_fake_mcount(relp)) {
uint_t const addend =
_w(_w(relp->r_offset) - recval + mcount_adjust);
mrelp->r_offset = _w(offbase
--
2.22.0


2019-06-27 05:56:24

by Michael Ellerman

[permalink] [raw]
Subject: Re: [PATCH] recordmcount: Fix spurious mcount entries on powerpc

"Naveen N. Rao" <[email protected]> writes:
> The recent change enabling HAVE_C_RECORDMCOUNT on powerpc started
> showing the following issue:
>
> # modprobe kprobe_example
> ftrace-powerpc: Not expected bl: opcode is 3c4c0001
> WARNING: CPU: 0 PID: 227 at kernel/trace/ftrace.c:2001 ftrace_bug+0x90/0x318
> Modules linked in:
> CPU: 0 PID: 227 Comm: modprobe Not tainted 5.2.0-rc6-00678-g1c329100b942 #2
> NIP: c000000000264318 LR: c00000000025d694 CTR: c000000000f5cd30
> REGS: c000000001f2b7b0 TRAP: 0700 Not tainted (5.2.0-rc6-00678-g1c329100b942)
> MSR: 900000010282b033 <SF,HV,VEC,VSX,EE,FP,ME,IR,DR,RI,LE,TM[E]> CR: 28228222 XER: 00000000
> CFAR: c0000000002642fc IRQMASK: 0
> <snip>
> NIP [c000000000264318] ftrace_bug+0x90/0x318
> LR [c00000000025d694] ftrace_process_locs+0x4f4/0x5e0
> Call Trace:
> [c000000001f2ba40] [0000000000000004] 0x4 (unreliable)
> [c000000001f2bad0] [c00000000025d694] ftrace_process_locs+0x4f4/0x5e0
> [c000000001f2bb90] [c00000000020ff10] load_module+0x25b0/0x30c0
> [c000000001f2bd00] [c000000000210cb0] sys_finit_module+0xc0/0x130
> [c000000001f2be20] [c00000000000bda4] system_call+0x5c/0x70
> Instruction dump:
> 419e0018 2f83ffff 419e00bc 2f83ffea 409e00cc 4800001c 0fe00000 3c62ff96
> 39000001 39400000 386386d0 480000c4 <0fe00000> 3ce20003 39000001 3c62ff96
> ---[ end trace 4c438d5cebf78381 ]---
> ftrace failed to modify
> [<c0080000012a0008>] 0xc0080000012a0008
> actual: 01:00:4c:3c
> Initializing ftrace call sites
> ftrace record flags: 2000000
> (0)
> expected tramp: c00000000006af4c

Aha, thanks. I saw that on one of my text boxes but hadn't pinned it
down to this commit.

> Fixes: c7d64b560ce80 ("powerpc/ftrace: Enable C Version of recordmcount")

That commit is the tip of my next, so I'll drop it for now and merge
them in the other order so there's breakage.

Steve are you OK if I merge this via the powerpc tree? I'll reword the
commit message so that it makes sense coming prior to the commit
mentioned above.

cheers

> Signed-off-by: Naveen N. Rao <[email protected]>
> ---
> scripts/recordmcount.h | 3 ++-
> 1 file changed, 2 insertions(+), 1 deletion(-)
>
> diff --git a/scripts/recordmcount.h b/scripts/recordmcount.h
> index 13c5e6c8829c..47fca2c69a73 100644
> --- a/scripts/recordmcount.h
> +++ b/scripts/recordmcount.h
> @@ -325,7 +325,8 @@ static uint_t *sift_rel_mcount(uint_t *mlocp,
> if (!mcountsym)
> mcountsym = get_mcountsym(sym0, relp, str0);
>
> - if (mcountsym == Elf_r_sym(relp) && !is_fake_mcount(relp)) {
> + if (mcountsym && mcountsym == Elf_r_sym(relp) &&
> + !is_fake_mcount(relp)) {
> uint_t const addend =
> _w(_w(relp->r_offset) - recval + mcount_adjust);
> mrelp->r_offset = _w(offbase
> --
> 2.22.0

2019-06-27 10:24:46

by Satheesh Rajendran

[permalink] [raw]
Subject: Re: [PATCH] recordmcount: Fix spurious mcount entries on powerpc

On Thu, Jun 27, 2019 at 12:08:01AM +0530, Naveen N. Rao wrote:
> The recent change enabling HAVE_C_RECORDMCOUNT on powerpc started
> showing the following issue:
>
> # modprobe kprobe_example
> ftrace-powerpc: Not expected bl: opcode is 3c4c0001
> WARNING: CPU: 0 PID: 227 at kernel/trace/ftrace.c:2001 ftrace_bug+0x90/0x318
> Modules linked in:
> CPU: 0 PID: 227 Comm: modprobe Not tainted 5.2.0-rc6-00678-g1c329100b942 #2
> NIP: c000000000264318 LR: c00000000025d694 CTR: c000000000f5cd30
> REGS: c000000001f2b7b0 TRAP: 0700 Not tainted (5.2.0-rc6-00678-g1c329100b942)
> MSR: 900000010282b033 <SF,HV,VEC,VSX,EE,FP,ME,IR,DR,RI,LE,TM[E]> CR: 28228222 XER: 00000000
> CFAR: c0000000002642fc IRQMASK: 0
> <snip>
> NIP [c000000000264318] ftrace_bug+0x90/0x318
> LR [c00000000025d694] ftrace_process_locs+0x4f4/0x5e0
> Call Trace:
> [c000000001f2ba40] [0000000000000004] 0x4 (unreliable)
> [c000000001f2bad0] [c00000000025d694] ftrace_process_locs+0x4f4/0x5e0
> [c000000001f2bb90] [c00000000020ff10] load_module+0x25b0/0x30c0
> [c000000001f2bd00] [c000000000210cb0] sys_finit_module+0xc0/0x130
> [c000000001f2be20] [c00000000000bda4] system_call+0x5c/0x70
> Instruction dump:
> 419e0018 2f83ffff 419e00bc 2f83ffea 409e00cc 4800001c 0fe00000 3c62ff96
> 39000001 39400000 386386d0 480000c4 <0fe00000> 3ce20003 39000001 3c62ff96
> ---[ end trace 4c438d5cebf78381 ]---
> ftrace failed to modify
> [<c0080000012a0008>] 0xc0080000012a0008
> actual: 01:00:4c:3c
> Initializing ftrace call sites
> ftrace record flags: 2000000
> (0)
> expected tramp: c00000000006af4c
>
> Looking at the relocation records in __mcount_loc showed a few spurious
> entries:
> RELOCATION RECORDS FOR [__mcount_loc]:
> OFFSET TYPE VALUE
> 0000000000000000 R_PPC64_ADDR64 .text.unlikely+0x0000000000000008
> 0000000000000008 R_PPC64_ADDR64 .text.unlikely+0x0000000000000014
> 0000000000000010 R_PPC64_ADDR64 .text.unlikely+0x0000000000000060
> 0000000000000018 R_PPC64_ADDR64 .text.unlikely+0x00000000000000b4
> 0000000000000020 R_PPC64_ADDR64 .init.text+0x0000000000000008
> 0000000000000028 R_PPC64_ADDR64 .init.text+0x0000000000000014
>
> The first entry in each section is incorrect. Looking at the relocation
> records, the spurious entries correspond to the R_PPC64_ENTRY records:
> RELOCATION RECORDS FOR [.text.unlikely]:
> OFFSET TYPE VALUE
> 0000000000000000 R_PPC64_REL64 .TOC.-0x0000000000000008
> 0000000000000008 R_PPC64_ENTRY *ABS*
> 0000000000000014 R_PPC64_REL24 _mcount
> <snip>
>
> The problem is that we are not validating the return value from
> get_mcountsym() in sift_rel_mcount(). With this entry, mcountsym is 0,
> but Elf_r_sym(relp) also ends up being 0. Fix this by ensuring mcountsym
> is valid before processing the entry.
>
> Fixes: c7d64b560ce80 ("powerpc/ftrace: Enable C Version of recordmcount")
> Signed-off-by: Naveen N. Rao <[email protected]>
> ---
> scripts/recordmcount.h | 3 ++-
> 1 file changed, 2 insertions(+), 1 deletion(-)
Hi,

linuxppc/merge branch latest commit 850f6274c5b5 was failing to boot IBM
Power8 Box, and the failure got resolved with this patch.
https://github.com/linuxppc/issues/issues/254

# git log -2 --oneline
0e0f55b31ea8 (HEAD -> issue_254) recordmcount: Fix spurious mcount entries on powerpc
850f6274c5b5 (origin/merge, merge) Automatic merge of branches 'master', 'next' and 'fixes' into merge
# uname -r
5.2.0-rc6-00123-g0e0f55b31ea8

Tested-by: Satheesh Rajendran <[email protected]>

Regards,
-Satheesh
>
> diff --git a/scripts/recordmcount.h b/scripts/recordmcount.h
> index 13c5e6c8829c..47fca2c69a73 100644
> --- a/scripts/recordmcount.h
> +++ b/scripts/recordmcount.h
> @@ -325,7 +325,8 @@ static uint_t *sift_rel_mcount(uint_t *mlocp,
> if (!mcountsym)
> mcountsym = get_mcountsym(sym0, relp, str0);
>
> - if (mcountsym == Elf_r_sym(relp) && !is_fake_mcount(relp)) {
> + if (mcountsym && mcountsym == Elf_r_sym(relp) &&
> + !is_fake_mcount(relp)) {
> uint_t const addend =
> _w(_w(relp->r_offset) - recval + mcount_adjust);
> mrelp->r_offset = _w(offbase
> --
> 2.22.0
>

2019-06-27 13:18:49

by Steven Rostedt

[permalink] [raw]
Subject: Re: [PATCH] recordmcount: Fix spurious mcount entries on powerpc

On Thu, 27 Jun 2019 15:55:47 +1000
Michael Ellerman <[email protected]> wrote:

> Steve are you OK if I merge this via the powerpc tree? I'll reword the
> commit message so that it makes sense coming prior to the commit
> mentioned above.

Yes, please add:

Acked-by: Steven Rostedt (VMware) <[email protected]>

Thanks,

-- Steve

2019-06-28 01:38:48

by Michael Ellerman

[permalink] [raw]
Subject: Re: [PATCH] recordmcount: Fix spurious mcount entries on powerpc

Steven Rostedt <[email protected]> writes:
> On Thu, 27 Jun 2019 15:55:47 +1000
> Michael Ellerman <[email protected]> wrote:
>
>> Steve are you OK if I merge this via the powerpc tree? I'll reword the
>> commit message so that it makes sense coming prior to the commit
>> mentioned above.
>
> Yes, please add:
>
> Acked-by: Steven Rostedt (VMware) <[email protected]>

Thanks.

cheers

2019-06-28 01:40:46

by Michael Ellerman

[permalink] [raw]
Subject: Re: [PATCH] recordmcount: Fix spurious mcount entries on powerpc

Satheesh Rajendran <[email protected]> writes:
> On Thu, Jun 27, 2019 at 12:08:01AM +0530, Naveen N. Rao wrote:
>> The recent change enabling HAVE_C_RECORDMCOUNT on powerpc started
>> showing the following issue:
>>
>> # modprobe kprobe_example
>> ftrace-powerpc: Not expected bl: opcode is 3c4c0001
>> WARNING: CPU: 0 PID: 227 at kernel/trace/ftrace.c:2001 ftrace_bug+0x90/0x318
>> Modules linked in:
>> CPU: 0 PID: 227 Comm: modprobe Not tainted 5.2.0-rc6-00678-g1c329100b942 #2
>> NIP: c000000000264318 LR: c00000000025d694 CTR: c000000000f5cd30
>> REGS: c000000001f2b7b0 TRAP: 0700 Not tainted (5.2.0-rc6-00678-g1c329100b942)
>> MSR: 900000010282b033 <SF,HV,VEC,VSX,EE,FP,ME,IR,DR,RI,LE,TM[E]> CR: 28228222 XER: 00000000
>> CFAR: c0000000002642fc IRQMASK: 0
>> <snip>
>> NIP [c000000000264318] ftrace_bug+0x90/0x318
>> LR [c00000000025d694] ftrace_process_locs+0x4f4/0x5e0
>> Call Trace:
>> [c000000001f2ba40] [0000000000000004] 0x4 (unreliable)
>> [c000000001f2bad0] [c00000000025d694] ftrace_process_locs+0x4f4/0x5e0
>> [c000000001f2bb90] [c00000000020ff10] load_module+0x25b0/0x30c0
>> [c000000001f2bd00] [c000000000210cb0] sys_finit_module+0xc0/0x130
>> [c000000001f2be20] [c00000000000bda4] system_call+0x5c/0x70
>> Instruction dump:
>> 419e0018 2f83ffff 419e00bc 2f83ffea 409e00cc 4800001c 0fe00000 3c62ff96
>> 39000001 39400000 386386d0 480000c4 <0fe00000> 3ce20003 39000001 3c62ff96
>> ---[ end trace 4c438d5cebf78381 ]---
>> ftrace failed to modify
>> [<c0080000012a0008>] 0xc0080000012a0008
>> actual: 01:00:4c:3c
>> Initializing ftrace call sites
>> ftrace record flags: 2000000
>> (0)
>> expected tramp: c00000000006af4c
>>
>> Looking at the relocation records in __mcount_loc showed a few spurious
>> entries:
>> RELOCATION RECORDS FOR [__mcount_loc]:
>> OFFSET TYPE VALUE
>> 0000000000000000 R_PPC64_ADDR64 .text.unlikely+0x0000000000000008
>> 0000000000000008 R_PPC64_ADDR64 .text.unlikely+0x0000000000000014
>> 0000000000000010 R_PPC64_ADDR64 .text.unlikely+0x0000000000000060
>> 0000000000000018 R_PPC64_ADDR64 .text.unlikely+0x00000000000000b4
>> 0000000000000020 R_PPC64_ADDR64 .init.text+0x0000000000000008
>> 0000000000000028 R_PPC64_ADDR64 .init.text+0x0000000000000014
>>
>> The first entry in each section is incorrect. Looking at the relocation
>> records, the spurious entries correspond to the R_PPC64_ENTRY records:
>> RELOCATION RECORDS FOR [.text.unlikely]:
>> OFFSET TYPE VALUE
>> 0000000000000000 R_PPC64_REL64 .TOC.-0x0000000000000008
>> 0000000000000008 R_PPC64_ENTRY *ABS*
>> 0000000000000014 R_PPC64_REL24 _mcount
>> <snip>
>>
>> The problem is that we are not validating the return value from
>> get_mcountsym() in sift_rel_mcount(). With this entry, mcountsym is 0,
>> but Elf_r_sym(relp) also ends up being 0. Fix this by ensuring mcountsym
>> is valid before processing the entry.
>>
>> Fixes: c7d64b560ce80 ("powerpc/ftrace: Enable C Version of recordmcount")
>> Signed-off-by: Naveen N. Rao <[email protected]>
>> ---
>> scripts/recordmcount.h | 3 ++-
>> 1 file changed, 2 insertions(+), 1 deletion(-)
> Hi,
>
> linuxppc/merge branch latest commit 850f6274c5b5 was failing to boot IBM
> Power8 Box, and the failure got resolved with this patch.
> https://github.com/linuxppc/issues/issues/254
>
> # git log -2 --oneline
> 0e0f55b31ea8 (HEAD -> issue_254) recordmcount: Fix spurious mcount entries on powerpc
> 850f6274c5b5 (origin/merge, merge) Automatic merge of branches 'master', 'next' and 'fixes' into merge
> # uname -r
> 5.2.0-rc6-00123-g0e0f55b31ea8
>
> Tested-by: Satheesh Rajendran <[email protected]>

Thanks. I've pulled the broken commit out of merge for now.

The fix and the original commit will show up in merge later today
probably.

cheers

2019-07-03 14:29:11

by Michael Ellerman

[permalink] [raw]
Subject: Re: [PATCH] recordmcount: Fix spurious mcount entries on powerpc

On Wed, 2019-06-26 at 18:38:01 UTC, "Naveen N. Rao" wrote:
> The recent change enabling HAVE_C_RECORDMCOUNT on powerpc started
> showing the following issue:
>
> # modprobe kprobe_example
> ftrace-powerpc: Not expected bl: opcode is 3c4c0001
> WARNING: CPU: 0 PID: 227 at kernel/trace/ftrace.c:2001 ftrace_bug+0x90/0x318
> Modules linked in:
> CPU: 0 PID: 227 Comm: modprobe Not tainted 5.2.0-rc6-00678-g1c329100b942 #2
> NIP: c000000000264318 LR: c00000000025d694 CTR: c000000000f5cd30
> REGS: c000000001f2b7b0 TRAP: 0700 Not tainted (5.2.0-rc6-00678-g1c329100b942)
> MSR: 900000010282b033 <SF,HV,VEC,VSX,EE,FP,ME,IR,DR,RI,LE,TM[E]> CR: 28228222 XER: 00000000
> CFAR: c0000000002642fc IRQMASK: 0
> <snip>
> NIP [c000000000264318] ftrace_bug+0x90/0x318
> LR [c00000000025d694] ftrace_process_locs+0x4f4/0x5e0
> Call Trace:
> [c000000001f2ba40] [0000000000000004] 0x4 (unreliable)
> [c000000001f2bad0] [c00000000025d694] ftrace_process_locs+0x4f4/0x5e0
> [c000000001f2bb90] [c00000000020ff10] load_module+0x25b0/0x30c0
> [c000000001f2bd00] [c000000000210cb0] sys_finit_module+0xc0/0x130
> [c000000001f2be20] [c00000000000bda4] system_call+0x5c/0x70
> Instruction dump:
> 419e0018 2f83ffff 419e00bc 2f83ffea 409e00cc 4800001c 0fe00000 3c62ff96
> 39000001 39400000 386386d0 480000c4 <0fe00000> 3ce20003 39000001 3c62ff96
> ---[ end trace 4c438d5cebf78381 ]---
> ftrace failed to modify
> [<c0080000012a0008>] 0xc0080000012a0008
> actual: 01:00:4c:3c
> Initializing ftrace call sites
> ftrace record flags: 2000000
> (0)
> expected tramp: c00000000006af4c
>
> Looking at the relocation records in __mcount_loc showed a few spurious
> entries:
> RELOCATION RECORDS FOR [__mcount_loc]:
> OFFSET TYPE VALUE
> 0000000000000000 R_PPC64_ADDR64 .text.unlikely+0x0000000000000008
> 0000000000000008 R_PPC64_ADDR64 .text.unlikely+0x0000000000000014
> 0000000000000010 R_PPC64_ADDR64 .text.unlikely+0x0000000000000060
> 0000000000000018 R_PPC64_ADDR64 .text.unlikely+0x00000000000000b4
> 0000000000000020 R_PPC64_ADDR64 .init.text+0x0000000000000008
> 0000000000000028 R_PPC64_ADDR64 .init.text+0x0000000000000014
>
> The first entry in each section is incorrect. Looking at the relocation
> records, the spurious entries correspond to the R_PPC64_ENTRY records:
> RELOCATION RECORDS FOR [.text.unlikely]:
> OFFSET TYPE VALUE
> 0000000000000000 R_PPC64_REL64 .TOC.-0x0000000000000008
> 0000000000000008 R_PPC64_ENTRY *ABS*
> 0000000000000014 R_PPC64_REL24 _mcount
> <snip>
>
> The problem is that we are not validating the return value from
> get_mcountsym() in sift_rel_mcount(). With this entry, mcountsym is 0,
> but Elf_r_sym(relp) also ends up being 0. Fix this by ensuring mcountsym
> is valid before processing the entry.
>
> Fixes: c7d64b560ce80 ("powerpc/ftrace: Enable C Version of recordmcount")
> Signed-off-by: Naveen N. Rao <[email protected]>
> Tested-by: Satheesh Rajendran <[email protected]>
> Acked-by: Steven Rostedt (VMware) <[email protected]>

Applied to powerpc next, thanks.

https://git.kernel.org/powerpc/c/80e5302e4bc85a6b685b7668c36c6487b5f90e9a

cheers