Re: bug on ftrace with v3.17-rc5
Hi,
On Wed, Sep 17, 2014 at 04:42:11PM -0400, Steven Rostedt wrote:
> On Wed, 17 Sep 2014 12:22:11 -0500
> Felipe Balbi wrote:
>
> > Hi,
> >
> > I just triggered a bug with trace by using tail on the trace file:
> >
> > # tail trace
> > [ 2940.039229] Unable to handle kernel paging request at virtual address
> > 814efa9e
> > [ 2940.046904] pgd = ec3dc000
> > [ 2940.049737] [814efa9e] *pgd=
> > [ 2940.053552] Internal error: Oops: 5 [#1] SMP ARM
> > [ 2940.058379] Modules linked in: usb_f_acm u_serial g_serial usb_f_uac2
> > libcomposite configfs xhci_hcd dwc3 udc_core matrix_keypad dwc3_omap
> > lis3lv02d_i2c lis3lv02d input_polldev [last unloaded: g_audio]
> > [ 2940.077238] CPU: 0 PID: 3020 Comm: tail Tainted: GW
> > 3.17.0-rc5-dirty #1097
> > [ 2940.085596] task: ed1b1040 ti: ed07c000 task.ti: ed07c000
> > [ 2940.091258] PC is at strnlen+0x18/0x68
> > [ 2940.095177] LR is at 0xfffe
> > [ 2940.098454] pc : []lr : []psr: a013
> > [ 2940.098454] sp : ed07ddb0 ip : ed07ddc0 fp : ed07ddbc
> > [ 2940.110445] r10: c070ff70 r9 : ed07de70 r8 :
> > [ 2940.115906] r7 : 814efa9e r6 : r5 : ed4b6087 r4 : ed4b50c7
> > [ 2940.122726] r3 : r2 : 814efa9e r1 : r0 : 814efa9e
> > [ 2940.129546] Flags: NzCv IRQs on FIQs on Mode SVC_32 ISA ARM Segment
> > user
> > [ 2940.137000] Control: 10c5387d Table: ac3dc059 DAC: 0015
> > [ 2940.143006] Process tail (pid: 3020, stack limit = 0xed07c248)
> > [ 2940.149098] Stack: (0xed07ddb0 to 0xed07e000)
> > [ 2940.153660] dda0: ed07dde4 ed07ddc0
> > c0359628 c0356dec
> > [ 2940.162203] ddc0: ed4b50c7 bf03ae9c ed4b6087 bf03ae9e 0002
> > ed07de3c ed07dde8
> > [ 2940.170740] dde0: c035ab50 c0359600 ff0a
> > ed07de30 ed4b5088
> > [ 2940.179275] de00: ed4b50c7 0fc0 ff0a0004 ed4b5088 ed4b5088
> > 1000
> > [ 2940.187810] de20: 1008 0fc0 ed4b5088 ed07de68 ed07de40
> > c00f1e64 c035a9c4
> > [ 2940.196341] de40: bf03dae0 ed07de70 ed4b4000 ec25b280 ed4b4000 ec25b280
> > bf03dae0 ed07de9c
> > [ 2940.204886] de60: ed07de78 bf033324 c00f1e0c bf03ae9c 814efa9e ed428bc0
> > 814eca3e
> > [ 2940.213428] de80: 814eba3e ed4b4000 03bd1201 c0c34790 ed07ded4 ed07dea0
> > c00edc0c bf0332d0
> > [ 2940.221994] dea0: 02c7 ed07df10 ed07decc ed07deb8 ed4b4000 209c
> > ec278ac0
> > [ 2940.230536] dec0: 2000 ec0db340 ed07def4 ed07ded8 c00ee7ec c00eda90
> > c00ee7b0 ec278ac0
> > [ 2940.239075] dee0: ed4b4000 02d5 ed07df44 ed07def8 c018b8d0 c00ee7bc
> > c0166d3c ec278af0
> > [ 2940.247621] df00: 0001f090 ed07df78 02c7 02c8
> > ec0db340
> > [ 2940.256173] df20: 0001f090 ed07df78 ec0db340 2000 0001f090
> > ed07df74 ed07df48
> > [ 2940.264729] df40: c0166e98 c018b5f4 0001 c018535c 000168c1
> > ec0db340 ec0db340
> > [ 2940.273284] df60: 2000 0001f090 ed07dfa4 ed07df78 c01675c4 c0166e0c
> > 000168c1
> > [ 2940.281829] df80: 2000 000a 0001f090 0003 c000f064 ed07c000
> > ed07dfa8
> > [ 2940.290365] dfa0: c000ede0 c0167584 2000 000a 0003 0001f090
> > 2000
> > [ 2940.298909] dfc0: 2000 000a 0001f090 0003 7fffe000 0001e1e0
> > 2004 002f
> > [ 2940.307445] dfe0: beed38ec 000104c8 b6e6397c 4010 0003
> >
> > [ 2940.315992] [] (strnlen) from []
> > (string.isra.8+0x34/0xe8)
> > [ 2940.323534] [] (string.isra.8) from []
> > (vsnprintf+0x198/0x3fc)
> > [ 2940.331461] [] (vsnprintf) from []
> > (trace_seq_printf+0x68/0x94)
> > [ 2940.339494] [] (trace_seq_printf) from []
> > (ftrace_raw_output_dwc3_log_request+0x60/0x78 [dwc3])
> > [ 2940.350424] [] (ftrace_raw_output_dwc3_log_request [dwc3])
> > from [] (print_trace_line+0x188/0x418)
>
> This shows it bugging with your tracepoint "dwc3_log_request".
>
> +DECLARE_EVENT_CLASS(dwc3_log_request,
> + TP_PROTO(struct dwc3_request *req),
> + TP_ARGS(req),
> + TP_STRUCT__entry(
> + __field(struct dwc3_request *, req)
> + ),
> + TP_fast_assign(
> + __entry->req = req;
> + ),
> + TP_printk("%s: req %p length %u/%u ==> %d",
> + __entry->req->dep->name, __entry->req,
> + __entry->req->request.actual, __entry->req->request.length,
> + __entry->req->request.status
> + )
> +);
>
> (Bah, cut and paste from the git web page doesn't format nicely)
>
> Anyway, I take issues with that: __entry->req->request.length,
> and all the other "__entry->req->*"
>
> Basically, you saved a pointer in the buffer called "req" and than you
> dereference it when you are printing. Does that pointer still exist?
>
> If whatever you assigned "req" to gets freed, you can not dereference
> it from the buffer! If you need to save the length and other fields, you
> need to do it in the fast assign.
good point, completely missed the fact that req could be long gone. I'll
go t
Re: bug on ftrace with v3.17-rc5
On Wed, 17 Sep 2014 12:22:11 -0500
Felipe Balbi wrote:
> Hi,
>
> I just triggered a bug with trace by using tail on the trace file:
>
> # tail trace
> [ 2940.039229] Unable to handle kernel paging request at virtual address
> 814efa9e
> [ 2940.046904] pgd = ec3dc000
> [ 2940.049737] [814efa9e] *pgd=
> [ 2940.053552] Internal error: Oops: 5 [#1] SMP ARM
> [ 2940.058379] Modules linked in: usb_f_acm u_serial g_serial usb_f_uac2
> libcomposite configfs xhci_hcd dwc3 udc_core matrix_keypad dwc3_omap
> lis3lv02d_i2c lis3lv02d input_polldev [last unloaded: g_audio]
> [ 2940.077238] CPU: 0 PID: 3020 Comm: tail Tainted: GW
> 3.17.0-rc5-dirty #1097
> [ 2940.085596] task: ed1b1040 ti: ed07c000 task.ti: ed07c000
> [ 2940.091258] PC is at strnlen+0x18/0x68
> [ 2940.095177] LR is at 0xfffe
> [ 2940.098454] pc : []lr : []psr: a013
> [ 2940.098454] sp : ed07ddb0 ip : ed07ddc0 fp : ed07ddbc
> [ 2940.110445] r10: c070ff70 r9 : ed07de70 r8 :
> [ 2940.115906] r7 : 814efa9e r6 : r5 : ed4b6087 r4 : ed4b50c7
> [ 2940.122726] r3 : r2 : 814efa9e r1 : r0 : 814efa9e
> [ 2940.129546] Flags: NzCv IRQs on FIQs on Mode SVC_32 ISA ARM Segment
> user
> [ 2940.137000] Control: 10c5387d Table: ac3dc059 DAC: 0015
> [ 2940.143006] Process tail (pid: 3020, stack limit = 0xed07c248)
> [ 2940.149098] Stack: (0xed07ddb0 to 0xed07e000)
> [ 2940.153660] dda0: ed07dde4 ed07ddc0
> c0359628 c0356dec
> [ 2940.162203] ddc0: ed4b50c7 bf03ae9c ed4b6087 bf03ae9e 0002
> ed07de3c ed07dde8
> [ 2940.170740] dde0: c035ab50 c0359600 ff0a
> ed07de30 ed4b5088
> [ 2940.179275] de00: ed4b50c7 0fc0 ff0a0004 ed4b5088 ed4b5088
> 1000
> [ 2940.187810] de20: 1008 0fc0 ed4b5088 ed07de68 ed07de40
> c00f1e64 c035a9c4
> [ 2940.196341] de40: bf03dae0 ed07de70 ed4b4000 ec25b280 ed4b4000 ec25b280
> bf03dae0 ed07de9c
> [ 2940.204886] de60: ed07de78 bf033324 c00f1e0c bf03ae9c 814efa9e ed428bc0
> 814eca3e
> [ 2940.213428] de80: 814eba3e ed4b4000 03bd1201 c0c34790 ed07ded4 ed07dea0
> c00edc0c bf0332d0
> [ 2940.221994] dea0: 02c7 ed07df10 ed07decc ed07deb8 ed4b4000 209c
> ec278ac0
> [ 2940.230536] dec0: 2000 ec0db340 ed07def4 ed07ded8 c00ee7ec c00eda90
> c00ee7b0 ec278ac0
> [ 2940.239075] dee0: ed4b4000 02d5 ed07df44 ed07def8 c018b8d0 c00ee7bc
> c0166d3c ec278af0
> [ 2940.247621] df00: 0001f090 ed07df78 02c7 02c8
> ec0db340
> [ 2940.256173] df20: 0001f090 ed07df78 ec0db340 2000 0001f090
> ed07df74 ed07df48
> [ 2940.264729] df40: c0166e98 c018b5f4 0001 c018535c 000168c1
> ec0db340 ec0db340
> [ 2940.273284] df60: 2000 0001f090 ed07dfa4 ed07df78 c01675c4 c0166e0c
> 000168c1
> [ 2940.281829] df80: 2000 000a 0001f090 0003 c000f064 ed07c000
> ed07dfa8
> [ 2940.290365] dfa0: c000ede0 c0167584 2000 000a 0003 0001f090
> 2000
> [ 2940.298909] dfc0: 2000 000a 0001f090 0003 7fffe000 0001e1e0
> 2004 002f
> [ 2940.307445] dfe0: beed38ec 000104c8 b6e6397c 4010 0003
>
> [ 2940.315992] [] (strnlen) from []
> (string.isra.8+0x34/0xe8)
> [ 2940.323534] [] (string.isra.8) from []
> (vsnprintf+0x198/0x3fc)
> [ 2940.331461] [] (vsnprintf) from []
> (trace_seq_printf+0x68/0x94)
> [ 2940.339494] [] (trace_seq_printf) from []
> (ftrace_raw_output_dwc3_log_request+0x60/0x78 [dwc3])
> [ 2940.350424] [] (ftrace_raw_output_dwc3_log_request [dwc3]) from
> [] (print_trace_line+0x188/0x418)
This shows it bugging with your tracepoint "dwc3_log_request".
+DECLARE_EVENT_CLASS(dwc3_log_request,
+ TP_PROTO(struct dwc3_request *req),
+ TP_ARGS(req),
+ TP_STRUCT__entry(
+ __field(struct dwc3_request *, req)
+ ),
+ TP_fast_assign(
+ __entry->req = req;
+ ),
+ TP_printk("%s: req %p length %u/%u ==> %d",
+ __entry->req->dep->name, __entry->req,
+ __entry->req->request.actual, __entry->req->request.length,
+ __entry->req->request.status
+ )
+);
(Bah, cut and paste from the git web page doesn't format nicely)
Anyway, I take issues with that: __entry->req->request.length,
and all the other "__entry->req->*"
Basically, you saved a pointer in the buffer called "req" and than you
dereference it when you are printing. Does that pointer still exist?
If whatever you assigned "req" to gets freed, you can not dereference
it from the buffer! If you need to save the length and other fields, you
need to do it in the fast assign.
-- Steve
> [ 2940.361507] [] (print_trace_line) from []
> (s_show+0x3c/0x12c)
> [ 2940.369330] [] (s_show) from [] (seq_read+0x2e8/0x4a0)
> [ 2940.376519] [] (seq_read) from [] (vfs_read+0x98/0x158)
> [ 2940.383796] [] (vfs_read) from [] (SyS_read+0x4c/0xa0)
> [ 2940.390981] [] (SyS_read) from []
> (ret_fast_syscall+0x0/0x48)
> [ 2940.398792] Code: e24cb004
Re: bug on ftrace with v3.17-rc5
Hi, On Wed, Sep 17, 2014 at 12:22:11PM -0500, Felipe Balbi wrote: > I just triggered a bug with trace by using tail on the trace file: > > # tail trace > [ 2940.039229] Unable to handle kernel paging request at virtual address > 814efa9e > [ 2940.046904] pgd = ec3dc000 > [ 2940.049737] [814efa9e] *pgd= > [ 2940.053552] Internal error: Oops: 5 [#1] SMP ARM > [ 2940.058379] Modules linked in: usb_f_acm u_serial g_serial usb_f_uac2 > libcomposite configfs xhci_hcd dwc3 udc_core matrix_keypad dwc3_omap > lis3lv02d_i2c lis3lv02d input_polldev [last unloaded: g_audio] > [ 2940.077238] CPU: 0 PID: 3020 Comm: tail Tainted: GW > 3.17.0-rc5-dirty #1097 > [ 2940.085596] task: ed1b1040 ti: ed07c000 task.ti: ed07c000 > [ 2940.091258] PC is at strnlen+0x18/0x68 > [ 2940.095177] LR is at 0xfffe > [ 2940.098454] pc : []lr : []psr: a013 > [ 2940.098454] sp : ed07ddb0 ip : ed07ddc0 fp : ed07ddbc > [ 2940.110445] r10: c070ff70 r9 : ed07de70 r8 : > [ 2940.115906] r7 : 814efa9e r6 : r5 : ed4b6087 r4 : ed4b50c7 > [ 2940.122726] r3 : r2 : 814efa9e r1 : r0 : 814efa9e > [ 2940.129546] Flags: NzCv IRQs on FIQs on Mode SVC_32 ISA ARM Segment > user > [ 2940.137000] Control: 10c5387d Table: ac3dc059 DAC: 0015 > [ 2940.143006] Process tail (pid: 3020, stack limit = 0xed07c248) > [ 2940.149098] Stack: (0xed07ddb0 to 0xed07e000) > [ 2940.153660] dda0: ed07dde4 ed07ddc0 > c0359628 c0356dec > [ 2940.162203] ddc0: ed4b50c7 bf03ae9c ed4b6087 bf03ae9e 0002 > ed07de3c ed07dde8 > [ 2940.170740] dde0: c035ab50 c0359600 ff0a > ed07de30 ed4b5088 > [ 2940.179275] de00: ed4b50c7 0fc0 ff0a0004 ed4b5088 ed4b5088 > 1000 > [ 2940.187810] de20: 1008 0fc0 ed4b5088 ed07de68 ed07de40 > c00f1e64 c035a9c4 > [ 2940.196341] de40: bf03dae0 ed07de70 ed4b4000 ec25b280 ed4b4000 ec25b280 > bf03dae0 ed07de9c > [ 2940.204886] de60: ed07de78 bf033324 c00f1e0c bf03ae9c 814efa9e ed428bc0 > 814eca3e > [ 2940.213428] de80: 814eba3e ed4b4000 03bd1201 c0c34790 ed07ded4 ed07dea0 > c00edc0c bf0332d0 > [ 2940.221994] dea0: 02c7 ed07df10 ed07decc ed07deb8 ed4b4000 209c > ec278ac0 > [ 2940.230536] dec0: 2000 ec0db340 ed07def4 ed07ded8 c00ee7ec c00eda90 > c00ee7b0 ec278ac0 > [ 2940.239075] dee0: ed4b4000 02d5 ed07df44 ed07def8 c018b8d0 c00ee7bc > c0166d3c ec278af0 > [ 2940.247621] df00: 0001f090 ed07df78 02c7 02c8 > ec0db340 > [ 2940.256173] df20: 0001f090 ed07df78 ec0db340 2000 0001f090 > ed07df74 ed07df48 > [ 2940.264729] df40: c0166e98 c018b5f4 0001 c018535c 000168c1 > ec0db340 ec0db340 > [ 2940.273284] df60: 2000 0001f090 ed07dfa4 ed07df78 c01675c4 c0166e0c > 000168c1 > [ 2940.281829] df80: 2000 000a 0001f090 0003 c000f064 ed07c000 > ed07dfa8 > [ 2940.290365] dfa0: c000ede0 c0167584 2000 000a 0003 0001f090 > 2000 > [ 2940.298909] dfc0: 2000 000a 0001f090 0003 7fffe000 0001e1e0 > 2004 002f > [ 2940.307445] dfe0: beed38ec 000104c8 b6e6397c 4010 0003 > > [ 2940.315992] [] (strnlen) from [] > (string.isra.8+0x34/0xe8) > [ 2940.323534] [] (string.isra.8) from [] > (vsnprintf+0x198/0x3fc) > [ 2940.331461] [] (vsnprintf) from [] > (trace_seq_printf+0x68/0x94) > [ 2940.339494] [] (trace_seq_printf) from [] > (ftrace_raw_output_dwc3_log_request+0x60/0x78 [dwc3]) > [ 2940.350424] [] (ftrace_raw_output_dwc3_log_request [dwc3]) from > [] (print_trace_line+0x188/0x418) > [ 2940.361507] [] (print_trace_line) from [] > (s_show+0x3c/0x12c) > [ 2940.369330] [] (s_show) from [] (seq_read+0x2e8/0x4a0) > [ 2940.376519] [] (seq_read) from [] (vfs_read+0x98/0x158) > [ 2940.383796] [] (vfs_read) from [] (SyS_read+0x4c/0xa0) > [ 2940.390981] [] (SyS_read) from [] > (ret_fast_syscall+0x0/0x48) > [ 2940.398792] Code: e24cb004 e351 e241e001 0a11 (e5d01000) > [ 2940.406980] ---[ end trace d8b38370fbb531f3 ]--- > > This is basically v3.17-rc5 with some USB patches I'm testing for v3.18, > including a patch where I added tracepoints to dwc3 [1] > > [1] > https://git.kernel.org/cgit/linux/kernel/git/balbi/usb.git/commit/?h=next&id=2c4cbe6e5a9c71408b496e00a78ea9284e98af16 btw, I've tracing for quite a while (over 20 minutes) without any issues, until this came out. -- balbi signature.asc Description: Digital signature
bug on ftrace with v3.17-rc5
Hi, I just triggered a bug with trace by using tail on the trace file: # tail trace [ 2940.039229] Unable to handle kernel paging request at virtual address 814efa9e [ 2940.046904] pgd = ec3dc000 [ 2940.049737] [814efa9e] *pgd= [ 2940.053552] Internal error: Oops: 5 [#1] SMP ARM [ 2940.058379] Modules linked in: usb_f_acm u_serial g_serial usb_f_uac2 libcomposite configfs xhci_hcd dwc3 udc_core matrix_keypad dwc3_omap lis3lv02d_i2c lis3lv02d input_polldev [last unloaded: g_audio] [ 2940.077238] CPU: 0 PID: 3020 Comm: tail Tainted: GW 3.17.0-rc5-dirty #1097 [ 2940.085596] task: ed1b1040 ti: ed07c000 task.ti: ed07c000 [ 2940.091258] PC is at strnlen+0x18/0x68 [ 2940.095177] LR is at 0xfffe [ 2940.098454] pc : []lr : []psr: a013 [ 2940.098454] sp : ed07ddb0 ip : ed07ddc0 fp : ed07ddbc [ 2940.110445] r10: c070ff70 r9 : ed07de70 r8 : [ 2940.115906] r7 : 814efa9e r6 : r5 : ed4b6087 r4 : ed4b50c7 [ 2940.122726] r3 : r2 : 814efa9e r1 : r0 : 814efa9e [ 2940.129546] Flags: NzCv IRQs on FIQs on Mode SVC_32 ISA ARM Segment user [ 2940.137000] Control: 10c5387d Table: ac3dc059 DAC: 0015 [ 2940.143006] Process tail (pid: 3020, stack limit = 0xed07c248) [ 2940.149098] Stack: (0xed07ddb0 to 0xed07e000) [ 2940.153660] dda0: ed07dde4 ed07ddc0 c0359628 c0356dec [ 2940.162203] ddc0: ed4b50c7 bf03ae9c ed4b6087 bf03ae9e 0002 ed07de3c ed07dde8 [ 2940.170740] dde0: c035ab50 c0359600 ff0a ed07de30 ed4b5088 [ 2940.179275] de00: ed4b50c7 0fc0 ff0a0004 ed4b5088 ed4b5088 1000 [ 2940.187810] de20: 1008 0fc0 ed4b5088 ed07de68 ed07de40 c00f1e64 c035a9c4 [ 2940.196341] de40: bf03dae0 ed07de70 ed4b4000 ec25b280 ed4b4000 ec25b280 bf03dae0 ed07de9c [ 2940.204886] de60: ed07de78 bf033324 c00f1e0c bf03ae9c 814efa9e ed428bc0 814eca3e [ 2940.213428] de80: 814eba3e ed4b4000 03bd1201 c0c34790 ed07ded4 ed07dea0 c00edc0c bf0332d0 [ 2940.221994] dea0: 02c7 ed07df10 ed07decc ed07deb8 ed4b4000 209c ec278ac0 [ 2940.230536] dec0: 2000 ec0db340 ed07def4 ed07ded8 c00ee7ec c00eda90 c00ee7b0 ec278ac0 [ 2940.239075] dee0: ed4b4000 02d5 ed07df44 ed07def8 c018b8d0 c00ee7bc c0166d3c ec278af0 [ 2940.247621] df00: 0001f090 ed07df78 02c7 02c8 ec0db340 [ 2940.256173] df20: 0001f090 ed07df78 ec0db340 2000 0001f090 ed07df74 ed07df48 [ 2940.264729] df40: c0166e98 c018b5f4 0001 c018535c 000168c1 ec0db340 ec0db340 [ 2940.273284] df60: 2000 0001f090 ed07dfa4 ed07df78 c01675c4 c0166e0c 000168c1 [ 2940.281829] df80: 2000 000a 0001f090 0003 c000f064 ed07c000 ed07dfa8 [ 2940.290365] dfa0: c000ede0 c0167584 2000 000a 0003 0001f090 2000 [ 2940.298909] dfc0: 2000 000a 0001f090 0003 7fffe000 0001e1e0 2004 002f [ 2940.307445] dfe0: beed38ec 000104c8 b6e6397c 4010 0003 [ 2940.315992] [] (strnlen) from [] (string.isra.8+0x34/0xe8) [ 2940.323534] [] (string.isra.8) from [] (vsnprintf+0x198/0x3fc) [ 2940.331461] [] (vsnprintf) from [] (trace_seq_printf+0x68/0x94) [ 2940.339494] [] (trace_seq_printf) from [] (ftrace_raw_output_dwc3_log_request+0x60/0x78 [dwc3]) [ 2940.350424] [] (ftrace_raw_output_dwc3_log_request [dwc3]) from [] (print_trace_line+0x188/0x418) [ 2940.361507] [] (print_trace_line) from [] (s_show+0x3c/0x12c) [ 2940.369330] [] (s_show) from [] (seq_read+0x2e8/0x4a0) [ 2940.376519] [] (seq_read) from [] (vfs_read+0x98/0x158) [ 2940.383796] [] (vfs_read) from [] (SyS_read+0x4c/0xa0) [ 2940.390981] [] (SyS_read) from [] (ret_fast_syscall+0x0/0x48) [ 2940.398792] Code: e24cb004 e351 e241e001 0a11 (e5d01000) [ 2940.406980] ---[ end trace d8b38370fbb531f3 ]--- This is basically v3.17-rc5 with some USB patches I'm testing for v3.18, including a patch where I added tracepoints to dwc3 [1] [1] https://git.kernel.org/cgit/linux/kernel/git/balbi/usb.git/commit/?h=next&id=2c4cbe6e5a9c71408b496e00a78ea9284e98af16 -- balbi signature.asc Description: Digital signature
