Re: bug on ftrace with v3.17-rc5

[Felipe Balbi]

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 <balbi@xxxxxx> 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=00000000
> > [ 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: G        W
> > 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 0xfffffffe
> > [ 2940.098454] pc : [<c0356df8>]    lr : [<fffffffe>]    psr: a0000013
> > [ 2940.098454] sp : ed07ddb0  ip : ed07ddc0  fp : ed07ddbc
> > [ 2940.110445] r10: c070ff70  r9 : ed07de70  r8 : 00000000
> > [ 2940.115906] r7 : 814efa9e  r6 : ffffffff  r5 : ed4b6087  r4 : ed4b50c7
> > [ 2940.122726] r3 : 00000000  r2 : 814efa9e  r1 : ffffffff  r0 : 814efa9e
> > [ 2940.129546] Flags: NzCv  IRQs on  FIQs on  Mode SVC_32  ISA ARM Segment user
> > [ 2940.137000] Control: 10c5387d  Table: ac3dc059  DAC: 00000015
> > [ 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: 00000000 ed4b50c7 bf03ae9c ed4b6087 bf03ae9e 00000002 ed07de3c ed07dde8
> > [ 2940.170740] dde0: c035ab50 c0359600 ffffffff ffffffff ff0a0000 ffffffff ed07de30 ed4b5088
> > [ 2940.179275] de00: ed4b50c7 00000fc0 ff0a0004 ffffffff ed4b5088 ed4b5088 00000000 00001000
> > [ 2940.187810] de20: 00001008 00000fc0 ed4b5088 00000000 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 00000000
> > [ 2940.213428] de80: 814eba3e ed4b4000 03bd1201 c0c34790 ed07ded4 ed07dea0 c00edc0c bf0332d0
> > [ 2940.221994] dea0: 000002c7 ed07df10 ed07decc ed07deb8 ed4b4000 0000209c ec278ac0 00000000
> > [ 2940.230536] dec0: 00002000 ec0db340 ed07def4 ed07ded8 c00ee7ec c00eda90 c00ee7b0 ec278ac0
> > [ 2940.239075] dee0: ed4b4000 000002d5 ed07df44 ed07def8 c018b8d0 c00ee7bc c0166d3c ec278af0
> > [ 2940.247621] df00: 0001f090 ed07df78 000002c7 00000000 000002c8 00000000 00000000 ec0db340
> > [ 2940.256173] df20: 0001f090 ed07df78 ec0db340 00002000 0001f090 00000000 ed07df74 ed07df48
> > [ 2940.264729] df40: c0166e98 c018b5f4 00000001 c018535c 000168c1 00000000 ec0db340 ec0db340
> > [ 2940.273284] df60: 00002000 0001f090 ed07dfa4 ed07df78 c01675c4 c0166e0c 000168c1 00000000
> > [ 2940.281829] df80: 00002000 0000000a 0001f090 00000003 c000f064 ed07c000 00000000 ed07dfa8
> > [ 2940.290365] dfa0: c000ede0 c0167584 00002000 0000000a 00000003 0001f090 00002000 00000000
> > [ 2940.298909] dfc0: 00002000 0000000a 0001f090 00000003 7fffe000 0001e1e0 00002004 0000002f
> > [ 2940.307445] dfe0: 00000000 beed38ec 000104c8 b6e6397c 40000010 00000003 00000000 00000000
> > [ 2940.315992] [<c0356df8>] (strnlen) from [<c0359628>] (string.isra.8+0x34/0xe8)
> > [ 2940.323534] [<c0359628>] (string.isra.8) from [<c035ab50>] (vsnprintf+0x198/0x3fc)
> > [ 2940.331461] [<c035ab50>] (vsnprintf) from [<c00f1e64>] (trace_seq_printf+0x68/0x94)
> > [ 2940.339494] [<c00f1e64>] (trace_seq_printf) from [<bf033324>] (ftrace_raw_output_dwc3_log_request+0x60/0x78 [dwc3])
> > [ 2940.350424] [<bf033324>] (ftrace_raw_output_dwc3_log_request [dwc3]) from [<c00edc0c>] (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 think of a better way to do this and get it fixed during the -rc. The
bad thing is that I really still wanna print the address of the request,
so it's easy to grep for its lifetime.

cheers

-- 
balbi

Attachment: signature.asc
Description: Digital signature