From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: linux-trace-users-owner@vger.kernel.org Received: from mail.kernel.org ([198.145.29.136]:36170 "EHLO mail.kernel.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S934981AbdCJKv3 (ORCPT ); Fri, 10 Mar 2017 05:51:29 -0500 Date: Fri, 10 Mar 2017 11:51:20 +0100 From: Masami Hiramatsu To: "Dorau, Lukasz" Cc: Ananth N Mavinakayanahalli , "Keshavamurthy, Anil S" , "David S. Miller" , "linux-trace-users@vger.kernel.org" , "Slusarz, Marcin" , "Jelinek, Sarah" , "Chernookyi, Vitalii" , "Buella, Gabor" Subject: Re: Why return probes of some syscalls sometimes are not called? Message-Id: <20170310115120.aa5edf952b42ba43d764605b@kernel.org> In-Reply-To: <20170309180054.7a4ad1194807ddb3d422e3ff@kernel.org> References: <20170309180054.7a4ad1194807ddb3d422e3ff@kernel.org> Mime-Version: 1.0 Content-Type: multipart/mixed; boundary="Multipart=_Fri__10_Mar_2017_11_51_20_+0100_AUTgZExGd_oOTiVn" Sender: linux-trace-users-owner@vger.kernel.org List-ID: This is a multi-part message in MIME format. --Multipart=_Fri__10_Mar_2017_11_51_20_+0100_AUTgZExGd_oOTiVn Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: 7bit On Thu, 9 Mar 2017 18:00:54 +0100 Masami Hiramatsu wrote: > On Thu, 9 Mar 2017 13:44:38 +0000 > "Dorau, Lukasz" wrote: > > > Hi, > > > > Could someone explain me why return probes of some syscalls (for example: futex, poll, epoll_wait) sometimes are not called? > > > > It can be reproduced using the following bash script: > > https://gist.github.com/ldorau/c439d9ec7635409a5016c42e3a9121ec > > > > Here are results gathered from 60 seconds test run on kernel 4.9.12 (Fedora 24): > > > > futex: p 56904 r 5489 (90% did not return (51415)) > > poll: p 43466 r 7703 (82% did not return (35763)) > > epoll_wait: p 73366 r 23551 (67% did not return (49815)) > > > > The whole log is attached below. > > > > Lukasz > > > > --- > > # ./test_kprobes.sh 60 > > > > Will trace using following kprobe_events: > > r:kprobes/r_futex sys_futex > > p:kprobes/p_futex sys_futex > > r:kprobes/r_poll sys_poll > > p:kprobes/p_poll sys_poll > > r:kprobes/r_epoll_wait sys_epoll_wait > > p:kprobes/p_epoll_wait sys_epoll_wait > > r:kprobes/r_select sys_select > > p:kprobes/p_select sys_select > > r:kprobes/r_fork sys_fork > > p:kprobes/p_fork sys_fork > > r:kprobes/r_vfork sys_vfork > > p:kprobes/p_vfork sys_vfork > > r:kprobes/r_mmap sys_mmap > > p:kprobes/p_mmap sys_mmap > > r:kprobes/r_open sys_open > > p:kprobes/p_open sys_open > > r:kprobes/r_close sys_close > > p:kprobes/p_close sys_close > > r:kprobes/r_write sys_write > > p:kprobes/p_write sys_write > > r:kprobes/r_read sys_read > > p:kprobes/p_read sys_read > > > > Results (60 sec): > > futex: p 56904 r 5489 (90% did not return (51415)) > > poll: p 43466 r 7703 (82% did not return (35763)) > > epoll_wait: p 73366 r 23551 (67% did not return (49815)) > > select: p 13355 r 13351 (0% did not return (4)) > > fork: p 0 r 0 (OK) > > vfork: p 0 r 0 (OK) > > mmap: p 4328 r 4328 (OK) > > open: p 4579 r 4579 (OK) > > close: p 7163 r 7163 (OK) > > write: p 22769 r 22769 (OK) > > read: p 40014 r 40014 (OK) > > > > OK, I just dumped kprobe_profile after the test, > > futex: p 7775 r 698 (91% did not return (7077)) > poll: p 18409 r 3523 (80% did not return (14886)) > epoll_wait: p 5122 r 2389 (53% did not return (2733)) > select: p 5411 r 5286 (2% did not return (125)) > fork: p 0 r 0 (OK) > vfork: p 0 r 0 (OK) > mmap: p 179 r 179 (OK) > open: p 921 r 921 (OK) > close: p 1005 r 1005 (OK) > write: p 5632 r 5631 (0% did not return (1)) > read: p 10879 r 10878 (0% did not return (1)) > r_futex 1091 0 > p_futex 8986 0 > r_poll 4276 0 > p_poll 20610 0 > r_epoll_wait 2849 0 > p_epoll_wait 5905 0 > r_select 10172 0 > p_select 10312 0 > r_fork 0 0 > p_fork 0 0 > r_vfork 0 0 > p_vfork 0 0 > r_mmap 2987 0 > p_mmap 2884 0 > r_open 4002 0 > p_open 3855 0 > r_close 4262 0 > p_close 4122 0 > r_write 14281 0 > p_write 14276 0 > r_read 41494 0 > p_read 41363 0 > > OK, there are no miss-counted event. So at least kprobe and kretprobe working correctly. > I also tried to use static tracepoints for that. > https://gist.github.com/mhiramat/04d782deaf110a6b3391e2ecb923325e > > ---- > $ sudo bash test_kprobes.sh 10 > Disabling all current probes ... > Removing old probe points ... > Adding new probe points ... > Enabling new probe points ... > Clearing old trace log ... > > Tracing for 10 seconds ... done > Saving trace log ... done > > Results (10 sec): > futex: p 9856 r 1258 (87% did not return (8598)) > poll: p 7531 r 4031 (46% did not return (3500)) > epoll_wait: p 1996 r 1617 (18% did not return (379)) > select: p 273 r 257 (5% did not return (16)) > Results (10 sec): > futex: p 9851 r 9851 (OK) > poll: p 7531 r 7531 (OK) > epoll_wait: p 1996 r 1996 (OK) > select: p 273 r 273 (OK) > ---- > Of course these events are collected in "different places" so > it could be different. But yeah, it seems sys_* function itself > dosen't return but jumps into ret_from_syscall etc. Please try attached patch (that is my miss that forgot to accumulate missed count of kretprobe). I've focused on futex and it showed there were some "misses" of kretprobe. ---- Disabling all current probes ... Removing old probe points ... Adding new probe points ... Enabling new probe points ... Clearing old trace log ... Tracing for 10 seconds ... done Saving trace log ... done Results (10 sec): futex: p 190 r 74 (61% did not return (116)) Results (10 sec): futex: p 190 r 190 (OK) $ cat /sys/kernel/debug/tracing/kprobe_profile r_futex 176 127 p_futex 298 0 ----- Actually, since the kretprobe is not well designed for the usecase probing on the sleep-able functions, it just fails if it invoked more than the number of CPUs in parallel. It is currently a limitation of kretprobe, but I'll solve it. Thanks, -- Masami Hiramatsu --Multipart=_Fri__10_Mar_2017_11_51_20_+0100_AUTgZExGd_oOTiVn Content-Type: application/octet-stream; name="trace-kprobes-show-sum-of" Content-Disposition: attachment; filename="trace-kprobes-show-sum-of" Content-Transfer-Encoding: base64 dHJhY2U6IGtwcm9iZXM6IFNob3cgc3VtIG9mIHByb2JlL3JldHByb2JlIG5taXNzZWQgY291bnQK CkZyb206IE1hc2FtaSBIaXJhbWF0c3UgPG1oaXJhbWF0QGtlcm5lbC5vcmc+CgpTaWduZWQtb2Zm LWJ5OiBNYXNhbWkgSGlyYW1hdHN1IDxtaGlyYW1hdEBrZXJuZWwub3JnPgotLS0KIGtlcm5lbC90 cmFjZS90cmFjZV9rcHJvYmUuYyB8ICAgIDIgKy0KIDEgZmlsZSBjaGFuZ2VkLCAxIGluc2VydGlv bigrKSwgMSBkZWxldGlvbigtKQoKZGlmZiAtLWdpdCBhL2tlcm5lbC90cmFjZS90cmFjZV9rcHJv YmUuYyBiL2tlcm5lbC90cmFjZS90cmFjZV9rcHJvYmUuYwppbmRleCAxMmZiNTQwLi5lZTdjNmRi IDEwMDY0NAotLS0gYS9rZXJuZWwvdHJhY2UvdHJhY2Vfa3Byb2JlLmMKKysrIGIva2VybmVsL3Ry YWNlL3RyYWNlX2twcm9iZS5jCkBAIC04OTYsNyArODk2LDcgQEAgc3RhdGljIGludCBwcm9iZXNf cHJvZmlsZV9zZXFfc2hvdyhzdHJ1Y3Qgc2VxX2ZpbGUgKm0sIHZvaWQgKnYpCiAJc2VxX3ByaW50 ZihtLCAiICAlLTQ0cyAlMTVsdSAlMTVsdVxuIiwKIAkJICAgdHJhY2VfZXZlbnRfbmFtZSgmdGst PnRwLmNhbGwpLAogCQkgICB0cmFjZV9rcHJvYmVfbmhpdCh0ayksCi0JCSAgIHRrLT5ycC5rcC5u bWlzc2VkKTsKKwkJICAgdGstPnJwLmtwLm5taXNzZWQgKyB0ay0+cnAubm1pc3NlZCk7CiAKIAly ZXR1cm4gMDsKIH0K --Multipart=_Fri__10_Mar_2017_11_51_20_+0100_AUTgZExGd_oOTiVn--