Bpftrace: kstack is sometimes empty and there seems to be no way to check for that situation

[pavlix]

Under some condition (e.g. when an amount of time has passed that suggests latency issues) I would like to print a kernel stack trace. More often than not that information is unavailable. I don't know exactly why that happens. I do not understand why there's no stack trace at that specific time.

profile:hz:99
/ @wantstack[tid] && ... /
{
    @wantstack[tid] = 0;
    printf("%s\n", kstack);
}

I wanted to at least try to get a stack trace at a later time by checking whether the stack trace is valid or not.

if (stack_trace_is_valid(kstack)) {
    @wantstack[tid] = 0;
    printf("%s\n", kstack);
}

According to the documentation there are no operations on the kstack and it is not convertible to a string, only printable with printf and used as a map key. There's also #891 looking for string operations on kstack and JSON representation.

[fbs]

It might be that the get_stackid call failed. Can you try it with this patch?

diff --git a/src/bpftrace.cpp b/src/bpftrace.cpp
index e0cba95..b7d87ca 100644
--- a/src/bpftrace.cpp
+++ b/src/bpftrace.cpp
@@ -1465,7 +1465,14 @@ std::vector<uint8_t> BPFtrace::find_empty_key(IMap &map, size_t size) const
 std::string BPFtrace::get_stack(uint64_t stackidpid, bool ustack, StackType stack_type, int indent)
 {
   int32_t stackid = stackidpid & 0xffffffff;
-  int pid = stackidpid >> 32;
+  int32_t pid = stackidpid >> 32;
+
+  if (stackid < 0)
+  {
+    std::cerr << "Invalid stack id: " << stackid << std::endl;
+    return
+  }
+
   auto stack_trace = std::vector<uint64_t>(stack_type.limit);
   int err = bpf_lookup_elem(stackid_maps_[stack_type]->mapfd_, &stackid, stack_trace.data());
   if (err)

In my testing I'm seeing the occational -14 (EFAULT). I'm not sure why the happen yet.

Relevant: https://github.com/torvalds/linux/commit/d5a3b1f691865be576c2bffa708549b8cdccda19

I'll work on a patch to get this error detection in and print all errors as the end

[pavlix]

Yep, that's it...

Invalid stack id: -14
Invalid stack id: -14
Invalid stack id: -14
...

[pavlix]

I found a bcc issue on the topic:

https://github.com/iovisor/bcc/issues/2702

I wouldn't expect much of a kernel stack from a syscall. Try something like block:block_rq_issue instead.

@brendangregg I am now getting pretty much reliable stack traces from syscalls (5.4.14, openSUSE Tumbleweed) using the following.

tracepoint:raw_syscalls:sys_enter
/ cpu == 0 && @SYSCALLS && @count /
{
    @count--;
    printf("sys_enter\n");
    printf("%s\n", kstack);
}

tracepoint:raw_syscalls:sys_exit
/ cpu == 0 && @SYSCALLS && @count /
{
    @count--;
    printf("sys_exit\n\n");
    printf("%s\n", kstack);
}

It's not very informative but it's there.

        syscall_slow_exit_work+175
        syscall_slow_exit_work+175
        do_syscall_64+356
        entry_SYSCALL_64_after_hwframe+73

sys_enter

        syscall_trace_enter+670
        syscall_trace_enter+670
        do_syscall_64+381
        entry_SYSCALL_64_after_hwframe+73

I am currently only getting the -14 with profile:....

[ajor]

This is the PR that removed error logging for empty stacks: https://github.com/iovisor/bpftrace/pull/428
It says kstack will be empty if the current thread is in user-mode

[pavlix]

Thanks a lot, @ajor. In that case I shouldn't need to explicitly check for empty stack (cc @fbs) but rather for the condition or task state. While I could track syscall entry and exit for the running tasks, that excludes (1) tasks that entered the kernel before I started tracking them as well as (2) kernel threads that are running in kernel mode from the start.

As I do not gather any information about tasks until they actually do something, the first time I learn about them is tracepoint:sched:sched_switch (or kprobe:finish_task_switch if you wish). That is also the time when I'd like to learn whether the task is resumed in user mode or kernel mode. Surely the kernel knows that and resumes a syscall/kthread or the user thread accordingly. My question is how to track that so that I always know when I'm in the kernel space and, at the same time, so that I can expect a valid kernel stack trace.

I don't see any way to do that, yet.

[fbs]

This is the PR that removed error logging for empty stacks: #428
It says kstack will be empty if the current thread is in user-mode

Ah that explains. I think it will be useful to have an error printed when bpftrace exits which links to some issue/pr/wiki page with details on what happened. Ignoring it just confuses users, like happend here.

[mmisono]

On x86, we can check the CPL value of the cs register.

profile:hz:99 {
  if (!(reg("cs") & 0x3)) {
    // kernel mode
  }
}

... but I found the above code did not work (on my environment; LLVM8) and wrote the patch here.
Alternatively, profile:hz:99 { if (!((reg("cs") & 0x3) == 3)) { ... } }' works.

[ajor]

Cool thanks @mmisono - we should probably add an architecture-dependent builtin to expose this to users