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
@@ -23,7 +23,7 @@#if 0#define DEBUGP printk#else-#define DEBUGP(fmt , ...) do { } while (0)+#define DEBUGP printk#endifstaticunsignedintftrace_nop=PPC_NOP_INSTR;
@@ -213,6 +213,8 @@ __ftrace_make_nop(struct module *mod,ptr=((unsignedlong)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);
So I take it that the above showed that the code worked for some?
quoted
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.
quoted
3d82fffe 398cce68 fffece68 toc: d00000000040faf8 6c656400 5f5f6b73
addr does not match
ptr: 6c6564005f5f6b73
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
Heh, I would have just done:
- #if 0
+ #if 1
;-)
-- Steve
quoted hunk
#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);
So I take it that the above showed that the code worked for some?
quoted
quoted
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.
quoted
quoted
3d82fffe 398cce68 fffece68 toc: d00000000040faf8 6c656400 5f5f6b73
addr does not match
ptr: 6c6564005f5f6b73
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
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).
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
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 <><
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 [off-list ref] wrote:
On Saturday 31 January 2009, Geoff Levand wrote:
quoted
quoted
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.
quoted
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 <><
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
From: Steven Rostedt <rostedt@goodmis.org> Date: 2009-02-04 21:52:31
On Sat, 31 Jan 2009, Arnd Bergmann wrote:
On Saturday 31 January 2009, Geoff Levand wrote:
quoted
quoted
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.
quoted
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
From: Benjamin Herrenschmidt <benh@kernel.crashing.org> Date: 2009-02-04 23:05:59
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.