search

ajor / bpftrace

High-level tracing language for Linux eBPF - development moved to https://github.com/iovisor/bpftrace
https://github.com/iovisor/bpftrace
Apache License 2.0
250 stars 15 forks source link

bpf: Failed to load program: Invalid argument, due to kern_version mismatch #8

Closed brendangregg closed 6 years ago

brendangregg commented 6 years ago

I just tried a fresh build on a 4.4 kernel.

# ./bpftrace -e 'kprobe:sys_read { @who[tid] = count(); }'
Error creating map: '@who'
Attaching 1 probe...
bpf: Failed to load program: Invalid argument

Error loading program: kprobe:sys_read

Here's the BPF syscalls:

# strace -febpf ./bpftrace -e 'kprobe:sys_read { @who[tid] = count(); }'
bpf(BPF_MAP_CREATE, {map_type=0x5 /* BPF_MAP_TYPE_??? */, key_size=8, value_size=8, max_entries=128}, 72) = -1 EINVAL (Invalid argument)
bpf(BPF_MAP_CREATE, {map_type=0x5 /* BPF_MAP_TYPE_??? */, key_size=8, value_size=8, max_entries=128}, 72) = -1 EINVAL (Invalid argument)
Error creating map: '@who'
bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_PERF_EVENT_ARRAY, key_size=4, value_size=4, max_entries=8}, 72) = -1 EINVAL (Invalid argument)
bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_PERF_EVENT_ARRAY, key_size=4, value_size=4, max_entries=8}, 72) = 3
Attaching 1 probe...
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0x7ffd8a1c820c, value=0x7ffd8a1c8210, flags=BPF_ANY}, 72) = 0
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0x7ffd8a1c820c, value=0x7ffd8a1c8210, flags=BPF_ANY}, 72) = 0
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0x7ffd8a1c820c, value=0x7ffd8a1c8210, flags=BPF_ANY}, 72) = 0
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0x7ffd8a1c820c, value=0x7ffd8a1c8210, flags=BPF_ANY}, 72) = 0
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0x7ffd8a1c820c, value=0x7ffd8a1c8210, flags=BPF_ANY}, 72) = 0
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0x7ffd8a1c820c, value=0x7ffd8a1c8210, flags=BPF_ANY}, 72) = 0
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0x7ffd8a1c820c, value=0x7ffd8a1c8210, flags=BPF_ANY}, 72) = 0
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0x7ffd8a1c820c, value=0x7ffd8a1c8210, flags=BPF_ANY}, 72) = 0
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=24, insns=0x7f567068b000, license="GPL", log_level=0, log_size=0, log_buf=0, kern_version=263168}, 72) = -1 E2BIG (Argument list too long)
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=24, insns=0x7f567068b000, license="GPL", log_level=0, log_size=0, log_buf=0, kern_version=263168}, 72) = -1 EINVAL (Invalid argument)
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=24, insns=0x7f567068b000, license="GPL", log_level=1, log_size=65536, log_buf=0x35597b0, kern_version=263168}, 72) = -1 EINVAL (Invalid argument)
bpf: Failed to load program: Invalid argument

Error loading program: kprobe:sys_read
+++ exited with 255 +++

Comparing to a working bcc tool:

# strace -febpf /usr/share/bcc/tools/ext4dist
bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_HASH, key_size=4, value_size=8, max_entries=10240}, 64) = -1 EINVAL (Invalid argument)
bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_HASH, key_size=4, value_size=8, max_entries=10240}, 64) = -1 EPERM (Operation not permitted)
bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_HASH, key_size=4, value_size=8, max_entries=10240}, 64) = 3
bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_HASH, key_size=16, value_size=8, max_entries=64}, 64) = -1 EINVAL (Invalid argument)
bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_HASH, key_size=16, value_size=8, max_entries=64}, 64) = 4
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=31, insns=0x7fb30a456bf0, license="GPL", log_level=0, log_size=0, log_buf=0, kern_version=263258}, 64) = -1 E2BIG (Argument list too long)
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=31, insns=0x7fb30a456bf0, license="GPL", log_level=0, log_size=0, log_buf=0, kern_version=263258}, 64) = 5
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=14, insns=0x7fb30a456ce8, license="GPL", log_level=0, log_size=0, log_buf=0, kern_version=263258}, 64) = -1 E2BIG (Argument list too long)
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=14, insns=0x7fb30a456ce8, license="GPL", log_level=0, log_size=0, log_buf=0, kern_version=263258}, 64) = 8
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=131, insns=0x7fb30a455838, license="GPL", log_level=0, log_size=0, log_buf=0, kern_version=263258}, 64) = -1 E2BIG (Argument list too long)
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=131, insns=0x7fb30a455838, license="GPL", log_level=0, log_size=0, log_buf=0, kern_version=263258}, 64) = 12
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=132, insns=0x7fb30a4567d0, license="GPL", log_level=0, log_size=0, log_buf=0, kern_version=263258}, 64) = -1 E2BIG (Argument list too long)
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=132, insns=0x7fb30a4567d0, license="GPL", log_level=0, log_size=0, log_buf=0, kern_version=263258}, 64) = 14
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=131, insns=0x7fb30a455000, license="GPL", log_level=0, log_size=0, log_buf=0, kern_version=263258}, 64) = -1 E2BIG (Argument list too long)
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=131, insns=0x7fb30a455000, license="GPL", log_level=0, log_size=0, log_buf=0, kern_version=263258}, 64) = 16
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=132, insns=0x7fb30a455418, license="GPL", log_level=0, log_size=0, log_buf=0, kern_version=263258}, 64) = -1 E2BIG (Argument list too long)
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=132, insns=0x7fb30a455418, license="GPL", log_level=0, log_size=0, log_buf=0, kern_version=263258}, 64) = 18
Tracing ext4 operation latency... Hit Ctrl-C to end.
^Cstrace: Process 21116 detached

So I can see that the kern_version is wrong.

As an experiment, I hardwired it in src/attached_probe.cpp's kernel_version(), and now bpftrace gets further and then fails for a different reason. I won't include details here as I think that's a separate bug.

brendangregg commented 6 years ago

The other issue I'm dealing with has to do with maps...

This ticket is for the kern_version issue. By hacking in the right kern_version, this following one-liner moves from broken to working:

# ./src/bpftrace -e 'kprobe:sys_nanosleep { printf("sleep by %d\n", pid); }'
Attaching 1 probe...
sleep by 10275
sleep by 1087

So why is kern_version busted? I'm on Ubuntu Xenial with a patched kernel (as we commonly run), and I'm sure there's a mismatch in the OS somewhere.

brendangregg commented 6 years ago

I just tried a different system, one where I had replaced the kernel with my own version (including make headers_install), and it just worked. So this really is a problem with one OS config.

brendangregg commented 6 years ago

Source in question:

static unsigned kernel_version()
{
  struct utsname utsname;
  uname(&utsname);
  unsigned x, y, z;
  sscanf(utsname.release, "%d.%d.%d", &x, &y, &z);
  return (x << 16) + (y << 8) + z;
}

Broken system:

# uname -r
4.4.0-98-generic

Which the source turns into:

$ perl -e 'print ((4 << 16) + (4 << 8) + 0)'
263168

But the working value (from bcc) is 263258, equivalent to 4.4.90. Here's dmesg:

# dmesg | grep -i linux
[    0.000000] Linux version 4.4.0-98-generic (buildd@lcy01-03) (gcc version 5.4.0 20160609 (Ubuntu 5.4.0-6ubuntu1~16.04.4) ) #121-Ubuntu SMP Tue Oct 10 14:24:03 UTC 2017 (Ubuntu 4.4.0-98.121-generic 4.4.90)
[...]

Note the 4.4.90 at the end of that line. I don't know yet how to dig that out. bcc uses a different approach (section info?).

For comparison, here is a system where it just works, without hacking kern_version:

# uname -r
4.14.12-virtual

# dmesg | grep -i linux
[    0.000000] Linux version 4.14.12-virtual (root@bgregg-c5.9xl-i-07f6e849adcafd9bc) (gcc version 5.4.0 20160609 (Ubuntu 5.4.0-6ubuntu1~16.04.5)) #1 SMP Tue Jan 9 10:08:55 UTC 2018
[...]
brendangregg commented 6 years ago

Ok, it looks like it's an Ubuntu kernel thing.

https://wiki.ubuntu.com/Kernel/FAQ#Kernel.2FFAQ.2FGeneralVersionRunning.How_can_we_determine_the_version_of_the_running_kernel.3F

My two systems:

system1# cat /proc/version_signature
Ubuntu 4.4.0-98.121-generic 4.4.90

system2# cat /proc/version_signature
cat: /proc/version_signature: No such file or directory

Maybe pull in the last field of /proc/version_signature if that file exists? With the comment that this is for Ubuntu.

taem commented 6 years ago

Hi,

I have the same issue:

$ sudo ./bpftrace -e 'BEGIN { printf("hi\n"); }'
Attaching 1 probe...
bpf: Failed to load program: Invalid argument

Error loading program: BEGIN
$ cat /etc/os-release 
PRETTY_NAME="Debian GNU/Linux buster/sid"
NAME="Debian GNU/Linux"
ID=debian
HOME_URL="https://www.debian.org/"
SUPPORT_URL="https://www.debian.org/support"
BUG_REPORT_URL="https://bugs.debian.org/"
$ uname -r
4.15.0-1-amd64
$ sudo dmesg | grep -i 'linux version'
[    0.000000] Linux version 4.15.0-1-amd64 (debian-kernel@lists.debian.org) (gcc version 7.3.0 (Debian 7.3.0-3)) #1 SMP Debian 4.15.4-1 (2018-02-18)
$ cat /proc/version_signature
cat: /proc/version_signature: No such file or directory

Tracepoint works:

$ cat /tmp/test.t
tracepoint:syscalls:sys_enter_open
{
  printf("%s: %s\n", comm, str(arg0))
}
$ sudo ./bpftrace /tmp/test.t
Attaching 1 probe...
plasmashell: 
plasmashell: 
plasmashell: 
[ ... ]
$ file bpftrace 
bpftrace: ELF 64-bit LSB executable, x86-64, version 1 (GNU/Linux), statically linked, for GNU/Linux 3.2.0, BuildID[sha1]=8f38504f2ddafb6d7fdaf2067919e8bb02e20dcc, with debug_info, not stripped
caringi commented 6 years ago

Hi,

I'm facing a similar problem...

./bpftrace -e 'BEGIN { printf("hi\n"); }'

Works for me...

Attaching 1 probe...
hi
^C

But the following command doesn't work:

./bpftrace -e 'kprobe:sys_read { @who[tid] = count(); }'

I get:

Attaching 1 probe...
bpf: Failed to load program: Invalid argument

Error loading program: kprobe:sys_read

Nor:

./bpftrace -e 'kprobe:[Ss]y[Ss]_*
{
  @[func] = count()
}'
Attaching 377 probes...
bpf: Failed to load program: Invalid argument

Error loading program: kprobe:SyS_accept

My system is a Fedora 27 with the following kernel:

$ uname -r
4.15.3-300.fc27.x86_64

Using strace:

strace -febpf ./bpftrace -e 'kprobe:[Ss]y[Ss]_*
{
  @[func] = count()
}'
bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_PERCPU_HASH, key_size=8, value_size=8, max_entries=128, map_flags=0, inner_map_fd=0, ...}, 72) = -1 EINVAL (Invalid argument)
bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_PERCPU_HASH, key_size=8, value_size=8, max_entries=128, map_flags=0, inner_map_fd=0}, 72) = 3
bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_PERF_EVENT_ARRAY, key_size=4, value_size=4, max_entries=4, map_flags=0, inner_map_fd=0, ...}, 72) = 4
Attaching 377 probes...
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=4, key=0x7ffc71c0aeac, value=0x7ffc71c0ae88, flags=BPF_ANY}, 72) = 0
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=4, key=0x7ffc71c0aeac, value=0x7ffc71c0ae88, flags=BPF_ANY}, 72) = 0
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=4, key=0x7ffc71c0aeac, value=0x7ffc71c0ae88, flags=BPF_ANY}, 72) = 0
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=4, key=0x7ffc71c0aeac, value=0x7ffc71c0ae88, flags=BPF_ANY}, 72) = 0
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=28, insns=0x7fb56e3e9000, license="GPL", log_level=0, log_size=0, log_buf=0, kern_version=265987, prog_flags=0, ...}, 72) = -1 EPERM (Operation not permitted)
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=28, insns=0x7fb56e3e9000, license="GPL", log_level=0, log_size=0, log_buf=0, kern_version=265987, prog_flags=0, ...}, 72) = -1 EINVAL (Invalid argument)
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=28, insns=0x7fb56e3e9000, license="GPL", log_level=1, log_size=65536, log_buf=0x2717d30, kern_version=265987, prog_flags=0, ...}, 72) = -1 EINVAL (Invalid argument)
bpf: Failed to load program: Invalid argument

Error loading program: kprobe:SyS_accept
+++ exited with 255 +++
brendangregg commented 6 years ago

@taem @caringi thanks for the details. I suspect you've hit the same bug, but here's how I would confirm it:

strace -febpf ./bpftrace -e 'kprobe:sys_nanosleep { printf("sleep by %d\n", pid); }'
strace -febpf /usr/share/bcc/tools/syncsnoop

The second command requires installing https://github.com/iovisor/bcc . The output of each will have the "kern_version=" -- if that is different for the bcc command, and that bcc command works, it'll confirm that we have this bug.

If Fedora/Debian don't have /proc/version_signature, then we'll need a different way to get the true kernel version. Maybe we just have to use bcc's approach (if bcc works on these systems, that is!)

brendangregg commented 6 years ago

For anyone hitting this, please test the following:

#include <stdio.h>
#include <linux/version.h>

int
main(int argc, char *argv[])
{
    printf("%d", LINUX_VERSION_CODE);
    return 0;
}

And see if the version number equals what is printed by strace -febpf ...

I've submitted this as #16.

taem commented 6 years ago

@brendangregg

BPFtrace: kern_version=265984 BCC: kern_version=265988

$ sudo strace -febpf ./bpftrace -e 'kprobe:sys_nanosleep { printf("sleep by %d\n", pid); }'
bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_PERF_EVENT_ARRAY, key_size=4, value_size=4, max_entries=2, map_flags=0, inner_map_fd=0, ...}, 72) = 3
Attaching 1 probe...
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0x7ffd1f96760c, value=0x7ffd1f967610, flags=BPF_ANY}, 72) = 0
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0x7ffd1f96760c, value=0x7ffd1f967610, flags=BPF_ANY}, 72) = 0
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=18, insns=0x7ff0f2abb000, license="GPL", log_level=0, log_size=0, log_buf=0, kern_version=265984, prog_flags=0, ...}, 72) = -1 EINVAL (Invalid argument)
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=18, insns=0x7ff0f2abb000, license="GPL", log_level=0, log_size=0, log_buf=0, kern_version=265984, prog_flags=0}, 72) = -1 EINVAL (Invalid argument)
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=18, insns=0x7ff0f2abb000, license="GPL", log_level=1, log_size=65536, log_buf=0x205ff50, kern_version=265984, prog_flags=0}, 72) = -1 EINVAL (Invalid argument)
bpf: Failed to load program: Invalid argument

Error loading program: kprobe:sys_nanosleep
+++ exited with 255 +++
$ sudo strace -febpf syncsnoop-bpfcc 
bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_PERF_EVENT_ARRAY, key_size=4, value_size=4, max_entries=8, map_flags=0, inner_map_fd=0, ...}, 72) = 3
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=14, insns=0x7f352ce0c7d0, license="GPL", log_level=0, log_size=0, log_buf=0, kern_version=265988, prog_flags=0, ...}, 72) = 4
TIME(s)            CALL
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0x7f3527c2cac0, value=0x7f3527c2cd90, flags=BPF_ANY}, 72) = 0
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0x7f3527c2cd90, value=0x7f3527c2cac0, flags=BPF_ANY}, 72) = 0
^Cstrace: Process 8469 detached
taem commented 6 years ago

@brendangregg

Kernel version equals to the one printed by strace.

$ /tmp/kern_ver 
265988
taem commented 6 years ago

@brendangregg Patch in #16 gives kern_version=265987:

$ sudo strace -febpf ./bpftrace -e 'kprobe:sys_nanosleep { printf("sleep by %d\n", pid); }'
bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_PERF_EVENT_ARRAY, key_size=4, value_size=4, max_entries=2, map_flags=0, inner_map_fd=0, ...}, 72) = 3
Attaching 1 probe...
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0x7fff2434857c, value=0x7fff24348580, flags=BPF_ANY}, 72) = 0
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0x7fff2434857c, value=0x7fff24348580, flags=BPF_ANY}, 72) = 0
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=18, insns=0x7f80ae6a3000, license="GPL", log_level=0, log_size=0, log_buf=0, kern_version=265987, prog_flags=0, ...}, 72) = -1 EINVAL (Invalid argument)
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=18, insns=0x7f80ae6a3000, license="GPL", log_level=0, log_size=0, log_buf=0, kern_version=265987, prog_flags=0}, 72) = -1 EINVAL (Invalid argument)
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=18, insns=0x7f80ae6a3000, license="GPL", log_level=1, log_size=65536, log_buf=0x22f8f50, kern_version=265987, prog_flags=0}, 72) = -1 EINVAL (Invalid argument)
bpf: Failed to load program: Invalid argument

Error loading program: kprobe:sys_nanosleep
+++ exited with 255 +++
ajor commented 6 years ago

I'm seeing a similar issue with the KERNEL_VERSION patch. I'm running Arch Linux with Linux 4.15.5, but the KERNEL_VERSION is saying I'm running 4.14.8. Checking my installed packages I've got:

core/linux-api-headers 4.14.8-1 [installed]
    Kernel headers sanitized for use in userspace
core/linux-headers 4.15.5-1 [installed]
    Header files and scripts for building modules for Linux kernel

Could you check what version of linux-headers you've got installed please @taem?

taem commented 6 years ago

@ajor 4.15.4

$ apt-cache policy linux-headers-4.15.0-1-amd64 
linux-headers-4.15.0-1-amd64:
  Installed: 4.15.4-1
  Candidate: 4.15.4-1
  Version table:
 *** 4.15.4-1 500
        500 http://httpredir.debian.org/debian unstable/main amd64 Packages
        100 /var/lib/dpkg/status
taem commented 6 years ago

Hi,

BPFtrace built not in Docker (with patch from #16) works as expected:

$ sudo strace -febpf ./bpftrace -e 'kprobe:sys_nanosleep { printf("sleep by %d\n", pid); }'
bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_PERF_EVENT_ARRAY, key_size=4, value_size=4, max_entries=2, map_flags=0, inner_map_fd=0, ...}, 72) = 3
Attaching 1 probe...
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0x7ffc438d3e4c, value=0x7ffc438d3e28, flags=BPF_ANY}, 72) = 0
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0x7ffc438d3e4c, value=0x7ffc438d3e28, flags=BPF_ANY}, 72) = 0
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=18, insns=0x7f482f22a000, license="GPL", log_level=0, log_size=0, log_buf=0, kern_version=265988, prog_flags=0, ...}, 72) = -1 EINVAL (Invalid argument)
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=18, insns=0x7f482f22a000, license="GPL", log_level=0, log_size=0, log_buf=0, kern_version=265988, prog_flags=0}, 72) = 7
sleep by 1139
sleep by 1298
sleep by 1139
sleep by 1298
sleep by 1139
sleep by 1298
sleep by 1139
^Cstrace: Process 15458 detached
ajor commented 6 years ago

Ah I didn't think about the docker build at all! That's going to be annoying...

We could maybe add build-time and run-time options to define a custom kernel version if we go with #16

JorgenRask commented 6 years ago

I have seen same problem on Ubuntu 17.10 (kernel 4.13). bpftrace -e 'kprobe:sys_nanosleep { printf("sleep by %d\n", tid); }' gives kern_version=265485 strace -febpf ./bpftrace -e 'kprobe:sys_nanosleep { printf("sleep by %d\n", pid); }' gives kern_version=265472 I tried to install the newest mainline kernel (4.15.14) but that did not help. Patch #16 fixes the issue. Is it really necessary to compile bpftrace on the exact same kernel you want to run it on?!

caringi commented 6 years ago

@brendangregg

Running...

strace -febpf ./bpftrace -e 'kprobe:sys_nanosleep { printf("sleep by %d\n", pid); }'

Kernel version:

kern_version=265987

And...

strace -febpf /usr/share/bcc/tools/syncsnoop

Kernel version:

kern_version=265987

Testing...

#include <stdio.h>
#include <linux/version.h>

int
main(int argc, char *argv[])
{
        printf("%d", LINUX_VERSION_CODE);
        return 0;
}

Output:

265999

The explanation for that is: I'm running a given kernel (4.15.3) but my distro has already received an updated kernel (4.15.15), which I didn't boot yet. The file /usr/include/linux/version.h is updated:

#define LINUX_VERSION_CODE 265999

In my case, applying the patch #16 also doesn't work...

strace -febpf ./bpftrace -e 'kprobe:sys_nanosleep { printf("sleep by %d\n", pid); }'
bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_PERF_EVENT_ARRAY, key_size=4, value_size=4, max_entries=4, map_flags=0, inner_map_fd=0, ...}, 72) = 3
Attaching 1 probe...
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0x7ffd64cef77c, value=0x7ffd64cef758, flags=BPF_ANY}, 72) = 0
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0x7ffd64cef77c, value=0x7ffd64cef758, flags=BPF_ANY}, 72) = 0
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0x7ffd64cef77c, value=0x7ffd64cef758, flags=BPF_ANY}, 72) = 0
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0x7ffd64cef77c, value=0x7ffd64cef758, flags=BPF_ANY}, 72) = 0
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=18, insns=0x7f382a3c3000, license="GPL", log_level=0, log_size=0, log_buf=0, kern_version=265999, prog_flags=0, ...}, 72) = -1 EINVAL (Invalid argument)
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=18, insns=0x7f382a3c3000, license="GPL", log_level=0, log_size=0, log_buf=0, kern_version=265999, prog_flags=0}, 72) = -1 EINVAL (Invalid argument)
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=18, insns=0x7f382a3c3000, license="GPL", log_level=1, log_size=65536, log_buf=0x2ea7b40, kern_version=265999, prog_flags=0}, 72) = -1 EINVAL (Invalid argument)
bpf: Failed to load program: Invalid argument

Error loading program: kprobe:sys_nanosleep
+++ exited with 255 +++

BTW, Fedora doesn't have /proc/version_signature

caringi commented 6 years ago

@brendangregg

I just rebooted my system and I was expecting that bpftrace would work now, but it didn't... 

strace -febpf ./bpftrace -e 'kprobe:sys_nanosleep { printf("sleep by %d\n", pid); }'
bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_PERF_EVENT_ARRAY, key_size=4, value_size=4, max_entries=4, map_flags=0, inner_map_fd=0, ...}, 72) = 3
Attaching 1 probe...
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0x7fff38121ccc, value=0x7fff38121ca8, flags=BPF_ANY}, 72) = 0
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0x7fff38121ccc, value=0x7fff38121ca8, flags=BPF_ANY}, 72) = 0
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0x7fff38121ccc, value=0x7fff38121ca8, flags=BPF_ANY}, 72) = 0
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0x7fff38121ccc, value=0x7fff38121ca8, flags=BPF_ANY}, 72) = 0
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=18, insns=0x7fc641916000, license="GPL", log_level=0, log_size=0, log_buf=0, kern_version=265999, prog_flags=0, ...}, 72) = -1 EPERM (Operation not permitted)
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=18, insns=0x7fc641916000, license="GPL", log_level=0, log_size=0, log_buf=0, kern_version=265999, prog_flags=0, ...}, 72) = -1 EINVAL (Invalid argument)
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=18, insns=0x7fc641916000, license="GPL", log_level=1, log_size=65536, log_buf=0x1f83b40, kern_version=265999, prog_flags=0, ...}, 72) = -1 EINVAL (Invalid argument)
bpf: Failed to load program: Invalid argument

Error loading program: kprobe:sys_nanosleep
+++ exited with 255 +++

syncsnoop seems to work...

strace -febpf /usr/share/bcc/tools/syncsnoop
bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_PERF_EVENT_ARRAY, key_size=4, value_size=4, max_entries=4, map_flags=0, inner_map_fd=0, ...}, 64) = 4
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=14, insns=0x7ff5d2df97d0, license="GPL", log_level=0, log_size=0, log_buf=0, kern_version=265999, prog_flags=0, ...}, 64) = 5
TIME(s)            CALL
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=4, key=0x7ff5c6c37340, value=0x7ff5c6c372b8, flags=BPF_ANY}, 64) = 0
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=4, key=0x7ff5c6c373c8, value=0x7ff5c6c372b8, flags=BPF_ANY}, 64) = 0
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=4, key=0x7ff5c6c37450, value=0x7ff5c6c372b8, flags=BPF_ANY}, 64) = 0
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=4, key=0x7ff5c6c374d8, value=0x7ff5c6c372b8, flags=BPF_ANY}, 64) = 0
^Cstrace: Process 4974 detached

My system is a Fedora 27 (updated) with kernel 4.15.15-300.fc27.x86_64.

ajor commented 6 years ago

With 2ced3ad2c145b413266114a6a9f2a4e45eb9002f, bpftrace will now try to load BPF programs using LINUX_VERSION_CODE from the kernel headers first, then falling back to parsing the output of uname if that fails (e.g. if the wrong kernel headers are used in the compilation)

brendangregg commented 6 years ago

closing issue, assuming fixed now.