some more about timestamps

debugging

3 files changed, 20 insertions, 17 deletions

diff --git a/internal/types/types.go b/internal/types/types.go
index 6e8cd3b..c4ea2ad 100644
--- a/internal/types/types.go
+++ b/internal/types/types.go
@@ -3,18 +3,20 @@ package types
 import "fmt"
 
 type OpenEvent struct {
-	FD       int32
-	TID      uint32
-	Time     uint64
-	Filename [256]byte // TODO, use same value as in ioriot.bpf.h
-	Comm     [16]byte
+	FD        int32
+	TID       uint32
+	EnterTime uint64
+	ExitTime  uint64
+	Filename  [256]byte // TODO, use same value as in ioriot.bpf.h
+	Comm      [16]byte
 }
 
 func (e OpenEvent) String() string {
 	filename := e.Filename[:]
 	comm := e.Comm[:]
-	return fmt.Sprintf("%v tid:%d fd:%d filename:%s, comm:%s",
-		e.Time, e.TID, e.FD, string(filename), string(comm))
+	duration := float64(e.ExitTime-e.EnterTime) / float64(1_000_000)
+	return fmt.Sprintf("time:(%v=(%v-%v)/1mio) tid:%d fd:%d filename:%s, comm:%s",
+		duration, e.EnterTime, e.ExitTime, e.TID, e.FD, string(filename), string(comm))
 }
 
 type FdEvent struct {
@@ -26,6 +28,7 @@ type FdEvent struct {
 }
 
 func (e FdEvent) String() string {
-	duration := (e.ExitTime - e.EnterTime) / 1000000000000.0
-	return fmt.Sprintf("%vms opId:%d tid:%v fd:%v", duration, e.OpID, e.TID, e.FD)
+	duration := float64(e.ExitTime-e.EnterTime) / float64(1_000_000)
+	return fmt.Sprintf("time:(%vms=(%v-%v)/1mio) opId:%d tid:%v fd:%v",
+		duration, e.EnterTime, e.ExitTime, e.OpID, e.TID, e.FD)
 }
diff --git a/ioriotng.bpf.c b/ioriotng.bpf.c
index 9c01d9f..e4286c2 100644
--- a/ioriotng.bpf.c
+++ b/ioriotng.bpf.c
@@ -17,13 +17,12 @@ int handle_enter_open(struct trace_event_raw_sys_enter *ctx) {
         return 0;
 
     u32 tid = bpf_get_current_pid_tgid();
-    u64 time = bpf_ktime_get_ns();
 
     struct open_event open_event = {};
-    open_event.tid = tid;
-    open_event.time = time;
     bpf_probe_read_user_str(open_event.filename, sizeof(open_event.filename), (void *)ctx->args[0]);
     bpf_get_current_comm(&open_event.comm, sizeof(open_event.comm));
+    open_event.tid = tid;
+    open_event.enter_time = bpf_ktime_get_ns();
 
     bpf_map_update_elem(&open_event_temp_map, &tid, &open_event, BPF_ANY);
 
@@ -40,6 +39,7 @@ int handle_exit_open(struct trace_event_raw_sys_exit *ctx) {
     if (!open_eventp) {
         return 0;
     }
+    open_eventp->exit_time = bpf_ktime_get_ns();
     open_eventp->fd = ctx->ret;
     bpf_perf_event_output(ctx, &open_event_map, BPF_F_CURRENT_CPU, open_eventp, sizeof(struct open_event));
     bpf_map_delete_elem(&open_event_temp_map, &tid);
@@ -55,10 +55,11 @@ int handle_enter_openat(struct trace_event_raw_sys_enter *ctx) {
     u32 tid = bpf_get_current_pid_tgid();
 
     struct open_event open_event = {};
-    open_event.tid = tid;
 
     bpf_probe_read_user_str(open_event.filename, sizeof(open_event.filename), (void *)ctx->args[1]);
     bpf_get_current_comm(&open_event.comm, sizeof(open_event.comm));
+    open_event.tid = tid;
+    open_event.enter_time = bpf_ktime_get_ns();
     bpf_map_update_elem(&open_event_temp_map, &tid, &open_event, BPF_ANY);
 
     return 0;
@@ -66,9 +67,6 @@ int handle_enter_openat(struct trace_event_raw_sys_enter *ctx) {
 
 SEC("tracepoint/syscalls/sys_exit_openat")
 int handle_exit_openat(struct trace_event_raw_sys_exit *ctx) {
-    if (filter())
-        return 0;
-
     return handle_exit_open(ctx);
 }
 
@@ -102,6 +100,7 @@ int handle_exit_close(struct trace_event_raw_sys_enter *ctx) {
         return 0;
     }
 
+    open_eventp->exit_time = bpf_ktime_get_ns();
     bpf_perf_event_output(ctx, &fd_event_map, BPF_F_CURRENT_CPU, open_eventp, sizeof(struct fd_event));
     bpf_map_delete_elem(&fd_event_temp_map, &tid);
 
diff --git a/maps.bpf.h b/maps.bpf.h
index c369037..9d795a8 100644
--- a/maps.bpf.h
+++ b/maps.bpf.h
@@ -18,7 +18,8 @@ struct {
 struct open_event {
     __s32 fd;
     __u32 tid;
-    __u64 time;
+    __u64 enter_time;
+    __u64 exit_time;
     char filename[MAX_FILENAME_LENGTH];
     char comm[MAX_PROGNAME_LENGTH];
 };