Conditionally log in the BPF program (#8)

with the `--verbose-bpf-logging` flag: ``` $ rbperf record --pid `pidof ruby-mri` --verbose-bpf-logging syscall enter_writev ``` Logs can be read from /sys/kernel/debug/tracing/trace_pipe
javierhonduco · Jul 8, 2022 · 422c5ca · 422c5ca
1 parent 65d01d1
commit 422c5ca
Show file tree

Hide file tree

Showing 4 changed files with 48 additions and 15 deletions.
diff --git a/src/bpf/rbperf.bpf.c b/src/bpf/rbperf.bpf.c
@@ -65,6 +65,15 @@ struct {
     __type(value, SampleState);
 } global_state SEC(".maps");
 
+const volatile bool verbose = false;
+
+#define LOG(fmt, ...)                       \
+    ({                                      \
+        if (verbose) {                      \
+            bpf_printk(fmt, ##__VA_ARGS__); \
+        }                                   \
+    })
+
 static inline_method u32 find_or_insert_frame(RubyFrame *frame) {
     u32 *found_id = bpf_map_lookup_elem(&stack_to_id, frame);
     if (found_id != NULL) {
@@ -90,12 +99,12 @@ static inline_method void read_ruby_string(u64 label, char *buffer,
                     (void *)(label + as_offset + 8 /* .long len */));
         int err = rbperf_read_str(buffer, buffer_len, (void *)(char_ptr));
         if (err < 0) {
-            bpf_printk("[warn] string @ 0x%llx [heap] failed with err=%d", (void *)(char_ptr), err);
+            LOG("[warn] string @ 0x%llx [heap] failed with err=%d", (void *)(char_ptr), err);
         }
     } else {
         int err = rbperf_read_str(buffer, buffer_len, (void *)(label + as_offset));
         if (err < 0) {
-            bpf_printk("[warn] string @ 0x%llx [stack] failed with err=%d", (void *)(label + as_offset), err);
+            LOG("[warn] string @ 0x%llx [stack] failed with err=%d", (void *)(label + as_offset), err);
         }
     }
 }
@@ -146,7 +155,7 @@ read_frame(u64 pc, u64 body, RubyFrame *current_frame,
     u64 flags;
     int label_offset = version_offsets->label_offset;
 
-    bpf_printk("[debug] reading stack");
+    LOG("[debug] reading stack");
 
     rbperf_read(&path_addr, 8,
                 (void *)(body + location_offset + path_offset));
@@ -163,7 +172,7 @@ read_frame(u64 pc, u64 body, RubyFrame *current_frame,
         }
 
     } else {
-        bpf_printk("[error] read_frame, wrong type");
+        LOG("[error] read_frame, wrong type");
         // Skip as we don't have the data types we were looking for
         return;
     }
@@ -176,7 +185,7 @@ read_frame(u64 pc, u64 body, RubyFrame *current_frame,
     read_ruby_string(label, current_frame->method_name,
                      sizeof(current_frame->method_name));
 
-    bpf_printk("[debug] method name=%s", current_frame->method_name);
+    LOG("[debug] method name=%s", current_frame->method_name);
 }
 
 SEC("perf_event")
@@ -218,7 +227,7 @@ int read_ruby_stack(struct bpf_perf_event_data *ctx) {
         RubyStackAddress ruby_stack_address = {};
 
         if (cfp > state->base_stack) {
-            bpf_printk("[debug] done reading stack");
+            LOG("[debug] done reading stack");
             break;
         }
 
@@ -280,14 +289,14 @@ int read_ruby_stack(struct bpf_perf_event_data *ctx) {
 
     if (cfp <= base_stack &&
         state->ruby_stack_program_count < BPF_PROGRAMS_COUNT) {
-        bpf_printk("[debug] traversing next chunk of the stack in a tail call");
+        LOG("[debug] traversing next chunk of the stack in a tail call");
         bpf_tail_call(ctx, &programs, RBPERF_STACK_READING_PROGRAM_IDX);
     }
 
     state->stack.stack_status = cfp > state->base_stack ? STACK_COMPLETE : STACK_INCOMPLETE;
 
     if (state->stack.size != state->stack.expected_size) {
-        bpf_printk("[error] stack size %d, expected %d", state->stack.size, state->stack.expected_size);
+        LOG("[error] stack size %d, expected %d", state->stack.size, state->stack.expected_size);
     }
 
     bpf_perf_event_output(ctx, &events, BPF_F_CURRENT_CPU, &state->stack, sizeof(RubyStack));
@@ -301,7 +310,7 @@ int on_event(struct bpf_perf_event_data *ctx) {
     ProcessData *process_data = bpf_map_lookup_elem(&pid_to_rb_thread, &pid);
 
     if (process_data != NULL && process_data->rb_frame_addr != 0) {
-        bpf_printk("[debug] reading Ruby stack");
+        LOG("[debug] reading Ruby stack");
 
         u64 ruby_current_thread_addr;
         u64 main_thread_addr;
@@ -313,15 +322,15 @@ int on_event(struct bpf_perf_event_data *ctx) {
         RubyVersionOffsets *version_offsets = bpf_map_lookup_elem(&version_specific_offsets, &process_data->rb_version);
 
         if (version_offsets == NULL) {
-            bpf_printk("[error] can't find offsets for version");
+            LOG("[error] can't find offsets for version");
             return 0;
         }
 
         rbperf_read(&ruby_current_thread_addr, 8,
                     (void *)process_data->rb_frame_addr);
 
-        bpf_printk("process_data->rb_frame_addr %llx", process_data->rb_frame_addr);
-        bpf_printk("ruby_current_thread_addr %llx", ruby_current_thread_addr);
+        LOG("process_data->rb_frame_addr 0x%llx", process_data->rb_frame_addr);
+        LOG("ruby_current_thread_addr 0x%llx", ruby_current_thread_addr);
 
         // Find the main thread and the ec
         rbperf_read(&main_thread_addr, 8,

diff --git a/src/bpf/vmlinux.h b/src/bpf/vmlinux.h
@@ -272,4 +272,11 @@ typedef __u32 __be32;
 
 typedef __u64 __be64;
 
-typedef __u32 __wsum;
+typedef __u32 __wsum;
+
+typedef _Bool bool;
+
+enum {
+    false = 0,
+    true = 1,
+};
diff --git a/src/main.rs b/src/main.rs
@@ -30,6 +30,8 @@ struct RecordSubcommand {
     duration: Option<u64>,
     #[clap(subcommand)]
     record_type: RecordType,
+    #[clap(long)]
+    verbose_bpf_logging: bool,
 }
 
 #[derive(clap::Subcommand, Debug)]
@@ -51,7 +53,11 @@ fn main() -> Result<()> {
                 },
                 RecordType::Syscall { name } => RbperfEvent::Syscall(name),
             };
-            let options = RbperfOptions { event };
+            let options = RbperfOptions {
+                event,
+                verbose_bpf_logging: record.verbose_bpf_logging,
+            };
+
             let mut r = Rbperf::new(options);
             r.add_pid(record.pid)?;
 

diff --git a/src/rbperf.rs b/src/rbperf.rs
@@ -37,6 +37,7 @@ pub struct Rbperf<'a> {
 
 pub struct RbperfOptions {
     pub event: RbperfEvent,
+    pub verbose_bpf_logging: bool,
 }
 
 fn handle_event(
@@ -101,12 +102,14 @@ impl<'a> Rbperf<'a> {
         if !arch::is_x86() {
             eprintln!("rbperf hasn't been thoroughly tested on non-x86 architectures");
         }
-
         let mut skel_builder = RbperfSkelBuilder::default();
         if log_enabled!(Level::Debug) {
             skel_builder.obj_builder.debug(true);
         }
         let mut open_skel = skel_builder.open().unwrap();
+        debug!("verbose_bpf_logging set to {}", options.verbose_bpf_logging);
+        open_skel.rodata().verbose = options.verbose_bpf_logging;
+
         match options.event {
             RbperfEvent::Cpu { sample_period: _ } => {
                 for prog in open_skel.obj.progs_iter_mut() {
@@ -120,6 +123,13 @@ impl<'a> Rbperf<'a> {
             }
         }
         let mut bpf = open_skel.load().unwrap();
+        for prog in bpf.obj.progs_iter() {
+            debug!(
+                "open prog: {} has {} intructions",
+                prog.name(),
+                prog.insn_cnt()
+            );
+        }
 
         let mut maps = bpf.maps_mut();
         let versions = maps.version_specific_offsets();
@@ -439,6 +449,7 @@ mod tests {
 
             let options = RbperfOptions {
                 event: RbperfEvent::Syscall("enter_writev".to_string()),
+                verbose_bpf_logging:true,
             };
             let mut r = Rbperf::new(options);
             r.add_pid(pid.unwrap()).unwrap();