* Callgraphs split at the kernel boundary
@ 2017-09-03 9:49 Ralph Böhme
2017-09-04 16:26 ` Milian Wolff
0 siblings, 1 reply; 5+ messages in thread
From: Ralph Böhme @ 2017-09-03 9:49 UTC (permalink / raw)
To: linux-perf-users
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
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: Callgraphs split at the kernel boundary
2017-09-03 9:49 Callgraphs split at the kernel boundary Ralph Böhme
@ 2017-09-04 16:26 ` Milian Wolff
2017-09-04 16:44 ` Milian Wolff
0 siblings, 1 reply; 5+ messages in thread
From: Milian Wolff @ 2017-09-04 16:26 UTC (permalink / raw)
To: Ralph Böhme; +Cc: linux-perf-users
[-- 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 --]
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: Callgraphs split at the kernel boundary
2017-09-04 16:26 ` Milian Wolff
@ 2017-09-04 16:44 ` Milian Wolff
2017-09-04 17:01 ` Ralph Böhme
0 siblings, 1 reply; 5+ messages in thread
From: Milian Wolff @ 2017-09-04 16:44 UTC (permalink / raw)
To: Milian Wolff; +Cc: Ralph Böhme, linux-perf-users
[-- 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 --]
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: Callgraphs split at the kernel boundary
2017-09-04 16:44 ` Milian Wolff
@ 2017-09-04 17:01 ` Ralph Böhme
2017-09-04 17:22 ` Milian Wolff
0 siblings, 1 reply; 5+ messages in thread
From: Ralph Böhme @ 2017-09-04 17:01 UTC (permalink / raw)
To: Milian Wolff; +Cc: linux-perf-users
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
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: Callgraphs split at the kernel boundary
2017-09-04 17:01 ` Ralph Böhme
@ 2017-09-04 17:22 ` Milian Wolff
0 siblings, 0 replies; 5+ messages in thread
From: Milian Wolff @ 2017-09-04 17:22 UTC (permalink / raw)
To: Ralph Böhme; +Cc: linux-perf-users
[-- 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 --]
^ permalink raw reply [flat|nested] 5+ messages in thread
end of thread, other threads:[~2017-09-04 17:22 UTC | newest]
Thread overview: 5+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2017-09-03 9:49 Callgraphs split at the kernel boundary Ralph Böhme
2017-09-04 16:26 ` Milian Wolff
2017-09-04 16:44 ` Milian Wolff
2017-09-04 17:01 ` Ralph Böhme
2017-09-04 17:22 ` Milian Wolff
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).