[BUG] No output using bpftrace with bpftime

[ScriptSathi]

Describe the bug Hello ! I've started to take a look at this feature, but I cannot run bpftrace with bpftime locally to do my tests on the CI.

Here is an example of the most basic bpftrace usage. In this example, bpftrace is loaded, but I have no output in stdout.

sudo bpftime -i ~/.bpftime load bpftrace -e 'BEGIN { printf("hello world\n"); }'
# or
#sudo LD_PRELOAD=$HOME/.bpftime/libbpftime-syscall-server.so bpftrace -e 'BEGIN { printf("hello world\n"); }'
[2024-04-08 16:56:09.039] [info] [syscall_context.hpp:86] manager constructed
#...
[2024-04-08 16:56:09][info][594282] bpftime-syscall-server started
Attaching 1 probe...
[2024-04-08 16:56:09][info][594282] Created uprobe/uretprobe perf event handler, module name /proc/self/exe, offset dd1a0

Another example I go the below error.

 $ sudo  ~/.bpftime/bpftime -i ~/.bpftime/ load bpftrace -e 'uretprobe:/bin/bash:readline { printf("%-6d %s\n", pid, str(retval)); }'
[2024-04-08 17:15:31.899] [info] [syscall_context.hpp:86] manager constructed
[2024-04-08 17:15:31.904] [info] [syscall_server_utils.cpp:24] Initialize syscall server
[2024-04-08 17:15:31][info][603253] Global shm constructed. shm_open_type 0 for bpftime_maps_shm
[2024-04-08 17:15:31][info][603253] Global shm initialized
[2024-04-08 17:15:31][info][603253] Enabling helper groups ufunc, kernel, shm_map by default
[2024-04-08 17:15:31][info][603253] bpftime-syscall-server started
No probes to attach
INFO [603253]: Global shm destructed
[2024-04-08 17:15:31.939] [error] Program exited abnormally: 1

Does the problem come from me ?

To Reproduce

Pull the latest master release and compile with

make release JOBS=$(nproc)

Then run

sudo bpftime -i ~/.bpftime load bpftrace -e 'BEGIN { printf("hello world\n"); }'

The probe is loaded, but you don't see the "hello world" message

Expected behavior

$ sudo bpftime -i ~/.bpftime load bpftrace -e 'BEGIN { printf("hello world\n"); }'
Attaching 1 probe...
hello world

Desktop (please complete the following information):

• OS: ArchLinux
• Version 6.6.24-1-lts

[Officeyutong]

Have you injected agent into any process with bpftime start or bpftime attach? bpftime only collectes information from injected process

[ScriptSathi]

I am not sure to understand what exactly is the difference between load and start.

But you are right ! I replace the load with start and it worked. But I don't understand why bpftrace does not use bpftime-server but instead bpftime-agent.

sudo bpftime -i ~/.bpftime start bpftrace -e 'BEGIN { printf("hello world\n"); }'
# hello world displayed

I'll try to understand the difference and then close this issue.

[Officeyutong]

I am not sure to understand what exactly is the difference between load and start.

But you are right ! I replace the load with start and it worked. But I don't understand why bpftrace does not use bpftime-server but instead bpftime-agent.

sudo bpftime -i ~/.bpftime start bpftrace -e 'BEGIN { printf("hello world\n"); }'
# hello world displayed

I'll try to understand the difference and then close this issue.

bpftime load means to start a process with syscall-server injected, while bpftime start means to start a process with agent injected. Syscall server is a part of bpftime that collects information (such as the loading of ebpf program, the creation of maps, or other things) and store them into shared memory. So it should be injected to the process which invoked libbpf for bpf purpose. Agent is a part of bpftime that reads things from shared memory, running ebpf programs on the specified attach point, and able to perform map operations requested by ebpf program. so it should be injected into process that we want to monitor, such as the process that we want to monitor using uprobe

[ScriptSathi]

Using the below oneliner from bpftrace documentation. It prints output continuously, so it can be easy to test.

BEGIN
{
    printf("Tracing open syscalls... Hit Ctrl-C to end.\n");
    printf("%-6s %-16s %4s %3s %s\n", "PID", "COMM", "FD", "ERR", "PATH");
}

tracepoint:syscalls:sys_enter_open,
tracepoint:syscalls:sys_enter_openat
{
    @filename[tid] = args.filename;
}

tracepoint:syscalls:sys_exit_open,
tracepoint:syscalls:sys_exit_openat
/@filename[tid]/
{
    $ret = args.ret;
    $fd = $ret >= 0 ? $ret : -1;
    $errno = $ret >= 0 ? 0 : - $ret;

    printf("%-6d %-16s %4d %3d %s\n", pid, comm, $fd, $errno,
    str(@filename[tid]));
    delete(@filename[tid]);
}

END
{
    clear(@filename);
}

Save it in file then start it with

sudo bpftime -i ~/.bpftime load bpftrace my_bpftrace_file.bt

Then open a new terminal and get the PID with ps -ef |grep bpftime

then

sudo bpftime -i $HOME/.bpftime attach 225318

# ...
# Successfully injected. ID: 1

But still no output from the the bpftime command. But when using start directly to load the file it worked without attaching to the process, but when first launch I have an shm error that does not appear if i launch the command a second time

[NobinPegasus]

I get this error.

pegasus@pegasus:~/Documents/bpftime$ sudo  ~/.bpftime/bpftime -i ~/.bpftime/ load bpftrace -e 'uretprobe:/bin/bash:readline { printf("%-6d %s\n", pid, str(retval)); }'
[2024-04-11 05:22:56.166] [info] [syscall_context.hpp:86] manager constructed
[2024-04-11 05:22:59.692] [info] [syscall_server_utils.cpp:24] Initialize syscall server
[2024-04-11 05:22:59][info][40260] Global shm constructed. shm_open_type 0 for bpftime_maps_shm
[2024-04-11 05:22:59][info][40260] Global shm initialized
[2024-04-11 05:22:59][info][40260] Enabling helper groups ufunc, kernel, shm_map by default
[2024-04-11 05:22:59][info][40260] bpftime-syscall-server started
terminate called after throwing an instance of 'std::bad_alloc'
  what():  std::bad_alloc

[Officeyutong]

I get this error.

pegasus@pegasus:~/Documents/bpftime$ sudo  ~/.bpftime/bpftime -i ~/.bpftime/ load bpftrace -e 'uretprobe:/bin/bash:readline { printf("%-6d %s\n", pid, str(retval)); }'
[2024-04-11 05:22:56.166] [info] [syscall_context.hpp:86] manager constructed
[2024-04-11 05:22:59.692] [info] [syscall_server_utils.cpp:24] Initialize syscall server
[2024-04-11 05:22:59][info][40260] Global shm constructed. shm_open_type 0 for bpftime_maps_shm
[2024-04-11 05:22:59][info][40260] Global shm initialized
[2024-04-11 05:22:59][info][40260] Enabling helper groups ufunc, kernel, shm_map by default
[2024-04-11 05:22:59][info][40260] bpftime-syscall-server started
terminate called after throwing an instance of 'std::bad_alloc'
  what():  std::bad_alloc

Seems that shared memory was full. You may change the value https://github.com/eunomia-bpf/bpftime/blob/8beba35449d21b52f14a637174faeab4b3866539/runtime/src/bpftime_shm_internal.cpp#L571 and https://github.com/eunomia-bpf/bpftime/blob/8beba35449d21b52f14a637174faeab4b3866539/runtime/src/bpftime_shm_internal.cpp#L604

[ScriptSathi]

@Officeyutong Concerning my previous comment, how bpftrace is suppose to work with bpftime ?

How to see a simple hello world if not with start ?

sudo bpftime -i ~/.bpftime load bpftrace -e 'BEGIN { printf("hello world\n"); }'

[Officeyutong]

@Officeyutong

Concerning my previous comment, how bpftrace is suppose to work with bpftime ?

How to see a simple hello world if not with start ?

sudo bpftime -i ~/.bpftime load bpftrace -e 'BEGIN { printf("hello world\n"); }'

As far as I known, you wont't get any output if you don't run bpftime start(or bpftime attach). If you don't run them, no eBPF programs will be executed. You may use other trace examples in example/bpftrace for testing purpose

[ScriptSathi]

Using the below oneliner from bpftrace documentation. It prints output continuously, so it can be easy to test.

BEGIN
{
  printf("Tracing open syscalls... Hit Ctrl-C to end.\n");
  printf("%-6s %-16s %4s %3s %s\n", "PID", "COMM", "FD", "ERR", "PATH");
}

tracepoint:syscalls:sys_enter_open,
tracepoint:syscalls:sys_enter_openat
{
  @filename[tid] = args.filename;
}

tracepoint:syscalls:sys_exit_open,
tracepoint:syscalls:sys_exit_openat
/@filename[tid]/
{
  $ret = args.ret;
  $fd = $ret >= 0 ? $ret : -1;
  $errno = $ret >= 0 ? 0 : - $ret;

  printf("%-6d %-16s %4d %3d %s\n", pid, comm, $fd, $errno,
  str(@filename[tid]));
  delete(@filename[tid]);
}

END
{
  clear(@filename);
}

Save it in file then start it with

sudo bpftime -i ~/.bpftime load bpftrace my_bpftrace_file.bt

Then open a new terminal and get the PID with ps -ef |grep bpftime

then

sudo bpftime -i $HOME/.bpftime attach 225318

# ...
# Successfully injected. ID: 1

But still no output from the the bpftime command. But when using start directly to load the file it worked without attaching to the process, but when first launch I have an shm error that does not appear if i launch the command a second time

But I still have no output with my above commands, what have I done wrong ?

[Officeyutong]

Using the below oneliner from bpftrace documentation. It prints output continuously, so it can be easy to test.

BEGIN
{
    printf("Tracing open syscalls... Hit Ctrl-C to end.\n");
    printf("%-6s %-16s %4s %3s %s\n", "PID", "COMM", "FD", "ERR", "PATH");
}

tracepoint:syscalls:sys_enter_open,
tracepoint:syscalls:sys_enter_openat
{
    @filename[tid] = args.filename;
}

tracepoint:syscalls:sys_exit_open,
tracepoint:syscalls:sys_exit_openat
/@filename[tid]/
{
    $ret = args.ret;
    $fd = $ret >= 0 ? $ret : -1;
    $errno = $ret >= 0 ? 0 : - $ret;

    printf("%-6d %-16s %4d %3d %s\n", pid, comm, $fd, $errno,
    str(@filename[tid]));
    delete(@filename[tid]);
}

END
{
    clear(@filename);
}

Save it in file then start it with

sudo bpftime -i ~/.bpftime load bpftrace my_bpftrace_file.bt

Then open a new terminal and get the PID with ps -ef |grep bpftime then

sudo bpftime -i $HOME/.bpftime attach 225318

# ...
# Successfully injected. ID: 1

But still no output from the the bpftime command. But when using start directly to load the file it worked without attaching to the process, but when first launch I have an shm error that does not appear if i launch the command a second time

But I still have no output with my above commands, what have I done wrong ?

use bpftime attach -s if you want to trace syscalls

[ScriptSathi]

So to close this issue, the good usage was

Starting bpftrace in Terminal 1

sudo bpftime -i $HOME/.bpftime/ load bpftrace trace_open_syscalls.bt

In Terminal 2 simply start any program that could call the syscall you want to call

sudo bpftime -i $HOME/.bpftime/ start -s /bin/bash