概要
以下、自分用のメモです。特にGo限定の話では無くて、straceコマンドのメモです。
前回、以下のような記事をメモしました。
ついでなので、バッファリングする・しないという行為がシステムコール上で
どのようになるのかを確認してみましょう。プログラミングの参考書とかで「バッファリングしましょう」って書かれていたりしますが、実際にOS側に仕事をお願いする際に、どんな形で渡されているのか、つまり、どんな形でシステムコールされているのかを知るのって結構いい勉強になります。
サンプル
ヘルパー関数
以下のソースでは、出力する値を生成するために簡単なヘルパーメソッドを用意して使っています。
package enumerable func Range(start, count int) <-chan int { ch := make(chan int) go func() { defer close(ch) for i := start; i <= count; i++ { ch <- i } }() return ch }
バッファリングなし
まずは、バッファリング無しからです。Goの場合は *os.File をそのまま使うとバッファリング無しなので、それでやります。
コードは以下のようなものです。
package main import ( "fmt" "os" "github.com/devlights/go-syscall-with-strace/pkg/enumerable" ) func main() { file, err := os.Create("out.txt") if err != nil { panic(err) } defer file.Close() for v := range enumerable.Range(1, 10) { fmt.Fprintln(file, v) } }
go-syscall-with-strace/cmd/unbuffered at main · devlights/go-syscall-with-strace · GitHub
実行するためのタスクファイルは以下のような感じ。
いろいろ出ると分かりづらいので、writeシステムコールのみに絞り込みしてます。
version: '3' vars: APPNAME: ./app SYSCALLLOG: syscall.log COMMANDOUT: out.txt STRACEFILTER: openat,read,write,clone,close tasks: run-unbuffered: dir: cmd/unbuffered cmds: - go build -o {{ .APPNAME }} - strace -y -e write {{ .APPNAME }} 2>&1 1>/dev/null | tee {{ .SYSCALLLOG }}
実行すると以下のようになります。
$ task run-unbuffered task: [run-unbuffered] go build -o ./app task: [run-unbuffered] strace -y -e write ./app 2>&1 1>/dev/null | tee syscall.log --- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=16435, si_uid=33333} --- write(3</workspace/go-syscall-with-strace/cmd/unbuffered/out.txt>, "1\n", 2) = 2 write(3</workspace/go-syscall-with-strace/cmd/unbuffered/out.txt>, "2\n", 2) = 2 write(3</workspace/go-syscall-with-strace/cmd/unbuffered/out.txt>, "3\n", 2) = 2 write(3</workspace/go-syscall-with-strace/cmd/unbuffered/out.txt>, "4\n", 2) = 2 write(3</workspace/go-syscall-with-strace/cmd/unbuffered/out.txt>, "5\n", 2) = 2 write(3</workspace/go-syscall-with-strace/cmd/unbuffered/out.txt>, "6\n", 2) = 2 write(3</workspace/go-syscall-with-strace/cmd/unbuffered/out.txt>, "7\n", 2) = 2 write(3</workspace/go-syscall-with-strace/cmd/unbuffered/out.txt>, "8\n", 2) = 2 write(3</workspace/go-syscall-with-strace/cmd/unbuffered/out.txt>, "9\n", 2) = 2 write(3</workspace/go-syscall-with-strace/cmd/unbuffered/out.txt>, "10\n", 3) = 3 +++ exited with 0 +++
fmt.Fprintln で呼び出しを行った時点で即 writeシステムコール が呼び出されていますね。
バッファリングあり
次はバッファリングありで同じ出力をしてみます。
package main import ( "bufio" "fmt" "os" "github.com/devlights/go-syscall-with-strace/pkg/enumerable" ) func main() { file, err := os.Create("out.txt") if err != nil { panic(err) } defer file.Close() bufW := bufio.NewWriter(file) for v := range enumerable.Range(1, 10) { fmt.Fprintln(bufW, v) } defer bufW.Flush() }
go-syscall-with-strace/cmd/buffered at main · devlights/go-syscall-with-strace · GitHub
実行するためのタスクファイルは以下のような感じ。
いろいろ出ると分かりづらいので、writeシステムコールのみに絞り込みしてます。
version: '3' vars: APPNAME: ./app SYSCALLLOG: syscall.log COMMANDOUT: out.txt STRACEFILTER: openat,read,write,clone,close tasks: run-buffered: dir: cmd/buffered cmds: - go build -o {{ .APPNAME }} - strace -y -e write {{ .APPNAME }} 2>&1 1>/dev/null | tee {{ .SYSCALLLOG }}
実行すると以下のようになります。
$ task run-buffered task: [run-buffered] go build -o ./app task: [run-buffered] strace -y -e write ./app 2>&1 1>/dev/null | tee syscall.log --- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=16688, si_uid=33333} --- --- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=16688, si_uid=33333} --- --- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=16688, si_uid=33333} --- write(3</workspace/go-syscall-with-strace/cmd/buffered/out.txt>, "1\n2\n3\n4\n5\n6\n7\n8\n9\n10\n", 21) = 21 +++ exited with 0 +++
writeシステムコールの数がグッと減って一回になりました。塊にして渡していますね。これがバッファリングされている状態です。
100回やそこらの呼び出し程度ぐらいでは全然バッファリング無しでも問題ないことが多いですので、常にバッファリングすることを気にする必要は無いですが、塵も積もればなんとやらって感じで、たとえ１回の呼び出しが1msとかで済むものでも何万回もバッファリング無しで行うとボトルネックになる場合があります。そのような状態が計測で確認出来た場合は、バッファリングしたら劇的に改善する場合もあったりします。
参考情報
過去の記事については、以下のページからご参照下さい。
サンプルコードは、以下の場所で公開しています。
