Callgraphs split at the kernel boundary

Callgraphs split at the kernel boundary

[Ralph Böhme]

Hi!

I'm noticing split callgraphs at the kernel boundary when recording callgraphs
with perf record. This happens with both DWARF and FP, eg

perf record -g --call-graph fp -p 3293, or
perf record -g --call-graph dwarf -p 3293

Here are two examples, sys_fcntl in perf script output:

DWARF:

smbd  3293 48551.772583:     250000 cpu-clock: 
            7fff8183eb75 _cond_resched ([kernel.kallsyms])
            7fff81264bfb locks_alloc_lock ([kernel.kallsyms])
            7fff812680a6 fcntl_setlk ([kernel.kallsyms])
            7fff81224182 sys_fcntl ([kernel.kallsyms])
            7fff81842a72 entry_SYSCALL_64_fastpath ([kernel.kallsyms])
            7f9aca651687 __libc_fcntl (/lib/x86_64-linux-gnu/libpthread-2.23.so)
            7f9ac407d032 fcntl_lock (/home/slow/git/samba/scratch/bin/default/lib/tdb/libtdb.so)

FP:

smbd  3293 48969.378250:     250000 cpu-clock: 
            7fff810c5b00 __init_waitqueue_head ([kernel.kallsyms])
            7fff812680a6 fcntl_setlk ([kernel.kallsyms])
            7fff81224182 sys_fcntl ([kernel.kallsyms])
            7fff81842a72 entry_SYSCALL_64_fastpath ([kernel.kallsyms])
                   10687 __libc_fcntl (/lib/x86_64-linux-gnu/libpthread-2.23.so)
                       c [unknown] ([unknown])
            556e17ea6470 [unknown] ([unknown])

I'm seeing this on different kernels and perf versions:

# uname -a && perf -v
Linux kazak 4.12.8-300.fc26.x86_64 #1 SMP Thu Aug 17 15:30:20 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux
perf version 4.12.8.300.fc26.x86_64.ga6ba

# uname -a && perf -v
Linux titan 4.4.0-79-generic #100-Ubuntu SMP Wed May 17 19:58:14 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux
perf version 4.4.67

Occasionally callgraphs are not split, but this seems to be the exception:

smbd 18113 298919.831823:     250000 cpu-clock: 
                  46e9a9 path_get (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
                  4605d5 do_dentry_open (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
                  461bfe vfs_open (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
                  473caf path_openat (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
                  475e8b do_filp_open (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
                  4620ea do_sys_open (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
                  46219e sys_open (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
                  a77737 entry_SYSCALL_64 (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
                   1189d [unknown] (/usr/lib64/libpthread-2.25.so)
                  1c51c6 dos_mode_check_compressed (/home/slow/git/samba/scratch/bin/default/source3/libsmbd-base-samba4.so)
                  1c5435 dos_mode (/home/slow/git/samba/scratch/bin/default/source3/libsmbd-base-samba4.so)
                  22a89d smbd_smb2_create_send (/home/slow/git/samba/scratch/bin/default/source3/libsmbd-base-samba4.so)
                  2269c4 smbd_smb2_request_process_create (/home/slow/git/samba/scratch/bin/default/source3/libsmbd-base-samba4.so)
                  219833 smbd_smb2_request_dispatch (/home/slow/git/samba/scratch/bin/default/source3/libsmbd-base-samba4.so)
                  21e974 smbd_smb2_io_handler (/home/slow/git/samba/scratch/bin/default/source3/libsmbd-base-samba4.so)
                  21ea7a smbd_smb2_connection_handler (/home/slow/git/samba/scratch/bin/default/source3/libsmbd-base-samba4.so)
                    f106 epoll_event_loop (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so)
                    f73e epoll_event_loop_once (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so)
                    c431 std_event_loop_once (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so)
                    51b9 _tevent_loop_once (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so)
                    54d4 tevent_common_loop_wait (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so)
                    c4d3 std_event_loop_wait (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so)
                    5577 _tevent_loop_wait (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so)
                  200da1 smbd_process (/home/slow/git/samba/scratch/bin/default/source3/libsmbd-base-samba4.so)
                    dd24 smbd_accept_connection (/home/slow/git/samba/scratch/bin/default/source3/smbd/smbd)
                    f106 epoll_event_loop (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so)
                    f73e epoll_event_loop_once (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so)
                    c431 std_event_loop_once (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so)
                    51b9 _tevent_loop_once (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so)
                    54d4 tevent_common_loop_wait (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so)
                    c4d3 std_event_loop_wait (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so)
                    5577 _tevent_loop_wait (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so)
                    eb27 smbd_parent_loop (/home/slow/git/samba/scratch/bin/default/source3/smbd/smbd)
                   10ce5 main (/home/slow/git/samba/scratch/bin/default/source3/smbd/smbd)
                   2050a __libc_start_main (/usr/lib64/libc-2.25.so)
        6e3e258d4c544155 [unknown] ([unknown])

The majority of callgraphs for sys_open is split as well:

smbd 18113 298923.760035:     250000 cpu-clock: 
                  3d7de6 file_ra_state_init (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
                  461bfe vfs_open (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
                  473caf path_openat (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
                  475e8b do_filp_open (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
                  4620ea do_sys_open (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
                  46219e sys_open (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
                  a77737 entry_SYSCALL_64 (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
                   1189d [unknown] (/usr/lib64/libpthread-2.25.so)
                     c70 [unknown] ([unknown])
              ee0000000b [unknown] ([unknown])
                      41 [unknown] ([unknown])

As a result overhead calcuation is split between userspace and kernel:
# perf report --stdio -g none

# To display the perf.data header info, please use --header/--header-only options.
#
# Total Lost Samples: 0
#
# Samples: 11K of event 'cpu-clock'
# Event count (approx.): 2754000000
#
# Children      Self  Command  Shared Object                Symbol                                       
# ........  ........  .......  ...........................  .....................
#
    54.73%     0.60%  smbd     [kernel.vmlinux]             [k] entry_SYSCALL_64e
    44.62%     0.09%  smbd     libtevent.so                 [.] epoll_event_loop
    44.62%     0.05%  smbd     libtevent.so                 [.] _tevent_loop_once

The following flamegraph shows this as well:

<https://www.samba.org/~slow/flamegraph-25453.svg>

Am I missing something? This renders CPU profiling with perf pretty useless for
my usecase with lots of syscalls.

Thanks!
-slow

Re: Callgraphs split at the kernel boundary

[Milian Wolff]

[-- Attachment #1: Type: text/plain, Size: 8979 bytes --]

On Sunday, September 3, 2017 11:49:13 AM CEST Ralph Böhme wrote:
> Hi!
> 
> I'm noticing split callgraphs at the kernel boundary when recording
> callgraphs with perf record. This happens with both DWARF and FP, eg
> 
> perf record -g --call-graph fp -p 3293, or
> perf record -g --call-graph dwarf -p 3293
> 
> Here are two examples, sys_fcntl in perf script output:
> 
> DWARF:
> 
> smbd  3293 48551.772583:     250000 cpu-clock:
>             7fff8183eb75 _cond_resched ([kernel.kallsyms])
>             7fff81264bfb locks_alloc_lock ([kernel.kallsyms])
>             7fff812680a6 fcntl_setlk ([kernel.kallsyms])
>             7fff81224182 sys_fcntl ([kernel.kallsyms])
>             7fff81842a72 entry_SYSCALL_64_fastpath ([kernel.kallsyms])
>             7f9aca651687 __libc_fcntl
> (/lib/x86_64-linux-gnu/libpthread-2.23.so) 7f9ac407d032 fcntl_lock
> (/home/slow/git/samba/scratch/bin/default/lib/tdb/libtdb.so)
> 
> FP:
> 
> smbd  3293 48969.378250:     250000 cpu-clock:
>             7fff810c5b00 __init_waitqueue_head ([kernel.kallsyms])
>             7fff812680a6 fcntl_setlk ([kernel.kallsyms])
>             7fff81224182 sys_fcntl ([kernel.kallsyms])
>             7fff81842a72 entry_SYSCALL_64_fastpath ([kernel.kallsyms])
>                    10687 __libc_fcntl
> (/lib/x86_64-linux-gnu/libpthread-2.23.so) c [unknown] ([unknown])
>             556e17ea6470 [unknown] ([unknown])
> 
> I'm seeing this on different kernels and perf versions:
> 
> # uname -a && perf -v
> Linux kazak 4.12.8-300.fc26.x86_64 #1 SMP Thu Aug 17 15:30:20 UTC 2017
> x86_64 x86_64 x86_64 GNU/Linux perf version 4.12.8.300.fc26.x86_64.ga6ba
> 
> # uname -a && perf -v
> Linux titan 4.4.0-79-generic #100-Ubuntu SMP Wed May 17 19:58:14 UTC 2017
> x86_64 x86_64 x86_64 GNU/Linux perf version 4.4.67
> 
> Occasionally callgraphs are not split, but this seems to be the exception:
> 
> smbd 18113 298919.831823:     250000 cpu-clock:
>                   46e9a9 path_get
> (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux) 4605d5
> do_dentry_open (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
> 461bfe vfs_open (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
> 473caf path_openat
> (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux) 475e8b
> do_filp_open (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
> 4620ea do_sys_open
> (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux) 46219e sys_open
> (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux) a77737
> entry_SYSCALL_64
> (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux) 1189d [unknown]
> (/usr/lib64/libpthread-2.25.so) 1c51c6 dos_mode_check_compressed
> (/home/slow/git/samba/scratch/bin/default/source3/libsmbd-base-samba4.so)
> 1c5435 dos_mode
> (/home/slow/git/samba/scratch/bin/default/source3/libsmbd-base-samba4.so)
> 22a89d smbd_smb2_create_send
> (/home/slow/git/samba/scratch/bin/default/source3/libsmbd-base-samba4.so)
> 2269c4 smbd_smb2_request_process_create
> (/home/slow/git/samba/scratch/bin/default/source3/libsmbd-base-samba4.so)
> 219833 smbd_smb2_request_dispatch
> (/home/slow/git/samba/scratch/bin/default/source3/libsmbd-base-samba4.so)
> 21e974 smbd_smb2_io_handler
> (/home/slow/git/samba/scratch/bin/default/source3/libsmbd-base-samba4.so)
> 21ea7a smbd_smb2_connection_handler
> (/home/slow/git/samba/scratch/bin/default/source3/libsmbd-base-samba4.so)
> f106 epoll_event_loop
> (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so) f73e
> epoll_event_loop_once
> (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so) c431
> std_event_loop_once
> (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so) 51b9
> _tevent_loop_once
> (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so) 54d4
> tevent_common_loop_wait
> (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so) c4d3
> std_event_loop_wait
> (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so) 5577
> _tevent_loop_wait
> (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so) 200da1
> smbd_process
> (/home/slow/git/samba/scratch/bin/default/source3/libsmbd-base-samba4.so)
> dd24 smbd_accept_connection
> (/home/slow/git/samba/scratch/bin/default/source3/smbd/smbd) f106
> epoll_event_loop
> (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so) f73e
> epoll_event_loop_once
> (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so) c431
> std_event_loop_once
> (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so) 51b9
> _tevent_loop_once
> (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so) 54d4
> tevent_common_loop_wait
> (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so) c4d3
> std_event_loop_wait
> (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so) 5577
> _tevent_loop_wait
> (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so) eb27
> smbd_parent_loop
> (/home/slow/git/samba/scratch/bin/default/source3/smbd/smbd) 10ce5 main
> (/home/slow/git/samba/scratch/bin/default/source3/smbd/smbd) 2050a
> __libc_start_main (/usr/lib64/libc-2.25.so) 6e3e258d4c544155 [unknown]
> ([unknown])
> 
> The majority of callgraphs for sys_open is split as well:
> 
> smbd 18113 298923.760035:     250000 cpu-clock:
>                   3d7de6 file_ra_state_init
> (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux) 461bfe vfs_open
> (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux) 473caf
> path_openat (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
> 475e8b do_filp_open
> (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux) 4620ea
> do_sys_open (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
> 46219e sys_open (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
> a77737 entry_SYSCALL_64
> (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux) 1189d [unknown]
> (/usr/lib64/libpthread-2.25.so) c70 [unknown] ([unknown])
>               ee0000000b [unknown] ([unknown])
>                       41 [unknown] ([unknown])
> 
> As a result overhead calcuation is split between userspace and kernel:
> # perf report --stdio -g none
> 
> # To display the perf.data header info, please use --header/--header-only
> options. #
> # Total Lost Samples: 0
> #
> # Samples: 11K of event 'cpu-clock'
> # Event count (approx.): 2754000000
> #
> # Children      Self  Command  Shared Object                Symbol
> # ........  ........  .......  ........................... 
> ..................... #
>     54.73%     0.60%  smbd     [kernel.vmlinux]             [k]
> entry_SYSCALL_64e 44.62%     0.09%  smbd     libtevent.so                
> [.] epoll_event_loop 44.62%     0.05%  smbd     libtevent.so               
>  [.] _tevent_loop_once
> 
> The following flamegraph shows this as well:
> 
> <https://www.samba.org/~slow/flamegraph-25453.svg>
> 
> Am I missing something? This renders CPU profiling with perf pretty useless
> for my usecase with lots of syscalls.

I'm not sure whether what I'm seeing is also related to your issue, but I just 
tested this:

~~~~~
#include <complex>
#include <cmath>
#include <random>
#include <iostream>
#include <thread>
#include <mutex>
#include <vector>
#include <future>

using namespace std;

mutex g_mutex;

double worker()
{
    lock_guard<mutex> guard(g_mutex);
    uniform_real_distribution<double> uniform(-1E5, 1E5);
    default_random_engine engine;
    double s = 0;
    for (int i = 0; i < 1000; ++i) {
        s += norm(complex<double>(uniform(engine), uniform(engine)));
    }
    return s;
}

int main()
{
    vector<std::future<double>> results;
    for (int i = 0; i < 10000; ++i) {
        results.push_back(async(launch::async, worker));
    }
    return 0;
}
~~~~~

Then compile and record it:

~~~~~
$ g++ --std=c++11 -pthread -O2 -g test.cpp -o test
$ perf record -c 100000 --call-graph dwarf ./test
[ perf record: Woken up 559 times to write data ]
[ perf record: Captured and wrote 144.038 MB perf.data (17566 samples) ]
~~~~~

The report then shows three big chunks where unwinding fails:

~~~~~
$ perf report --stdio --no-children
...
    20.56%  test     [kernel.vmlinux]     [.] syscall_return_via_sysret
            |
            ---syscall_return_via_sysret

    12.76%  test     [kernel.vmlinux]     [.] entry_SYSCALL_64_fastpath
            |
            ---entry_SYSCALL_64_fastpath

     6.64%  test     [kernel.vmlinux]     [.] native_irq_return_iret
            |
            ---native_irq_return_iret
~~~~~

This happens with both, libunwind and elfutils' libdw. 
-- 
Milian Wolff | milian.wolff@kdab.com | Senior Software Engineer
KDAB (Deutschland) GmbH&Co KG, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt Experts

[-- Attachment #2: smime.p7s --]
[-- Type: application/pkcs7-signature, Size: 3826 bytes --]

Re: Callgraphs split at the kernel boundary

[Milian Wolff]

[-- Attachment #1: Type: text/plain, Size: 9838 bytes --]

On Monday, September 4, 2017 6:26:21 PM CEST Milian Wolff wrote:
> On Sunday, September 3, 2017 11:49:13 AM CEST Ralph Böhme wrote:
> > Hi!
> > 
> > I'm noticing split callgraphs at the kernel boundary when recording
> > callgraphs with perf record. This happens with both DWARF and FP, eg
> > 
> > perf record -g --call-graph fp -p 3293, or
> > perf record -g --call-graph dwarf -p 3293
> > 
> > Here are two examples, sys_fcntl in perf script output:
> > 
> > DWARF:
> > 
> > smbd  3293 48551.772583:     250000 cpu-clock:
> >             7fff8183eb75 _cond_resched ([kernel.kallsyms])
> >             7fff81264bfb locks_alloc_lock ([kernel.kallsyms])
> >             7fff812680a6 fcntl_setlk ([kernel.kallsyms])
> >             7fff81224182 sys_fcntl ([kernel.kallsyms])
> >             7fff81842a72 entry_SYSCALL_64_fastpath ([kernel.kallsyms])
> >             7f9aca651687 __libc_fcntl
> > 
> > (/lib/x86_64-linux-gnu/libpthread-2.23.so) 7f9ac407d032 fcntl_lock
> > (/home/slow/git/samba/scratch/bin/default/lib/tdb/libtdb.so)
> > 
> > FP:
> > 
> > smbd  3293 48969.378250:     250000 cpu-clock:
> >             7fff810c5b00 __init_waitqueue_head ([kernel.kallsyms])
> >             7fff812680a6 fcntl_setlk ([kernel.kallsyms])
> >             7fff81224182 sys_fcntl ([kernel.kallsyms])
> >             7fff81842a72 entry_SYSCALL_64_fastpath ([kernel.kallsyms])
> >             
> >                    10687 __libc_fcntl
> > 
> > (/lib/x86_64-linux-gnu/libpthread-2.23.so) c [unknown] ([unknown])
> > 
> >             556e17ea6470 [unknown] ([unknown])
> > 
> > I'm seeing this on different kernels and perf versions:
> > 
> > # uname -a && perf -v
> > Linux kazak 4.12.8-300.fc26.x86_64 #1 SMP Thu Aug 17 15:30:20 UTC 2017
> > x86_64 x86_64 x86_64 GNU/Linux perf version 4.12.8.300.fc26.x86_64.ga6ba
> > 
> > # uname -a && perf -v
> > Linux titan 4.4.0-79-generic #100-Ubuntu SMP Wed May 17 19:58:14 UTC 2017
> > x86_64 x86_64 x86_64 GNU/Linux perf version 4.4.67
> > 
> > Occasionally callgraphs are not split, but this seems to be the exception:
> > 
> > smbd 18113 298919.831823:     250000 cpu-clock:
> >                   46e9a9 path_get
> > 
> > (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux) 4605d5
> > do_dentry_open (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
> > 461bfe vfs_open
> > (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
> > 473caf path_openat
> > (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux) 475e8b
> > do_filp_open (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
> > 4620ea do_sys_open
> > (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux) 46219e
> > sys_open
> > (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux) a77737
> > entry_SYSCALL_64
> > (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux) 1189d
> > [unknown]
> > (/usr/lib64/libpthread-2.25.so) 1c51c6 dos_mode_check_compressed
> > (/home/slow/git/samba/scratch/bin/default/source3/libsmbd-base-samba4.so)
> > 1c5435 dos_mode
> > (/home/slow/git/samba/scratch/bin/default/source3/libsmbd-base-samba4.so)
> > 22a89d smbd_smb2_create_send
> > (/home/slow/git/samba/scratch/bin/default/source3/libsmbd-base-samba4.so)
> > 2269c4 smbd_smb2_request_process_create
> > (/home/slow/git/samba/scratch/bin/default/source3/libsmbd-base-samba4.so)
> > 219833 smbd_smb2_request_dispatch
> > (/home/slow/git/samba/scratch/bin/default/source3/libsmbd-base-samba4.so)
> > 21e974 smbd_smb2_io_handler
> > (/home/slow/git/samba/scratch/bin/default/source3/libsmbd-base-samba4.so)
> > 21ea7a smbd_smb2_connection_handler
> > (/home/slow/git/samba/scratch/bin/default/source3/libsmbd-base-samba4.so)
> > f106 epoll_event_loop
> > (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so) f73e
> > epoll_event_loop_once
> > (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so) c431
> > std_event_loop_once
> > (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so) 51b9
> > _tevent_loop_once
> > (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so) 54d4
> > tevent_common_loop_wait
> > (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so) c4d3
> > std_event_loop_wait
> > (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so) 5577
> > _tevent_loop_wait
> > (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so) 200da1
> > smbd_process
> > (/home/slow/git/samba/scratch/bin/default/source3/libsmbd-base-samba4.so)
> > dd24 smbd_accept_connection
> > (/home/slow/git/samba/scratch/bin/default/source3/smbd/smbd) f106
> > epoll_event_loop
> > (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so) f73e
> > epoll_event_loop_once
> > (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so) c431
> > std_event_loop_once
> > (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so) 51b9
> > _tevent_loop_once
> > (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so) 54d4
> > tevent_common_loop_wait
> > (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so) c4d3
> > std_event_loop_wait
> > (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so) 5577
> > _tevent_loop_wait
> > (/home/slow/git/samba/scratch/bin/default/lib/tevent/libtevent.so) eb27
> > smbd_parent_loop
> > (/home/slow/git/samba/scratch/bin/default/source3/smbd/smbd) 10ce5 main
> > (/home/slow/git/samba/scratch/bin/default/source3/smbd/smbd) 2050a
> > __libc_start_main (/usr/lib64/libc-2.25.so) 6e3e258d4c544155 [unknown]
> > ([unknown])
> > 
> > The majority of callgraphs for sys_open is split as well:
> > 
> > smbd 18113 298923.760035:     250000 cpu-clock:
> >                   3d7de6 file_ra_state_init
> > 
> > (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux) 461bfe
> > vfs_open
> > (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux) 473caf
> > path_openat (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
> > 475e8b do_filp_open
> > (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux) 4620ea
> > do_sys_open (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
> > 46219e sys_open
> > (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
> > a77737 entry_SYSCALL_64
> > (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux) 1189d
> > [unknown]
> > (/usr/lib64/libpthread-2.25.so) c70 [unknown] ([unknown])
> > 
> >               ee0000000b [unknown] ([unknown])
> >               
> >                       41 [unknown] ([unknown])
> > 
> > As a result overhead calcuation is split between userspace and kernel:
> > # perf report --stdio -g none
> > 
> > # To display the perf.data header info, please use --header/--header-only
> > options. #
> > # Total Lost Samples: 0
> > #
> > # Samples: 11K of event 'cpu-clock'
> > # Event count (approx.): 2754000000
> > #
> > # Children      Self  Command  Shared Object                Symbol
> > # ........  ........  .......  ...........................
> > ..................... #
> > 
> >     54.73%     0.60%  smbd     [kernel.vmlinux]             [k]
> > 
> > entry_SYSCALL_64e 44.62%     0.09%  smbd     libtevent.so
> > [.] epoll_event_loop 44.62%     0.05%  smbd     libtevent.so
> > 
> >  [.] _tevent_loop_once
> > 
> > The following flamegraph shows this as well:
> > 
> > <https://www.samba.org/~slow/flamegraph-25453.svg>
> > 
> > Am I missing something? This renders CPU profiling with perf pretty
> > useless
> > for my usecase with lots of syscalls.
> 
> I'm not sure whether what I'm seeing is also related to your issue, but I
> just tested this:
> 
> ~~~~~
> #include <complex>
> #include <cmath>
> #include <random>
> #include <iostream>
> #include <thread>
> #include <mutex>
> #include <vector>
> #include <future>
> 
> using namespace std;
> 
> mutex g_mutex;
> 
> double worker()
> {
>     lock_guard<mutex> guard(g_mutex);
>     uniform_real_distribution<double> uniform(-1E5, 1E5);
>     default_random_engine engine;
>     double s = 0;
>     for (int i = 0; i < 1000; ++i) {
>         s += norm(complex<double>(uniform(engine), uniform(engine)));
>     }
>     return s;
> }
> 
> int main()
> {
>     vector<std::future<double>> results;
>     for (int i = 0; i < 10000; ++i) {
>         results.push_back(async(launch::async, worker));
>     }
>     return 0;
> }
> ~~~~~
> 
> Then compile and record it:
> 
> ~~~~~
> $ g++ --std=c++11 -pthread -O2 -g test.cpp -o test
> $ perf record -c 100000 --call-graph dwarf ./test
> [ perf record: Woken up 559 times to write data ]
> [ perf record: Captured and wrote 144.038 MB perf.data (17566 samples) ]
> ~~~~~
> 
> The report then shows three big chunks where unwinding fails:
> 
> ~~~~~
> $ perf report --stdio --no-children
> ...
>     20.56%  test     [kernel.vmlinux]     [.] syscall_return_via_sysret
> 
>             ---syscall_return_via_sysret
> 
>     12.76%  test     [kernel.vmlinux]     [.] entry_SYSCALL_64_fastpath
> 
>             ---entry_SYSCALL_64_fastpath
> 
>      6.64%  test     [kernel.vmlinux]     [.] native_irq_return_iret
> 
>             ---native_irq_return_iret
> ~~~~~
> 
> This happens with both, libunwind and elfutils' libdw.

In my case, it seems to help to remove the filter. I.e. by default perf 
nowadays uses `cycles:uppp` on my system. If I instead specify `cycles:P` 
explicitly at `perf record` time, the issue above seems to be reduced, albeit 
not completely. Does this help in your situation too?

Cheers

-- 
Milian Wolff | milian.wolff@kdab.com | Senior Software Engineer
KDAB (Deutschland) GmbH&Co KG, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt Experts

[-- Attachment #2: smime.p7s --]
[-- Type: application/pkcs7-signature, Size: 3826 bytes --]

Re: Callgraphs split at the kernel boundary

[Ralph Böhme]

On Mon, Sep 04, 2017 at 06:44:23PM +0200, Milian Wolff wrote:
> In my case, it seems to help to remove the filter. I.e. by default perf 
> nowadays uses `cycles:uppp` on my system. If I instead specify `cycles:P` 
> explicitly at `perf record` time, the issue above seems to be reduced, albeit 
> not completely. Does this help in your situation too?

nope, I still mostly see split callgraphs, when recording with

# perf record -e cycles:P -g -p 30027

Eg (from perf script):

smbd 30027 66331.499304:     250000 cpu-clock:HG: 
                  9a8233 tcp_chrono_start (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
                  997565 skb_entail (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
                  99ba5d tcp_sendmsg (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
                  9c81c8 inet_sendmsg (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
                  920f08 sock_sendmsg (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
                  920fac sock_write_iter (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
                  463e72 __do_readv_writev (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
                  463fdc do_readv_writev (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
                  464260 vfs_writev (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
                  4642e1 do_writev (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
                  465510 sys_writev (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
                  a77737 entry_SYSCALL_64 (/usr/lib/debug/lib/modules/4.12.8-300.fc26.x86_64/vmlinux)
                  106680 __GI___writev (/usr/lib64/libc-2.25.so)
              c846d36d60 [unknown] ([unknown])
              c846d36f10 [unknown] ([unknown])
        65742f746e657665 [unknown] ([unknown])

Also wondering about the bottom three unresolved symbols... *scratches head*

Cheerio!
-slow

Re: Callgraphs split at the kernel boundary

[Milian Wolff]

[-- Attachment #1: Type: text/plain, Size: 1020 bytes --]

On Monday, September 4, 2017 7:01:27 PM CEST Ralph Böhme wrote:
> On Mon, Sep 04, 2017 at 06:44:23PM +0200, Milian Wolff wrote:
> > In my case, it seems to help to remove the filter. I.e. by default perf
> > nowadays uses `cycles:uppp` on my system. If I instead specify `cycles:P`
> > explicitly at `perf record` time, the issue above seems to be reduced,
> > albeit not completely. Does this help in your situation too?
> 
> nope, I still mostly see split callgraphs, when recording with
> 
> # perf record -e cycles:P -g -p 30027
> 
> Eg (from perf script):
> 
> smbd 30027 66331.499304:     250000 cpu-clock:HG:

I just realize that you are using this from within a VM which has no access to 
the PMU (so it's not using cycles but cpu-clock). So I doubt the issues we two 
are seeing are directly related.

Sorry for the noise

-- 
Milian Wolff | milian.wolff@kdab.com | Senior Software Engineer
KDAB (Deutschland) GmbH&Co KG, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt Experts

[-- Attachment #2: smime.p7s --]
[-- Type: application/pkcs7-signature, Size: 3826 bytes --]