Re: Ftrace vs perf user page fault statistics differences

[Will Hawkins]

Thank you for your response. I have included responses to your questions inline.

On Mon, Jun 12, 2017 at 9:20 PM, Steven Rostedt <rostedt@xxxxxxxxxxx> wrote:
> On Mon, 12 Jun 2017 20:20:42 -0400
> Will Hawkins <whh8b@xxxxxxxxxxxx> wrote:
>
>> Dear Mr. Rostedt and Kernel community,
>>
>> I hope that this is an appropriate place to ask this question, Please
>> forgive me for wasting your time if it is not. I've searched for
>> answers to this question on LKML and the "net" before asking. I
>> apologize if I already missed the question and answer somewhere else.
>
> No no, this is the correct forum.

Whew.

>
>>
>> I was doing a gut check of my understanding of how the Kernel pages in
>> a binary program for execution. I created a very small program that is
>> two pages. The entry point to the program is on page a and the code
>> simply jumps to the second page (b) for its termination.
>>
>> I compiled the program and dropped the kernel's memory caches [1].
>> Then I ran the program under perf:
>>
>> perf record --call-graph fp -e page-faults ../one_page_play/page
>
> Can you supply this program. So I can see exactly what it does?

I have attached the binary to this email. I also provided the source
so you can reproduce the situation directly. You can use the makefile
provided as long as you have nasm installed.

Although this is a response to a later question, I won't bury the
lede: The program was written by hand in asm, compiled with nasm to
object code and then run through gcc to get the output binary. Here is
how that works:

nasm -felf64 page.s && gcc -nostdlib page.o -o page

The result, as far as ldd is concerned:

hawkinsw@moormans:~/code/one_page_play$ ldd page
    not a dynamic executable


>
>>
>> I looked at the results:
>>
>> perf report
>>
>> and the results were as I expected. There were two page faults for
>> loading the code into memory and a page fault to
>> copy_user_enhanced_fast_string invoked by execve's implementation when
>> loading the binary.
>
> What does perf script show you?

Here is what perf report --stdio shows:

# Overhead  Command      Shared Object                              Symbol
# ........  .......  .................  ..................................
#
    33.33%     page  page               [.] _start
               |
               --- _start

    33.33%     page  page               [.] target
               |
               --- target

    33.33%     page  [kernel.kallsyms]  [k] copy_user_enhanced_fast_string
               |
               --- copy_user_enhanced_fast_string
                   load_elf_binary
                   search_binary_handler
                   do_execve_common.isra.23
                   sys_execve
                   stub_execve
                   0x7f51698a31e7



Here is what perf script shows:

page 28787 113626.587935: page-faults:
        ffffffff81376609 copy_user_enhanced_fast_string ([kernel.kallsyms])
        ffffffff812197bf load_elf_binary ([kernel.kallsyms])
        ffffffff811c76df search_binary_handler ([kernel.kallsyms])
        ffffffff811c8c8e do_execve_common.isra.23 ([kernel.kallsyms])
        ffffffff811c9176 sys_execve ([kernel.kallsyms])
        ffffffff8173afc9 stub_execve ([kernel.kallsyms])
            7f51698a31e7 [unknown] ([unknown])

page 28787 113626.587961: page-faults:
                  4000e0 _start (/home/hawkinsw/code/one_page_play/page)

page 28787 113626.587968: page-faults:
                  401473 target (/home/hawkinsw/code/one_page_play/page)

Again, this seems like exactly what I would expect.

>
>>
>> I decided to run the application under ftrace just for fun. I wanted
>> an excuse to learn more about it and this seemed like the perfect
>> chance. I used the incredible trace-cmd suite for the actual
>> incantation of ftrace. I won't include the actual incantations here
>> because I used many of them while digging around.
>
> what events did you enable?

Sorry for not including this in my first email. I enabled
exceptions:page_fault_user. I ran the trace-cmd record like this:

sudo ./trace-cmd record -e exceptions:page_fault_user -T --profile -l
handle_mm_fault ../one_page_play/page

and generated output like this:

./trace-cmd report --profile

>
>>
>> The results are both expected and unexpected. I see output like this:
>>
>> Event: page_fault_user:0x4000e0
>>
>> which indicates that there is a page fault at the program's entry
>> point (and matches what I saw with the perf output). I have another
>> similar entry that confirms the other expected page fault when loading
>> the second page of the test application.
>>
>> However, I also see entries like this:
>>
>> Event: page_fault_user:0x7f4f590934c4 (1)
>
> This could very well be the dynamic linker.

As I mentioned earlier, the program is statically linked. I did that
for this very reason. I wanted to isolate the page faults for loading
the program itself and not have to worry about interference from the
static linker. I was *trying* to be intentional about getting these
results. I appear to be missing the boat somewhere.

>
>>
>> The addresses of the faults I see that match that pattern are not
>> loaded into the application binary. What I discovered as I
>> investigated, is that those page faults seem to occur when the kernel
>> is attempting to record the output of stack traces, etc.
>
> Are you sure? What does ldd give you of your program?

I posted this output above, a little out of order. I will repeat here:

hawkinsw@moormans:~/code/one_page_play$ ldd page
    not a dynamic executable

>
>>
>> After thinking through this, I came up with the following hypothesis
>> which is the crux of this email:
>>
>> Ftrace's act of recording the traces that I requested to its ring
>> buffer generated page faults of their own. These page faults are
>> generated on behalf of the traced program and get reported in the
>> results.
>
> There are no page faults that happen by the ftrace ring buffer that
> would be associated with the program.

This is what I would have expected, but it was/is my best guess. I

>
>>
>> If that is correct/reasonable, it explains the differences between
>> what perf is reporting and what ftrace is reporting and I am happy.
>> If, however, that is a bogus conclusion, please help me understand
>> what is going on.
>
> I'll need to know more about exactly what you are doing to help out.

I hope that the information I posted above was helpful. Please let me
know what additional information I can provide.

Thanks again for taking the time to investigate this with me. I'm sure
it's something simple that I am missing.

Will

>
>>
>> I know that everyone who is on this email is incredibly busy and has
>> much to do. I hope that I've included enough information to make it
>> possible for you experts to advise, but not included too much to waste
>> your time.
>>
>> If you have the time or interest in answering, I would love to hear
>> your responses. Please CC me directly on all responses.
>
> No worries about Ccing you directly. LKML gets over 600 emails a day.
> Nobody reads it all. If someone isn't Cc'd directly, they will most
> likely never respond.
>
>>
>> Thanks again for your time!
>
> No problem.
>
> -- Steve
>
>>
>> Will
>>
>> [1] I used echo 3 > /proc/sys/vm/drop_caches to accomplish this and
>> issued it between every run. It may have been overkill, but I did it
>> anyway.
>

Attachment: page
Description: Binary data

Attachment: page.s
Description: Binary data

Attachment: Makefile
Description: Binary data