github.com/ks888/tgo@v0.0.0-20190130135156-80bf89407292/README.md (about) 1 # tgo: a function tracer to boost your debugging 2 3 [![GoDoc](https://godoc.org/github.com/ks888/tgo?status.svg)](https://godoc.org/github.com/ks888/tgo/lib/tracer) 4 [![Build Status](https://travis-ci.com/ks888/tgo.svg?branch=master)](https://travis-ci.com/ks888/tgo) 5 [![Go Report Card](https://goreportcard.com/badge/github.com/ks888/tgo)](https://goreportcard.com/report/github.com/ks888/tgo) 6 7 ### Examples 8 9 In this example, the functions called between `tracer.Start()` and `tracer.Stop()` are traced. 10 11 ```golang 12 package main 13 14 import ( 15 "fmt" 16 "os" 17 "strconv" 18 19 "github.com/ks888/tgo/lib/tracer" 20 ) 21 22 func fib(n int) int { 23 if n == 0 || n == 1 { 24 return n 25 } 26 return fib(n-1) + fib(n-2) 27 } 28 29 func main() { 30 tracer.Start() 31 32 var n int64 33 if len(os.Args) > 1 { 34 n, _ = strconv.ParseInt(os.Args[1], 10, 64) 35 } 36 val := fib(int(n)) 37 fmt.Println(val) 38 39 tracer.Stop() 40 } 41 ``` 42 43 When you run the program, the trace logs are printed: 44 45 ```shell 46 % go build fib.go 47 % ./fib 3 48 \ (#01) strconv.ParseInt(s = "3", base = 10, bitSize = 64) (...) 49 / (#01) strconv.ParseInt(s = "3", base = 10, bitSize = 64) (i = 3, err = nil) 50 \ (#01) main.fib(n = 3) (...) 51 / (#01) main.fib(n = 3) (~r1 = 2) 52 \ (#01) fmt.Println(a = []{int(2)}) (...) 53 2 54 / (#01) fmt.Println(a = []{int(2)}) (n = 2, err = nil) 55 ``` 56 57 Now let's use the tgo to boost your debugging. The example below sorts the int slice using the quicksort, *but it has the bug*. 58 59 ```golang 60 package main 61 62 import ( 63 "fmt" 64 65 "github.com/ks888/tgo/lib/tracer" 66 ) 67 68 func qsort(data []int, start, end int) { 69 if end-start <= 1 { 70 return 71 } 72 73 index := partition(data, start, end) 74 qsort(data, start, index-1) 75 qsort(data, index, end) 76 return 77 } 78 79 func partition(data []int, start, end int) int { 80 pivot := data[(start+end)/2] 81 left, right := start, end 82 for { 83 for left <= end && data[left] < pivot { 84 left++ 85 } 86 for right >= start && data[right] > pivot { 87 right-- 88 } 89 if left > right { 90 return left 91 } 92 93 data[left], data[right] = data[right], data[left] 94 left++ 95 right-- 96 } 97 } 98 99 func main() { 100 tracer.SetTraceLevel(2) // will be explained later 101 tracer.Start() 102 103 testdata := []int{3, 1, 2, 5, 4} 104 qsort(testdata, 0, len(testdata)-1) 105 106 tracer.Stop() 107 108 fmt.Println(testdata) 109 } 110 ``` 111 112 The result is `[2 1 3 4 5]`, which is obviously not sorted. 113 114 ```shell 115 % go build qsort.go 116 % ./qsort 117 \ (#01) main.qsort(data = []{3, 1, 2, 5, 4}, start = 0, end = 4) () 118 |\ (#01) main.partition(data = []{3, 1, 2, 5, 4}, start = 0, end = 4) (...) 119 |/ (#01) main.partition(data = []{2, 1, 3, 5, 4}, start = 0, end = 4) (~r3 = 2) 120 |\ (#01) main.qsort(data = []{2, 1, 3, 5, 4}, start = 0, end = 1) () 121 |/ (#01) main.qsort(data = []{2, 1, 3, 5, 4}, start = 0, end = 1) () 122 |\ (#01) main.qsort(data = []{2, 1, 3, 5, 4}, start = 2, end = 4) () 123 |/ (#01) main.qsort(data = []{2, 1, 3, 4, 5}, start = 2, end = 4) () 124 / (#01) main.qsort(data = []{2, 1, 3, 4, 5}, start = 0, end = 4) () 125 [2 1 3 4 5] 126 ``` 127 128 Now the trace logs help you find a bug. 129 130 1. The 1st line of the logs shows `main.qsort` is called properly. `main.qsort` sorts the `data` between `start` and `end` (inclusive). 131 2. The 2nd and 3rd lines tell us `main.partition` works as expected here. `main.partition` partitions the `data` between `start` and `end` (inclusive) and returns the pivot index. 132 3. The 4th and 5th lines are ... strange. `start` is 0 and `end` is 1, but the `data` between 0 and 1 is not sorted. 133 134 Let's see the implementation of `main.qsort`, assuming `start` is 0 and `end` is 1. It becomes apparent the `if` statement at the 1st line has the off-by-one error. `end-start <= 1` should be `end-start <= 0`. We found the bug. 135 136 It's possible to use print debugging instead, but we may need to scatter print functions and run the code again and again. Also, it's likely the logs are less structured. The tgo approach is faster and clearer and so can boost your debugging. 137 138 ### Features 139 140 * As easy as print debug: just insert 1-2 line(s) to your code 141 * But more powerful: visually tells you what's actually going on in your code 142 * Works without debugging info 143 * It's actually important for testing. See the usage below for more details. 144 * Support Linux/Mac OS X 145 146 ### Install 147 148 *Note: supported go version is 1.10 or later.* 149 150 #### Mac OS X 151 152 Install the `tgo` binary and its library: 153 154 ``` 155 go get -u github.com/ks888/tgo/cmd/tgo 156 ``` 157 158 If you have an error, you may need to install Xcode Command Line Tools: `xcode-select --install` 159 160 #### Linux 161 162 Install the `tgo` binary and its library: 163 164 ``` 165 go get -u github.com/ks888/tgo/cmd/tgo 166 ``` 167 168 The `tgo` binary attaches to your process using the ptrace mechanism. To enable this, run the command below: 169 170 ``` 171 sudo sh -c 'echo 0 > /proc/sys/kernel/yama/ptrace_scope' 172 ``` 173 174 If you run the program in the docker container, add the `--cap-add sys_ptrace` option. For example: 175 176 ``` 177 docker run --cap-add sys_ptrace -it golang:1 /bin/bash 178 ``` 179 180 #### Windows 181 182 Not supported. 183 184 ### Usage 185 186 Basically you just need to specify the starting point with `tracer.Start()` and the ending point with `tracer.Stop()`. 187 188 ```golang 189 package main 190 191 import ( 192 "fmt" 193 194 "github.com/ks888/tgo/lib/tracer" 195 ) 196 197 func fib(n int) int { 198 if n == 0 || n == 1 { 199 return n 200 } 201 return fib(n-1) + fib(n-2) 202 } 203 204 func main() { 205 tracer.Start() 206 207 val := fib(3) 208 fmt.Println(val) 209 210 tracer.Stop() 211 } 212 ``` 213 214 When you build and run this program, you can see the function trace logs of `fib()` and `fmt.Println()`. Though `fib()` is called recursively, only the 1st call's log is printed. 215 216 ```shell 217 % go build simple.go 218 % ./simple 219 \ (#01) main.fib(n = 3) (...) 220 / (#01) main.fib(n = 3) (~r1 = 2) 221 \ (#01) fmt.Println(a = []{int(2)}) (...) 222 2 223 / (#01) fmt.Println(a = []{int(2)}) (n = 2, err = nil) 224 ``` 225 226 All the examples in this doc are available in the `_examples` directory. If this example doesn't work, check the error value `tracer.Start()` returns. 227 228 #### Set TraceLevel 229 230 You often need a little deeper trace logs. For example, you may want to know the functions `fib()` and `fmt.Println()` call internally. You can do that by adjusting the trace level with `tracer.SetTraceLevel()`. 231 232 ```golang 233 package main 234 235 import ( 236 "fmt" 237 238 "github.com/ks888/tgo/lib/tracer" 239 ) 240 241 func fib(n int) int { 242 if n == 0 || n == 1 { 243 return n 244 } 245 return fib(n-1) + fib(n-2) 246 } 247 248 func main() { 249 tracer.SetTraceLevel(2) 250 tracer.Start() 251 252 val := fib(3) 253 fmt.Println(val) 254 255 tracer.Stop() 256 } 257 ``` 258 259 In this example, the trace level is 2. Because the default level is 1, now the trace logs go one level deeper. 260 261 ```shell 262 % go build tracelevel.go 263 % ./tracelevel 264 \ (#01) main.fib(n = 3) (...) 265 |\ (#01) main.fib(n = 2) (...) 266 |/ (#01) main.fib(n = 2) (~r1 = 1) 267 |\ (#01) main.fib(n = 1) (...) 268 |/ (#01) main.fib(n = 1) (~r1 = 1) 269 / (#01) main.fib(n = 3) (~r1 = 2) 270 \ (#01) fmt.Println(a = []{int(2)}) (...) 271 |\ (#01) fmt.Fprintln(a = -, w = -) (...) 272 2 273 |/ (#01) fmt.Fprintln(a = -, w = -) (n = 2, err = nil) 274 / (#01) fmt.Println(a = []{int(2)}) (n = 2, err = nil) 275 ``` 276 277 Note that the input args of `fmt.Fprintln` is `-` (not available) here. It's likely the debugging info are omitted due to optimization. To see the complete result, set `"-gcflags=-N"` (fast, but may not complete) or `"-gcflags=all=-N"` (slow, but complete) to `GOFLAGS` environment variable. 278 279 ```shell 280 % GOFLAGS="-gcflags=all=-N" go build tracelevel.go 281 ``` 282 283 #### Works without debugging info 284 285 If you run the program with `go test` or `go run`, debugging info, such as DWARF data, are dropped. Fortunately, tgo works even in such a case. Let's trace the test for the fib function: 286 287 ```golang 288 package main 289 290 import ( 291 "testing" 292 293 "github.com/ks888/tgo/lib/tracer" 294 ) 295 296 func TestFib(t *testing.T) { 297 tracer.Start() 298 actual := fib(3) 299 tracer.Stop() 300 301 if actual != 2 { 302 t.Errorf("wrong: %v", actual) 303 } 304 } 305 ``` 306 307 ``` 308 % go test -v fib.go fib_test.go 309 === RUN TestFib 310 \ (#06) command-line-arguments.fib(0x3, 0x0) () 311 / (#06) command-line-arguments.fib(0x3, 0x2) () 312 --- PASS: TestFib (0.46s) 313 PASS 314 ok command-line-arguments 0.485s 315 ``` 316 317 Functions are traced as usual, but args are the entire args value, divided by pointer size. In this example, `\ (#06) command-line-arguments.fib(0x3, 0x0) ()` indicates 1st input args is `0x3` and the initial return value is `0x0`. Because it's difficult to separate input args from the return args without debugging info, all args are shown as the input args. This format imitates the stack trace shown in the case of panic. 318 319 If you want to show the args as usual, set `"-ldflags=-w=false"` to `GOFLAGS` environment variable so that the debugging info is included in the binary. For example: 320 321 ``` 322 % GOFLAGS="-ldflags=-w=false" go test -v fib.go fib_test.go 323 === RUN TestFib 324 \ (#18) command-line-arguments.fib(n = 3) (...) 325 / (#18) command-line-arguments.fib(n = 3) (~r1 = 2) 326 --- PASS: TestFib (0.55s) 327 PASS 328 ok command-line-arguments 0.578s 329 ``` 330 331 Note that GOFLAGS is not supported in go 1.10 or earlier. 332 333 #### Tips 334 335 There are some random tips: 336 * There are more options to change the tgo's behaviors. See the [godoc](https://godoc.org/github.com/ks888/tgo/lib/tracer) for details. 337 * When a go routine calls `tracer.Start()`, it means only that go routine is traced. Other go routines are not affected. 338 * Similarly, `tracer.Stop()` just stops the tracing of the go routine which called that function. 339 * Builtin functions are not traced. These functions are usually replaced with `runtime` package functions or assembly instructions.