Dynamic-ftrace not working in PlayStation3

Dynamic-ftrace not working in PlayStation3

[Remis Lima Baima]

Hi to all. I was tracing a bug in the snd_usb_audio driver
(PlayStation 3, Kernel 2.6.29-rc2,
git://git.kernel.org/pub/scm/linux/kernel/git/geoff/ps3-linux.git) and
for that I tried to use the "dynamic ftrace" to get less debug output.
But it did not work at all. Ftrace (without the "dynamic ftrace"
support) works normally. So I traced the "dynamic ftrace" bug and I
think that I found the bug location but I got stucked. Could anyone
help, please? Below is the link with the debug output:

PS1: The problem seems to happen in the file
"./git/linux-2.6/arch/powerpc/kernel/ftrace.c" around the line 217:
"if (ptr != GET_ADDR(addr)) {". It returns true.
PS2: I enabled the "DEBUGP" macro to get the debug output below and
changed the line 218 to "printk(KERN_ERR "addr does not match \nptr:
%lx \naddr: %lx \nGET_ADDR(addr): %lx \n", ptr, addr,
GET_ADDR(addr));".

//*************************************************************************************************************************************
ip:d000000000045aec jumps to d000000000046340 r2: d000000000050c00
3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
ip:d0000000000458d0 jumps to d000000000046340 r2: d000000000050c00
3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
ip:d000000000045838 jumps to d000000000046340 r2: d000000000050c00
3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
ip:d0000000000456dc jumps to d000000000046340 r2: d000000000050c00
3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
ip:d000000000045624 jumps to d000000000046340 r2: d000000000050c00
3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
ip:d0000000000453b4 jumps to d000000000046340 r2: d000000000050c00
3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
ip:d00000000004527c jumps to d000000000046340 r2: d000000000050c00
3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
ip:d000000000045204 jumps to d000000000046340 r2: d000000000050c00
3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
ip:d00000000004519c jumps to d000000000046340 r2: d000000000050c00
3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
ip:d000000000044844 jumps to d000000000046340 r2: d000000000050c00
3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
ip:d000000000044770 jumps to d000000000046340 r2: d000000000050c00
3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
ip:d00000000004465c jumps to d000000000046340 r2: d000000000050c00
3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
ip:d00000000004444c jumps to d000000000046340 r2: d000000000050c00
3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
ip:d000000000044390 jumps to d000000000046340 r2: d000000000050c00
3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
ip:d00000000004427c jumps to d000000000046340 r2: d000000000050c00
3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
ip:d0000000000441f8 jumps to d000000000046340 r2: d000000000050c00
3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
ip:d00000000004418c jumps to d000000000046340 r2: d000000000050c00
3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
ip:d000000000044118 jumps to d000000000046340 r2: d000000000050c00
3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
ip:d00000000004402c jumps to d000000000046340 r2: d000000000050c00
3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
ip:d00000000008cce0 jumps to d00000000008d8b0 r2: d000000000097cc0
3d82ffff 398c5bf0 ffff5bf0 toc: d00000000008d8d0 c0000000 00007cac
ip:d00000000008cb90 jumps to d00000000008d8b0 r2: d000000000097cc0
3d82ffff 398c5bf0 ffff5bf0 toc: d00000000008d8d0 c0000000 00007cac
ip:d00000000008ca10 jumps to d00000000008d8b0 r2: d000000000097cc0
3d82ffff 398c5bf0 ffff5bf0 toc: d00000000008d8d0 c0000000 00007cac
ip:d00000000008c924 jumps to d00000000008d8b0 r2: d000000000097cc0
3d82ffff 398c5bf0 ffff5bf0 toc: d00000000008d8d0 c0000000 00007cac
ip:d00000000008c808 jumps to d00000000008d8b0 r2: d000000000097cc0
3d82ffff 398c5bf0 ffff5bf0 toc: d00000000008d8d0 c0000000 00007cac
ip:d00000000008c57c jumps to d00000000008d8b0 r2: d000000000097cc0
3d82ffff 398c5bf0 ffff5bf0 toc: d00000000008d8d0 c0000000 00007cac
ip:d00000000008c4ac jumps to d00000000008d8b0 r2: d000000000097cc0
3d82ffff 398c5bf0 ffff5bf0 toc: d00000000008d8d0 c0000000 00007cac
ip:d00000000008c328 jumps to d00000000008d8b0 r2: d000000000097cc0
3d82ffff 398c5bf0 ffff5bf0 toc: d00000000008d8d0 c0000000 00007cac
ip:d00000000008c260 jumps to d00000000008d8b0 r2: d000000000097cc0
3d82ffff 398c5bf0 ffff5bf0 toc: d00000000008d8d0 c0000000 00007cac
ip:d00000000008c0d4 jumps to d00000000008d8b0 r2: d000000000097cc0
3d82ffff 398c5bf0 ffff5bf0 toc: d00000000008d8d0 c0000000 00007cac
ip:d00000000008c02c jumps to d00000000008d8b0 r2: d000000000097cc0
3d82ffff 398c5bf0 ffff5bf0 toc: d00000000008d8d0 c0000000 00007cac
ps3_system_bus_match:362: dev=10.2(ioc0_03), drv=10.2(ps3vram): match
ps3_system_bus_match:362: dev=10.2(ioc0_03), drv=10.2(ps3vram): match
ps3vram ioc0_03: created ram cache: 7 entries, 256 KiB each
mtd: Giving out device 0 to ps3vram
ps3vram ioc0_03: reserved 245 MiB of gpu memory
ip:d0000000000cd944 jumps to d0000000000cdff8 r2: d0000000000d8e20
3d82ffff 398c51d8 ffff51d8 toc: d0000000000ce018 c0000000 00007cac
ip:d0000000000cd840 jumps to d0000000000cdff8 r2: d0000000000d8e20
3d82ffff 398c51d8 ffff51d8 toc: d0000000000ce018 c0000000 00007cac
ip:d0000000000cd550 jumps to d0000000000cdff8 r2: d0000000000d8e20
3d82ffff 398c51d8 ffff51d8 toc: d0000000000ce018 c0000000 00007cac
ip:d0000000000cd4a8 jumps to d0000000000cdff8 r2: d0000000000d8e20
3d82ffff 398c51d8 ffff51d8 toc: d0000000000ce018 c0000000 00007cac
ip:d0000000000cd414 jumps to d0000000000cdff8 r2: d0000000000d8e20
3d82ffff 398c51d8 ffff51d8 toc: d0000000000ce018 c0000000 00007cac
ip:d0000000000cd2a8 jumps to d0000000000cdff8 r2: d0000000000d8e20
3d82ffff 398c51d8 ffff51d8 toc: d0000000000ce018 c0000000 00007cac
ip:d0000000000cd0d4 jumps to d0000000000cdff8 r2: d0000000000d8e20
3d82ffff 398c51d8 ffff51d8 toc: d0000000000ce018 c0000000 00007cac
ip:d0000000000cd018 jumps to d0000000000cdff8 r2: d0000000000d8e20
3d82ffff 398c51d8 ffff51d8 toc: d0000000000ce018 c0000000 00007cac
ip:d0000000000ccf54 jumps to d0000000000cdff8 r2: d0000000000d8e20
3d82ffff 398c51d8 ffff51d8 toc: d0000000000ce018 c0000000 00007cac
ip:d0000000000cce0c jumps to d0000000000cdff8 r2: d0000000000d8e20
3d82ffff 398c51d8 ffff51d8 toc: d0000000000ce018 c0000000 00007cac
ip:d0000000000ccc8c jumps to d0000000000cdff8 r2: d0000000000d8e20
3d82ffff 398c51d8 ffff51d8 toc: d0000000000ce018 c0000000 00007cac
ip:d0000000000ccbac jumps to d0000000000cdff8 r2: d0000000000d8e20
3d82ffff 398c51d8 ffff51d8 toc: d0000000000ce018 c0000000 00007cac
ip:d0000000000ccaf8 jumps to d0000000000cdff8 r2: d0000000000d8e20
3d82ffff 398c51d8 ffff51d8 toc: d0000000000ce018 c0000000 00007cac
ip:d0000000000cca10 jumps to d0000000000cdff8 r2: d0000000000d8e20
3d82ffff 398c51d8 ffff51d8 toc: d0000000000ce018 c0000000 00007cac
ip:d0000000000cc998 jumps to d0000000000cdff8 r2: d0000000000d8e20
3d82ffff 398c51d8 ffff51d8 toc: d0000000000ce018 c0000000 00007cac
ip:d0000000000cc940 jumps to d0000000000cdff8 r2: d0000000000d8e20
3d82ffff 398c51d8 ffff51d8 toc: d0000000000ce018 c0000000 00007cac
ip:d0000000000cc828 jumps to d0000000000cdff8 r2: d0000000000d8e20
3d82ffff 398c51d8 ffff51d8 toc: d0000000000ce018 c0000000 00007cac
ip:d0000000000cc7b8 jumps to d0000000000cdff8 r2: d0000000000d8e20
3d82ffff 398c51d8 ffff51d8 toc: d0000000000ce018 c0000000 00007cac
ip:d0000000000cc5bc jumps to d0000000000cdff8 r2: d0000000000d8e20
3d82ffff 398c51d8 ffff51d8 toc: d0000000000ce018 c0000000 00007cac
ip:d0000000000cc408 jumps to d0000000000cdff8 r2: d0000000000d8e20
3d82ffff 398c51d8 ffff51d8 toc: d0000000000ce018 c0000000 00007cac
ip:d0000000000cc2dc jumps to d0000000000cdff8 r2: d0000000000d8e20
3d82ffff 398c51d8 ffff51d8 toc: d0000000000ce018 c0000000 00007cac
ip:d0000000000cc268 jumps to d0000000000cdff8 r2: d0000000000d8e20
3d82ffff 398c51d8 ffff51d8 toc: d0000000000ce018 c0000000 00007cac
ip:d0000000000cc208 jumps to d0000000000cdff8 r2: d0000000000d8e20
3d82ffff 398c51d8 ffff51d8 toc: d0000000000ce018 c0000000 00007cac
ip:d0000000000cc1b4 jumps to d0000000000cdff8 r2: d0000000000d8e20
3d82ffff 398c51d8 ffff51d8 toc: d0000000000ce018 c0000000 00007cac
ip:d0000000000cc170 jumps to d0000000000cdff8 r2: d0000000000d8e20
3d82ffff 398c51d8 ffff51d8 toc: d0000000000ce018 c0000000 00007cac
ip:d0000000000cc0b4 jumps to d0000000000cdff8 r2: d0000000000d8e20
3d82ffff 398c51d8 ffff51d8 toc: d0000000000ce018 c0000000 00007cac
ip:d0000000000cc01c jumps to d0000000000cdff8 r2: d0000000000d8e20
3d82ffff 398c51d8 ffff51d8 toc: d0000000000ce018 c0000000 00007cac
ps3_system_bus_match:362: dev=11.0(lpm_01), drv=11.0(ps3-lpm): match
ps3_system_bus_match:362: dev=11.0(lpm_01), drv=11.0(ps3-lpm): match
ps3-lpm lpm_01:  <- ps3_lpm_probe:1245:
ip:d0000000003fe280 jumps to d0000000003ffad8 r2: d000000000422c70
3d82fffe 398cce68 fffece68 toc: d00000000040faf8 6c656400 5f5f6b73
addr does not match
ptr: 6c6564005f5f6b73
addr: c0000000004ff128
GET_ADDR(addr): c000000000007cac
------------[ cut here ]------------
Badness at /home/remis/git/linux-2.6/kernel/trace/ftrace.c:441
NIP: c0000000000b1cb8 LR: c0000000000b335c CTR: 0000000000000000
REGS: c00000000d82b780 TRAP: 0700   Not tainted
(2.6.29-rc2-00839-g22530b0-dirty)
MSR: 8000000000020032 <CE,IR,DR>  CR: 24002482  XER: 00000000
TASK = c00000000d7be440[1237] 'modprobe' THREAD: c00000000d828000 CPU: 0
GPR00: 0000000000000001 c00000000d82ba00 c00000000054bf18 ffffffffffffffea
GPR04: d0000000003fe280 c00000000006076c 0000000000000000 0000000000000002
GPR08: 0000000000000000 c000000000b94df0 c000000002a92c20 c00000000d7be440
GPR12: 0000000024002484 c00000000057d300 d000000000417a50 c00000000d82bc78
GPR16: d000000000285fe8 0000000000000549 d00000000028560c d000000000417a18
GPR20: d000000000416ee8 d000000000417a00 000000032945b5f0 0000000000000001
GPR24: c0000000004ff128 c00000000d552560 c0000000004b0270 d0000000003fe280
GPR28: d0000000003fe280 c00000000d552588 c0000000004f8948 c00000000d82ba00
NIP [c0000000000b1cb8] .ftrace_bug+0x98/0x210
LR [c0000000000b335c] .ftrace_convert_nops+0x23c/0x344
Call Trace:
[c00000000d82ba00] [c0000000004ff128] _mcount+0x0/0x18 (unreliable)
[c00000000d82baa0] [c0000000000b335c] .ftrace_convert_nops+0x23c/0x344
[c00000000d82bb70] [c0000000000b349c] .ftrace_init_module+0x38/0x50
[c00000000d82bbf0] [c0000000000a0870] .load_module+0x12dc/0x1898
[c00000000d82bd80] [c0000000000a0ffc] .SyS_init_module+0x90/0x248
[c00000000d82be30] [c0000000000074dc] syscall_exit+0x0/0x40
Instruction dump:
41be0010 e93e8010 38000001 9009002c e93e8000 e97e8008 e87e80c0 48000130
80090030 7c000034 5400d97e 78000020 <0b000000> 2fa00000 41be0010 e93e8010
ftrace failed to modify [<d0000000003fe280>] 0xd0000000003fe280
 actual: 48:00:18:59
//*************************************************************************************************************************************

Re: Dynamic-ftrace not working in PlayStation3

[Geoff Levand]

Hi,

Remis Lima Baima wrote:
> Hi to all. I was tracing a bug in the snd_usb_audio driver
> (PlayStation 3, Kernel 2.6.29-rc2,
> git://git.kernel.org/pub/scm/linux/kernel/git/geoff/ps3-linux.git) and
> for that I tried to use the "dynamic ftrace" to get less debug output.
> But it did not work at all. Ftrace (without the "dynamic ftrace"
> support) works normally. So I traced the "dynamic ftrace" bug and I
> think that I found the bug location but I got stucked. Could anyone
> help, please? Below is the link with the debug output:
> 
> PS1: The problem seems to happen in the file
> "./git/linux-2.6/arch/powerpc/kernel/ftrace.c" around the line 217:
> "if (ptr != GET_ADDR(addr)) {". It returns true.
> PS2: I enabled the "DEBUGP" macro to get the debug output below and
> changed the line 218 to "printk(KERN_ERR "addr does not match \nptr:
> %lx \naddr: %lx \nGET_ADDR(addr): %lx \n", ptr, addr,
> GET_ADDR(addr));".
> 
> //*************************************************************************************************************************************
> ip:d000000000045aec jumps to d000000000046340 r2: d000000000050c00
> 3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
> ip:d0000000000458d0 jumps to d000000000046340 r2: d000000000050c00
> 3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
> ip:d000000000045838 jumps to d000000000046340 r2: d000000000050c00
> 3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
> ip:d0000000000456dc jumps to d000000000046340 r2: d000000000050c00
> 3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
...
> ps3_system_bus_match:362: dev=11.0(lpm_01), drv=11.0(ps3-lpm): match
> ps3_system_bus_match:362: dev=11.0(lpm_01), drv=11.0(ps3-lpm): match
> ps3-lpm lpm_01:  <- ps3_lpm_probe:1245:
> ip:d0000000003fe280 jumps to d0000000003ffad8 r2: d000000000422c70
> 3d82fffe 398cce68 fffece68 toc: d00000000040faf8 6c656400 5f5f6b73
> addr does not match
> ptr: 6c6564005f5f6b73
> addr: c0000000004ff128
> GET_ADDR(addr): c000000000007cac

I don't know so much about ftrace, but to get a better idea of the
problem, could you try with the patch below?

Is ps3-lpm built as a loadable module, and if so, is it the first one
that got loaded?

Also, try to either build with CONFIG_PS3_LPM=n, or delete ps3-lpm.ko
so it does not get loaded to see what happens.

-Geoff

--- a/arch/powerpc/kernel/ftrace.c
+++ b/arch/powerpc/kernel/ftrace.c
@@ -23,7 +23,7 @@
 #if 0
 #define DEBUGP printk
 #else
-#define DEBUGP(fmt , ...)	do { } while (0)
+#define DEBUGP printk
 #endif
 
 static unsigned int ftrace_nop = PPC_NOP_INSTR;
@@ -213,6 +213,8 @@ __ftrace_make_nop(struct module *mod,
 
 	ptr = ((unsigned long)jmp[0] << 32) + jmp[1];
 
+	printk("ptr %lx, addr %lx, GET_ADDR %lx\n", ptr, addr, GET_ADDR(addr));
+
 	/* This should match what was called */
 	if (ptr != GET_ADDR(addr)) {
 		printk(KERN_ERR "addr does not match %lx\n", ptr);

Re: Dynamic-ftrace not working in PlayStation3

[Steven Rostedt]

On Thu, 29 Jan 2009, Geoff Levand wrote:

> > 
> > //*************************************************************************************************************************************
> > ip:d000000000045aec jumps to d000000000046340 r2: d000000000050c00
> > 3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
> > ip:d0000000000458d0 jumps to d000000000046340 r2: d000000000050c00
> > 3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
> > ip:d000000000045838 jumps to d000000000046340 r2: d000000000050c00
> > 3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
> > ip:d0000000000456dc jumps to d000000000046340 r2: d000000000050c00
> > 3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
> ...

So I take it that the above showed that the code worked for some?

> > ps3_system_bus_match:362: dev=11.0(lpm_01), drv=11.0(ps3-lpm): match
> > ps3_system_bus_match:362: dev=11.0(lpm_01), drv=11.0(ps3-lpm): match
> > ps3-lpm lpm_01:  <- ps3_lpm_probe:1245:
> > ip:d0000000003fe280 jumps to d0000000003ffad8 r2: d000000000422c70

Could you find out what that function is? Perhaps do a:

	printk("ip:%pF\n", ip);

As long as you have kallsyms on, that should point to the function that's 
the problem.

> > 3d82fffe 398cce68 fffece68 toc: d00000000040faf8 6c656400 5f5f6b73
> > addr does not match
> > ptr: 6c6564005f5f6b73

ptr is the same info as the last line above.

> > addr: c0000000004ff128
> > GET_ADDR(addr): c000000000007cac
> 
> I don't know so much about ftrace, but to get a better idea of the
> problem, could you try with the patch below?
> 
> Is ps3-lpm built as a loadable module, and if so, is it the first one
> that got loaded?
> 
> Also, try to either build with CONFIG_PS3_LPM=n, or delete ps3-lpm.ko
> so it does not get loaded to see what happens.
> 
> -Geoff
> 
> --- a/arch/powerpc/kernel/ftrace.c
> +++ b/arch/powerpc/kernel/ftrace.c
> @@ -23,7 +23,7 @@
>  #if 0

Heh, I would have just done:

- #if 0
+ #if 1

;-)


-- Steve

>  #define DEBUGP printk
>  #else
> -#define DEBUGP(fmt , ...)	do { } while (0)
> +#define DEBUGP printk
>  #endif
>  
>  static unsigned int ftrace_nop = PPC_NOP_INSTR;
> @@ -213,6 +213,8 @@ __ftrace_make_nop(struct module *mod,
>  
>  	ptr = ((unsigned long)jmp[0] << 32) + jmp[1];
>  
> +	printk("ptr %lx, addr %lx, GET_ADDR %lx\n", ptr, addr, GET_ADDR(addr));
> +
>  	/* This should match what was called */
>  	if (ptr != GET_ADDR(addr)) {
>  		printk(KERN_ERR "addr does not match %lx\n", ptr);
> 
> 
> 
> 

Re: Dynamic-ftrace not working in PlayStation3

[Michael Ellerman]

[-- Attachment #1: Type: text/plain, Size: 2114 bytes --]

On Thu, 2009-01-29 at 22:38 -0500, Steven Rostedt wrote:
> On Thu, 29 Jan 2009, Geoff Levand wrote:
> 
> > > 
> > > //*************************************************************************************************************************************
> > > ip:d000000000045aec jumps to d000000000046340 r2: d000000000050c00
> > > 3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
> > > ip:d0000000000458d0 jumps to d000000000046340 r2: d000000000050c00
> > > 3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
> > > ip:d000000000045838 jumps to d000000000046340 r2: d000000000050c00
> > > 3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
> > > ip:d0000000000456dc jumps to d000000000046340 r2: d000000000050c00
> > > 3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
> > ...
> 
> So I take it that the above showed that the code worked for some?
> 
> > > ps3_system_bus_match:362: dev=11.0(lpm_01), drv=11.0(ps3-lpm): match
> > > ps3_system_bus_match:362: dev=11.0(lpm_01), drv=11.0(ps3-lpm): match
> > > ps3-lpm lpm_01:  <- ps3_lpm_probe:1245:
> > > ip:d0000000003fe280 jumps to d0000000003ffad8 r2: d000000000422c70
> 
> Could you find out what that function is? Perhaps do a:
> 
> 	printk("ip:%pF\n", ip);
> 
> As long as you have kallsyms on, that should point to the function that's 
> the problem.
> 
> > > 3d82fffe 398cce68 fffece68 toc: d00000000040faf8 6c656400 5f5f6b73
> > > addr does not match
> > > ptr: 6c6564005f5f6b73
> 
> ptr is the same info as the last line above.

6c656400 5f5f6b73 = "led\0__ks"

:)

> > --- a/arch/powerpc/kernel/ftrace.c
> > +++ b/arch/powerpc/kernel/ftrace.c
> > @@ -23,7 +23,7 @@
> >  #if 0
> 
> Heh, I would have just done:
> 
> - #if 0
> + #if 1
> 
> ;-)

Should do s/DEBUGP/pr_debug/g

cheers


-- 
Michael Ellerman
OzLabs, IBM Australia Development Lab

wwweb: http://michael.ellerman.id.au
phone: +61 2 6212 1183 (tie line 70 21183)

We do not inherit the earth from our ancestors,
we borrow it from our children. - S.M.A.R.T Person

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 197 bytes --]

Re: Dynamic-ftrace not working in PlayStation3

[Geoff Levand]

Hi,

I did a bit of work on this today.

Steven Rostedt wrote:
>> > ip:d000000000045aec jumps to d000000000046340 r2: d000000000050c00
>> > 3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
>> > ip:d0000000000458d0 jumps to d000000000046340 r2: d000000000050c00
>> > 3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
>> > ip:d000000000045838 jumps to d000000000046340 r2: d000000000050c00
>> > 3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
>> > ip:d0000000000456dc jumps to d000000000046340 r2: d000000000050c00
>> > 3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
>> ...
> 
> So I take it that the above showed that the code worked for some?

In my trials it blows up on the first load_module() call, and for my
config that was usbcore:

ip:d000000000305298 jumps to d000000000306ad8 r2: d000000000329bb8 3d82fffe 398ccf20 fffecf20 toc: d000000000316af8 5f666f72 5f726573
ptr 5f666f725f726573, addr c0000000005d0e40, GET_ADDR c000000000007cac
<3>addr does not match 5f666f725f726573
<0>------------[ cut here ]------------
<3>Badness at /home/geoff/projects/cell/ps3-linux-dev/kernel/trace/ftrace.c:441
NIP: c0000000000b3038 LR: c0000000000b46bc CTR: 0000000000000000
REGS: c00000001d143780 TRAP: 0700   Not tainted  (2.6.29-rc3-02162-gec97e82-dirty)
MSR: 8000000000020032 <CE,IR,DR>  CR: 42222442  XER: 00000000
TASK = c000000006f64640[373] 'modprobe' THREAD: c00000001d140000 CPU: 1
<6>GPR00: 0000000000000001 c00000001d143a00 c000000000625988 ffffffffffffffea
<6>GPR04: d000000000305298 c0000000000628c0 0000000000000000 0000000000000002
<6>GPR08: 0000000000000000 c000000000c6ce80 0000000000020000 c000000006f64640
<6>GPR12: 0000000042222444 c000000000655500 d00000000031e9d0 c00000001d143c78
<6>GPR16: d00000000018cbe0 0000000000000549 d00000000018c208 d00000000031e998
<6>GPR20: d00000000031de00 d00000000031e980 00000001e48bc1f0 0000000000000001
<6>GPR24: c0000000005d0e40 c00000001d47b2b8 c000000000576270 d000000000305298
<6>GPR28: d000000000305298 c00000001d47b2e0 c0000000005c6960 c00000001d143a00
NIP [c0000000000b3038] .ftrace_bug+0x98/0x210
LR [c0000000000b46bc] .ftrace_convert_nops+0x23c/0x344
Call Trace:
[c00000001d143a00] [c0000000000628c0] .vprintk+0x394/0x42c (unreliable)
[c00000001d143aa0] [c0000000000b46bc] .ftrace_convert_nops+0x23c/0x344
[c00000001d143b70] [c0000000000b47fc] .ftrace_init_module+0x38/0x50
[c00000001d143bf0] [c0000000000a1c70] .load_module+0x12e0/0x189c
[c00000001d143d80] [c0000000000a23fc] .SyS_init_module+0x90/0x248
[c00000001d143e30] [c0000000000074dc] syscall_exit+0x0/0x40
Instruction dump:
41fe0010 e93e8010 38000001 9009002c e93e8000 e97e8008 e87e80b0 48000130
80090030 7c000034 5400d97e 78000020 <0b000000> 2fa00000 41fe0010 e93e8010
<6>ftrace failed to modify [<d000000000305298>] 0xd000000000305298
 actual: 48:00:18:41
<6>usbcore: registered new interface driver usbfs

 
This ptr of 5f666f725f726573 seems bogus.  I think this code is not
working correctly:

	offset = (unsigned)((unsigned short)jmp[0]) << 16 |
		(unsigned)((unsigned short)jmp[1]);

	tramp = mod->arch.toc + offset + 32;

	if (probe_kernel_read(jmp, (void *)tramp, 8)) {
		printk(KERN_ERR "Failed to read %lx\n", tramp);
		return -EFAULT;
	}

	ptr = ((unsigned long)jmp[0] << 32) + jmp[1];

addr and GET_ADDR(addr) seem OK, System.map shows both to be _mcount.
If I force it to continue with this:

	if (ptr != GET_ADDR(addr)) {
		printk(KERN_ERR "addr does not match %lx\n", ptr);
		//return -EINVAL;
	}

It loads a lot of modules, but eventually it fails with the
following, which seems to mean a bad tramp value.

ip:d0000000005f08cc jumps to d0000000005f1920 r2: d0000000006031c8 3d82ffff 398ce758 ffffe758 toc: d000000000601940<3>Failed to read d000000000601940
<0>------------[ cut here ]------------
<3>Badness at /home/geoff/projects/cell/ps3-linux-dev/kernel/trace/ftrace.c:436
NIP: c0000000000b3000 LR: c0000000000b46dc CTR: 0000000000000001
REGS: c00000001d5b7780 TRAP: 0700   Not tainted  (2.6.29-rc3-02162-gec97e82-dirty)
MSR: 8000000000020032 <CE,IR,DR>  CR: 22222442  XER: 20000000
TASK = c000000006fea7c0[712] 'modprobe' THREAD: c00000001d5b4000 CPU: 0
<6>GPR00: 0000000000000001 c00000001d5b7a00 c000000000625998 fffffffffffffff2
<6>GPR04: d0000000005f08cc c000000000062054 0000000000000000 0000000000000002
<6>GPR08: 0000000000000000 c000000000c6ce80 000000000001ffff c000000006fea7c0
<6>GPR12: 0000000022222444 c000000000655300 d0000000005f9fd0 c00000001d5b7c78
<6>GPR16: d000000000565c58 0000000000000215 d0000000005653e5 d0000000005f9f98
<6>GPR20: d0000000005f9860 d0000000005f9f80 00000002cfe82a50 0000000000000001
<6>GPR24: c0000000005d0e50 c00000001d21e6f0 c000000000576270 d0000000005f08cc
<6>GPR28: d0000000005f08cc c00000001d21e718 c0000000005c6960 c00000001d5b7a00
NIP [c0000000000b3000] .ftrace_bug+0x60/0x210
LR [c0000000000b46dc] .ftrace_convert_nops+0x25c/0x364
Call Trace:
[c00000001d5b7a00] [0000000000000004] 0x4 (unreliable)
[c00000001d5b7aa0] [c0000000000b46dc] .ftrace_convert_nops+0x25c/0x364
[c00000001d5b7b70] [c0000000000b481c] .ftrace_init_module+0x38/0x50
[c00000001d5b7bf0] [c0000000000a1c70] .load_module+0x12e0/0x189c
[c00000001d5b7d80] [c0000000000a23fc] .SyS_init_module+0x90/0x248
[c00000001d5b7e30] [c0000000000074dc] syscall_exit+0x0/0x40
Instruction dump:
419e001c 2f83ffff 419e010c 2f83ffea e93e8010 409e013c 48000040 e93e8010
8009002c 7c000034 5400d97e 78000020 <0b000000> 2fa00000 41fe0010 e93e8010
<6>ftrace faulted on modifying [<d0000000005f08cc>] 0xd0000000005f08cc

-Geoff

Re: Dynamic-ftrace not working in PlayStation3

[Steven Rostedt]

[ added Ben and Paul to Cc, since they helped me write the code ]

On Fri, 30 Jan 2009, Geoff Levand wrote:

> Hi,
> 
> I did a bit of work on this today.
> 
> Steven Rostedt wrote:
> >> > ip:d000000000045aec jumps to d000000000046340 r2: d000000000050c00
> >> > 3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
> >> > ip:d0000000000458d0 jumps to d000000000046340 r2: d000000000050c00
> >> > 3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
> >> > ip:d000000000045838 jumps to d000000000046340 r2: d000000000050c00
> >> > 3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
> >> > ip:d0000000000456dc jumps to d000000000046340 r2: d000000000050c00
> >> > 3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
> >> ...
> > 
> > So I take it that the above showed that the code worked for some?
> 
> In my trials it blows up on the first load_module() call, and for my
> config that was usbcore:

But does it blow up on the first instance? If it does not, then those 
instances are working.

> 
> ip:d000000000305298 jumps to d000000000306ad8 r2: d000000000329bb8 3d82fffe 398ccf20 fffecf20 toc: d000000000316af8 5f666f72 5f726573
> ptr 5f666f725f726573, addr c0000000005d0e40, GET_ADDR c000000000007cac
> <3>addr does not match 5f666f725f726573
> <0>------------[ cut here ]------------
> <3>Badness at /home/geoff/projects/cell/ps3-linux-dev/kernel/trace/ftrace.c:441
> NIP: c0000000000b3038 LR: c0000000000b46bc CTR: 0000000000000000
> REGS: c00000001d143780 TRAP: 0700   Not tainted  (2.6.29-rc3-02162-gec97e82-dirty)
> MSR: 8000000000020032 <CE,IR,DR>  CR: 42222442  XER: 00000000
> TASK = c000000006f64640[373] 'modprobe' THREAD: c00000001d140000 CPU: 1
> <6>GPR00: 0000000000000001 c00000001d143a00 c000000000625988 ffffffffffffffea
> <6>GPR04: d000000000305298 c0000000000628c0 0000000000000000 0000000000000002
> <6>GPR08: 0000000000000000 c000000000c6ce80 0000000000020000 c000000006f64640
> <6>GPR12: 0000000042222444 c000000000655500 d00000000031e9d0 c00000001d143c78
> <6>GPR16: d00000000018cbe0 0000000000000549 d00000000018c208 d00000000031e998
> <6>GPR20: d00000000031de00 d00000000031e980 00000001e48bc1f0 0000000000000001
> <6>GPR24: c0000000005d0e40 c00000001d47b2b8 c000000000576270 d000000000305298
> <6>GPR28: d000000000305298 c00000001d47b2e0 c0000000005c6960 c00000001d143a00
> NIP [c0000000000b3038] .ftrace_bug+0x98/0x210
> LR [c0000000000b46bc] .ftrace_convert_nops+0x23c/0x344
> Call Trace:
> [c00000001d143a00] [c0000000000628c0] .vprintk+0x394/0x42c (unreliable)
> [c00000001d143aa0] [c0000000000b46bc] .ftrace_convert_nops+0x23c/0x344
> [c00000001d143b70] [c0000000000b47fc] .ftrace_init_module+0x38/0x50
> [c00000001d143bf0] [c0000000000a1c70] .load_module+0x12e0/0x189c
> [c00000001d143d80] [c0000000000a23fc] .SyS_init_module+0x90/0x248
> [c00000001d143e30] [c0000000000074dc] syscall_exit+0x0/0x40
> Instruction dump:
> 41fe0010 e93e8010 38000001 9009002c e93e8000 e97e8008 e87e80b0 48000130
> 80090030 7c000034 5400d97e 78000020 <0b000000> 2fa00000 41fe0010 e93e8010
> <6>ftrace failed to modify [<d000000000305298>] 0xd000000000305298
>  actual: 48:00:18:41
> <6>usbcore: registered new interface driver usbfs
> 
>  
> This ptr of 5f666f725f726573 seems bogus.  I think this code is not
> working correctly:

Well, obviously the code is not working correctly, if it is blowing up
 ;-)

> 
> 	offset = (unsigned)((unsigned short)jmp[0]) << 16 |
> 		(unsigned)((unsigned short)jmp[1]);
> 
> 	tramp = mod->arch.toc + offset + 32;
> 
> 	if (probe_kernel_read(jmp, (void *)tramp, 8)) {
> 		printk(KERN_ERR "Failed to read %lx\n", tramp);
> 		return -EFAULT;
> 	}
> 
> 	ptr = ((unsigned long)jmp[0] << 32) + jmp[1];
> 
> addr and GET_ADDR(addr) seem OK, System.map shows both to be _mcount.
> If I force it to continue with this:
> 
> 	if (ptr != GET_ADDR(addr)) {
> 		printk(KERN_ERR "addr does not match %lx\n", ptr);
> 		//return -EINVAL;

Please do not do that! You risk writing random stuff over random memory.

If the ptr does not equal what we want, then we can not guarantee that we
are writing what we want to where we want.

> 	}
> 
> It loads a lot of modules, but eventually it fails with the
> following, which seems to mean a bad tramp value.
> 
> ip:d0000000005f08cc jumps to d0000000005f1920 r2: d0000000006031c8 3d82ffff 398ce758 ffffe758 toc: d000000000601940<3>Failed to read d000000000601940
> <0>------------[ cut here ]------------
> <3>Badness at /home/geoff/projects/cell/ps3-linux-dev/kernel/trace/ftrace.c:436
> NIP: c0000000000b3000 LR: c0000000000b46dc CTR: 0000000000000001
> REGS: c00000001d5b7780 TRAP: 0700   Not tainted  (2.6.29-rc3-02162-gec97e82-dirty)
> MSR: 8000000000020032 <CE,IR,DR>  CR: 22222442  XER: 20000000
> TASK = c000000006fea7c0[712] 'modprobe' THREAD: c00000001d5b4000 CPU: 0
> <6>GPR00: 0000000000000001 c00000001d5b7a00 c000000000625998 fffffffffffffff2
> <6>GPR04: d0000000005f08cc c000000000062054 0000000000000000 0000000000000002
> <6>GPR08: 0000000000000000 c000000000c6ce80 000000000001ffff c000000006fea7c0
> <6>GPR12: 0000000022222444 c000000000655300 d0000000005f9fd0 c00000001d5b7c78
> <6>GPR16: d000000000565c58 0000000000000215 d0000000005653e5 d0000000005f9f98
> <6>GPR20: d0000000005f9860 d0000000005f9f80 00000002cfe82a50 0000000000000001
> <6>GPR24: c0000000005d0e50 c00000001d21e6f0 c000000000576270 d0000000005f08cc
> <6>GPR28: d0000000005f08cc c00000001d21e718 c0000000005c6960 c00000001d5b7a00
> NIP [c0000000000b3000] .ftrace_bug+0x60/0x210
> LR [c0000000000b46dc] .ftrace_convert_nops+0x25c/0x364
> Call Trace:
> [c00000001d5b7a00] [0000000000000004] 0x4 (unreliable)
> [c00000001d5b7aa0] [c0000000000b46dc] .ftrace_convert_nops+0x25c/0x364
> [c00000001d5b7b70] [c0000000000b481c] .ftrace_init_module+0x38/0x50
> [c00000001d5b7bf0] [c0000000000a1c70] .load_module+0x12e0/0x189c
> [c00000001d5b7d80] [c0000000000a23fc] .SyS_init_module+0x90/0x248
> [c00000001d5b7e30] [c0000000000074dc] syscall_exit+0x0/0x40
> Instruction dump:
> 419e001c 2f83ffff 419e010c 2f83ffea e93e8010 409e013c 48000040 e93e8010
> 8009002c 7c000034 5400d97e 78000020 <0b000000> 2fa00000 41fe0010 e93e8010
> <6>ftrace faulted on modifying [<d0000000005f08cc>] 0xd0000000005f08cc

The following I snipped out of your previous email (and this goes with the 
above).

> 3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac
> ip:d0000000000456dc jumps to d000000000046340 r2: d000000000050c00
> 3d82ffff 398c5740 ffff5740 toc: d000000000046360 c0000000 00007cac

Here the ptr == c0000000 00007cac, which looks like a legitimate address,
and everything worked fine and dandy.

...
> ps3_system_bus_match:362: dev=11.0(lpm_01), drv=11.0(ps3-lpm): match
> ps3_system_bus_match:362: dev=11.0(lpm_01), drv=11.0(ps3-lpm): match
> ps3-lpm lpm_01:  <- ps3_lpm_probe:1245:
> ip:d0000000003fe280 jumps to d0000000003ffad8 r2: d000000000422c70
> 3d82fffe 398cce68 fffece68 toc: d00000000040faf8 6c656400 5f5f6b73

Here the pointer is bogus.  We need to find out why. Is the r2 "toc" that 
is used bogus? We may need to disassemble the module and look at it 
deeper. I'm not an PPC expect, I just based my code off of the module_64.c 
code.

-- Steve


> addr does not match
> ptr: 6c6564005f5f6b73
> addr: c0000000004ff128
> GET_ADDR(addr): c000000000007cac

Re: Dynamic-ftrace not working in PlayStation3

[Arnd Bergmann]

On Saturday 31 January 2009, Geoff Levand wrote:
> > 
> > So I take it that the above showed that the code worked for some?
> 
> In my trials it blows up on the first load_module() call, and for my
> config that was usbcore:

I looked into it some more with Remis yesterday, and we got ftrace
working by building usbcore and alsa into the kernel. Incidentally,
usbcore is the largest module in this installation (~3MB), which
indicates that it is in some way either related to the size of the
module.

> This ptr of 5f666f725f726573 seems bogus.  I think this code is not
> working correctly:

This is an ascii string "_for_res", probably part of
usb_lock_device_for_reset. We saw the same behaviour, but
a different string.

	Arnd <><

Re: Dynamic-ftrace not working in PlayStation3

[Remis]

Complementing what Arnd said, we got the dynamic ftrace to work. Just
changed 4 things in the *menuconfig*.
Before these were built as modules (this is the default I guess):
CONFIG_USB=m
CONFIG_SOUND=m
CONFIG_SND=m
CONFIG_SND_USB_AUDIO=m

Then got them built into the kernel:
CONFIG_USB=y
CONFIG_SOUND=y
CONFIG_SND=y
CONFIG_SND_USB_AUDIO=y

And everything worked just fine.
In my config when I also tried to build the *CONFIG_SND_PS3* into the
kernel, the kernel did not boot (probably another bug !? :-).

Cheers,
Remis

On Sat, Jan 31, 2009 at 11:25 AM, Arnd Bergmann <arnd@arndb.de> wrote:
> On Saturday 31 January 2009, Geoff Levand wrote:
>> >
>> > So I take it that the above showed that the code worked for some?
>>
>> In my trials it blows up on the first load_module() call, and for my
>> config that was usbcore:
>
> I looked into it some more with Remis yesterday, and we got ftrace
> working by building usbcore and alsa into the kernel. Incidentally,
> usbcore is the largest module in this installation (~3MB), which
> indicates that it is in some way either related to the size of the
> module.
>
>> This ptr of 5f666f725f726573 seems bogus.  I think this code is not
>> working correctly:
>
> This is an ascii string "_for_res", probably part of
> usb_lock_device_for_reset. We saw the same behaviour, but
> a different string.
>
>        Arnd <><

Re: Dynamic-ftrace not working in PlayStation3

[Geert Uytterhoeven]

On Sun, 1 Feb 2009, Remis wrote:
> Complementing what Arnd said, we got the dynamic ftrace to work. Just
> changed 4 things in the *menuconfig*.
> Before these were built as modules (this is the default I guess):
> CONFIG_USB=m
> CONFIG_SOUND=m
> CONFIG_SND=m
> CONFIG_SND_USB_AUDIO=m
> 
> Then got them built into the kernel:
> CONFIG_USB=y
> CONFIG_SOUND=y
> CONFIG_SND=y
> CONFIG_SND_USB_AUDIO=y
> 
> And everything worked just fine.
> In my config when I also tried to build the *CONFIG_SND_PS3* into the
> kernel, the kernel did not boot (probably another bug !? :-).

JFYI, I always use CONFIG_SND_PS3=y in my PS3 kernels, so it should work.
Probably it conflicts with something else I have not enabled...

With kind regards,

Geert Uytterhoeven
Software Architect

Sony Techsoft Centre Europe
The Corporate Village · Da Vincilaan 7-D1 · B-1935 Zaventem · Belgium

Phone:    +32 (0)2 700 8453
Fax:      +32 (0)2 700 8622
E-mail:   Geert.Uytterhoeven@sonycom.com
Internet: http://www.sony-europe.com/

A division of Sony Europe (Belgium) N.V.
VAT BE 0413.825.160 · RPR Brussels
Fortis · BIC GEBABEBB · IBAN BE41293037680010

Re: Dynamic-ftrace not working in PlayStation3

[Steven Rostedt]

On Sat, 31 Jan 2009, Arnd Bergmann wrote:

> On Saturday 31 January 2009, Geoff Levand wrote:
> > > 
> > > So I take it that the above showed that the code worked for some?
> > 
> > In my trials it blows up on the first load_module() call, and for my
> > config that was usbcore:
> 
> I looked into it some more with Remis yesterday, and we got ftrace
> working by building usbcore and alsa into the kernel. Incidentally,
> usbcore is the largest module in this installation (~3MB), which
> indicates that it is in some way either related to the size of the
> module.
> 
> > This ptr of 5f666f725f726573 seems bogus.  I think this code is not
> > working correctly:
> 
> This is an ascii string "_for_res", probably part of
> usb_lock_device_for_reset. We saw the same behaviour, but
> a different string.

OK, I've been able to reproduce it. It looks like the assumptions of the 
trampoline that I've made is not correct if the size of the module is over 
some limit.  I had to make usb-core into a module, and I see the same 
bug.

I'll take a deeper look into it.

-- Steve

Re: Dynamic-ftrace not working in PlayStation3

[Benjamin Herrenschmidt]

> OK, I've been able to reproduce it. It looks like the assumptions of the 
> trampoline that I've made is not correct if the size of the module is over 
> some limit.  I had to make usb-core into a module, and I see the same 
> bug.
> 
> I'll take a deeper look into it.

Thanks ! I've been a bit swamped lately and didn't get a chance to dig
into that one .. yet. Let me know if you are stuck tho.

Cheers
Ben.