Deep dive into log/slog package

by Pana

Slide 1

Slide 1 text

Deep dive into log/slog package Pana@Go Conference mini 2023 Winter IN KYOTO

Slide 2

Slide 2 text

本日のトークの内容 ● 自己紹介 ● log/slogパッケージの概要 ● 基本的なAPI ● パフォーマンスに関して

Slide 3

Slide 3 text

自己紹介 ● 宮鼻 (Pana) ● 株式会社SODAでWebエンジニア ○ 2年くらいGoを書いている ○ Zennに記事を書いている ● 好き ○ コーヒー ☕ ○ つけ麺 ● GitHub ○ k3forx

Slide 4

Slide 4 text

本日話すこと/話さないこと ● 話すこと ○ log/slogが実装/導入された背景や目的 ○ 公開されているAPIの概要/内部のアーキテクチャ ○ パフォーマンス観点での詳細な実装/設計 ● 話さないこと ○ log/slogのAPIの詳細な使い方 ○ Webアプリケーションとの連携

Slide 5

Slide 5 text

log/slogパッケージの概要

Slide 6

Slide 6 text

log/slogパッケージとは ● Go1.21のリリースで開発された構造化ログのための標準ライブラリ ○ 現時点 (2023/11時点) ではテキスト形式とJSON形式での出力をサポートしている ● 他のロギングパッケージは？ ○ logrus, zap, zerologなど色々ある

Slide 7

Slide 7 text

なぜlog/slogパッケージが開発された？ ● 色々なパッケージが開発された結果 ○ 巨大なアプリケーションでは依存関係を通して様々なロギングパッケージに依存している ● 何を解決したかった？ ○ ログを統一的に扱えるようできる ○ ユーザーがカスタマイズ可能な ”バックエンド” を定義した ○ 将来的に色々なロギングパッケージがこの “バックエンド” を受け付ける (実装する) ようになることを期待 ○ より高品質なバックエンドを作成するためにGoのコミュニティが協力し合える ○ 詳細は Proposal: Structured Logging#what-does-success-look-like に記載がある

Slide 8

Slide 8 text

基本的なアーキテクチャ ● Logger構造体 ○ ユーザー (開発者) から呼ばれる関数を定義 ○ Record構造体を生成しHandlerにわたす ● Record構造体 ○ ログの内容を構造体として保持する ● Handlerインターフェイス ○ Record構造体を受け取り処理する

Slide 9

Slide 9 text

基本的なAPI (使い方)

Slide 10

Slide 10 text

Infoメソッドをみてみる Output: ● time, levelが出力 (デフォルト) ● 第一引数はmsgのvalueとして出力 (デフォルト) ● その後の引数はkey-valueとして出力 (なくても良い) ソースの位置の出力有無などが設定できる

Slide 11

Slide 11 text

内部の構造を見てみる 1. Record構造体を生成 + argsを追加 2. Hanlderインターフェイスに渡すログレベル

Slide 12

Slide 12 text

同じ情報を固定で出力させる Output: ● Withメソッドを使えば同じメッセージを出力できる

Slide 13

Slide 13 text

同じような情報をまとめて出力 Output: ● WithGroupメソッドを使えば、オプションのkey-valueをまとめて出力できる

Slide 14

Slide 14 text

パフォーマンスに関して

Slide 15

Slide 15 text

随所に現れるパフォーマンスを意識した設計 ● log/slogでいうパフォーマンスとは？ ○ 主にメモリアロケーションのこと ○ つまり、メモリのアロケーションをできるだけ少なくしている

Slide 16

Slide 16 text

どこに現れるか？ ● 色々な構造体/インターフェイス/型に現れている！！ ○ Logger構造体 ○ Handlerインターフェイス ○ Record構造体 ■ Add関数 ○ Attr (Value) 構造体 ○ etc…

Slide 17

Slide 17 text

どこに現れるか？ ● 色々な構造体/インターフェイスに現れている！！ ○ Logger構造体 ○ Handlerインターフェイス ○ Record構造体 ⭐ ■ Add関数 ⭐ ○ Attr (Value) 構造体 ⭐ ○ etc…

Slide 18

Slide 18 text

関数の呼び出し (インライン展開) ● インライン展開とは？ ○ 関数を呼び出す側に呼び出される側の関数のコードを展開し、関数への制御転送をしないようにする方法。これにより関数呼び出しに伴うオーバーヘッドを削減する (Wikipediaより抜粋) ● コンパイラがいい感じにインライン展開してくれる ● インライン展開できるかどうかは細かい条件がある ○ https://github.com/golang/go/wiki/CompilerOptimizations#fun ction-inlining

Slide 19

Slide 19 text

関数の呼び出し (直接 vs 間接) ● 試してみる ● ビルドの最適化オプションを有効化

Slide 20

Slide 20 text

関数の呼び出し (直接 vs 間接) ● 試してみる ● 実行ファイルを逆アセンブルする

Slide 21

Slide 21 text

関数の呼び出し (直接 vs 間接) ● インターフェイス経由でのメソッド呼び出しはインライン展開されない場合がある (されることもある) ○ 関数呼び出しにオーバーヘッドが生じるのでパフォーマンスに影響する可能性がある ● log/slogではどこで意識されているのか？ ○ Loggerはインターフェイスではなく構造体になっている ■ 呼び出し側でインターフェイスによる間接的なメソッド呼び出しにならないようにしている ○ Infoメソッドなどはインターフェイス経由ではなく直接呼び出せるようになっている

Slide 22

Slide 22 text

Logger構造体のパフォーマンスメモ ✍ インライン展開されるようにインターフェースではなく構造体として定義されている

Slide 23

Slide 23 text

Handlerインターフェイス Handleメソッド以外はパフォーマンス (最適化) のためのメソッド

Slide 24

Slide 24 text

Handlerインターフェイス (Enabledメソッド) メソッドの最初に呼ばれる →早期リターン

Slide 25

Slide 25 text

Enabledメソッドのパフォーマンスメモ ✍ 無駄にログを出力しないように関数の一番最初に呼ばれるようになっている

Slide 26

Slide 26 text

Handlerインターフェイス (WithAttrsメソッド) ● WithAttrメソッドは引数のattrsを[]byteに変換した後、新しいHandler を生成する ○ Handlerは内部にhandlerStateを持つ ○ bufの型の*buffer.Bufferは実際には[]byte型 ● さらに[]byteはsync.Poolを使用

Slide 27

Slide 27 text

sync.Poolとは？ ● GoDocをみてみる ○ 「... Pool’s purpose is to cache allocated but unused items for later reuse, relieving pressure on the garbage collector. …」

Slide 28

Slide 28 text

sync.Poolとは？ ● GoDocをみてみる ○ 「プールの目的は、割り当てられたが未使用のアイテムをキャッシュし、後で再利用することで、ガベージ・コレクターの負担を軽減することである。」 ● → 一時的に何かしらの値を保持して後で使いたい時 /確保のコストが高いものをあらかじめに用意しておきたい時に便利 ● log/slogパッケージ以外では、fmtパッケージやencoding/jsonパッケージでも使用されている ● パフォーマンスに関するベンチマーク等の話はたくさん記事が出ているのでここでは割愛

Slide 29

Slide 29 text

sync.Poolの基本的な使い方 ● GoDocのExampleをみてみる 1. 再利用したいアイテムを定義 2. アイテムを利用したい場合は Get メソッドを呼ぶ 3. アイテムを更新した後は Putメソッドを呼ぶ

Slide 30

Slide 30 text

log/slogパッケージではどう使われているか？ ● 実装 Freeメソッドで空にした後に Putメソッドを呼ぶある程度大きい初期化を行うことで appendによるメモリの再確保を避ける

Slide 31

Slide 31 text

log/slogパッケージではどう使われているか？ Handleメソッドでは書き込む内容を bufにつめて、出力したのちにFreeメソッドを呼ぶ → bufは常に空に初期化される WithAttrsメソッドでは引数のattrsをbufにつめて、新しいhandlerを返すような処理 → 元々のHandlerに影響を出さずに、引数のattrsを高速に出力できるような仕組み

Slide 32

Slide 32 text

WithAttrsメソッドのパフォーマンスメモ ✍ ● sync.Poolを使うことによって Handlerのメソッドを呼ぶたびに都度メモリを確保しないようになっている ● 引数のattrsはbufに保存され、新しい Handler ではその保存された bufを内部的に保持している

Slide 33

Slide 33 text

Record構造体 (Addメソッド) anyの可変長引数をAttrに変換してる

Slide 34

Slide 34 text

Attr構造体 (Value構造体) uint64とanyのみでGoの型を表現している

Slide 35

Slide 35 text

こう思いました... Valueフィールドの型はanyだとダメなのか？

Slide 36

Slide 36 text

結論は... Valueの方がanyより少しだけメモリ効率が良い →文字列 (string型) を例に考えてみる

Slide 37

Slide 37 text

(おさらい) Goにおけるany型とstring型

Slide 38

Slide 38 text

stringをanyで表現しようとすると... stringへのポインタ (anyが持つ)　＋　byteへのポインタ (stringが持つ)

Slide 39

Slide 39 text

Value構造体でのstringの表現を見てみる文字列の長さ byteへのポインタ anyの場合

Slide 40

Slide 40 text

Value構造体でのstringの表現を見てみる文字列の長さ byteへのポインタ Valueの場合

Slide 41

Slide 41 text

Attr (Value) 構造体のパフォーマンスメモ ✍ Value構造体を定義することで anyをそのまま扱うより少しだけメモリ効率が良い設計になっている

Slide 42

Slide 42 text

Record構造体 (Addメソッド) なんかちょっと複雑なことをやっているように見える...なぜ？

Slide 43

Slide 43 text

Record構造体最初に長さ5の配列が初期化される

Slide 44

Slide 44 text

Record構造体 (Addメソッド) 最初 (nFront=0, len(r.Front)=5) は初期化済みの5つの配列にAttrを詰める配列が埋まったあとは、残りの argsを (Attr単位で) カウントして、最初にその容量を確保している (appendによる再確保はない)

Slide 45

Slide 45 text

なぜ nAttrsInline = 5となっているのか？ A. zapを使っているコードを調べたところ9割くらいのロガーが5個の key-valueを出力していた (https://youtu.be/8rnI2xLrdeM?si=oCuKdvPQcrW08dXF から)

Slide 46

Slide 46 text

Record構造体のAdd関数のパフォーマンスメモ ✍ ● zapの使い方から使用される key-valueペアの個数を調査していた ● 最初にその個数分のメモリだけ初期化し、追加でメモリの再確保が可能な限り起きないようになっていた (起きたとしても 1回)

Slide 47

Slide 47 text

まとめ

Slide 48

Slide 48 text

log/slogパッケージまとめ ● 構造化ログを生成する初の標準パッケージ ● パフォーマンスについて色々な工夫が見られた ○ メモリのアロケーションを何回も行わない工夫が見られた ● 突き詰めて実装コードを読んでみると、意外と難しいことはやっていないように思えた ○ Goの言語仕様をきちんと理解した上の設計/実装になっていた ● Logger構造体やHandlerインターフェイスのパフォーマンスに関する調査は後日ブログで公開予定

Slide 49

Slide 49 text

ありがとうございました