Use frame pointer unwinding for v8-based application (#1836)

We can't unwind nodejs and other v8-base applications as we can't
continue unwinding after the first AoT frame:

```
[...]
	current pc: 7fb0cf84904a
	current sp: 7fff93701498
	current bp: 7fff937014d8
[debug] Unwinding JITed stacks
[debug] Within unwinding machinery loop
	current pc: 157a329
	current sp: 7fff937014e8
	current bp: 7fff93701548
~about to check shards found=1
~checking shards now
[info] found chunk
le offset: 0
========== left 0 right 249997
	.done
	=> table_index: 206094
	=> adjusted pc: 157a329
	cfa type: 4, offset: 0 (row pc: 156f656)
[info] PC 157a329 not contained in the unwind info, found marker
[warn] mapping not added yet rbp 7fff93701548
pid 227936 tgid 227936
```

Turns out this AoT function doesn't have the corresponding DWARF unwind
information:

```
$ dist/eh-frame --executable /home/javierhonduco/.nvm/versions/node/v16.13.0/bin/node | grep 157a3
$
```

After cross-validating the output with `bpftrace`'s and checking v8's
source code it was clear why this is happening:

```
157a32a Builtins_InterpreterEntryTrampoline+202 (/home/javierhonduco/.nvm/versions/node/v16.13.0/bin/node)
157a32a Builtins_InterpreterEntryTrampoline+202 (/home/javierhonduco/.nvm/versions/node/v16.13.0/bin/node)
157a32a Builtins_InterpreterEntryTrampoline+202 (/home/javierhonduco/.nvm/versions/node/v16.13.0/bin/node)
1578538 Builtins_JSEntryTrampoline+88 (/home/javierhonduco/.nvm/versions/node/v16.13.0/bin/node)
15782c3 Builtins_JSEntry+131 (/home/javierhonduco/.nvm/versions/node/v16.13.0/bin/node)
[...]
7f65c5e29510 __libc_start_call_main+128 (/usr/lib64/libc.so.6)
```

The `Builtins_` functions above seem to be emmited via a custom code
generator[0]. No special linker `.cfi` directives are used, so this is
effectively like writting raw assembly with frame pointers set up, but
without telling the rest of the tooling how to produce unwidn
information it.

Test Plan
=========

- node: https://pprof.me/95f85d0
- basic-cpp-no-fp: https://pprof.me/a6099f2
- ruby: https://pprof.me/4ecf047

- [0]:
https://github.com/v8/v8/blob/e554f1e97e30f6e4cf6eef2c5049c17ca708e103/src/builtins/x64/builtins-x64.cc

bpf/cpu/cpu.bpf.c

@@ -565,32 +565,35 @@ static __always_inline bool retrieve_task_registers(u64 *ip, u64 *sp, u64 *bp) {
 static __always_inline bool has_fp(u64 current_fp) {
   u64 next_fp;
   u64 ra;
+  int i;
 
-  for (int i = 0; i < MAX_STACK_DEPTH; i++) {
+  for (i = 0; i < MAX_STACK_DEPTH; i++) {
     int err = bpf_probe_read_user(&next_fp, 8, (void *)current_fp);
     bpf_probe_read_user(&ra, 8, (void *)current_fp + 8);
     if (err < 0) {
-      // LOG("[debug] fp read failed with %d", err);
-      return false;
-    }
-    // Some cpp binaries, such as testdata/out/basic-cpp
-    // seem to have rbp set to 1 in the bottom frame. This
-    // does not comply with the x86_64 ABI.
-    //
-    // Additionally, we consider that stacks with just one
-    // frame aren't valid. This is just a heuristic, as most
-    // processes should at least have two frames.
-    //
-    // For both cases above, we prefer to unwind using the
-    // DWARF-derived unwind information.
-    if (next_fp == 0) {
-      // LOG("[debug] fp success");
-      return i > 0;
+      // LOG("[debug] fp read failed with %d i %d", err, i);
+      // We might have reached the bottom frame.
+      break;
     }
     current_fp = next_fp;
   }
 
-  LOG("[debug] fp not enough frames");
+  // Some cpp binaries, such as testdata/out/basic-cpp
+  // seem to have rbp set to 1 in the bottom frame. This
+  // does not comply with the x86_64 ABI.
+  //
+  // Additionally, we consider that stacks with just 2
+  // frames aren't valid. This is just a heuristic, as most
+  // processes should at least have two frames.
+  //
+  // For both cases above, we prefer to unwind using the
+  // DWARF-derived unwind information.
+  if (next_fp == 0) {
+    // LOG("[debug] fp success: %d", i > 2);
+    return i > 2;
+  }
+
+  LOG("[debug] last frame pointer is not zero");
   return false;
 }
 
@@ -711,7 +714,7 @@ int walk_user_stacktrace_impl(struct bpf_perf_event_data *ctx) {
         // For some weird reason commenting out this and the next err log line results in a panic
         // Using more than 3 arguments also results in a panic in some older kernels because of
         // https://github.com/libbpf/libbpf/blob/f7eb43b90f4c8882edf6354f8585094f8f3aade0/src/bpf_helpers.h#L287-L289
-        LOG("[debug] err = %d", err);
+        LOG("[error] rbp failed with err = %d", err);
         return 0;
       }
 
@@ -724,7 +727,7 @@ int walk_user_stacktrace_impl(struct bpf_perf_event_data *ctx) {
         //  For some weird reason commenting out this and the next err log line results in a panic
         //  Using more than 3 arguments also results in a panic in some older kernels because of
         //  https://github.com/libbpf/libbpf/blob/f7eb43b90f4c8882edf6354f8585094f8f3aade0/src/bpf_helpers.h#L287-L289
-        LOG("[debug] err = %d", err);
+        LOG("[error] ra failed with err = %d", err);
         return 0;
       }
 
@@ -824,8 +827,10 @@ int walk_user_stacktrace_impl(struct bpf_perf_event_data *ctx) {
     }
 
     // Set unwind_state->unwinding_jit to false once we have checked for switch from JITed unwinding to DWARF unwinding
+    if(unwind_state->unwinding_jit) {
+      LOG("[debug] Switched to mixed-mode DWARF unwinding");
+    }
     unwind_state->unwinding_jit = false;
-    LOG("[debug] Switched to mixed-mode DWARF unwinding");
 
     if (found_rbp_type == RBP_TYPE_REGISTER || found_rbp_type == RBP_TYPE_EXPRESSION) {
       LOG("\t[error] frame pointer is %d (register or exp), bailing out", found_rbp_type);
@@ -890,7 +895,9 @@ int walk_user_stacktrace_impl(struct bpf_perf_event_data *ctx) {
       }
 
       if (proc_info->is_jit_compiler) {
-        LOG("[info] rip=0, Section not added, yet");
+        LOG("[warn] mapping not added yet");
+        request_refresh_process_info(ctx, user_pid);
+
         bump_unwind_error_jit();
         return 1;
       }
@@ -954,7 +961,8 @@ int walk_user_stacktrace_impl(struct bpf_perf_event_data *ctx) {
       }
 
       if (proc_info->is_jit_compiler) {
-        LOG("[info] Section not added, yet");
+        LOG("[warn] mapping not added yet rbp %llx", unwind_state->bp);
+        request_refresh_process_info(ctx, user_pid);
         bump_unwind_error_jit();
         return 1;
       }
@@ -1055,11 +1063,8 @@ int profile_cpu(struct bpf_perf_event_data *ctx) {
     return 0;
   }
 
-  if (has_fp(unwind_state->bp)) {
-    add_stack(ctx, pid_tgid, STACK_WALKING_METHOD_FP, NULL);
-    return 0;
-  }
 
+  // 1. If we have unwind information for a process, use it.
   if (has_unwind_information(user_pid)) {
     bump_samples();
 
@@ -1072,19 +1077,21 @@ int profile_cpu(struct bpf_perf_event_data *ctx) {
         return 1;
       }
 
-      LOG("[warn] IP 0x%llx not covered, could be a new/JIT mapping.", unwind_state->ip);
-
       if (unwind_table_result == FIND_UNWIND_MAPPING_NOT_FOUND) {
+        LOG("[warn] IP 0x%llx not covered, mapping not found.", unwind_state->ip);
         request_refresh_process_info(ctx, user_pid);
         bump_unwind_error_pc_not_covered();
         return 1;
       } else if (unwind_table_result == FIND_UNWIND_JITTED) {
+
+
         if (!unwinder_config.mixed_stack_enabled) {
+          LOG("[warn] IP 0x%llx not covered, JIT (but disabled)!.", unwind_state->ip);
           bump_unwind_error_jit();
           return 1;
         }
       } else if (proc_info->is_jit_compiler) {
-
+        LOG("[warn] IP 0x%llx not covered, may be JIT!.", unwind_state->ip);
         request_refresh_process_info(ctx, user_pid);
         // We assume this failed because of a new JIT segment.
         bump_unwind_error_jit();
@@ -1097,6 +1104,14 @@ int profile_cpu(struct bpf_perf_event_data *ctx) {
     return 0;
   }
 
+  // 2. We did not have unwind information, let's see if we can unwind with frame
+  // pointers.
+  if (has_fp(unwind_state->bp)) {
+    add_stack(ctx, pid_tgid, STACK_WALKING_METHOD_FP, NULL);
+    return 0;
+  }
+
+  // 3. Request unwind information.
   request_unwind_information(ctx, user_pid);
   return 0;
 }

pkg/profiler/cpu/cpu.go

@@ -284,7 +284,7 @@ func (p *CPU) addUnwindTableForProcess(pid int) {
 	if err != nil {
 		// It might not exist as reading procfs is racy.
 		if !errors.Is(err, os.ErrNotExist) {
-			level.Error(p.logger).Log("msg", "frame pointer detection failed", "executable", executable, "err", err)
+			level.Debug(p.logger).Log("msg", "frame pointer detection failed", "executable", executable, "err", err)
 		}
 		return
 	}

pkg/stack/unwind/executable.go

@@ -126,6 +126,21 @@ func HasFramePointers(executable string) (bool, error) {
 		return want.LessThan(have), nil
 	}
 
+	// v8 uses a custom code generator for some of it's ahead-of-time functions. They do contain
+	// frame pointers, but no DWARF unwind information, so we force frame pointer unwinding as
+	// mixed mode unwinding (fp -> DWARF) won't work here.
+	//
+	// HACK: This is a somewhat a brittle check.
+	elfSymbols, err := elf.Symbols()
+	if err != nil {
+		return false, fmt.Errorf("failed to read symbols: %w", err)
+	}
+	for _, symbol := range elfSymbols {
+		if strings.Contains(symbol.Name, "InterpreterEntryTrampoline") {
+			return true, nil
+		}
+	}
+
 	// By default, assume there frame pointers are not present.
 	return false, nil
 }