initial support for logging time diffs between syscalls

2 files changed, 46 insertions, 15 deletions

diff --git a/internal/event.go b/internal/event.go
index beb8af6..acc8324 100644
--- a/internal/event.go
+++ b/internal/event.go
@@ -5,8 +5,13 @@ import (
 	. "ioriotng/internal/generated/types"
 	"strconv"
 	"strings"
+	"sync"
 )
 
+var poolOfEventPairs = sync.Pool{
+	New: func() interface{} { return &eventPair{} },
+}
+
 type event interface {
 	String() string
 	GetTraceId() TraceId
@@ -16,26 +21,43 @@ type event interface {
 	Recycle()
 }
 
-type enterExitEvent struct {
+// Represents a pair of enter and exit events (e.g. entering the syscall + exiting it)
+type eventPair struct {
 	enterEv, exitEv    event
 	file               file
 	comm               string
+	duration           uint32
 	tracepointMismatch bool
+	// To calculate the time difference from the previoud event.
+	prevPair       *eventPair
+	durationToPrev uint32
+}
+
+func newEventPair(enterEv event) *eventPair {
+	e := poolOfEventPairs.Get().(*eventPair)
+	e.enterEv = enterEv
+	return e
+}
+
+func (e *eventPair) calculateDurations() {
+	e.duration = e.exitEv.GetTime() - e.enterEv.GetTime()
+	if e.prevPair != nil {
+		e.durationToPrev = e.enterEv.GetTime() - e.prevPair.exitEv.GetTime()
+	}
 }
 
-func (e enterExitEvent) is(id TraceId) bool {
+func (e *eventPair) is(id TraceId) bool {
 	return e.enterEv.GetTraceId() == id
 }
 
-func (e enterExitEvent) String() string {
+func (e *eventPair) String() string {
 	var sb strings.Builder
 
 	if e.tracepointMismatch {
 		sb.WriteString("MISMATCH ")
 	}
 
-	duration := e.exitEv.GetTime() - e.enterEv.GetTime()
-	sb.WriteString(fmt.Sprintf("%08d µs", duration))
+	sb.WriteString(fmt.Sprintf("%08dµs %08dµs", e.durationToPrev, e.duration))
 
 	sb.WriteString(" ")
 	sb.WriteString(e.comm)
@@ -58,11 +80,13 @@ func (e enterExitEvent) String() string {
 	return sb.String()
 }
 
-func (e enterExitEvent) dump() string {
+func (e *eventPair) dump() string {
 	return fmt.Sprintf("%v with enterEv(%v) and exitEv(%v)", e, e.enterEv, e.exitEv)
 }
 
-func (e enterExitEvent) recycle() {
+func (e *eventPair) recycle() {
 	e.enterEv.Recycle()
 	e.exitEv.Recycle()
+	e.prevPair = nil
+	poolOfEventPairs.Put(e)
 }
diff --git a/internal/eventloop.go b/internal/eventloop.go
index 9ce0149..9b6cdcb 100644
--- a/internal/eventloop.go
+++ b/internal/eventloop.go
@@ -12,26 +12,30 @@ import (
 
 func eventLoop(bpfModule *bpf.Module, rawCh <-chan []byte) {
 	for ev := range events(rawCh) {
-		fmt.Println(ev)
-		ev.recycle()
+		fmt.Println(ev.String())
+		if ev.prevPair != nil {
+			// Only recycle the previous event, as the current event is the previous
+			// event of the next event!
+			ev.prevPair.recycle()
+		}
 	}
 	fmt.Println("Good bye")
 }
 
-func events(rawCh <-chan []byte) <-chan enterExitEvent {
+func events(rawCh <-chan []byte) <-chan *eventPair {
 	// Channel of events (enter+exit tracepoint results of a syscall).
-	evCh := make(chan enterExitEvent)
+	evCh := make(chan *eventPair)
 	// Temp. store of sys_enter tracepoints per Tid.
-	enterEvs := make(map[uint32]enterExitEvent)
+	enterEvs := make(map[uint32]*eventPair)
 	// Track all open files by file descriptor.
 	files := make(map[int32]file)
 	// Program or thread name of the current Tid.
 	comms := make(map[uint32]string)
+	// Previous event (to calculate time differences between two events)
+	prevPairs := make(map[uint32]*eventPair)
 
 	enter := func(enterEv event) {
-		enterEvs[enterEv.GetTid()] = enterExitEvent{
-			enterEv: enterEv,
-		}
+		enterEvs[enterEv.GetTid()] = newEventPair(enterEv)
 	}
 
 	exit := func(exitEv event) {
@@ -96,6 +100,9 @@ func events(rawCh <-chan []byte) <-chan enterExitEvent {
 			panic(fmt.Sprintf("unknown type: %v", v))
 		}
 
+		ev.prevPair, _ = prevPairs[ev.enterEv.GetTid()]
+		ev.calculateDurations()
+		prevPairs[ev.enterEv.GetTid()] = ev
 		evCh <- ev
 	}