Goのロギングライブラリから見たゼロアロケーション

はじめに

UZOUという広告配信プラットフォームでバックエンドエンジニアをしている@muroon01です。

Goのロギングライブラリであるzerolog, zapは(使用法によりますが)ゼロアロケーションであると言われています。 そこでゼロアロケーションのロギングライブラリとは一体どのようなつくりなのか、またGoのソースをゼロアロケーションにする方法について記述していきたいと思います。

ゼロアロケーションとは？

(メモリ)アロケーションとはプログラムが動作するのに必要なメモリの割り当てを意味しており、スタック領域へのもの(静的アロケーション)とヒープ領域へのもの(動的アロケーション)が存在します。

スタック領域へのメモリの割当は割当サイズおよび確保・解放されるタイミングがプログラムの記述時に静的に決まります。

一方、ヒープ領域は宣言時にメモリの最大割当サイズを指定せずに、プログラム実行時に状況に応じてメモリ確保でき、ガーベッジコレクタによりメモリが解放されます。よってスタック領域に比べてパフォーマンスが落ちます。

ここで言うゼロアロケーションとは後述するGoのベンチマークテストにおけるallocs/opがゼロであることを指します。allocs/opはベンチマークテストの1オペレーションあたりのメモリアロケーションの量で、これを抑えるにはヒープ領域へのメモリアロケーション(動的アロケーション)を抑えることが重要になります。

Goではコンパイル時にエスケープ分析と呼ばれる手法を使って、スタック領域への割り当てとヒープ領域への割り当てを選択します。

アロケーションをチェックする方法

Goによるアプリケーションのメモリアロケーションをチェックする方法として下記の3つが存在します。

チェック方法	内容
go test -bench	ベンチマークテストを実施。オペレーション総実行回数、オペレーションあたりのメモリ使用量とアロケーションを表示
go build -gcflags '-m'	コンパイル時に実施されるエスケープ解析の結果を表示
pprof	GoのプロファイルングツールでCPU, メモリプロファイルが可能

go test -benchにてベンチマークテストによる結果を得られます。58056385はオペレーション総実行回数、ns/opは1オペレーションあたりの実行時間、B/opは1オペレーションあたりのメモリ消費量、allocs/opは1オペレーションあたりのメモリアロケーションの量です。

$ go test -bench .
BenchmarkEvent-16       58056385            21.30 ns/op        8 B/op          1 allocs/op

go build -gcflags '-m'を使用するとエスケープ解析の結果が得られ、どこでアロケーションが発生するかがわかります。

$ go build -gcflags '-m' .
# command-line-arguments
    :
./event.go:68:7: &event{...} escapes to heap
./event.go:68:23: make([]byte, 0, 500) escapes to heap

またgo build -gcflags '-m -m'のように-gcflagsの-mを複数回重ねることができ、更に詳細な情報が得られます。

ゼロアロケーションロギングライブラリのつくり

それでは簡単なロギングライブラリを例にGoでヒープ領域へのメモリ割り当てを行わないつくりにする方法を見ていきたいと思います。

• go 1.17,go 1.18 環境
• source code

Goのロギングライブラリで求められる最低限の仕様

• Levelによる操作
  • 出力先を制御
  • Fatalレベルの場合は出力後にos.Exit(1)を実施する
• 出力方法を設定できるようにする
  • 標準出力
  • ファイル出力
  • リモートへ送信
• 外部からgoroutineで実行されることを考慮する

求められるつくり

• 外部から出力するデータを受け付けるインターフェイスはなるべくシンプルにする
  • 例えばInfoログを出力するメソッドはInfoという名前の1つのfuncを実行すると書き込みまで完了するようにする。
    • ロギングライブラリの初期設定は別途予め行っておく
    • goroutineで呼ばれても1つのfuncで完結していればrace状態にはならず問題ない
• 出力データなどロギングイベント情報はstructにまとめる

以上のことを踏まえると、ロギングライブラリ内部ではログの出力内容に関わる情報を保持するstructを設け、出力処理に渡す構成がよく使用されます。

最もシンプルな例

上記を踏まえた最もシンプルな例として下記のようなソースを考えます。

var LogWriter io.Writer // ログの出力(使用時に外部から指定可能)

// event
type event struct {
    buf   []byte         // ログmsgなど出力内容
    level Level          // ログLevel
    done  func(b []byte) // ログ出力用完了channel (Panic, Fatal用)
}

func (e event) write() {
    if e.done != nil {
        defer e.done(e.buf)
    }
    LogWriter.Write(e.buf)
}

func newEvent(buf []byte, level Level, done func(b []byte)) *event {
    return &event{
        buf:   buf,
        level: level,
        done:  done,
    }
}

// Infoレベルの出力
func Info(msg string) {
    e := newEvent([]byte(msg), InfoLevel, nil)
    e.write()
}

// Fatalの出力
func Fatal(err error) {
    e := newEvent([]byte(err.Error()), FatalLevel, fatalFunc)
    e.write()
}

func fatalFunc(b []byte) { os.Exit(1) }

ここでベンチマークテストで使用時のメモリアロケーションを調べてみます。

func BenchmarkEvent(b *testing.B) {
    LogWriter = testWriter
    b.ReportAllocs()
    b.ResetTimer()

    b.RunParallel(func(pb *testing.PB) {
        for pb.Next() {
            Info("test")
        }
    })
}

ベンチマークテストの結果からメモリーアロケーションが発生しています。 さらに-gcflags '-m'でビルドするとnewEvent funcでeventインスタンス生成時にヒープメモリにアロケーションすることがわかります。

$ go test -bench .
BenchmarkEvent-16       58056385            21.30 ns/op        8 B/op          1 allocs/op

$ go build -gcflags '-m' event.go
    :
./event.go:42:9: &event{...} escapes to heap

sync.Poolを使って動的アロケーションを抑える

sync.Poolを使ってevent.bufをなるべくを使い回すようにします。

var eventPool = &sync.Pool{
    New: func() interface{} {
        return &event{
            buf: make([]byte, 0, 500),
        }
    },
}

func newEvent(buf []byte, level Level, done func(b []byte)) *event {
    e := eventPool.Get().(*event)
    e.buf = e.buf[:0]
    e.buf = append(e.buf, buf...)
    e.level = level
    e.done = nil
    if done != nil {
        e.done = done
    }
    return e
}

func putEvent(e *event) {
    eventPool.Put(e)
}

// Infoレベルの出力
func Info(msg string) {
    e := newEvent([]byte(msg), InfoLevel, nil)
    e.write()
    putEvent(e)
}

// Fatalの出力
func Fatal(msg string) {
    e := newEvent([]byte(err.Error()), FatalLevel, fatalFunc)
    e.write()
    putEvent(e)
}

ここで変更していることはsync.Poolを使ってevent structをGet, Putしているところとeventのbufフィールドに代入を行わずにzeroにしてからappendしているところです。

1. sync.Poolを使ってevent structをGet, Putしている
2. eventのbufフィールドに代入を行わずにlenをzeroにしてからappendしている

もう少し詳しく見ていきますと

まずeventインスタンスをPoolするsync.Poolを定義します。ここではNew func定義でbufフィールドの初期のcapacityは500byteに設定します。

var eventPool = &sync.Pool{
    New: func() interface{} {
        return &event{
            buf: make([]byte, 0, 500),
        }
    },
}

newEvent funcでsync.PoolよりeventインスタンスをGetし、取得したevent.bufのlengthを0にした後に、bufの中身をappendしていきます。

func newEvent(buf []byte, level Level, done func(b []byte)) *event {
    e := eventPool.Get().(*event)
    e.buf = e.buf[:0]
    e.buf = append(e.buf, buf...)

write()実行後にeventPool.Putを実施します。

func Info(msg string) {
    e := newEvent([]byte(msg), InfoLevel, nil)
    e.write()
    putEvent(e)     // 内部でeventPool.Put(e)

以上で500byte以内のメッセージであれば新たにアロケーションされることなくログを出力し続けることができます。

先程と同じベンチマークテストを実施すると、オペレーション毎のアロケーションがゼロになっていることがわかります。

BenchmarkEvent-16        54997969            19.17 ns/op        0 B/op          0 allocs/op

厳密には全くアロケーションが起きていないわけではなく、エスケープ分析の結果を見ていると下記のようにヒープ領域へエスケープしている結果が見られます。

$ go build -gcflags '-m' event.go
    :
./event.go:53:10: &event{...} escapes to heap
./event.go:54:13: make([]byte, 0, 500) escapes to heap

ただこれはどちらもsync.PoolのNew func(eventポインタ生成と[]byteの生成)内の処理を指します。sync.Poolにより再利用されていることによりベンチマークテストにてオペレーション単位ではほぼゼロになることがわかります。

zerologやzap

上記のロギングライブラリとzerolog, zapでは外部インターフェイス(LogWriterなどの各種設定や各レベルのログイベントの書き込みの指定)の構成が異なります。特にzerologではメソッドチェーンでロギングイベントstructを引き回す構成になってます。ただしロギングイベントstructを設け、sync.Poolを使用しているところはzerolog, zap同じになっています。

• zerolog
  • Event struct
  • event Pool
• zap
  • zapcore.Entry struct
  • buffer Pool
    • こちらでキャストして使用している

もう少しGoのゼロアロケーションについて見ていく

上記はものすごく単純な例ですが、実際には出力メッセージ以外でもTime情報だったり他の情報をevent structのフィールドに持たせたくなるケースが生じると思います。

ただここで注意が必要なのはsync.Poolを使えばなんでもゼロアロケーションになるかというとそういうわけではなく、いくつかの注意が必要です。

ポインタは使用しない

• ポインタ変数の新たな宣言が存在すると動的アロケーションの原因となりえる
  • よって今回のロギングライブラリの例で言えば、eventポインタはsync.Poolの対象にして再利用する
• event structにはポインタフィールドは持たない

sliceを使用する場合

• sliceを初期化するタイミングで動的アロケーションが発生する
• sliceにappendする場合はcapacityを超えると新たなアロケーションが発生する
• slice型の変数、フィールドに新たにslice型の変数を代入しても新たなアロケーションが発生する
• 配列(要素数固定)が使用できるなら配列にするのが理想的

sliceのアロケーションの特性としては上記の通りです。sliceを繰り返し使う場合はeventPoolの例の通りsync.PoolのNew funcでcapacityを設けてsync.PoolからGetした後にsliceのlengthを0にした後にappendして使用すると良いです。

無名関数の使用も動的アロケーションが発生する

無名関数の定義・使用時に動的アロケーションが発生します。都度使うような処理内では避けたほうが良いかと思います。

下記のようにFatal内に無名関数にて定義した場合、エスケープ分析でfunc literal escapes to heapが現れます。

func Fatal(err error) {
    e := newEvent(
        []byte(err.Error()), 
        FatalLevel, 
        func(b []byte) { os.Exit(1) },
    )
    e.write()
}

# result of go build -gcflags '-m'
./event.go:99:3: func literal escapes to heap

time.Timeは内部でポインタを使用している

Location(タイムゾーン情報)ポインタをフィールドで持っているので、タイムゾーン関連で注意が必要です。

time.Time関連で新たな動的アロケーションが発生するのは、事前で定義されていない(UTC, Local以外の)Locationを新たに定義し利用する場合です。

tm = time.Time{} // no allocation

tm = time.Now().In(time.UTC) // no allocation

utc, _ := time.LoadLocation("UTC") // no allocation
tm = time.Now().In(utc) // no allocation

local, _ := time.LoadLocation("Local") // no allocation
tm = time.Now().In(local) // no allocation

tm = time.Now().In(time.Local) // no allocation

jst, _ := time.LoadLocation("Asia/Tokyo") // allocation occurs
tm = time.Now().In(jst)

都度発生する処理の中でtime.LoadLocation("Asia/Tokyo")を実施するのではなくJST用Locationは事前に定義しておき代入することをおすすめします。(事前にtime.Localに代入するほうがさらに良いです)

また、time.Timeでなく別の型に変換して扱う方法もあると思います。

• Unix Timeの整数で扱う
• byteに変換して扱う
  • func (Time) AppendFormatを使用してbyteに変換すると引数のcapacityが足りていれば直接書き込みを行い新たなメモリアロケーションを避けられる
  • zerolog上での使用法

interfaceについて

interfaceの使用についても触れておきたいと思います。ログライブラリとしては必要ありませんが、上記のsync.Poolを使ったコードをあえて下記のようにeventInterface interfaceとして扱った場合を検証しました。

type eventInterface interface {
    write()
}

func newEventInterface(buf []byte, level Level, done func(b []byte)) eventInterface {
    return newEvent(buf, level, done) // sync.Pool Getを実施
}

func putEventInterface(e eventInterface) {
    if _, ok := e.(*event); !ok {
        panic("invalid type")
    }
    eventPool.Put(e)
}

func Info(msg string) {
    e := newEventInterface([]byte(msg), InfoLevel, nil)
    e.write()
    putEventInterface(e)
}

ベンチマークテストの結果です(※go1.17, go1.18環境下)。上がevent structのみを使用したもの。下がinterfaceを使用したものです。結果的にはアロケーションは見当たりませんでした。

BenchmarkEvent-16                         63091771                17.45 ns/op            0 B/op          0 allocs/op
BenchmarkEventWithInterface-16            61353092                17.18 ns/op            0 B/op          0 allocs/op

またgo build -gcflags '-m'の結果もpanicの引数のcastのアロケーションなのでinterface使用自体のアロケーションの増加は見当たりませんでした。

./interface.go:13:8: "invalid type" escapes to heap

GoのVersionによってメモリアロケーションは変わる

Goのアロケーションのルールは言語仕様では規定されていません。GoのバージョンUpにおけるコンパイラの修正によりアロケーション周りの状況は変化します。

上記のinterfaceの例でsync.Poolを使わない場合も含めて比較しました。

go version	sync.Pool使用のB/op	sync.Pool使用のallocs/op	sync.Pool不使用のB/op	sync.Pool不使用のallocs/op
go 1.17	0	0	8	1
go 1.13	0	0	56	2

sync.Poolを使用しないでinterfaceを使用した場合はアロケーションが増加していることがわかりますが、注目なのはGoのバージョンによってさらにアロケーションが増減することがわかります。

またsync.Pool不使用時のエスケープ分析を見てみると、Goのバージョンによって結果が変わっていることもわかります。

# go 1.17
normallog/interface.go:8:17: &event{...} escapes to heap
normallog/interface.go:13:31: ([]byte)(msg) escapes to heap

# go 1.13
normallog/interface.go:8:17: newEvent(buf, level, done) escapes to heap
normallog/interface.go:8:17: &event literal escapes to heap
normallog/interface.go:13:31: ([]byte)(msg) escapes to heap
normallog/interface.go:13:24: newEvent(buf, level, done) escapes to heap
normallog/interface.go:13:24: &event literal escapes to heap

おわりに

改めて今回のおさらいとしては下記の通りです。

• ロギングイベント情報はstructにまとめてsync.Poolに格納・取得し使用する
• slice型を使用する場合は、特定の大きさのcapacityを設けて、sync.PoolのNew func内で生成する。Get後にlengthを0にしてからappendして再利用する
• sync.Poolへの格納対象以外でポインタは使わない。また格納対象struct内にもポインタフィールドは設けない
• 都度発生するような処理の中では無名関数の利用は避ける
• time.Timeはタイムゾーン情報にポインタを使用している
  • UTC, Local以外のタイムゾーンを使用する際にはログ使用前に定義しておく
  • UnixTImeの整数もしくは[]byteに変換
• interfaceの使用自体には動的アロケーションは見られないが、実装対象はsync.Poolをする
• GoのVersionによってメモリアロケーションは大きく変わる

ロギングライブラリの用途以外でもプロセス中も大量の要素が生成・消滅するプロセスなどで参考にしていただけるのではないかと思ってます。

ただ、特徴の認識だけで動的アロケーション回避するソースコードを書くのはコンパイラの中身を理解している方でもないと難しいと思います。実際にエスケープ解析を実施すると動的アロケーションが発生するか否かはコードの書き方によって非常に繊細に変化する場合もあります。

また上記で記載したとおり、Goのアロケーションのルールは言語仕様では規定されているわけではありません。

本記事はgo 1.17,go 1.18環境で こちらを実施した実績とzap, zerologをもとに記載しております。一実績の参考にしていただいた上で、アロケーションのチェックしていただければと思います。

We are hiring!!

現在、UZOUではAWS上にGoを始めとしてPython, Ruby, TypeScript, JavaScriptを使用して開発を行っており、これらに通じた方や今後実施してみたいと思う方を募集中です。

本ブログはUZOUのロギングライブラリについて調べていく過程で書かせていただきました。またAthenaを使用したUZOUのデータ基盤について書かれたこちらもよろしければご覧ください。