Bcc: Can't use syscall tracepoints

[brendangregg]

 # ./tools/trace.py t:syscalls:sys_enter_newfstat
Ioctl(PERF_EVENT_IOC_SET_BPF): Invalid argument
Failed to attach BPF to tracepoint

Here's newfstat.py:

#!/usr/bin/python

from __future__ import print_function
from bcc import BPF

# load BPF program
b = BPF(text="""
TRACEPOINT_PROBE(syscalls, sys_enter_newfstat) {
    bpf_trace_printk("%d\\n", args->fd);
    return 0;
};
""", debug=0)

# header
print("%-18s %-16s %-6s %s" % ("TIME(s)", "COMM", "PID", "FD"))

# format output
while 1:
    try:
        (task, pid, cpu, flags, ts, msg) = b.trace_fields()
    except ValueError:
        continue
    print("%-18.9f %-16s %-6d %s" % (ts, task, pid, msg))

output:

# ./newfstat.py 
ioctl(PERF_EVENT_IOC_SET_BPF): Invalid argument
Traceback (most recent call last):
  File "./newfstat.py", line 12, in <module>
    """, debug=0)
  File "/usr/lib/python2.7/dist-packages/bcc/__init__.py", line 212, in __init__
    self._trace_autoload()
  File "/usr/lib/python2.7/dist-packages/bcc/__init__.py", line 767, in _trace_autoload
    self.attach_tracepoint(tp=tp, fn_name=fn.name)
  File "/usr/lib/python2.7/dist-packages/bcc/__init__.py", line 585, in attach_tracepoint
    raise Exception("Failed to attach BPF to tracepoint")
Exception: Failed to attach BPF to tracepoint

Testing on 4.8-rc4. Same problem with other syscall tracepoints.

I can use kprobes as a workaround in the meantime, but this should be a nice example of using tracepoints...

[4ast]

hmm. looks like syscalls:sys_(enter|exit)_* are not considered proper 'tracepoint' from kernel point of view, though perf thinks they are.

[goldshtn]

@4ast: Yes, and what's interesting is that perf works just fine with these tracepoints, e.g. perf record -e syscalls:* works (albeit a bit slowly) and records all syscalls. Is there something we need to do differently to record these?

[goldshtn]

@4ast @brendangregg Is there anything else we can do to trace syscalls? I've been playing with funccount and realized that we really don't have any tool that is capable of safely tracing all syscalls. Hacks like kprobe on SyS_* or do_sys_* cover only a small part.

[4ast]

why kprobe of sys_* is not enough?
All syscall entry points in the kernel start with sys_. There are ~300 of them, so we're well within reasonable kprobe count limits.
Long ago I had a patch to attach to syscall_entry/exit, but it was slower comparing to kprobe of sys_, so I didn't push for it after initial RFC stage.

[goldshtn]

@4ast Well here's the thing:

# cat /proc/kallsyms | grep '[Tt] sys_' | wc -l
376
# cat /sys/kernel/debug/tracing/available_filter_functions | grep '^sys_' | wc -l
37

So, attaching to 'sys_*' with funccount only traces these 37 functions.

This is on Linux 4.9, FC23.

[vitalyvch]

@goldshtn, The most of syscalls start from "SyS_", not from "sys_".

[vitalyvch]

@goldshtn,

realized that we really don't have any tool that is capable of safely tracing all syscalls

I just now work on this kind tool, but in pure C on top of libbcc.so. And, yes, I would like to have a support for tracepoints in my tool, over already implemented support of kprobes.

[goldshtn]

You're right, thanks! Tracing sys_* and SyS_* produces the desired result. Now just need to fix a bug in BPF.get_kprobe_functions that returns the same function name multiple times.

[vitalyvch]

So, since last commits, tracing sys_* and SyS_* does not produce the desired result: #940

@goldshtn

[vitalyvch]

so

# ./trace.py t:raw_syscalls:sys_enter

currently works on kernel 4.8, 4.9 and 4.11 but @ldorau tells that there are a lot of lost calls.

[ldorau]

I meant:
There were a lot of messages „Lost samples….”.
I did not count the number of lost samples.

[goldshtn]

Well if you trace them, sure. The tracing output can't keep up. But if you just aggregate (e.g. count them like syscount does) it works fine - for me anyway. I've measured syscount with 5M events/s and never saw the "Lost samples" message. (On a 1-core VM.)

[goldshtn]

@4ast Just out of curiosity, what is the root cause for the syscall tracepoints not working with PERF_EVENT_IOC_SET_BPF? You wrote above:

looks like syscalls:sys_(enter|exit)_* are not considered proper 'tracepoint' from kernel point of view

... but is this something easily fixable? Where is the relevant part that breaks?

[brendangregg]

@vitalyvch @ldorau see my last comment in #1016. Is a feedback loop the cause of your lost samples? Or just the volume of messages? Both have different fixes.

[4ast]

@goldshtn adding support for sys_enter_* is straightforward. I'll be happy to review the patches and help to get them in.

[goldshtn]

@4ast I'd love to do the patches but I don't know where to start - could you nudge me in the direction of the source area that needs to be fixed?

[4ast]

old patch was enabling it for syscalls: https://lkml.org/lkml/2015/1/15/905
but it was via ftrace infra. Now everything is done via perf.
Take a look at kprobe_perf_func(). Similar code needs to be added to perf_syscall_enter().
bpf prog context will be syscall_trace_enter. Just needs to be wrapper into uapi struct.

[vitalyvch]

Is a feedback loop the cause of your lost samples?

No.

Or just the volume of messages? Both have different fixes.

We just have forgotten to enlarge ring buffer of trace.py using -b option. Default 64 pages unexpectedly was too small. We did not play with high syscall rate in that experiment.

[4ast]

@goldshtn are you still planning to hack the syscalls support in the kernel? ;) If not, I can take a stab.

[goldshtn]

TBH I didn't have much time but took a quick look on a flight and didn't really understand what you meant above, specifically where the bpf_prog would come from.

[4ast]

bpf_prog would attach via ioctl same way as for tracepoints and kprobes.
In perf_syscall_enter() it will be in sys_data->enter_event->prog.

[ldorau]

Anything has changed? Any updates on this issue? Has it been fixed?

[yonghong-song]

Yes, it has been fixed. Please checkout the latest bcc and give a try.

On Tue, Jun 27, 2017 at 12:00 AM, Lukasz Dorau [e-mail]
wrote:

Anything has changed? Any updates on this issue? Has it been fixed?

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub
https://github.com/iovisor/bcc/issues/748#issuecomment-311270807, or mute
the thread
https://github.com/notifications/unsubscribe-auth/ALq6oj7aHdj4DHzXaREqfLaIVN7BfHwZks5sIKiXgaJpZM4KWXZm
.

[brendangregg]

Does it need a newer kernel, or does trace.py need updating? Just tried it quickly on 4.9.0-rc5:

# ./trace.py t:syscalls:sys_enter_newfstat
In file included from /virtual/main.c:5:
/lib/modules/4.9.0-rc5-virtual/build/include/linux/fs.h:2693:9: warning: comparison of unsigned enum expression < 0 is always false [-Wtautological-compare]
        if (id < 0 || id >= READING_MAX_ID)
            ~~ ^ ~
1 warning generated.
ioctl(PERF_EVENT_IOC_SET_BPF): Invalid argument
Failed to attach BPF to tracepoint

[yonghong-song]

I tried latest net-next kernel and it works fine.
The above error (ioctl PERF_EVENT_IOC_SET_BPF) invalid argument error happens when either perf event or bpf prog type are incorrect. So the actual problem happens earlier.

[yonghong-song]

Sorry. My statement above that sys_enter_newfstat works fine is incorrect. I forgot the context how I did the experiments. I did a preliminary study on how to fix in kernel based on Alexei's above suggestions. Seems doable. I will prepare a kernel patch soon.

[yonghong-song]

The patch has been pushed into net-next. It should be available for 4.13.
Close the issue.

[nickdesaulniers]

The use of VLA's broke compiling the kernel with Clang for me.

kernel/trace/trace_syscalls.c:568:17: error: fields must have a constant size: 'variable length array in structure' extension will never be supported
                unsigned long args[sys_data->nb_args];
                              ^
$ git show --pretty=fuller cf5f5cea27065
commit cf5f5cea270655dd49370760576c64b228583b79
Author:     Yonghong Song <[email protected]>
AuthorDate: Fri Aug 4 16:00:09 2017 -0700
Commit:     David S. Miller <[email protected]>
CommitDate: Mon Aug 7 14:09:48 2017 -0700

[yonghong-song]

On Wed, Sep 6, 2017 at 9:51 PM, Nick Desaulniers
[e-mail] wrote:

The use of VLA's broke compiling the kernel with Clang for me.

kernel/trace/trace_syscalls.c:568:17: error: fields must have a constant
size: 'variable length array in structure' extension will never be supported
unsigned long args[sys_data->nb_args];

One fix could be change sys_data->nb_args to "6" or I need to make
some macro in the header
to indicate maximum arg number. Will provide a fix soon.

                          ^

$ git show --pretty=fuller cf5f5cea27065
commit cf5f5cea270655dd49370760576c64b228583b79
Author: Yonghong Song [e-mail]
AuthorDate: Fri Aug 4 16:00:09 2017 -0700
Commit: David S. Miller [e-mail]
CommitDate: Mon Aug 7 14:09:48 2017 -0700

—
You are receiving this because you modified the open/close state.
Reply to this email directly, view it on GitHub, or mute the thread.

[nickdesaulniers]

yes, I see that arm and arm64 have #define SYSCALL_MAX_ARGS 6 but was not sure if that was safe to use for all archs. Please cc me and Matthias Kaehlcke on the patch. Thanks :D

[nickdesaulniers]

oh, looks like for arm it's defined as 7. Not sure if other arch's have upper bounds?

[yonghong-song]

6 is safe. The syscall tracepoint related definition is in linux:include/linux/syscalls.h.

...
#define SYSCALL_TRACE_ENTER_EVENT(sname)                                \
...
#define SYSCALL_TRACE_EXIT_EVENT(sname)                                 \
...
#define SYSCALL_METADATA(sname, nb, ...)                        \
...
                .nb_args        = nb,                           \

The maximum "nb" here is 6. But there is no macro for this "6". So I will have to use either "6" or invent a macro.

[yonghong-song]

@nickdesaulniers , I am ready to submit the patch. Could you send me your and Matthias Kaehlcke's email address so I can cc you?

[nickdesaulniers]

grep git log in the kernel

On Sep 7, 2017 11:09 AM, "yonghong-song" [e-mail] wrote:

@nickdesaulniers https://github.com/nickdesaulniers , I am ready to
submit the patch. Could you send me your and Matthias Kaehlcke's email
address so I can cc you?

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/iovisor/bcc/issues/748#issuecomment-327877955, or mute
the thread
https://github.com/notifications/unsubscribe-auth/ABvUX92sKHeF1aX6A0Ingco8T3RQ3M0Fks5sgC_sgaJpZM4KWXZm
.