Tracing System Time Access in Go Programs Link to heading

Background Link to heading

We recently had a use case where we wanted to figure out anytime a program tried to access the system time. Given the recent eBPF experiments, I wanted to see if there’s a system call to do this, and there is: the gettimeofday syscall, which can give us the current time.

However, for optimization purposes, it seems like Go programs do not directly make a syscall whenever time.Now() is called. Instead, they use a mechanism called vDSO in Linux, whereby some common Kernel functions can be dynamically linked into the executable through a shared object provided by the Kernel. With this mechanism, the program can directly access the system time without a userspace -> Kernelspace jump for this syscall. Slide 10 in this presentation has good info about the vDSO mechanism. More information about Go’s vDSO usage can be found in this blog post.

Tracing with uprobes Link to heading

uprobe is an eBPF mechanism that allows us to trace any userspace function. What if we set a uprobe to trace the time.Now() function? That should work, right?

With uprobes, we can dynamically attach to userspace functions and collect information whenever those functions are called. By attaching a uprobe to time.Now(), we can effectively trace every access to the system time, even if it’s optimized using vDSO.

Ok, let’s start by inspecting the functions in a sample Go program that just prints the current time:

File: main.go

package main

import (
    "fmt"
    "time"
)

func main() {
    currentTime := time.Now()
    fmt.Println(currentTime)
}

This simple program retrieves and prints the current system time using time.Now().

Build the program using:

$ go build main.go

Then run:

$ objdump -tT main | grep "time.Now"
objdump: main: not a dynamic object
0000000000491120 g     F .text    000000000000006e time.Now

Ok, now that we see the time.Now function, let’s write a uprobe using bpftrace. You can learn more about bpftrace and related tools here.

$ sudo bpftrace -e 'uprobe:/home/kousikk/time-now/main:"time.Now" { printf("PID: %d\n", pid); }'

This trace will print the PID of any execution of the main binary that accesses the time.Now() function. Great!

Performance Penalty of Tracing Link to heading

While using uprobes with eBPF is a powerful way to trace system time access, it does come with a performance cost. Attaching uprobes adds overhead because every time the traced function is called, there comes a switch from userspace (time.Now() running through vDSO mechanism) to Kernel space to run the uprobe. In fact, an argument can be made that this defeats the whole purpose of using vDSO!

Lets write a simple program to analyze how slow performance can get.

package main

import (
	"fmt"
	"time"
)

func main() {
	const iterations = 100000
	start := time.Now()

	for i := 0; i < iterations; i++ {
		_ = time.Now()
	}

	duration := time.Since(start)
	fmt.Printf("Time taken for %d calls to time.Now(): %v\n", iterations, duration)
}

Running this without any uprobe on time.Now(), we see that it takes ~3.4ms:

kousiktn@kousiktn:~/projects/ebpf-time-now$ ./main
Time taken for 100000 calls to time.Now(): 3.389458ms

And when we attach a uprobe on time.Now() with a very simple counter like:

kousiktn@kousiktn:~/projects/ebpf-time-now$ sudo bpftrace -e 'uprobe:/home/kousiktn/projects/ebpf-time-now/main:"time.Now" { @++ }'
Attaching 1 probe...

(in another terminal):

kousiktn@kousiktn:~/projects/ebpf-time-now$ ./main
Time taken for 100000 calls to time.Now(): 170.72405ms

That’s roughly 50x slower!! This maybe a pathological example, but goes to show how slow uprobe can get if we aren’t aware of the performance slowdown it maybe causing.