Re: [RFC PATCH v2 2/3] pstore: Add register read/write{b,w,l,q} tracing support

[Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org>]

On 8/28/2018 9:32 PM, Steven Rostedt wrote:
> On Tue, 28 Aug 2018 18:47:33 +0530
> Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org> wrote:
> 
>> On 8/27/2018 9:45 PM, Steven Rostedt wrote:
>>> On Sat, 25 Aug 2018 12:54:07 +0530
>>> Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.org> wrote:
>>>
>>>    
>>>> Ftrace does not trace __raw{read,write}{b,l,w,q}() functions. I am not
>>>> sure why and how it is filtered out because I do not see any notrace
>>>> flag in those functions, maybe that whole directory is filtered out.
>>>> So adding this functionality to ftrace would mean removing the notrace
>>>> for these functions i.e., something like using
>>>> __raw{read,write}{b,l,w,q}() as the available filter functions. Also
>>>> pstore ftrace does not filter functions to trace I suppose?
>>>
>>> It's not traced because it is inlined. Simply make the __raw_read
>>> function a normal function and it will be traced. And then you could
>>> use ftrace to read the function.
>>>
>>> If this has to be per arch, you can register your callback with the
>>> REGS flags, and pt_regs will be passed to your callback function you
>>> attached to __raw_read*() as if you inserted a break point at that
>>> location, and you can get any reg data you want there.
>>>
>>>   
>>
>> Thank you very much for the information Steven. Ok so we can get
>> function parameters with pt_regs.
> 
> Yes.
> 
>>
>>>>
>>>> Coming to the reason as to why it would be good to keep this separate
>>>> from ftrace would be:
>>>> * Ftrace can get ip and parent ip, but suppose we need extra data (field
>>>> data) as in above sample output we would not be able to get through ftrace.
>>>
>>> As mentioned above, you can get regs (and ftrace is being expanded now
>>> to get parameters of functions).
>>>    
>> You mean there is another way to get parameters other than regs?
> 
> No, but you could register a callback function to be called when a
> function is hit, and the pt_regs are passed to it. We are working on
> getting parameters from the pt_regs (see this patch:
>   http://lkml.kernel.org/r/152465885737.26224.2822487520472783854.stgit@devbox)
> 
Cool, thanks for the link.
>>
>>>>
>>>> * Although this patch is for tracing register read/write, we can easily
>>>> add more functionality since we have dynamic_rtb api which can be hooked
>>>> to functions and start tracing events(IRQ, Context ID) something similar
>>>> to tracepoints.
>>>> Initially thought of having tracepoints for logging register read/write
>>>> but I do not know if we can export tracepoint data to pstore since the
>>>> main usecase is to debug unknown resets and hangs.
>>>
>>> I don't know why not? We have read/write tracepoints for
>>> read/write_msr() calls in x86.
>>>
>>> Anything can add a hook to the callback of the tracepoints, and use
>>> that infrastructure instead of creating yet another dynamic code
>>> modification infrastructure.
>>>    
>> Thanks for pointing out to read/write_msr, I checked it and was able to
>> implement something similar for arm64. But still can we export
>> tracepoint data to pstore because we need to debug reset cases and for
>> that pstore is of real importance?. If so then it would be great to have
>> various events logged into pstore which can be a lot of help for debugging.
>>
>> Also with the current dynamic filtering of read/write(PATCH 3/3), it is
>> a lot easier to filter register read/write since we use dynamic debug
>> framework which provides file, function and line level filtering
>> capacity. Maybe if we can add something like this to trace events it
>> would be better?
> 
> I would recommend using the tracepoint infrastructure. Note,
> tracepoints and trace events are two different things. Trace events use
> tracepoints, and you use trace events to create tracepoints, thus they
> are tightly coupled. But once a tracepoint exists, anything can connect
> to them without needing to use the trace event.
> 
> Let's look at the read_msr trace event. Because it is in a header, to
> avoid "include hell" we open code some of it:
> 
> static inline unsigned long long native_read_msr(unsigned int msr)
> {
> 	unsigned long long val;
> 
> 	val = __rdmsr(msr);
> 
> 	if (msr_tracepoint_active(__tracepoint_read_msr))
> 		do_trace_read_msr(msr, val, 0);
> 
> 	return val;
> }
> 
> Where:
> 
> #ifdef CONFIG_TRACEPOINTS
> #define msr_tracepoint_active(t) static_key_false(&(t).key)
> #else
> #define msr_tracepoint_active(t) false
> #endif
> 
> We have to open code the access to the tracepoint.key because msr.h is
> used in a lot of critical headers, we couldn't use the normal
> tracepoint.h header here.
> 
> The "static_key_false()" is a jump label that is just a nop. When the
> static_key is enabled, the nop is converted to a static "jmp" to the
> code that calls "do_trace_read_msr()". This is a function call to a
> function defined in msr.c (where we can do proper includes), and all
> that does is call the tracepoint "trace_read_msr()", which is also a
> static key that, when enabled, will iterate over a list of functions it
> should call with the defined parameters (msr, val, failed).
> 
> When defining the trace event for "read_msr", it creates the tracepoint
> "trace_read_msr()" and we place it in this do_trace_read_msr()
> function. The TRACE_EVENT() macros creates everything that is needed to
> connect the trace event "read_msr" to the tracepoint
> "trace_read_msr()", and you can enable this via the tracefs subsystem
> or via perf.
> 
> But you can also add your own hook to that tracepoint. If you have code
> that does:
> 
> register_trace_read_msr(func, data);
> 
> The "func" gets called when trace_read_msr() is hit. Thus you could
> have:
> 
> static void my_func(void *data, unsigned msr, u64 val, int failed)
> {
> 	struct my_struct *my_data = data;
> 
> 	do_something_with(my_data, msr, val, failed);
> }
> 
> {
> 	struct my_struct *my_data;
> 
> 	my_data = kzalloc(sizeof(*my_data)), GFP_KERNEL);
> 
> 	register_trace_read_msr(my_func, my_data);
> }
> 
> 
> And then your function "my_func" will be called with any data you
> registered with it (you may register "NULL" if you don't need to pass
> in data), and it will also get the parameters passed to trace_read_msr()
> 
> If you want to have you "my_func" record into pstore, then it will
> happen at runtime, and if the system resets, you have your data where
> you want it.
> 

Wow, thank you so much for the detailed explanation, it helps a lot. I 
will try to use this and post next version soon.

- Sai Prakash