sgykfjsm.github.com

Goでfunctionが実行された順番を追いかける

Goはgo routineを使って並行処理を容易に書くことができるが、下手に書くと色々なfunctionが相互に入り乱れて処理が追いづらいときがある。ここではGoでfunctionをトレースする方法をメモしておく。

結論から言えば、runtime.Callerを使えば良い。なお、debug.PrintStackでstack traceを出力することができるが、標準エラー出力となるのでちょっと使いづらい。しかし、ただコンソールで出力したいだけなら、debug.PrintStackのほうが簡単であるし、これ以降を読む必要は無い。

簡単な使い方

runtime.Callerとは何なのかはマニュアルを参照すべきだけど、簡単に言うと、引数の数値に応じてCallerが呼び出された時点での呼び出し元の情報を提供してくれるfunctionと言える。例えば、以下のような処理を想定してみる。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
package main

import (
  "log"
  "runtime"
)

func doCaller() {
  programCounter, sourceFileName, sourceFileLineNum, ok := runtime.Caller(1)
  log.Printf("programCounter: %v\n", programCounter)
  log.Printf("souruntime: %s\n", sourceFileName)
  log.Printf("sourceFileLineNum: %d\n", sourceFileLineNum)
  log.Printf("ok: %t\n", ok)
}

func callCaller() {
  doCaller()
}

func main() {
  callCaller()
}

https://play.golang.org/p/X_tDUvfR7s

上記の場合、処理はmain -> callCaller -> doCallerの順で実行され、この順番でgoroutineのstackにfunctionが積み上がる(正確にはmainの前にruntime.mainruntime.goexitが呼び出されているがここでは省略する)。runtime.Callerの引数はskip intと定義されているが、イメージとしては配列のインデックスみたいな感じで、stackの上から何番目の情報を取得するか、を指定することができる。上記の場合、1を指定しているので、callCallerの情報を取得することができる。結果は以下の通り。なんかタイムスタンプがおかしい気がするが、気にしない。

1
2
3
4
2009/11/10 23:00:00 programCounter: 132352
2009/11/10 23:00:00 souruntime: /tmp/sandbox627002569/main.go
2009/11/10 23:00:00 sourceFileLineNum: 17
2009/11/10 23:00:00 ok: true

変数名から何となく推測できると思うけど、runtime.Callerの返り値の1つ目はプログラムカウンター、2つ目がビルドされたソースファイル名(実行ファイル名では無いことに注意)、3つ目はソースファイル内での呼びだされた位置、4つ目は情報が取得できたか否かを示すbooleanとなっている。

これだけだと、どの関数から呼ばれたか?がわからないので、もう少し処理を追加してみる。使うfunctionはFuncForPCだ。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
package main

import (
  "log"
  "runtime"
  "strings"
)

func doCaller() {
  programCounter, sourceFileName, sourceFileLineNum, ok := runtime.Caller(1)
  log.Printf("programCounter: %v\n", programCounter)
  log.Printf("souruntime: %s\n", sourceFileName)
  log.Printf("sourceFileLineNum: %d\n", sourceFileLineNum)
  log.Printf("ok: %t\n", ok)

  println("-----")

  fn := runtime.FuncForPC(programCounter)
  log.Printf("Function Name: %s\n", fn.Name())
  fileName, fileLine := fn.FileLine(programCounter)
  log.Printf("FileName:%s, FileLine: %d\n", fileName, fileLine)

  splitedFnName := strings.Split(fn.Name(), ".")
  packageName := splitedFnName[0]
  callerFuncName := splitedFnName[1]
  log.Printf("packageName: %s\n", packageName)
  log.Printf("functionName: %s\n", callerFuncName)

}

func callCaller() {
  doCaller()
}

func main() {
  callCaller()
}

https://play.golang.org/p/sFMnwYTHYF

結果は以下の通り。

1
2
3
4
5
6
7
8
9
2009/11/10 23:00:00 programCounter: 134432
2009/11/10 23:00:00 souruntime: /tmp/sandbox246241909/main.go
2009/11/10 23:00:00 sourceFileLineNum: 32
2009/11/10 23:00:00 ok: true
-----
2009/11/10 23:00:00 Function Name: main.callCaller
2009/11/10 23:00:00 FileName:/tmp/sandbox246241909/main.go, FileLine: 33
2009/11/10 23:00:00 packageName: main
2009/11/10 23:00:00 functionName: callCaller

FuncForPCは引数で受け取ったプログラムカウンターの詳細な情報を返してくれる。見ての通り、Callerで取得したプログラムカンターから呼び出し元のfunction名、ファイル情報諸々を取得することができる。

このように、CallerFuncForPCを使うことで、ある関数がどこから呼び出されたのかを知ることができる。

もう1歩踏み込んでみる

実際にデバッグする際には、最初のエントリーポイントからエラーが発生したfunctionまでを順に辿りたいことある。上記のdoCallerを全ての関数にdeferで登録しておけば出来なくはないが、そんなことはしたくないはず。通常はlog.Fatalなどでプログラムを終了させる直前とかに呼び出し情報を取得できるようにしておきたいはず。要は呼び出し情報をまとめて取得して、良い感じに扱いたいのだ。

とても安直な発想だが、Callerの引数を1つずつインクリメントしてたどる方法をここでは試してみる。例えば以下の様な感じ。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
package main

import (
  "fmt"
  "regexp"
  "runtime"
)

var (
  re = regexp.MustCompile(`^(\S.+)\.(\S.+)$`)
)

type CallerInfo struct {
  PackageName  string
  FunctionName string
  FileName     string
  FileLine     int
}

func Dump() (callerInfo []*CallerInfo) {
  for i := 1; ; i++ {
      pc, _, _, ok := runtime.Caller(i) // https://golang.org/pkg/runtime/#Caller
      if !ok {
          break
      }

      fn := runtime.FuncForPC(pc)
      fileName, fileLine := fn.FileLine(pc)

      _fn := re.FindStringSubmatch(fn.Name())
      callerInfo = append(callerInfo, &CallerInfo{
          PackageName:  _fn[1],
          FunctionName: _fn[2],
          FileName:     fileName,
          FileLine:     fileLine,
      })
  }
  return
}

func foo() {
  info := Dump()
  for i := len(info) - 1; i > -1; i-- {
      v := info[i]
      fmt.Printf("%02d: %s.%s@%s:%d\n", i, v.PackageName, v.FunctionName, v.FileName, v.FileLine)
  }
}

func bar() {
  foo()
}

func main() {
  bar()
}

https://play.golang.org/p/iED00tQ9EW

上記を実行すると、以下の様にスタックの下から、つまりfunctionが実行された順番に表示される。

1
2
3
4
5
04: runtime.goexit@/usr/local/go/src/runtime/asm_amd64p32.s:1133
03: runtime.main@/usr/local/go/src/runtime/proc.go:120
02: main.main@/tmp/sandbox266928852/main.go:55
01: main.bar@/tmp/sandbox266928852/main.go:51
00: main.foo@/tmp/sandbox266928852/main.go:42

余談

Callergoroutineのstackに積み上げられた情報を出力するため、対象の処理にgo xxx()go funcが含まれていると、上記のように必ずしもruntime.goexit->runtime.mainの順番で始まるとは限らないことに注意すること。例えば、以下の様な感じ。

1
2
3
4
5
6
7
8
9
func main() {
  var wg sync.WaitGroup
  wg.Add(1)
  go func() {
      bar()
      wg.Done()
  }()
  wg.Wait()
}

https://play.golang.org/p/WZE3lItf8h

上記の結果は以下の通りで、runtime.mainが無いことがわかる。これはgo funcfunc mainとは異なるgoroutineで処理されていることを示している(と思う)。

1
2
3
4
03: runtime.goexit@/usr/local/go/src/runtime/asm_amd64p32.s:1133
02: main.main.func1@/tmp/sandbox306261972/main.go:59
01: main.bar@/tmp/sandbox306261972/main.go:52
00: main.foo@/tmp/sandbox306261972/main.go:43

また、次の場合は同じ関数をclosureでラップせずにgoroutineとして起動した場合。

1
2
3
4
func main() {
  go bar()
  time.Sleep(1 * time.Second)
}

https://play.golang.org/p/CcNp-Do9mb

結果は以下の様になる。

1
2
3
02: runtime.goexit@/usr/local/go/src/runtime/asm_amd64p32.s:1133
01: main.bar@/tmp/sandbox385327178/main.go:52
00: main.foo@/tmp/sandbox385327178/main.go:43

go funcの場合と違って、closureを経由せずに、bar以降の処理を別のgoroutineとして起動させていることがわかる。

ちゃんとわかっている人からすれば当然のことに思われるだろうが、自分のようなGo初心者だと出力内容を見て、アレ?と思うかもしれないので、goroutineを使う処理のstack情報を取得する場合は注意すること。