ringbuf prototype for emitting sampled syscall completion records with latency numbers

tanelpoder · tanelpoder · commit 6e4484a4ec0e · 2024-12-28T21:13:42.000-05:00
diff --git a/next/src/xcapture.bpf.c b/next/src/xcapture.bpf.c
@@ -10,11 +10,11 @@
 char LICENSE[] SEC("license") = "Dual BSD/GPL";
 char VERSION[] = "3.0.0";
 
-// ? figure this out without including kernel .h files (platform and kconfig-dependent)
+// figure this out without including kernel .h files (platform and kconfig-dependent)
 #define PAGE_SIZE 4096
 #define THREAD_SIZE (PAGE_SIZE << 2)
 
-// for map_get lookups
+// for map_get lookups & empty map creations
 static __u32 zero = 0;
 
 
@@ -44,20 +44,14 @@ struct {
 } task_storage SEC(".maps");
 
 
-// static struct task_storage *get_task_storage(struct task_struct *task)
-// {
-//     struct task_storage *storage;
-//     
-//     storage = bpf_task_storage_get(&task_storage, task, NULL, BPF_LOCAL_STORAGE_GET_F_CREATE);
-//     bpf_printk("bpf_task_storage_get = %llx \n", storage);
-// 
-//     if (!storage)
-//         return NULL;
-//         
-//     return storage;
-// }
+// ringbuf for event completion events
+struct {
+    __uint(type, BPF_MAP_TYPE_RINGBUF);
+    __uint(max_entries, 256 * 1024);
+} completion_events SEC(".maps");
 
 
+// kernel version-adaptive task state retrieval
 static __u32 get_task_state(void *arg)
 {
     if (bpf_core_field_exists(struct task_struct___pre514, state)) {
@@ -70,6 +64,17 @@ static __u32 get_task_state(void *arg)
 }
 
 
+// xcapture start ktime for syscall duration sanitization later on
+__u64 program_start_time = 0;
+
+SEC("tp_btf/sys_enter")
+int handle_init(void *ctx)
+{
+    if (program_start_time == 0)
+        program_start_time = bpf_ktime_get_ns();
+    return 0;
+}
+
 
 SEC("raw_tracepoint/sys_enter")
 int handle_sys_enter(struct bpf_raw_tracepoint_args *ctx)
@@ -78,16 +83,17 @@ int handle_sys_enter(struct bpf_raw_tracepoint_args *ctx)
 
     storage = bpf_task_storage_get(&task_storage, bpf_get_current_task_btf(), 0, 
                                   BPF_LOCAL_STORAGE_GET_F_CREATE);
-
     if (!storage)
         return 0;
     
     storage->sc_enter_time = bpf_ktime_get_ns();
+    storage->sc_sampled = false; // new syscall, can't have been seen yet by sampler
     storage->sc_sequence_num += 1;
     storage->in_syscall_nr = (s32)ctx->args[1];  // syscall nr
     return 0;
 }
 
+
 SEC("raw_tracepoint/sys_exit")
 int handle_sys_exit(struct bpf_raw_tracepoint_args *ctx)
 {
@@ -97,9 +103,36 @@ int handle_sys_exit(struct bpf_raw_tracepoint_args *ctx)
                                   BPF_LOCAL_STORAGE_GET_F_CREATE);
     if (!storage)
         return 0;
-    
+
+    // Only emit completion events for syscalls that were caught in a sample
+    if (storage->sc_sampled) {
+        struct sc_completion_event *event;
+        
+        // Reserve space in the ringbuf
+        event = bpf_ringbuf_reserve(&completion_events, sizeof(*event), 0);
+        if (!event)
+            goto cleanup;  // ringbuf full, skip this event
+            
+        // Get current task info for pid/tgid
+        struct task_struct *task = bpf_get_current_task_btf();
+        event->pid = BPF_CORE_READ(task, pid);
+        event->tgid = BPF_CORE_READ(task, tgid);
+        
+        // Fill in syscall completion details
+        event->completed_syscall_nr     = storage->in_syscall_nr;
+        event->completed_sc_sequence_nr = storage->sc_sequence_num;
+        event->completed_sc_enter_time  = storage->sc_enter_time;
+        event->completed_sc_exit_time   = bpf_ktime_get_ns();
+        
+        // Submit the event
+        bpf_ringbuf_submit(event, 0);
+    }
+
+cleanup:
+    // Reset syscall tracking state
     storage->in_syscall_nr = -1;
     storage->sc_enter_time = 0;
+
     return 0;
 }
 
@@ -120,7 +153,7 @@ int get_tasks(struct bpf_iter__task *ctx)
     __u32 task_state = get_task_state(task);
     __u32 task_flags = task->flags;
   
-    // idle kernel worker thread waiting for work or other kernel threads in S state
+    // idle kernel worker thread waiting for work or other kernel threads in S state (also, they make no syscalls)
     if ((task_state & TASK_NOLOAD) || ((task_flags & PF_KTHREAD) && (task_state & TASK_INTERRUPTIBLE)))
         return 0;
 
@@ -197,7 +230,8 @@ int get_tasks(struct bpf_iter__task *ctx)
     bpf_probe_read_kernel(&file, sizeof(file), &fd_array[t->syscall_args[0]]);
 
     if (file) {
-        // bpf_d_path() doesn't work in a non-tracing task iterator program context?
+        // bpf_d_path() doesn't work in a simple task iterator program context (?)
+        // task_vma, task_files should work since kernel #3d06f34 (bpf: Allow bpf_d_path in bpf_iter program)
         struct path file_path;
         bpf_probe_read_kernel(&file_path, sizeof(file_path), &file->f_path);
         struct dentry *dentry = BPF_CORE_READ(file, f_path.dentry);
@@ -212,22 +246,50 @@ int get_tasks(struct bpf_iter__task *ctx)
     ret = bpf_get_task_stack(task, t->kstack, sizeof(__u64) * MAX_STACK_LEN, 0);
     t->kstack_len = ret <= 0 ? ret : ret / sizeof(t->kstack[0]);
 
-    // read task storage map experiment
+    
+    // put all this into a task_storage map for emitting to userspace
     struct task_storage *storage;
 
     storage = bpf_task_storage_get(&task_storage, task, NULL, BPF_LOCAL_STORAGE_GET_F_CREATE);
 
     if (!storage) // for the verifier
         return 0;
 
-    t->storage.in_syscall_nr = storage->in_syscall_nr;
-    t->storage.sample_ktime  = sample_ktime;
-    t->storage.sc_enter_time = storage->sc_enter_time;
-    t->storage.sc_sequence_num    = storage->sc_sequence_num;
+    // use "storage" here not "t->storage" (I need to come up with better naming of things)
+    storage->sc_sampled      = true; // used for deciding when to emit syscall completion records
+
+    // if this is the first time we see this task and it's already in a syscall,
+    // set its sc_enter_time to program start time instead of 0
+    if (storage->sc_enter_time == 0 && storage->in_syscall_nr >= 0) {
+        storage->sc_enter_time = program_start_time;
+    }
+
+    // "t" is the final struct for emitting everything to userspace
+    t->storage.in_syscall_nr   = storage->in_syscall_nr;
+    t->storage.sample_ktime    = sample_ktime;
+    t->storage.sc_enter_time   = storage->sc_enter_time;
+    t->storage.sc_sequence_num = storage->sc_sequence_num;
 
     bpf_seq_write(seq, t, sizeof(struct task_info));
     return 0;
 }
 
 
 
+// maybe for refactoring later
+
+// static struct task_storage *get_task_storage(struct task_struct *task)
+// {
+//     struct task_storage *storage;
+//     
+//     storage = bpf_task_storage_get(&task_storage, task, NULL, BPF_LOCAL_STORAGE_GET_F_CREATE);
+//     bpf_printk("bpf_task_storage_get = %llx \n", storage);
+// 
+//     if (!storage)
+//         return NULL;
+//         
+//     return storage;
+// }
+
+
+
diff --git a/next/src/xcapture.c b/next/src/xcapture.c
@@ -14,6 +14,9 @@
 #include "xcapture.skel.h"
 #include <syscall_names.h>
 
+// global, set once during startup arg checking
+bool output_csv = false;
+
 
 // handle CTRL+C and sigpipe etc
 static volatile bool exiting = false;
@@ -72,8 +75,9 @@ static const char *safe_syscall_name(__s32 syscall_nr)
 
 
 // ns is signed as sometimes there's small negative durations reported due to
-// concurrency of BPF task iterator vs event capture probes running on different CPUs
-struct timespec subtract_ns_from_timespec(struct timespec ts, __s64 ns) {
+// concurrency of BPF task iterator vs event capture probes running on different CPUs (?)
+struct timespec subtract_ns_from_timespec(struct timespec ts, __s64 ns) 
+{
     struct timespec result = ts;
 
     if (result.tv_nsec < (long)(ns % 1000000000)) {
@@ -87,12 +91,44 @@ struct timespec subtract_ns_from_timespec(struct timespec ts, __s64 ns) {
     return result;
 }
 
+// handle ringbuf completion events, don't bother trying to format 
+// wallclock time as these are ktime timestamps
+static int handle_event(void *ctx, void *data, size_t data_sz)
+{
+    const struct sc_completion_event *e = data;
+    
+    // Calculate duration in microseconds
+    __u64 duration_us = (e->completed_sc_exit_time - e->completed_sc_enter_time) / 1000;
+
+    if (output_csv) {
+        printf("SC_END,%d,%d,%d,%llu,%llu,%llu,%llu\n",
+               e->pid,
+               e->tgid,
+               e->completed_syscall_nr,
+               e->completed_sc_sequence_nr,
+               e->completed_sc_enter_time,
+               e->completed_sc_exit_time,
+               duration_us);
+    } else {
+        printf("SC_END  %7d  %7d  %-20s  %12llu  %26llu  %26llu  %'16llu\n",
+               e->pid,
+               e->tgid,
+               safe_syscall_name(e->completed_syscall_nr),
+               e->completed_sc_sequence_nr,
+               e->completed_sc_enter_time,
+               e->completed_sc_exit_time,
+               duration_us);
+    }
+    
+    return 0;
+}
+
+
 
 int main(int argc, char **argv)
 {
     // super simple check to avoid proper argument handling for now
     // if any args are given to xcapture, output CSV
-    bool output_csv = false;
     if (argc > 1)
         output_csv = true;
 
@@ -124,6 +160,16 @@ int main(int argc, char **argv)
         goto cleanup;
     }
 
+
+    /* Set up ring buffer polling */
+    struct ring_buffer *rb = NULL;
+    rb = ring_buffer__new(bpf_map__fd(skel->maps.completion_events), handle_event, NULL, NULL);
+    if (!rb) {
+        fprintf(stderr, "Failed to create ring buffer\n");
+        goto cleanup;
+    }
+
+
     struct timespec sample_ts; // sample timestamp
     char timestamp[64];
 
@@ -143,13 +189,13 @@ int main(int argc, char **argv)
         // Print output (kernel pid printed as TID in userspace and kernel tgid as PID)
         if (output_csv) {
             if (!header_printed) {
-                printf("%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s\n",
-                      "TIMESTAMP", "TID", "TGID", "STATE", "USER", "EXE", "COMM",
+                printf("%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s\n",
+                      "TYPE", "TIMESTAMP", "TID", "TGID", "STATE", "USER", "EXE", "COMM",
                       "SYSCALL_PASSIVE", "SYSCALL_ACTIVE", "SC_ENTRY_TIME", "SC_US_SO_FAR", "SC_SEQ_NUM", "ARG0", "FILENAME");
             }
         } else {
-            printf("%-26s  %7s  %7s  %-6s  %-16s  %-20s  %-16s  %-20s  %-20s  %-26s  %16s  %12s  %-16s  %s\n",
-                   "TIMESTAMP", "TID", "TGID", "STATE", "USER", "EXE", "COMM",
+            printf("%-6s  %-26s  %7s  %7s  %-6s  %-16s  %-20s  %-16s  %-20s  %-20s  %-26s  %16s  %12s  %-16s  %s\n",
+                   "TYPE", "TIMESTAMP", "TID", "TGID", "STATE", "USER", "EXE", "COMM",
                    "SYSCALL_PASSIVE", "SYSCALL_ACTIVE", "SC_ENTRY_TIME", "SC_US_SO_FAR", "SC_SEQ_NUM", "ARG0", "FILENAME");
         }
 
@@ -174,6 +220,7 @@ int main(int argc, char **argv)
             if (ret == 0)
                 break;
 
+
             __s64 duration_ns = 0; // event duration so far, from its start to sampling point
             if (buf.storage.sc_enter_time) 
                 duration_ns = buf.storage.sample_ktime - buf.storage.sc_enter_time;
@@ -188,7 +235,8 @@ int main(int argc, char **argv)
             snprintf(sc_start_time_str + 19, sizeof(sc_start_time_str) - 19, ".%06ld", sc_start_timespec.tv_nsec / 1000);
 
             if (output_csv) {
-                printf("%s,%d,%d,%s,\"%s\",\"%s\",\"%s\",%s,%s,%s,%lld,%lld,%llx,\"%s\"\n",
+                printf("%s,%s,%d,%d,%s,\"%s\",\"%s\",\"%s\",%s,%s,%s,%lld,%lld,%llx,\"%s\"\n",
+                    "SAMPLE",
                     timestamp,
                     buf.pid,
                     buf.tgid,
@@ -208,7 +256,8 @@ int main(int argc, char **argv)
                 );
             }
             else {
-                printf("%-26s  %7d  %7d  %-6s  %-16s  %-20s  %-16s  %-20s  %-20s  %-26s  %'16lld  %12lld  %-16llx  %s\n",
+                printf("%-6s  %-26s  %7d  %7d  %-6s  %-16s  %-20s  %-16s  %-20s  %-20s  %-26s  %'16lld  %12lld  %-16llx  %s\n",
+                    "SAMPLE",
                     timestamp,
                     buf.pid,
                     buf.tgid,
@@ -227,7 +276,14 @@ int main(int argc, char **argv)
                     buf.filename[0] ? buf.filename : "-"
                 );
             }
+        }
 
+
+        /* Ring buffer poll for event completions */
+        err = ring_buffer__poll(rb, 100 /* timeout, ms */);
+        if (err < 0) {
+            fprintf(stderr, "Error polling ring buffer: %d\n", err);
+            goto cleanup;
         }
 
 
@@ -249,7 +305,13 @@ int main(int argc, char **argv)
     cleanup:
     /* Clean up */
     fflush(stdout);
-    close(iter_fd); // the fd might already be closed above, but this would just return an EBADF then
+    close(iter_fd); /* the fd might already be closed above, but this would just return an EBADF then */
+
+    /* Release event completion ring buffer */
+    if (rb) {
+        ring_buffer__free(rb);
+    }
+
     xcapture_bpf__destroy(skel);
 
     return err < 0 ? -err : 0;
diff --git a/next/src/xcapture.h b/next/src/xcapture.h
@@ -34,19 +34,39 @@
 #define PF_KTHREAD            0x00200000  /* I am a kernel thread */
 
 
+// global xcapture start time (for syscall duration sanitization later on)
+extern __u64 program_start_time;
+
 // to be used with BPF_MAP_TYPE_TASK_STORAGE
 struct task_storage {
     __u64 sample_ktime;
+
     __s32 in_syscall_nr;
     __u64 sc_enter_time;
     __u64 sc_sequence_num; // any syscall entry in a task will increment this single counter
 
+    bool  sc_sampled:1;    // task iterator will set the following fields only if it catches a task 
+                           // in syscall during its sampling (later used for event completion records)
+    // block I/O latency sampling (not implemented yet)
     __u64 bio_queue_ktime;
     __u32 bio_dev;
     __u64 bio_sector;
 };
 
-// use kernel nomenclature in kernel side eBPF code (pid,tgid)
+
+// to be emitted via ringbuf only on *sampled* event completions, for getting the correct measured event times
+// so we are not going to emit millions of events per sec here (just up to num active threads * sampling rate)
+struct sc_completion_event {
+    pid_t pid;  // pid, tgid, completed_sc_sequence_nr, completed_sc_enter_time are the unique identifier here
+    pid_t tgid;
+    __u64 completed_sc_sequence_nr;
+    __u64 completed_sc_enter_time;
+    __u64 completed_sc_exit_time;
+    __s32 completed_syscall_nr;
+};
+
+
+// use kernel nomenclature in kernel side eBPF code (pid=thread_id, tgid=process_id)
 struct task_info {
     struct task_struct * addr;  // task kernel address for task storage lookups elsewhere
     pid_t pid;   // task id (tid in userspace)
