dynamic ftrace/recordmcount.c problem on ARMv5

DISCUSSION Marc Kleine-Budde 4 participants 10 messages Jan 13, 2016 – Mar 20, 2016

lore

Share & tools

lore

Marc Kleine-Budde

author

2016-01-13 08:51 UTC #0 lore raw

Hello,

I'm on a ARMv5 (freescale mx25) and seeing this ftrace bug during bootup:

Quoted 11 lines

[    0.059235] ------------[ cut here ]------------
[    0.059449] WARNING: CPU: 0 PID: 0 at kernel/trace/ftrace.c:1938 ftrace_bug+0x210/0x2c8()
[    0.059645] Modules linked in:
[    0.059780] CPU: 0 PID: 0 Comm: swapper Not tainted 4.0.9-20151211-1-g45dbe7d2c077 #1
[    0.059966] Hardware name: Freescale i.MX25 (Device Tree Support)
[    0.060157] [<8000f494>] (unwind_backtrace) from [<8000ce3c>] (show_stack+0x20/0x24)
[    0.060396] [<8000ce3c>] (show_stack) from [<8041ea68>] (dump_stack+0x20/0x28)
[    0.060630] [<8041ea68>] (dump_stack) from [<8001a74c>] (warn_slowpath_common+0x88/0xc0)
[    0.060853] [<8001a74c>] (warn_slowpath_common) from [<8001a840>] (warn_slowpath_null+0x2c/0x34)
[    0.061091] [<8001a840>] (warn_slowpath_null) from [<80083748>] (ftrace_bug+0x210/0x2c8)
[    0.061332] [<80083748>] (ftrace_bug) from [<80083bb8>] (ftrace_process_locs+0x330/0x6f0)

Quoted 8 lines

[    0.061576] [<80083bb8>] (ftrace_process_locs) from [<805bdc84>] (ftrace_init+0x8c/0x14c)
[    0.061815] [<805bdc84>] (ftrace_init) from [<805b0c80>] (start_kernel+0x33c/0x3b4)
[    0.062039] [<805b0c80>] (start_kernel) from [<80008040>] (0x80008040)
[    0.062238] ---[ end trace cb88537fdc8fa200 ]---
[    0.062364] ftrace failed to modify [<8000c7d8>] walk_stackframe+0x24/0x44
[    0.062544]  actual: 16:ff:2f:e1
[    0.062702] ftrace record flags: 0
[    0.062803]  (0)   expected tramp: 8000e864

The problem is that walk_stackframe ends up in the __mcount_loc section, although it has a "notrace" attribute:

Quoted 2 lines

$ grep notrace arch/arm/kernel/stacktrace.c | grep walk_stackframe
void notrace walk_stackframe(struct stackframe *frame,

To reproduce:

- use the arm compiler from kernel.org:

Quoted 1 line

https://www.kernel.org/pub/tools/crosstool/files/bin/x86_64/4.9.0/x86_64-gcc-4.9.0-nolibc_arm-unknown-linux-gnueabi.tar.xz

- linus master
(67990608c8b9 Merge tag 'pm+acpi-4.5-rc1-1' of
git://git.kernel.org/pub/scm/linux/kernel/git/rafael/linux-pm)

- a ARMv5 config

Quoted 1 line

make imx_v4_v5_defconfig

- switch on the function tracer and dynamic ftrace

Quoted 3 lines

CONFIG_HAVE_FUNCTION_TRACER=y
CONFIG_HAVE_FUNCTION_GRAPH_TRACER=y
CONFIG_HAVE_DYNAMIC_FTRACE=y

- build the object file that contains walk_stackframe:

Quoted 1 line

$ make arch/arm/kernel/stacktrace.o

Observations:

- There is no branch to the mcount function ("bl 0 <__gnu_mcount_nc>"), which is good:

Quoted 6 lines

$ objdump -d arch/arm/kernel/stacktrace.o |grep "<walk_stackframe>:" -A12
00000000 <walk_stackframe>:
   0:	e1a0c00d 	mov	ip, sp
   4:	e92dd878 	push	{r3, r4, r5, r6, fp, ip, lr, pc}
   8:	e24cb004 	sub	fp, ip, #4
   c:	e1a04000 	mov	r4, r0

Quoted 8 lines

  10:	e1a06001 	mov	r6, r1
  14:	e1a05002 	mov	r5, r2
  18:	e1a00004 	mov	r0, r4
  1c:	e1a01005 	mov	r1, r5
  20:	e1a0e00f 	mov	lr, pc
  24:	e12fff16 	bx	r6
  28:	e3500000 	cmp	r0, #0
  2c:	189da878 	ldmne	sp, {r3, r4, r5, r6, fp, sp, pc}

There are 5 calls to __gnu_mcount_nc in the object file:

Quoted 6 lines

$ objdump -x arch/arm/kernel/stacktrace.o | grep R_ARM_CALL | grep __gnu_mcount_nc
00000054 R_ARM_CALL        __gnu_mcount_nc
0000016c R_ARM_CALL        __gnu_mcount_nc
00000234 R_ARM_CALL        __gnu_mcount_nc
0000026c R_ARM_CALL        __gnu_mcount_nc
000002f4 R_ARM_CALL        __gnu_mcount_nc

However there are 6 references in the __mcount_loc section:

Quoted 5 lines

$ readelf -R __mcount_loc arch/arm/kernel/stacktrace.o                            
Hex dump of section '__mcount_loc':
0x00000000 24000000 54000000 6c010000 34020000 $...T...l...4...
0x00000010 6c020000 f4020000 l.......

Note: The first and wrong offset is 0x24, which is a "bx r6" (see above objdump of stacktrace.o):

Quoted 1 line

24: e12fff16 bx r6

I hacked scripts/Makefile.build to use the perl version of recordmcount, that works without problems.

regards,
Marc

Signature · 4 lines

Pengutronix e.K.                  | Marc Kleine-Budde           |
Industrial Linux Solutions        | Phone: +49-231-2826-924     |
Vertretung West/Dortmund          | Fax:   +49-5121-206917-5555 |
Amtsgericht Hildesheim, HRA 2686  | http://www.pengutronix.de   |

Steven Rostedt

2016-01-13 16:09 UTC #1 lore raw

Quoted 9 lines · On Wed, 13 Jan 2016 09:51:28 +0100 Marc Kleine-Budde <[email protected]> wrote:

There are 5 calls to __gnu_mcount_nc in the object file:

Quoted 6 lines

$ objdump -x arch/arm/kernel/stacktrace.o | grep R_ARM_CALL | grep __gnu_mcount_nc
00000054 R_ARM_CALL        __gnu_mcount_nc
0000016c R_ARM_CALL        __gnu_mcount_nc
00000234 R_ARM_CALL        __gnu_mcount_nc
0000026c R_ARM_CALL        __gnu_mcount_nc
000002f4 R_ARM_CALL        __gnu_mcount_nc

However there are 6 references in the __mcount_loc section:

Quoted 9 lines

Quoted 5 lines
$ readelf -R __mcount_loc arch/arm/kernel/stacktrace.o                            
Hex dump of section '__mcount_loc':
0x00000000 24000000 54000000 6c010000 34020000 $...T...l...4...
0x00000010 6c020000 f4020000 l.......
Note: The first and wrong offset is 0x24, which is a "bx r6" (see above objdump of stacktrace.o):
Quoted 1 line
24: e12fff16 bx r6

Interesting. Have you tried a make mrproper and tried again? Also, do you use hardlinks with ccache?

Quoted 3 lines

I hacked scripts/Makefile.build to use the perl version of recordmcount, that works without problems.

Note, you could also just removed CONFIG_HAVE_C_RECORDMCOUNT from arch/arm/Kconfig.

-- Steve

Marc Kleine-Budde

author

2016-01-13 16:24 UTC #2 lore raw

Quoted 18 lines · Steven Rostedt

Quoted 15 lines · On Wed, 13 Jan 2016 09:51:28 +0100 Marc Kleine-Budde <[email protected]> wrote:
There are 5 calls to __gnu_mcount_nc in the object file:
Quoted 6 lines
$ objdump -x arch/arm/kernel/stacktrace.o | grep R_ARM_CALL | grep __gnu_mcount_nc
00000054 R_ARM_CALL        __gnu_mcount_nc
0000016c R_ARM_CALL        __gnu_mcount_nc
00000234 R_ARM_CALL        __gnu_mcount_nc
0000026c R_ARM_CALL        __gnu_mcount_nc
000002f4 R_ARM_CALL        __gnu_mcount_nc  
However there are 6 references in the __mcount_loc section:
Quoted 5 lines
$ readelf -R __mcount_loc arch/arm/kernel/stacktrace.o                            
Hex dump of section '__mcount_loc':
0x00000000 24000000 54000000 6c010000 34020000 $...T...l...4...
0x00000010 6c020000 f4020000 l.......

Quoted 6 lines

Quoted 3 lines
Note: The first and wrong offset is 0x24, which is a "bx r6" (see above objdump of stacktrace.o):
Quoted 1 line
24: e12fff16 bx r6
Interesting. Have you tried a make mrproper and tried again? Also, do you use hardlinks with ccache?

That happens on ARMv5 with a clean build. No ccache involved (this issue should be fixed on >= v4.4)

Quoted 5 lines

Quoted 2 lines
I hacked scripts/Makefile.build to use the perl version of recordmcount, that works without problems.
Note, you could also just removed CONFIG_HAVE_C_RECORDMCOUNT from arch/arm/Kconfig.

This is the patch I'm using as a workaround.

regards,
Marc

Signature · 4 lines

Pengutronix e.K.                  | Marc Kleine-Budde           |
Industrial Linux Solutions        | Phone: +49-231-2826-924     |
Vertretung West/Dortmund          | Fax:   +49-5121-206917-5555 |
Amtsgericht Hildesheim, HRA 2686  | http://www.pengutronix.de   |

Steven Rostedt

2016-01-13 16:27 UTC #3 lore raw

Quoted 2 lines · On Wed, 13 Jan 2016 17:23:52 +0100 Marc Kleine-Budde <[email protected]> wrote:

That happens on ARMv5 with a clean build. No ccache involved (this issue should be fixed on >= v4.4)

It's fixed in mainline? If so, maybe you can do a reverse bisect to find the patch that fixes it.

-- Steve

Marc Kleine-Budde

author

2016-01-13 16:30 UTC #4 lore raw

Quoted 8 lines · Steven Rostedt

Quoted 2 lines · On Wed, 13 Jan 2016 17:23:52 +0100 Marc Kleine-Budde <[email protected]> wrote:
That happens on ARMv5 with a clean build. No ccache involved (this issue should be fixed on >= v4.4)
It's fixed in mainline? If so, maybe you can do a reverse bisect to find the patch that fixes it.

Sorry for the confusion - I mean the ccache hardlink issue should be fixed on mainline, with:
dd39a26538e3 scripts: recordmcount: break hardlinks a50bd4393558 ftrace/scripts: Have recordmcount copy the object file

The recordmcount.c problem on ARMv5 occurs on mainline.

Marc

Signature · 4 lines

Pengutronix e.K.                  | Marc Kleine-Budde           |
Industrial Linux Solutions        | Phone: +49-231-2826-924     |
Vertretung West/Dortmund          | Fax:   +49-5121-206917-5555 |
Amtsgericht Hildesheim, HRA 2686  | http://www.pengutronix.de   |

Marc Kleine-Budde

author

2016-02-08 15:38 UTC #5 lore raw

In reply to Marc Kleine-Budde

Quoted 86 lines · Marc Kleine-Budde

Hello,
I'm on a ARMv5 (freescale mx25) and seeing this ftrace bug during bootup:
Quoted 11 lines
[    0.059235] ------------[ cut here ]------------
[    0.059449] WARNING: CPU: 0 PID: 0 at kernel/trace/ftrace.c:1938 ftrace_bug+0x210/0x2c8()
[    0.059645] Modules linked in:
[    0.059780] CPU: 0 PID: 0 Comm: swapper Not tainted 4.0.9-20151211-1-g45dbe7d2c077 #1
[    0.059966] Hardware name: Freescale i.MX25 (Device Tree Support)
[    0.060157] [<8000f494>] (unwind_backtrace) from [<8000ce3c>] (show_stack+0x20/0x24)
[    0.060396] [<8000ce3c>] (show_stack) from [<8041ea68>] (dump_stack+0x20/0x28)
[    0.060630] [<8041ea68>] (dump_stack) from [<8001a74c>] (warn_slowpath_common+0x88/0xc0)
[    0.060853] [<8001a74c>] (warn_slowpath_common) from [<8001a840>] (warn_slowpath_null+0x2c/0x34)
[    0.061091] [<8001a840>] (warn_slowpath_null) from [<80083748>] (ftrace_bug+0x210/0x2c8)
[    0.061332] [<80083748>] (ftrace_bug) from [<80083bb8>] (ftrace_process_locs+0x330/0x6f0)
Quoted 8 lines
[    0.061576] [<80083bb8>] (ftrace_process_locs) from [<805bdc84>] (ftrace_init+0x8c/0x14c)
[    0.061815] [<805bdc84>] (ftrace_init) from [<805b0c80>] (start_kernel+0x33c/0x3b4)
[    0.062039] [<805b0c80>] (start_kernel) from [<80008040>] (0x80008040)
[    0.062238] ---[ end trace cb88537fdc8fa200 ]---
[    0.062364] ftrace failed to modify [<8000c7d8>] walk_stackframe+0x24/0x44
[    0.062544]  actual: 16:ff:2f:e1
[    0.062702] ftrace record flags: 0
[    0.062803]  (0)   expected tramp: 8000e864
The problem is that walk_stackframe ends up in the __mcount_loc section, although it has a "notrace" attribute:
Quoted 2 lines
$ grep notrace arch/arm/kernel/stacktrace.c | grep walk_stackframe
void notrace walk_stackframe(struct stackframe *frame,
To reproduce:
- use the arm compiler from kernel.org:
Quoted 1 line
https://www.kernel.org/pub/tools/crosstool/files/bin/x86_64/4.9.0/x86_64-gcc-4.9.0-nolibc_arm-unknown-linux-gnueabi.tar.xz
- linus master
(67990608c8b9 Merge tag 'pm+acpi-4.5-rc1-1' of
git://git.kernel.org/pub/scm/linux/kernel/git/rafael/linux-pm)
- a ARMv5 config
Quoted 1 line
make imx_v4_v5_defconfig
- switch on the function tracer and dynamic ftrace
Quoted 3 lines
CONFIG_HAVE_FUNCTION_TRACER=y
CONFIG_HAVE_FUNCTION_GRAPH_TRACER=y
CONFIG_HAVE_DYNAMIC_FTRACE=y
- build the object file that contains walk_stackframe:
Quoted 1 line
$ make arch/arm/kernel/stacktrace.o
Observations:
- There is no branch to the mcount function ("bl 0 <__gnu_mcount_nc>"), which is good:
Quoted 6 lines
$ objdump -d arch/arm/kernel/stacktrace.o |grep "<walk_stackframe>:" -A12
00000000 <walk_stackframe>:
   0:	e1a0c00d 	mov	ip, sp
   4:	e92dd878 	push	{r3, r4, r5, r6, fp, ip, lr, pc}
   8:	e24cb004 	sub	fp, ip, #4
   c:	e1a04000 	mov	r4, r0
Quoted 8 lines
  10:	e1a06001 	mov	r6, r1
  14:	e1a05002 	mov	r5, r2
  18:	e1a00004 	mov	r0, r4
  1c:	e1a01005 	mov	r1, r5
  20:	e1a0e00f 	mov	lr, pc
  24:	e12fff16 	bx	r6
  28:	e3500000 	cmp	r0, #0
  2c:	189da878 	ldmne	sp, {r3, r4, r5, r6, fp, sp, pc}
There are 5 calls to __gnu_mcount_nc in the object file:
Quoted 6 lines
$ objdump -x arch/arm/kernel/stacktrace.o | grep R_ARM_CALL | grep __gnu_mcount_nc
00000054 R_ARM_CALL        __gnu_mcount_nc
0000016c R_ARM_CALL        __gnu_mcount_nc
00000234 R_ARM_CALL        __gnu_mcount_nc
0000026c R_ARM_CALL        __gnu_mcount_nc
000002f4 R_ARM_CALL        __gnu_mcount_nc
However there are 6 references in the __mcount_loc section:
Quoted 5 lines
$ readelf -R __mcount_loc arch/arm/kernel/stacktrace.o                            
Hex dump of section '__mcount_loc':
0x00000000 24000000 54000000 6c010000 34020000 $...T...l...4...
0x00000010 6c020000 f4020000 l.......

Quoted 6 lines

Note: The first and wrong offset is 0x24, which is a "bx r6" (see above objdump of stacktrace.o):
Quoted 1 line
24: e12fff16 bx r6
I hacked scripts/Makefile.build to use the perl version of recordmcount, that works without problems.

Has anyone looked at this issue?

regards,
Marc

Signature · 4 lines

Pengutronix e.K.                  | Marc Kleine-Budde           |
Industrial Linux Solutions        | Phone: +49-231-2826-924     |
Vertretung West/Dortmund          | Fax:   +49-5121-206917-5555 |
Amtsgericht Hildesheim, HRA 2686  | http://www.pengutronix.de   |

Steven Rostedt

2016-02-08 15:53 UTC #6 lore raw

Quoted 5 lines · On Mon, 8 Feb 2016 16:38:49 +0100 Marc Kleine-Budde <[email protected]> wrote:

Quoted 2 lines
I hacked scripts/Makefile.build to use the perl version of recordmcount, that works without problems.
Has anyone looked at this issue?

Sorry, I had a personal issue that took me offline for a while, and I forgot about it. I'll try to make time this week to look into it.

-- Steve

Uwe Kleine-König

2016-03-11 09:22 UTC #7 lore raw

In reply to Marc Kleine-Budde

Hello,

Quoted 24 lines · Marc Kleine-Budde

Hello,

I'm on a ARMv5 (freescale mx25) and seeing this ftrace bug during bootup:

Quoted 11 lines

[    0.059235] ------------[ cut here ]------------
[    0.059449] WARNING: CPU: 0 PID: 0 at kernel/trace/ftrace.c:1938 ftrace_bug+0x210/0x2c8()
[    0.059645] Modules linked in:
[    0.059780] CPU: 0 PID: 0 Comm: swapper Not tainted 4.0.9-20151211-1-g45dbe7d2c077 #1
[    0.059966] Hardware name: Freescale i.MX25 (Device Tree Support)
[    0.060157] [<8000f494>] (unwind_backtrace) from [<8000ce3c>] (show_stack+0x20/0x24)
[    0.060396] [<8000ce3c>] (show_stack) from [<8041ea68>] (dump_stack+0x20/0x28)
[    0.060630] [<8041ea68>] (dump_stack) from [<8001a74c>] (warn_slowpath_common+0x88/0xc0)
[    0.060853] [<8001a74c>] (warn_slowpath_common) from [<8001a840>] (warn_slowpath_null+0x2c/0x34)
[    0.061091] [<8001a840>] (warn_slowpath_null) from [<80083748>] (ftrace_bug+0x210/0x2c8)
[    0.061332] [<80083748>] (ftrace_bug) from [<80083bb8>] (ftrace_process_locs+0x330/0x6f0)

Quoted 8 lines

[    0.061576] [<80083bb8>] (ftrace_process_locs) from [<805bdc84>] (ftrace_init+0x8c/0x14c)
[    0.061815] [<805bdc84>] (ftrace_init) from [<805b0c80>] (start_kernel+0x33c/0x3b4)
[    0.062039] [<805b0c80>] (start_kernel) from [<80008040>] (0x80008040)
[    0.062238] ---[ end trace cb88537fdc8fa200 ]---
[    0.062364] ftrace failed to modify [<8000c7d8>] walk_stackframe+0x24/0x44
[    0.062544]  actual: 16:ff:2f:e1
[    0.062702] ftrace record flags: 0
[    0.062803]  (0)   expected tramp: 8000e864

Quoted 2 lines

The problem is that walk_stackframe ends up in the __mcount_loc section, although it has a "notrace" attribute:

Not having much clue about elf and stuff, but being hit by this problem I added some debug output to recordmcount.c and found that sift_rel_mcount (aka sift32_rel_mcount) loops over .rel.text which looks as follows for me:

	$ readelf -R .rel.text arch/arm/kernel/stacktrace.o 
	...
	Relocation section '.rel.text' at offset 0xb5c contains 15 entries:
	 Offset     Info    Type            Sym.Value  Sym. Name
	0000001c  00000028 R_ARM_V4BX       
	0000002c  00001d1c R_ARM_CALL        00000000   unwind_frame
	00000044  00001f1c R_ARM_CALL        00000000   __gnu_mcount_nc
	00000104  0000201c R_ARM_CALL        00000000   in_sched_functions
	00000118  00002102 R_ARM_ABS32       00000000   __exception_text_start
	0000011c  00002202 R_ARM_ABS32       00000000   __exception_text_end
	00000130  00001f1c R_ARM_CALL        00000000   __gnu_mcount_nc
	00000194  00001c1c R_ARM_CALL        00000000   walk_stackframe
	000001e0  00000902 R_ARM_ABS32       0000003c   save_trace
	000001e4  00000c02 R_ARM_ABS32       00000120   __save_stack_trace
	000001ec  00001f1c R_ARM_CALL        00000000   __gnu_mcount_nc
	00000218  00001f1c R_ARM_CALL        00000000   __gnu_mcount_nc
	00000260  00001c1c R_ARM_CALL        00000000   walk_stackframe
	0000028c  00000902 R_ARM_ABS32       0000003c   save_trace
	00000294  00001f1c R_ARM_CALL        00000000   __gnu_mcount_nc
	...

and the unwanted entry in __mcount_loc is generated from the first line which isn't a call, but just the information that there is a bx call that needs a fixup for ARMv4 machines (that don't support the bx instruction).

For this entry get_mcountsym returns 0.

recordmcount.pl only operates on R_ARM_(CALL|PC24|THM_CALL) types for ARM and so does it right.

I don't know how to fix recordmcount.[ch], but maybe this is enough info to allow someone more knowledgeable to fix it.

Best regards
Uwe

Signature · 2 lines

Pengutronix e.K.                           | Uwe Kleine-König            |
Industrial Linux Solutions                 | http://www.pengutronix.de/  |

Namhyung Kim

2016-03-20 03:48 UTC #8 lore raw

Hi,

Quoted 61 lines · Uwe Kleine-König

Hello,

Quoted 24 lines · Marc Kleine-Budde

Hello,

I'm on a ARMv5 (freescale mx25) and seeing this ftrace bug during bootup:

Quoted 11 lines

[    0.059235] ------------[ cut here ]------------
[    0.059449] WARNING: CPU: 0 PID: 0 at kernel/trace/ftrace.c:1938 ftrace_bug+0x210/0x2c8()
[    0.059645] Modules linked in:
[    0.059780] CPU: 0 PID: 0 Comm: swapper Not tainted 4.0.9-20151211-1-g45dbe7d2c077 #1
[    0.059966] Hardware name: Freescale i.MX25 (Device Tree Support)
[    0.060157] [<8000f494>] (unwind_backtrace) from [<8000ce3c>] (show_stack+0x20/0x24)
[    0.060396] [<8000ce3c>] (show_stack) from [<8041ea68>] (dump_stack+0x20/0x28)
[    0.060630] [<8041ea68>] (dump_stack) from [<8001a74c>] (warn_slowpath_common+0x88/0xc0)
[    0.060853] [<8001a74c>] (warn_slowpath_common) from [<8001a840>] (warn_slowpath_null+0x2c/0x34)
[    0.061091] [<8001a840>] (warn_slowpath_null) from [<80083748>] (ftrace_bug+0x210/0x2c8)
[    0.061332] [<80083748>] (ftrace_bug) from [<80083bb8>] (ftrace_process_locs+0x330/0x6f0)

Quoted 8 lines

[    0.061576] [<80083bb8>] (ftrace_process_locs) from [<805bdc84>] (ftrace_init+0x8c/0x14c)
[    0.061815] [<805bdc84>] (ftrace_init) from [<805b0c80>] (start_kernel+0x33c/0x3b4)
[    0.062039] [<805b0c80>] (start_kernel) from [<80008040>] (0x80008040)
[    0.062238] ---[ end trace cb88537fdc8fa200 ]---
[    0.062364] ftrace failed to modify [<8000c7d8>] walk_stackframe+0x24/0x44
[    0.062544]  actual: 16:ff:2f:e1
[    0.062702] ftrace record flags: 0
[    0.062803]  (0)   expected tramp: 8000e864

Quoted 2 lines

The problem is that walk_stackframe ends up in the __mcount_loc section, although it has a "notrace" attribute:

	$ readelf -R .rel.text arch/arm/kernel/stacktrace.o 
	...
	Relocation section '.rel.text' at offset 0xb5c contains 15 entries:
	 Offset     Info    Type            Sym.Value  Sym. Name
	0000001c  00000028 R_ARM_V4BX       
	0000002c  00001d1c R_ARM_CALL        00000000   unwind_frame
	00000044  00001f1c R_ARM_CALL        00000000   __gnu_mcount_nc
	00000104  0000201c R_ARM_CALL        00000000   in_sched_functions
	00000118  00002102 R_ARM_ABS32       00000000   __exception_text_start
	0000011c  00002202 R_ARM_ABS32       00000000   __exception_text_end
	00000130  00001f1c R_ARM_CALL        00000000   __gnu_mcount_nc
	00000194  00001c1c R_ARM_CALL        00000000   walk_stackframe
	000001e0  00000902 R_ARM_ABS32       0000003c   save_trace
	000001e4  00000c02 R_ARM_ABS32       00000120   __save_stack_trace
	000001ec  00001f1c R_ARM_CALL        00000000   __gnu_mcount_nc
	00000218  00001f1c R_ARM_CALL        00000000   __gnu_mcount_nc
	00000260  00001c1c R_ARM_CALL        00000000   walk_stackframe
	0000028c  00000902 R_ARM_ABS32       0000003c   save_trace
	00000294  00001f1c R_ARM_CALL        00000000   __gnu_mcount_nc
	...

Quoted 4 lines

For this entry get_mcountsym returns 0.
recordmcount.pl only operates on R_ARM_(CALL|PC24|THM_CALL) types for ARM and so does it right.

Hmm.. that means we need to check the reloc types? It seems the binutils treats R_ARM_THM_PC22 as R_ARM_THM_CALL.

in /usr/include/elf.h:
#define R_ARM_SBREL32 9
#define R_ARM_THM_PC22 10 /* PC relative 24 bit (Thumb32 BL). */
#define R_ARM_THM_PC8 11 /* PC relative & 0x3FC

in binutils-gdb/include/elf/arm.h:
RELOC_NUMBER (R_ARM_SBREL32, 9)
RELOC_NUMBER (R_ARM_THM_CALL, 10)
RELOC_NUMBER (R_ARM_THM_PC8, 11)

So following patch (untested) works for you?

Thanks,
Namhyung

scripts/recordmcount.c +15 -0

index e167592793a7..dcc7896dce25 100644
@@ -398,6 +398,20 @@ static void MIPS64_r_info(Elf64_Rel *const rp, unsigned sym, unsigned type)
 	}).r_info;
 }
 
+static int ARM_is_fake_mcount(Elf32_Rel const *rp)
+{
+	unsigned r_type = ELF32_R_TYPE(w(rp->r_info));
+
+	switch (r_type) {
+	case R_ARM_CALL:
+	case R_ARM_PC24:
+	case R_ARM_THM_PC22:
+		return 0;
+	default:
+		return 1;
+	}
+}
+
 static void
 do_file(char const *const fname)
 {

@@ -454,6 +468,7 @@ do_file(char const *const fname)
 		break;
 	case EM_ARM:	 reltype = R_ARM_ABS32;
 			 altmcount = "__gnu_mcount_nc";
+			 is_fake_mcount32 = ARM_is_fake_mcount;
 			 break;
 	case EM_AARCH64:
 			reltype = R_AARCH64_ABS64;

Uwe Kleine-König

2016-03-20 20:00 UTC #9 lore raw

Hello,

Quoted 73 lines · Namhyung Kim

Quoted 59 lines · Uwe Kleine-König
Quoted 24 lines · Marc Kleine-Budde
Hello,
I'm on a ARMv5 (freescale mx25) and seeing this ftrace bug during bootup:
Quoted 11 lines
[    0.059235] ------------[ cut here ]------------
[    0.059449] WARNING: CPU: 0 PID: 0 at kernel/trace/ftrace.c:1938 ftrace_bug+0x210/0x2c8()
[    0.059645] Modules linked in:
[    0.059780] CPU: 0 PID: 0 Comm: swapper Not tainted 4.0.9-20151211-1-g45dbe7d2c077 #1
[    0.059966] Hardware name: Freescale i.MX25 (Device Tree Support)
[    0.060157] [<8000f494>] (unwind_backtrace) from [<8000ce3c>] (show_stack+0x20/0x24)
[    0.060396] [<8000ce3c>] (show_stack) from [<8041ea68>] (dump_stack+0x20/0x28)
[    0.060630] [<8041ea68>] (dump_stack) from [<8001a74c>] (warn_slowpath_common+0x88/0xc0)
[    0.060853] [<8001a74c>] (warn_slowpath_common) from [<8001a840>] (warn_slowpath_null+0x2c/0x34)
[    0.061091] [<8001a840>] (warn_slowpath_null) from [<80083748>] (ftrace_bug+0x210/0x2c8)
[    0.061332] [<80083748>] (ftrace_bug) from [<80083bb8>] (ftrace_process_locs+0x330/0x6f0)
Quoted 8 lines
[    0.061576] [<80083bb8>] (ftrace_process_locs) from [<805bdc84>] (ftrace_init+0x8c/0x14c)
[    0.061815] [<805bdc84>] (ftrace_init) from [<805b0c80>] (start_kernel+0x33c/0x3b4)
[    0.062039] [<805b0c80>] (start_kernel) from [<80008040>] (0x80008040)
[    0.062238] ---[ end trace cb88537fdc8fa200 ]---
[    0.062364] ftrace failed to modify [<8000c7d8>] walk_stackframe+0x24/0x44
[    0.062544]  actual: 16:ff:2f:e1
[    0.062702] ftrace record flags: 0
[    0.062803]  (0)   expected tramp: 8000e864
Quoted 2 lines
The problem is that walk_stackframe ends up in the __mcount_loc section, although it has a "notrace" attribute:
Not having much clue about elf and stuff, but being hit by this problem I added some debug output to recordmcount.c and found that sift_rel_mcount (aka sift32_rel_mcount) loops over .rel.text which looks as follows for me:
	$ readelf -R .rel.text arch/arm/kernel/stacktrace.o 
	...
	Relocation section '.rel.text' at offset 0xb5c contains 15 entries:
	 Offset     Info    Type            Sym.Value  Sym. Name
	0000001c  00000028 R_ARM_V4BX       
	0000002c  00001d1c R_ARM_CALL        00000000   unwind_frame
	00000044  00001f1c R_ARM_CALL        00000000   __gnu_mcount_nc
	00000104  0000201c R_ARM_CALL        00000000   in_sched_functions
	00000118  00002102 R_ARM_ABS32       00000000   __exception_text_start
	0000011c  00002202 R_ARM_ABS32       00000000   __exception_text_end
	00000130  00001f1c R_ARM_CALL        00000000   __gnu_mcount_nc
	00000194  00001c1c R_ARM_CALL        00000000   walk_stackframe
	000001e0  00000902 R_ARM_ABS32       0000003c   save_trace
	000001e4  00000c02 R_ARM_ABS32       00000120   __save_stack_trace
	000001ec  00001f1c R_ARM_CALL        00000000   __gnu_mcount_nc
	00000218  00001f1c R_ARM_CALL        00000000   __gnu_mcount_nc
	00000260  00001c1c R_ARM_CALL        00000000   walk_stackframe
	0000028c  00000902 R_ARM_ABS32       0000003c   save_trace
	00000294  00001f1c R_ARM_CALL        00000000   __gnu_mcount_nc
	...
and the unwanted entry in __mcount_loc is generated from the first line which isn't a call, but just the information that there is a bx call that needs a fixup for ARMv4 machines (that don't support the bx instruction).
Quoted 4 lines
For this entry get_mcountsym returns 0.
recordmcount.pl only operates on R_ARM_(CALL|PC24|THM_CALL) types for ARM and so does it right.
Hmm.. that means we need to check the reloc types? It seems the binutils treats R_ARM_THM_PC22 as R_ARM_THM_CALL.
in /usr/include/elf.h:
#define R_ARM_SBREL32 9
#define R_ARM_THM_PC22 10 /* PC relative 24 bit (Thumb32 BL). */
#define R_ARM_THM_PC8 11 /* PC relative & 0x3FC

Quoted 7 lines

in binutils-gdb/include/elf/arm.h:
RELOC_NUMBER (R_ARM_SBREL32, 9)
RELOC_NUMBER (R_ARM_THM_CALL, 10)
RELOC_NUMBER (R_ARM_THM_PC8, 11)
So following patch (untested) works for you?

Yes, it changes the output of $(readelf -R __mcount_loc arch/arm/kernel/stacktrace.o) from

Hex dump of section '__mcount_loc':
0x00000000 24000000 54000000 6c010000 34020000 $...T...l...4...
0x00000010 6c020000 f4020000 l.......

Hex dump of section '__mcount_loc':
0x00000000 54000000 6c010000 34020000 6c020000 T...l...4...l...
0x00000010 f4020000 ....

on top of 4.5. I don't have the machine handy where I saw the problem, so I cannot test at the moment, but I assume your change is fine.

Thanks
Uwe

Signature · 2 lines

Pengutronix e.K.                           | Uwe Kleine-König            |
Industrial Linux Solutions                 | http://www.pengutronix.de/  |