Introduction

Having some basic skills in debugging Go programs can save any programmer a good amount of time trying to identify problems. I believe in logging as much information as you can, but sometimes a panic occurs and what you logged is not enough. Understanding the information in a stack trace can sometimes mean the difference between finding the bug now or needing to add more logging and waiting for it to happen again.





I have been seeing stack traces since I started writing Go. At some point we all do something silly that causes the runtime to kill our program and throw a stack trace. I am going to show you the information the stack trace provides, including how to identify the value for each parameter that was passed into each function.



Functions

Let’s start with a small piece of code that will produce a stack trace:



Listing 1



01 package main

02

03 func main() {

04 slice := make([]string, 2, 4)

05 Example(slice, "hello", 10)

06 }

07

08 func Example(slice []string, str string, i int) {

09 panic("Want stack trace")

10 }

Listing 1 shows a program where the

main

function calls the

Example

function on line 05. The

Example

function is declared on line 08 and accepts three parameters, a slice of strings, a string and an integer. The only code

Example

executes is a call to the built-in function

panic

on line 09, which immediately produces a stack trace:

Listing 2

Panic: Want stack trace



goroutine 1 [running]:

main.Example(0x2080c3f50, 0x2, 0x4, 0x425c0, 0x5, 0xa)

/Users/bill/Spaces/Go/Projects/src/github.com/goinaction/code/

temp/main.go:9 +0x64

main.main()

/Users/bill/Spaces/Go/Projects/src/github.com/goinaction/code/

temp/main.go:5 +0x85



goroutine 2 [runnable]:

runtime.forcegchelper()

/Users/bill/go/src/runtime/proc.go:90

runtime.goexit()

/Users/bill/go/src/runtime/asm_amd64.s:2232 +0x1



goroutine 3 [runnable]:

runtime.bgsweep()

/Users/bill/go/src/runtime/mgc0.go:82

runtime.goexit()

/Users/bill/go/src/runtime/asm_amd64.s:2232 +0x1

The stack trace in listing 2 shows all the goroutines that existed at the time of the panic, the status of each routine and the call stack under that respective goroutine. The goroutines that were running and the one that caused the stack trace will be at the top. Let’s focus on the goroutine that panicked.

Listing 3

01 goroutine 1 [running]:

02 main.Example(0x2080c3f50, 0x2, 0x4, 0x425c0, 0x5, 0xa)

/Users/bill/Spaces/Go/Projects/src/github.com/goinaction/code/

temp/main.go:9 +0x64

03 main.main()

/Users/bill/Spaces/Go/Projects/src/github.com/goinaction/code/

temp/main.go:5 +0x85

The stack trace on line 01 in listing 3 is showing that goroutine 1 was running prior to the panic. On line 02, we see that the code that panicked was in the

Example

function in package

main

. The line indented shows the code file and path this function is located in, plus the line of code that was executing. In this case, the code on line 09 was running which is the call to

panic

Line 03 shows the name of the function that called

Example

. This is the

main

function in the

main

package. Underneath the function name once again, the line that is indented shows the code file, path and line of code where the call to

Example

was made.The stack trace is showing the chain of function calls in the scope of that goroutine up to the time the panic occurred. Now, let’s focus on the values for each parameter that was passed into the

Example

function:

Listing 4

// Declaration

main.Example(slice []string, str string, i int)



// Call to Example by main.

slice := make([]string, 2, 4)

Example(slice, "hello", 10)



// Stack trace

main.Example(0x2080c3f50, 0x2, 0x4, 0x425c0, 0x5, 0xa)

Listing 4 shows the values from the stack trace that were passed into the

Example

function when the call was made by

main

and the declaration of the function. When you compare the values from the stack trace with the function declaration, it doesn’t seem to match up. The declaration of the

Example

function accepts three parameters but the stack trace is showing six hexadecimal values. The key to understanding how the values do match up with the parameters requires knowing the implementation for each parameter type.Let’s start with the first parameter which is a slice of strings. A slice is a reference type in Go. This means the value for a slice is a header value with a pointer to some underlying data. In the case of a slice, the header value is a three word structure that contains a pointer to an underlying array, the length of the slice and the capacity. The values associated with the slice header are represented by the first three values in the stack trace:

Listing 5

// Slice parameter value

slice := make([]string, 2, 4)



// Slice header values

Pointer: 0x2080c3f50

Length: 0x2

Capacity: 0x4



// Declaration

main.Example(slice []string, str string, i int)



// Stack trace

main.Example(0x2080c3f50, 0x2, 0x4, 0x425c0, 0x5, 0xa)

Listing 5 shows how the first three values in the stack trace do match up with the slice parameter. The first value represents the pointer to the underlying array of strings. The length and capacity numbers used to initialize the slice match with the second and third values. Those three values represent each value of the slice header, the first parameter.

Figure 1

figure provided by Georgi Knox





Now let’s look at the second parameter which is a string. A string is also a reference type but this header value is immutable. The header value for a string is declared as a two word structure that contains a pointer to an underlying byte array and the length of the string:

Listing 6

// String parameter value

"hello"



// String header values

Pointer: 0x425c0

Length: 0x5



// Declaration

main.Example(slice []string, str string, i int)



// Stack trace

main.Example(0x2080c3f50, 0x2, 0x4, 0x425c0, 0x5, 0xa)

Listing 6 shows how the fourth and fifth values in the stack trace do match up with the string parameter. The fourth value represents the pointer to the underlying array of bytes and the fifth value is the length of the string which was 5. The string

"hello"

requires 5 bytes. Those two values represent each value of the string header, the second parameter.

Figure 2

figure provided by Georgi Knox

The third parameter is an integer which is a single word value:

Listing 7

// Integer parameter value

10



// Integer value

Base 16: 0xa



// Declaration

main.Example(slice []string, str string, i int)



// Stack trace

main.Example(0x2080c3f50, 0x2, 0x4, 0x425c0, 0x5, 0xa)

Listing 7 shows how the last value in the stack trace matches up with the integer parameter. The very last value in the trace is hexadecimal number

0xa

, which is the value of 10. The same value that was passed in for that parameter. That value represents the third parameter.

Figure 3

figure provided by Georgi Knox





Methods

Let’s change the program so the Example function is now a method:

Listing 8

01 package main

02

03 import "fmt"

04

05 type trace struct{}

06

07 func main() {

08 slice := make([]string, 2, 4)

09

10 var t trace

11 t.Example(slice, "hello", 10)

12 }

13

14 func (t *trace) Example(slice []string, str string, i int) {

15 fmt.Printf("Receiver Address: %p

", t)

16 panic("Want stack trace")

17 }

Listing 8 changes the original program by declaring a new type named

trace

on line 05 and converting the

Example

function into a method on line 14. The conversion is accomplished by re-declaring the function with a pointer receiver of type

trace

. Then on line 10, a variable named

t

is declared of type

trace

and the method call is made with the variable on line 11.Since the method is declared with a pointer receiver, Go will take the address of the

t

variable to support the receiver type, even though the method call is made with a value. This time when the program is run, the stack trace is a little different:

Listing 9

Receiver Address: 0x1553a8

panic: Want stack trace



01 goroutine 1 [running]:

02 main.(*trace).Example(0x1553a8, 0x2081b7f50, 0x2, 0x4, 0xdc1d0, 0x5, 0xa)

/Users/bill/Spaces/Go/Projects/src/github.com/goinaction/code/

temp/main.go:16 +0x116



03 main.main()

/Users/bill/Spaces/Go/Projects/src/github.com/goinaction/code/

temp/main.go:11 +0xae

The first thing you should notice in listing 9 is that the stack trace on line 02 is making it clear this was a method call using a pointer receiver. The name of the function is now displayed with

(*trace)

between the package name and the method name. The second thing to notice is how the value list now shows the value of the receiver first. Method calls are really function calls with the first parameter being the receiver value. We are seeing this implementation detail in action from the stack trace.Since nothing else changed with the declaration or call to the

Example

method, all the other values remain the same. The line numbers where the call to

Example

is made and where the panic occurred changed and reflects the new code.

Packing

When you have multiple parameters that fit inside of a single word, then the values for the parameters in the stack trace will be packed together:





Listing 10

01 package main

02

03 func main() {

04 Example(true, false, true, 25)

05 }

06

07 func Example(b1, b2, b3 bool, i uint8) {

08 panic("Want stack trace")

09 }

Listing 10 shows a new sample program that changes the

Example

function to accept four parameters. The first three are booleans and the last one is an eight bit unsigned integer. A boolean value is also an eight bit value, so all four parameters fit inside of a single word on both 32 and 64 bit architectures. When the program runs, it produces an interesting stack trace:

Listing 11

01 goroutine 1 [running]:

02 main.Example(0x19010001)

/Users/bill/Spaces/Go/Projects/src/github.com/goinaction/code/

temp/main.go:8 +0x64

03 main.main()

/Users/bill/Spaces/Go/Projects/src/github.com/goinaction/code/

temp/main.go:4 +0x32

Instead of there being four values in the stack trace for the call to

Example

, there is a single value. All four individual 8 bit values were packed together into a single word:

Listing 12

// Parameter values

true, false, true, 25



// Word value

Bits Binary Hex Value

00-07 0000 0001 01 true

08-15 0000 0000 00 false

16-23 0000 0001 01 true

24-31 0001 1001 19 25



// Declaration

main.Example(b1, b2, b3 bool, i uint8)



// Stack trace

main.Example(0x19010001)

Listing 12 shows how the value in the stack trace matches up with all four parameter values that were passed in. The value of

true

is an 8 bit value that is represented with the value of 1 and the value of

false

is represented with the value of 0. The value of 25 in binary is 11001 which converts to 19 in hexadecimal. Now when we look at the hexadecimal value represented in the stack trace, we see how it does represent the values that were passed in.

Conclusion

The Go runtime provides a great deal of information to help us debug our programs. In this post we concentrated on stack traces. The ability to decode the values that were passed into each function throughout the call stack is huge. It has helped me more than once to identify my bug very quickly. Now that you know how to read stack traces, hopefully you can leverage this knowledge the next time a stack trace happens to you.