goでchannelやgoroutineを試すサンプルコードを書く時に便利なログ出力にする方法
標準のlogパッケージの使いかたをちょっと変えるだけで便利な形式で出力できそうなのでメモ。
:warning:まずはじめに大前提として、これはgoの挙動を確認するためのサンプルコードを書いてみるときの話であって、実際にアプリケーションなりツールなりを作ろうとしたときの話ではない。
(なので実際の開発でどのような形式のログ出力が良いかだとか、オススメのロガーの設定はというような話でもなく、何か外部のライブラリを使うと便利という話ではない)
準備
ちょっとだけlogパッケージの機能について触れる。既に分かっている人は読み飛ばしても良い。
defaultの出力
デフォルトでなにも考えずにlog出力をしてみたときには以下のような出力になる。
log.Println("hello")
出力結果
2018/12/20 06:59:38 hello
デフォルトでは以下の様な形式で出力される。
<date> <log message>
logに渡すオプション
よくあるログライブラリと同様に少しだけ出力内容を変えることができる。
ちなみにlog.Println()という呼び出しはpackage内に保持したloggerを利用するショートカット。
log.go
var std = New(os.Stderr, "", LstdFlags) func Println(v ...interface{}) { std.Output(2, fmt.Sprintln(v...)) }
ここで LstdFlagsは Ldate | Ltime の意味。実際に利用できるオプションに以下のようなものがある。
const ( Ldate = 1 << iota // the date in the local time zone: 2009/01/23 Ltime // the time in the local time zone: 01:23:23 Lmicroseconds // microsecond resolution: 01:23:23.123123. assumes Ltime. Llongfile // full file name and line number: /a/b/c/d.go:23 Lshortfile // final file name element and line number: d.go:23. overrides Llongfile LUTC // if Ldate or Ltime is set, use UTC rather than the local time zone LstdFlags = Ldate | Ltime // initial values for the standard logger )
幸い、log packageが保持したloggerのオプション設定を変えるショートカットも用意されている。
// SetFlags sets the output flags for the logger. func (l *Logger) SetFlags(flag int) { l.mu.Lock() defer l.mu.Unlock() l.flag = flag }
channelやgoroutineなどを使ったサンプルコード用の出力について
ここからが本題。実はちょっとした手間でchannelやgoroutineなどを利用するサンプルコードに適した表現に変えることができる。自分の理解のためのメモ書き程度のサンプルコードを書いて試してみるときに参考になるかもしれない。
ログ出力の分解能を上げて実行時間を短くする
デフォルトのログ出力では日付と時刻程度しかわからない。そして時刻の分解能が1秒単位なので、ついついサンプルコードに取り入れるwaittimeも１秒単位で指定してしまいがち。 例えば以下の様な形に。
package main import ( "log" "time" ) func main() { if err := run(); err != nil { log.Fatalf("%+v", err) } } func run() error { log.Printf("hello") time.Sleep(1 * time.Second) log.Printf("bye") return nil }
出力結果
$ time go run main.go 2018/12/20 07:14:50 hello 2018/12/20 07:14:51 bye real 0m1.198s user 0m0.191s sys 0m0.057s
ログ出力の分解能を上げてあげれば、わざわざ１秒待つ必要もない。例えば100ミリ秒にする。
--- 00stdlog/main.go 2018-12-20 07:12:04.519056801 +0900 +++ 01stdflags/main.go 2018-12-20 07:17:52.012278508 +0900 @@ -6,6 +6,7 @@ ) func main() { + log.SetFlags(log.Lmicroseconds) if err := run(); err != nil { log.Fatalf("%+v", err) } @@ -13,7 +14,7 @@ func run() error { log.Printf("hello") - time.Sleep(1 * time.Second) + time.Sleep(100 * time.Millisecond) log.Printf("bye") return nil }
実行時間を短くできる。
07:20:22.480065 hello 07:20:22.580553 bye real 0m0.287s user 0m0.181s sys 0m0.050s
メッセージの位置を表示する
ついでに出力の位置自体も表示してくれると嬉しい。先ほどと同様にオプションを追加する。
これはサンプルコードに限らずprint debugをしているときにも有用かもしれない。例えばわざわざメッセージを変えて出力していた部分があるとする(後々消すことになる)。
t := time.Now() fmt.Println(t, "start xxxx") doSomething() fmt.Println(t - time.Now(), "end xxxx")
この部分の記述にわざわざメッセージを変えるのが面倒に感じることがある(どうせ消すので)。最悪Lshortfileを加えて、以下だけで済む。
log.Println("tick")
doSomething()
log.Println("tick") // 同じメッセージではあるけれど行数を確認できる
これを踏まえて、コードの位置も追加すると便利。
+++ 02with-shortfile/main.go 2018-12-20 07:26:41.252069947 +0900 @@ -6,7 +6,7 @@ ) func main() { - log.SetFlags(log.Lmicroseconds) + log.SetFlags(log.Lmicroseconds | log.Lshortfile) if err := run(); err != nil { log.Fatalf("%+v", err) }
出力結果
07:26:51.089306 main.go:16: hello 07:26:51.189609 main.go:18: bye
(おまけ) goroutine idも表示してみる
ついでに、goroutine idも一緒に表示できると便利かもしれない。例えば以下の様なgoroutineのコードを実行するときなどにどのgoroutineで動作しているか分かると理解のためには便利。
通常は自分でIDなどを付与してあげないとどのgoroutineが処理をしているかがわからないので（厳密に言えばどのgoroutineで動作しているかという話とコード上のどのタスク(頭の中)が処理しているかは別物ではあるけれど）。
var wg sync.WaitGroup for i := 0; i < 5; i++ { wg.Add(1) go func() { defer wg.Done() log.Println("hello") }() } wg.Wait()
出力結果
07:48:30.099717 main.go:21: hello 07:48:30.099696 main.go:21: hello 07:48:30.099740 main.go:21: hello 07:48:30.099749 main.go:21: hello 07:48:30.099745 main.go:21: hello
幸い、loggerは内部で利用しているio.Writerも変えられるので、以下の様なコードを追加することで、無理やりgoroutine idを付加させることもできなくはない。 (:warning: 内部的にはstopTheWorld()などが呼ばれているので注意。簡単にgoroutine idを取り出せない理由はhttps://qiita.com/ruiu/items/3574ac383f750bf95042)
type withGoroutineID struct { out io.Writer } func (w *withGoroutineID) Write(p []byte) (int, error) { // goroutine <id> [running]: firstline := []byte(strings.SplitN(string(debug.Stack()), "\n", 2)[0]) return w.out.Write(append(firstline[:len(firstline)-10], p...)) }
このwithGoroutineIDをsetOutput()で書き換えて使う。
diff -u 03goroutine/main.go 04withgoroutine/main.go --- 03goroutine/main.go 2018-12-20 07:48:23.878165771 +0900 +++ 04withgoroutine/main.go 2018-12-20 07:43:41.521625136 +0900 @@ -1,12 +1,26 @@ package main import ( + "io" "log" + "os" + "runtime/debug" + "strings" "sync" ) +type withGoroutineID struct { + out io.Writer +} + +func (w *withGoroutineID) Write(p []byte) (int, error) { + // goroutine <id> [running]: + firstline := []byte(strings.SplitN(string(debug.Stack()), "\n", 2)[0]) + return w.out.Write(append(firstline[:len(firstline)-10], p...)) +} + func main() { - log.SetFlags(log.Lmicroseconds | log.Lshortfile) + log.SetOutput(&withGoroutineID{out: os.Stderr}) if err := run(); err != nil { log.Fatalf("%+v", err) }
実行結果
goroutine 22 2018/12/20 07:53:18 hello goroutine 18 2018/12/20 07:53:18 hello goroutine 19 2018/12/20 07:53:18 hello goroutine 20 2018/12/20 07:53:18 hello goroutine 21 2018/12/20 07:53:18 hello
goroutine idが付加されている。
ついでに数が少ないなら色を変えてみても良いかもしれない。
最終的なコード
最終的なコードは以下。
package main import ( "io" "log" "os" "runtime/debug" "strings" "sync" ) type withGoroutineID struct { out io.Writer } func (w *withGoroutineID) Write(p []byte) (int, error) { // goroutine <id> [running]: firstline := []byte(strings.SplitN(string(debug.Stack()), "\n", 2)[0]) return w.out.Write(append(firstline[:len(firstline)-10], p...)) } func main() { log.SetOutput(&withGoroutineID{out: os.Stderr}) if err := run(); err != nil { log.Fatalf("%+v", err) } } func run() error { var wg sync.WaitGroup for i := 0; i < 5; i++ { wg.Add(1) go func() { defer wg.Done() log.Println("hello") }() } wg.Wait() return nil }
