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
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
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
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
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
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
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
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
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
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
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
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
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.
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 }
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
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
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)
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)
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
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)
"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
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)
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
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\n", t)
16 panic("Want stack trace")
17 }
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\n", 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
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 }
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
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)
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.
有疑问加站长微信联系（非本文作者）
