Re: Ftrace vs perf user page fault statistics differences

[Will Hawkins]

On Wed, Jun 14, 2017 at 4:01 PM, Steven Rostedt <rostedt@xxxxxxxxxxx> wrote:
> On Wed, 14 Jun 2017 13:47:17 -0400
> Will Hawkins <whh8b@xxxxxxxxxxxx> wrote:
>
>
>> > That's how trace-cmd parses it.
>>
>> In the kernel version that I am running (again, pretty old) I do not
>> have this file. I do, however, have
>
> It may be due to the kernel version. It gets the functions
> from /proc/kallsyms. That could have have an issue. Although, I have
> this too:
>
> # grep per_cpu_start /proc/kallsyms
> 0000000000000000 A __per_cpu_start

Here's my result of a similar command:

# cat /proc/kallsyms | grep per_cpu_start
0000000000000000 D __per_cpu_start

There's only the difference between (what I think is) the flag value
there in the second column.

>
> But I don't see it being converted in my report.
>
> Hmm, it's not saved. Interesting:
>
>  trace-cmd report -f
>
> to see the list of saved functions. I need to figure out why it does
> for you, but not for me.

sudo ./trace-cmd report -f | grep per_cpu_start
0000000000000000 __per_cpu_start

>
>>
>> /sys/kernel/debug/tracing/events/exceptions/page_fault_user/format
>>
>> and the contents are:
>>
>> name: page_fault_user
>> ID: 79
>> format:
>>     field:unsigned short common_type;    offset:0;    size:2;    signed:0;
>>     field:unsigned char common_flags;    offset:2;    size:1;    signed:0;
>>     field:unsigned char common_preempt_count;    offset:3;    size:1;signed:0;
>>     field:int common_pid;    offset:4;    size:4;    signed:1;
>>
>>     field:unsigned long address;    offset:8;    size:8;    signed:0;
>>     field:unsigned long ip;    offset:16;    size:8;    signed:0;
>>     field:unsigned long error_code;    offset:24;    size:8;    signed:0;
>>
>> print fmt: "address=%pf ip=%pf error_code=0x%lx", (void
>> *)REC->address, (void *)REC->ip, REC->error_code
>>
>> Again, this looks like exactly what I would expect since address has
>> the cr2 value in that function. Plus, we know that the raw value is
>> correct. I suppose that the "symbolification" of that value is done in
>> trace-cmd, right? So, perhaps that is where I should start looking for
>> the problem?
>>
>> I definitely want to follow up on this and help where I can. That
>> said, I think I am satisfied with "our" (really, your) answer to the
>> original problem.
>
> It has something to do with the reading of the function names
> in /proc/kallsyms.
>
> Ah, I bet it's a change in the kernel. A recent update to trace-cmd was
> to ignore functions in kallsyms of type "A" (which you can see is what
> I have above).

And my output (above) seems to show that mine shows the per_cpu_start
as a D instead of an A. Perhaps that is why we are seeing differences
in our report? It's still curious that it would match 0x000..0 with
something that is clearly, well, not 0x00...0.

Let me know if there is a spot in the code where it decides whether to
symbolize. Or, I can work backward from the recent change you
mentioned above to find that spot if you will tell me the hash of that
commit.

Thanks again for working through this with me!

I hope you had a good weekend,
Will

>
> What do you have when you do:
>
>  sudo grep per_cpu_start /proc/kallsyms
>
> May or may not need sudo depending on if the kernel lets non root have
> access to kallsyms.
>
>
> -- Steve