Re: [PATCH 3/6] tracing: Add tp_pstore cmdline to have tracepoints go to pstore

[Sai Prakash Ranjan]

On 10/9/2018 4:10 AM, Joel Fernandes wrote:
> On Mon, Oct 08, 2018 at 10:36:59AM -0400, Steven Rostedt wrote:
> > On Mon, 8 Oct 2018 19:46:15 +0530
> > Sai Prakash Ranjan <saiprakash.ranjan@xxxxxxxxxxxxxx> wrote:
> >
> > > Hi Joel,
> > >
> > > Sorry for the long delay in updating this thread.
> > > But I just observed one weird behaviour in ftrace-ramoops when I was
> > > trying to use binary record instead of rendering text for event-ramoops.
> > >
> > > Even though we set the ftrace-size in device tree for ramoops, the
> > > actual ftrace-ramoops record seems to have more records than specified size.
> > > Is this expected or some bug?
> >
> > If ftrace-ramoops is using logic similar to the ftrace ring buffer,
> > then yes, it will be able to store more events than specified. The
> > ftrace ring buffer is broken up into pages, and everything is rounded
> > up to the nearest page (note, the data may be smaller than a page,
> > because each page also contains a header).
>
> In the pstore code, the pages are contiguous. The platform drivers for that
> platform configure 'ftrace-size' which is in bytes. That is further divided
> by the number of CPUs. The records from all the buffers are then merged at read time.
>
> Each function trace record is of type:
> struct pstore_ftrace_record {
>          unsigned long ip;
>          unsigned long parent_ip;
>          u64 ts;
> };
>
> which should be 24 bytes.
>
> But there is an ECC block (with ECC data and ECC header) added to each CPU in
> this case of the backing store of the pstore being RAM (pstore backing stores
> can be other media types too).

Thanks for this info.

> > > Below is the ftrace-ramoops size passed in dtsi for db410c and we can
> > > see that the ftrace record is more.
> > >
> > > # cat /sys/module/ramoops/parameters/ftrace_size
> > > 131072
> >
> > I'm assuming this too is like the ftrace ring buffer, where the size is
> > per cpu (and why you do a search per cpu below).
> >
> > > #
> > > # cat /sys/fs/pstore/ftrace-ramoops-0 | wc -c
> > > 560888
> > > #
> > > # cat /sys/fs/pstore/ftrace-ramoops-0 | grep CPU:0 | wc -c
> > > 137758
> > > #
> > > # cat /sys/fs/pstore/ftrace-ramoops-0 | grep CPU:1 | wc -c
> > > 140560
> > > #
> > > # cat /sys/fs/pstore/ftrace-ramoops-0 | grep CPU:2 | wc -c
> > > 141174
> > > #
> > > # cat /sys/fs/pstore/ftrace-ramoops-0 | grep CPU:3 | wc -c
> > > 141396
> > > #
>
> That could be because you're counting text characters when you're counting.
> You need to count the binary size.

Right thanks.

> > If you are using binary record, isn't this what you want? The
> > ftrace_size is the size of how much binary data is stored. When you
> > translate the binary into human text, the text should be bigger.
> >
> > > I don't see this in console or dmesg ramoops and also with the
> > > event-ramoops which I have posted since we don't use binary record, only
> > > ftrace-ramoops uses binary record to store trace data.
> > >
> > > Also regarding the warning on "event_call->event.funcs->trace()" call,
> > > I see it everytime without spinlock. Also we see output_printk using
> > > spinlock when making this call. I could not find a way to pass event
> > > buffer size and allocate in pstore. Steven can give some hints with this
> > > I guess.
>
> The spinlock warning you're talking about is this one correct?
>
> [    1.389382] WARNING: CPU: 2 PID: 2 at kernel/trace/trace_output.c:289 trace_raw_output_prep+0x18/0xa0
> [    1.389416] Modules linked in:
> which you reported here:
> https://lkml.org/lkml/2018/9/22/319
>
> This warning happens I think because you're trying to format the events while
> the trace events are being generated. You said you got this warning when you
> didn't use the spinlock. I believe the spinlocking prevents such races, but
> if you didn't need to format the events into text into text in the first
> place, then you wouldn't need such locking at all.
>
> I believe ftrace doesn't have such issues because such locking is taken care
> off when the trace events are formatted from the trace buffer and displayed,
> but I could be wrong about that.. I'll let Steven provide more inputs about
> how this warning can occur.
Yes Steven would have more insight on this warning.

> As a suggestion, please always provide references to the warnings you're
> referring to, such as previous LKML posts or atleast the warning message so
> folks know which warning you're talking about.

Yes sure.

Thanks,
Sai

--
QUALCOMM INDIA, on behalf of Qualcomm Innovation Center, Inc. is a member
of Code Aurora Forum, hosted by The Linux Foundation