From: Milian Wolff <milian.wolff@kdab.com>
To: Milian Wolff <milian.wolff@kdab.com>
Cc: "Ralph Böhme" <slow@samba.org>, linux-perf-users@vger.kernel.org
Subject: Re: Callgraphs split at the kernel boundary
Date: Mon, 04 Sep 2017 18:44:23 +0200 [thread overview]
Message-ID: <4314827.rDNsEPmXDr@milian-kdab2> (raw)
In-Reply-To: <15526878.WJkr8vPO1G@milian-kdab2>
[-- 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 --]
next prev parent reply other threads:[~2017-09-04 16:44 UTC|newest]
Thread overview: 5+ messages / expand[flat|nested] mbox.gz Atom feed top
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 [this message]
2017-09-04 17:01 ` Ralph Böhme
2017-09-04 17:22 ` Milian Wolff
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=4314827.rDNsEPmXDr@milian-kdab2 \
--to=milian.wolff@kdab.com \
--cc=linux-perf-users@vger.kernel.org \
--cc=slow@samba.org \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
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).