Patchwork Dynamic-ftrace not working in PlayStation3

login
register
mail settings
Submitter Geoff Levand
Date Jan. 30, 2009, 3:12 a.m.
Message ID <49827003.5050307@am.sony.com>
Download mbox | patch
Permalink /patch/21148/
State Not Applicable
Headers show

Comments

Geoff Levand - Jan. 30, 2009, 3:12 a.m.
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
Steven Rostedt - Jan. 30, 2009, 3:38 a.m.
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);
> 
> 
> 
>
Michael Ellerman - Jan. 30, 2009, 5:44 a.m.
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
Geoff Levand - Jan. 31, 2009, 3:04 a.m.
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
Steven Rostedt - Jan. 31, 2009, 6:20 a.m.
[ 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
Arnd Bergmann - Jan. 31, 2009, 10:25 a.m.
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 <><
Remis - Feb. 1, 2009, 1:28 p.m.
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 <><
Geert Uytterhoeven - Feb. 2, 2009, 8:24 a.m.
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
Steven Rostedt - Feb. 4, 2009, 9:52 p.m.
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
Benjamin Herrenschmidt - Feb. 4, 2009, 11:05 p.m.
> 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.

Patch

--- 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);