Probing golang runtime using SystemTap

I recently saw an article from Uber Engineering describing an issue they were having with an increase in latency. The Uber engineers suspected that their code was running out of stack space causing the golang runtime to issue a stack growth, which would introduce additional latency due to memory allocation and copying. The engineers ended up modifying the golang runtime with additional instrumentation to report these stack growths to confirm their suspicions. This situation is a perfect example of where SystemTap could have been used.

SystemTap is a tool that can be used to perform live analysis of a running program. It is able to interrupt normal control flow and execute code specified by a SystemTap script, which can allow users to temporarily modify a running program without having to change the source and recompile.

Here is a SystemTap script that can be used to replicate the patch done in the Uber article:

global printstackgrow
 
probe process(PATH).statement("runtime.newstack@/usr/lib/golang/src/runtime/stack.go:936")
{
  shouldPrintStack = printstackgrow % 1000 == 0
  printstackgrow++

  if (shouldPrintStack) {
    oldSize = $thisg->m->curg->stack->hi - $thisg->m->curg->stack->lo
    newSize = oldSize * 2
    printf("runtime: newstack: %d -> %d\n", oldSize, newSize)
    print_ubacktrace_fileline($thisg->m->morebuf->pc,
                              $thisg->m->morebuf->sp,
                              $thisg->m->morebuf->lr)
  }
}

This script introduces a probe within the runtime.newstack() function at line 936 of stack.go (this location will depend on your golang installation) for the executable specified by PATH. When we reach that point in execution, SystemTap will redirect and execute the code placed within the probe handler shown above. The handler performs the same steps done in the Uber article patch, printing out the change in stack size and a backtrace for every 1000 hits of runtime.newstack().

Now let's see this script in action. I am going to use the following golang example to demonstrate. This program prints out some text and spawns go routines to do the same, just to get to a point where a stack needs to be grown and runtime.newstack() is called.

$ cat example.go
package main

import (
  "fmt"
  "time"
)

func say(s string)
{
  for i := 0; i < 5; i++ {
    time.Sleep(1 * time.Millisecond)
    fmt.Println(s)
  }
}

func main()
{
  go say("world")
  say("hello")
}

For this demonstration, I will simplify the SystemTap script a little. The sampling code to limit output isn't needed, as there won't be too much output with the example. Also now we have an actual executable, generated using go build example.go, which can be used to replace PATH.

$ cat newstack.stp
probe process("./example").statement("runtime.newstack@/usr/lib/golang/src/runtime/stack.go:936")
{
  oldSize = $thisg->m->curg->stack->hi - $thisg->m->curg->stack->lo
  newSize = oldSize * 2
  printf("runtime: newstack: %d -> %d\n", oldSize, newSize)
  print_ubacktrace_fileline($thisg->m->morebuf->pc, 
                            $thisg->m->morebuf->sp, 
                            $thisg->m->morebuf->lr)
}

When we run this script, we get:

$ ls
newstack.stp  example  example.go
$ stap newstack.stp
                        <== execute "./example" in another terminal
    :
runtime: newstack: 2048 -> 4096
 0x40d748 : runtime.mallocgc+0x548/0x9d0 at /usr/lib/golang/src/runtime/malloc.go:740 [/home/juddin/example]
 0x40dd48 : runtime.newobject+0x38/0x60 at /usr/lib/golang/src/runtime/malloc.go:839 [/home/juddin/example]
    :
 0x47c4cb : fmt.Fprintln+0x8b/0x100 at /usr/lib/golang/src/fmt/print.go:255 [/home/juddin/example]
 0x47c597 : fmt.Println+0x57/0x90 at /usr/lib/golang/src/fmt/print.go:264 [/home/juddin/example]
 0x4827a4 : main.say+0xa4/0xd0 at /home/juddin/example.go:9 [/home/juddin/example]
 0x44ecb1 : runtime.goexit+0x1/0x10 at /usr/lib/golang/src/runtime/asm_amd64.s:2362 [/home/juddin/example]

I have omitted some of the output to make things a little clearer and focused on the points of interest. As can be seen from the backtrace, a stack growth is triggered from main.say(). So, we are able to determine that our code indeed does cause a stack growth, and we did this without having to modify the target program, never mind the go runtime or compiler.