Unengineered Weblog

PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND

Go の新機能 Range Over Func を使って database/sql の Query を楽にする

Go 1.22 から実験的機能として Range Over Func が実装された。 このブログでは Range Over Func とは何か、どういうものなのか、といった説明はしないので、知らない人は次のページを見てほしい。

go.dev

標準パッケージの database/sqlRDB を Query するのはボイラープレートまみれになる。

database/sql のドキュメントにあるサンプルコードは次のようになっている。

rows, err := db.QueryContext(ctx, "SELECT name FROM users WHERE age=?", age)
if err != nil {
    log.Fatal(err)
}
defer rows.Close()

names := make([]string, 0)
for rows.Next() {
    var name string
    if err := rows.Scan(&name); err != nil {
        log.Fatal(err)
    }
    names = append(names, name)
}
// Check for errors from iterating over rows.
if err := rows.Err(); err != nil {
    log.Fatal(err)
}

https://pkg.go.dev/database/sql#example-Rows から引用。

このコードは長い。 error チェックを3回もしているのが大きな要因だ。さすがに SELECT 文の実行という定型的なことに毎回こんなコードを書きたくない。面倒だ。

だから、このサンプルコードのような (*DB).QueryContext(*Rows).Next(*Rows).Scan の一連の流れを、関数として独立して、いかなるクエリでもボイラープレートを書かずに済ましたい。以下このような関数の名前を QueryScan にする。

よし、 QueryScan を書こう!

func QueryScan(ctx context.Context, db *sql.DB, query string, args ...any) ... {
    ...???
}

…って、あれ?この関数の実装ってそんな簡単じゃない?

そう、自明ではない問題がいくつかある。 もっとも大きな問題は (*Rows).Scan の引数がクエリごとに違うこと。型も引数の数もクエリごとに違う。これらの情報をどうやって渡すの?そして返り値の型はどうするの? reflection つかうの?あれ面倒くさいなこれ。となる。

普通の開発ではサードパーティSQL ライブラリを使うのがいいんだろうけど、今回それは置いておこう。また reflect パッケージで頑張ってつくるのも今回はしない。QueryScan 関数は画面に収まる程度にしたい。

このブログではそれらの問題を Range Over Func を使うことで、まあまあ解決した関数 QueryScan を提案する。それは (*DB).QueryContext(*Rows).Next の一連の流れを、関数としてまとめたものだ。

Range Over Func を使った実装

提案する関数は次のように定義される。

type scanfunc func(dest ...any)

func QueryScan(ctx context.Context, db *sql.DB, query string, args ...any) iter.Seq2[scanfunc, error]

この関数の実装は後で紹介する。

そして QueryScan 関数を使うと、このブログで最初に提示したサンプルコードは次のようになる。

names := make([]string, 0)
for scan, err := range QueryScan(ctx, db, `SELECT name FROM users WHERE age=?`, age) {
    if err != nil {
        log.Fatal(err)
    }
    var name string
    scan(&name) // scan には返り値がない。返り値を無視しているわけではない。
    names = append(names, name)
}

うおおおおおお

error のチェックが3回から1回に減って、コード行数も16 行から 9行に減っている。 コードが短い分読みやすいのではないだろうか。

この関数のポイントとしては (*Rows).Scan 自体は結局手で書かないといけないところだ。エラーの返り値がないラップされた関数 scan を使っているので多少は楽になっているものの、この部分の面倒さは残る。しかしながら、 (*Rows).Scan の引数がクエリごとに違うという問題は解決している。

では QueryScan はどのような実装になっているのだろうか。中身を見てみよう。

type scanfunc func(dest ...any) // 再掲

func QueryScan(ctx context.Context, db *sql.DB, query string, args ...any) iter.Seq2[scanfunc, error] {
    return func(yield func(scanfunc, error) bool) {
        rows, err := db.QueryContext(ctx, query, args...)
        if err != nil {
            yield(nil, err)
            return
        }
        defer rows.Close()

        for rows.Next() {
            var scanErr error
            if !yield(func(dest ...any) {
                scanErr = rows.Scan(dest...)
            }, nil) {
                return // ここは困る!scanErr が渡せないからだ。後述する。
            }

            if scanErr != nil {
                yield(nil, scanErr)
                return
            }
        }

        if err := rows.Err(); err != nil {
            yield(nil, err)
            return
        }
    }
}

QueryScan の実装は、最初に引用した pkg.go.dev にあるサンプルコードと似ていることに気がつくだろうか。むしろほとんど一緒である。違うのは (*Rows).Scan (をラップした関数)と error を yield に渡しているところだ。

yield 関数が呼ばれるたび、 range over func の for 文の中身が1回実行される。言い換えると、for のループが1回まわる。QueryScandb.QueryContext とそのエラー処理をしているところに注目してみよう。つぎの部分だ。

    rows, err := db.QueryContext(ctx, query, args...)
    if err != nil {
        yield(nil, err)
        return
    }

yield が1回だけ実行されるので、 QueryScan のユーザー(呼び出し側)から見ると、ループが1回だけまわって終了しているように見える。このループで渡される値は、(nil, err) だ。つまりエラーだけを渡している。

yield を呼び出している別のところも見てみよう。たとえば、 rows.Scan が失敗するとどうなるのか? あるループの中で、 scan が失敗すると、次にもう1回だけ scanErr を渡すためのループが実行される。yield(nil, scanErr)の部分だ。そしてループは終了する。

この QueryScan の問題点

提案しておいてなんだが、この QueryScan は面白いものの、Range Over Func のハックだなぁとは思う。オーバーエンジニアリングかもしれない。また問題点もある。

大きな問題点は、for で error が渡されたときだけ break すると仮定していることだ。 error が渡されたループで break するのは問題はない。(というか error が渡されたときは最後のループなので、 break してもしなくても同じだ。)しかしながら、正常系つまり nil error が渡された時に break されると困ることがある。なぜなら次のループで、 error が渡されるかもしれないが、それを無視することになるからだ。 前述した QueryScan の実装で「ここは困る!」とコメントした部分だ。

for scan, err := range QueryScan(...) {
    if err != nil {
        log.Print(err)
        break  // ここの break は問題がない。 return でもよい。
    }
    ...

    // もしかすると、次のループで error が渡ってくるかもしれない。
    // ここで break するとその error チェックができない。
    break
}

このような break をするケースはほとんどないだろうけど。

一応解決策はある。それは break ができてしまう range over func をやめること。この記事の前提を崩すように見えるが、そんなこともない。QueryScan の返り値を iter.Seq2 すなわち

func(yield func(scanfunc, error) bool)

ではなく、

func(yield func(scanfunc)) error

で書くということだ。 Range Over Func は yield の返り値の bool で break かどうか分岐していた。 yield の返り値がなくなったので、 break できなくなった。また error をかえす場所を変えた。後者をかえす QueryScan の実装は宿題とする。

for 文では書けなくなるが、考え方自体は変わっていない。たとえば次のように呼び出すことになる。

err := QueryScan(ctx, db, `SELECT name FROM users WHERE age=?`, age)(func(scan scanfunc) {
    var name string
    scan(&name)
    names = append(names, name)
})

こっちの方が好きな人がいるかもしれない。こちらはbreak の問題がなくなり、エラーの渡し方も標準的だ。僕もこっちの方が好きかもしれない。

まあこのブログは新機能の range over func をせっかくなら使ってみたという欲張りがあったので、最初は range over func を使った手法を紹介したのだった。

Go スライスのソート順を維持したまま要素を追加する

スライスのソートを維持したまま要素を追加する関数 appendSorted の実装

func appendSorted[S ~[]E, E cmp.Ordered](s S, e E) S {
        i, _ := slices.BinarySearch(s, e)
        return slices.Insert(s, i, e)
}

挙動

s = []int{}
s = appendSorted(s, 4)  // [4]
s = appendSorted(s, 1)  // [1 4]
s = appendSorted(s, 9)  // [1 4 9]
s = appendSorted(s, 5)  // [1 4 5 9]
s = appendSorted(s, 3)  // [1 3 4 5 9]
s = appendSorted(s, 11) // [1 3 4 5 9 11]

計算量

配列の長さを n とすると、BinarySearch は  O(\log n), Insert は  O(n) だから、 appendSorted は  O(n) 。一方、単純に append と sort する実装だと、  O(n \log n) だから、早くなっている。平衡二分木を使えば、もっと早くなりそうだけど、コードも短いし十分実用的でしょう。

Mackerel をファイルシステムにした

この記事ははてなエンジニア Advent Calendar 2023の 12月36日 2024年1月5日の記事です。

developer.hatenastaff.com

Mackerel をファイルシステムにしてみましょう。 Mackerel でファイルシステムを監視するのではありません。 Mackerel をファイルシステムにするのです。

じゃん

mackerelfs と言います。よろしくおねがいします。 github.com

/home/rmatsuoka/mackerel ディレクトリに mackerelfs をマウントしましょう(マウントの方法は後半説明します。)最初は ctl ファイルだけがあります。

$ ls -l 
total 0
--w--w--w- 1 rmatsuoka rmatsuoka 0 Jul 14  2042 ctl

さて Mackerel を操作するときは API キーが必要です。 mackerelfs にも API キーを登録しましょう。ここでは私のオーガニゼーション rmatsuoka のものを使います。登録するには ctl ファイルに以下のように書き込むだけです。

$ echo "new $MACKEREL_APIKEY" > ctl

すると mackerel ディレクトリに rmatsuoka というディレクトリが登場しました。

$ ls -l 
total 0
--w--w--w- 1 rmatsuoka rmatsuoka 0 Jul 14  2042 ctl
dr-xr-xr-x 1 rmatsuoka rmatsuoka 0 Jul 14  2042 rmatsuoka
$ ls -1F rmatsuoka/
hosts/
service/

rmatsuoka/hosts 以下にはホストがディレクトリとして一覧になっています。

$ ls -1F rmatsuoka/hosts/
ctl
rmatsuoka-desktop/
Ryuichis-MacBook-Pro.local/

このオーガニゼーションでは私用の端末 rmatsuoka-desktop, Ryuichi-MacBook-Pro.local を監視しています。

rmatsuoka-desktop のメトリック一覧は hosts/rmatsuoka-desktop/metrics を readdir すれば、ファイル(ディレクトリ)として見ることができます。

$ ls -F rmatsuoka/hosts/rmatsuoka-desktop/metrics/
cpu.guest.percentage/
cpu.idle.percentage/
cpu.iowait.percentage/
cpu.irq.percentage/
cpu.nice.percentage/
cpu.softirq.percentage/
cpu.steal.percentage/
cpu.system.percentage/
cpu.user.percentage/
ctl
custom.linux.context_switches.context_switches/
custom.linux.disk.elapsed.iotime_sda/
...

<metric_name>/1hour 以下にあるファイルを読むと過去一時間分のメトリックが取得できます。ホストのカスタムメトリックと同じ形式になっています。

ホストのカスタムメトリックを投稿する - Mackerel ヘルプ

$ cat rmatsuoka/hosts/rmatsuoka-desktop/metrics/cpu.system.percentage/1hour 
cpu.system.percentage   5.542648  1704379920
cpu.system.percentage   5.857077  1704379980
...

metrics/service を readdir しましょう。サービス一覧が見ることができます。このオーガニゼーションには devices というサービスがあります。

$ ls -1F rmatsuoka/service/
ctl 
devices/

devices のロール(ここでは desktop と laptop)とサービスメトリックは rmatsuoka/service/devices 以下にあります。

$ ls -1F rmatsuoka/service/devices/
ctl
desktop/
laptop/
metrics/
$ ls -1F rmatsuoka/service/devices/desktop/
ctl
memo
rmatsuoka-desktop/

ちなみにディレクトリの至るところにある ctl ファイルに reload と write するとそのディレクトリの情報を reload してくれます。

$ echo reload > rmatsuoka/service/devices/ctl

見終わったので、 rmatsuoka オーガニゼーションを mackerelfs から取り除きましょう。mackerelfs のルートにある ctl に書き込むだけです。

$ echo delete rmatsuoka > ctl
$ ls
ctl

ファイルシステムの形をしたアプリケーション

mackerelfs はファイルシステムですが、データを収納するストレージではありません。Mackerel の情報を取得するアプリケーション / インターフェースです。 古くから Unix の「ファイル」とは単にデータの塊を指すだけではなく、デバイスのインターフェースでもありました。今の Unix-like な OS でも /dev 以下にデバイスファイルがありますね。これによってユーザーからはファイルもデバイスopen, read, write など同じ方法で扱うことができます。この考えを更に推し進めた Plan 9 はコンピュータ上のプロセスや、ネットワーク、アプリケーションまで様々なリソースを(ファイルではなく)ファイルシステムとして表現しました。これによって「ネットワークにアクセスする」、「プロセスを見る」といった処理は専用のシステムコールではなく open, read などのファイル用のシステムコールで賄えるようになります。 Linux でもプロセスは /proc 以下にファイルシステムで表現されています。/proc があるおかげで Linux, Plan 9ps コマンドはシンプル(つまり /proc 以下にあるファイルを読むだけ)になっています。一方 /proc がない他の Unix-like では ps コマンドは SUID がついていて強力な権限でゴニョゴニョしている。

mackerelfs は Plan 9 のアプリケーションから着想を得てつくりました。Mackerel のホストやサービスといった情報はファイルにマッピングされ、ユーザーはファイルを操作するシステムコールだけで Mackerel をの情報を取得することができます。

ところでアプリケーションの UI / UX という観点から mackerelfs を見てみましょう。このブログの前半では mackerelfs を使ってみた様子を紹介しました。そこでは lscat, echo のように Unix の基本的なコマンドで完結しています。ファイルシステムなので当然ですね。Unix に慣れた人なら、すぐ使えるのではないかなと思います。 ctl ファイルの挙動は独特ですが。

Mackerel には mkr というCLI アプリケーションがあります。これもシンプルな操作で CLI から Mackerel を操作することができますが、一定程度使い方を学ぶ必要があります。

mackerel.io

さらに mackerelfs は、ファイルIO をつかって簡単にスクリプトを組み、操作を自動化させることができます。コマンドラインで行ったことをそのままスクリプトに書き起こせばよいので、手動と自動の間に連続性があります。また http リクエストができない AWK をつかってスクリプトを組むこともできます。

#!/usr/bin/awk -f

BEGIN {
    while (getline < "rmatsuoka/hosts/rmatsuoka-desktop/metrics/cpu.system.percentage/1hour")) {
        ...
    }
}
...

このようにファイルシステム型のアプリケーションは基本的なコマンドのみで操作が完結したり、自動化しやすかったりの特徴をもっており、使いやすいツールのカタチとしての可能性があると思います。

mackerelfs をマウントする方法

mackerelfs は

func FS() fs.FS

という関数だけが用意されたライブラリです。 fs.FS は Go の標準パッケージ io/fs に定義されたファイルシステムを抽象化したインターフェースです。

pkg.go.dev

fs.FS は標準パッケージの定義ですから、 fs.FS をコンピュータにマウントするサードパーティライブラリはいくつか存在すると思います。 例えば僕が作った ya9p は fs.FS をPlan 9ファイルシステム通信プロトコル 9P2000 によって操作できます。mackerelfs にはこの ya9p を使ったコマンド mackerel9p が用意してあります。

github.com

Linux, macOS などは 9P2000 は 9fans/plan9port にある 9pfuse を使えば FUSE 経由でマウントできます。(macOSFUSE を使うには macFUSE も必要です。)

$ go install github.com/rmatsuoka/mackerelfs/cmd/mackerel9p@latest
$ mackerel9p
$ mkdir mackerel
$ 9pfuse 'tcp!localhost!8000' mackerel

注意事項

  • mackerelfs はこのアドベントカレンダーに向けて大急ぎで作ったので機能が足りてなかったり挙動が不安定です。
  • mackerelfs は私 id:rmatsuoka 個人のプロジェクトとしてつくったプロダクトで、 Mackerel 公式として提供するものではありません。

perl のワンライナーで日本語 (UTF-8) を使う

ややこしかったので

こうする

$ perl -Mutf8 -CSDA [のこりのオプション...]

使用例

$ echo 'にゃんぱす' | perl -Mutf8 -CSDA -nlE 'say length($_);'
5

かんたんな説明

  • -Mutf8 でプログラムが UTF-8 で記述されていると指定
  • -C オプションの次の引数で要素が UTF-8エンコーディングしていることを指定
    • S stdin, stdout, stderr が UTF-8
    • D IO ストリームが UTF-8
    • A プログラムの起動時引数 @ARGVUTF-8

ちなみに -C オプションを引数なしに書くと -CSDL を指定したことになる。これは引数 A がない。だから引数に UTF-8エンコードされた文字列がくるとおかしくなる。

$ perl -Mutf8 -C -wE 'say $ARGV[0];' にゃんぱす
ã«ããã±ã

参考資料

  • -Mutf8 の説明

perldoc.perl.org

  • -CSDA の説明

perldoc.perl.org

OpenTelemetry のヒストグラムメトリックを計装して Mackerel に投稿する

Mackerel Advent Calendar 2023 12月17日の記事です。 qiita.com

Mackerel は OpenTelemetry のメトリックに対応するよう開発中です。この記事では OpenTelemetry のヒストグラムメトリックの詳細と Mackerel での扱い、 SDK を用いてヒストグラムを計装する方法を解説します。

Mackerel の OpenTelemetry のメトリック対応

mackerel.io

クローズドベータテスト中の Mackerel の OpenTelemetry 対応では最近ヒストグラムメトリックに対応しました。OpenTelemetry の仕様では

  • gauge
  • sum
  • histogram
  • exponential histogram

の4種類のメトリックが定められています(summary はすでに legacy 扱いのため省略しています)。

opentelemetry.io

今回の対応で Mackerel は上記4種のメトリック全てに対応しました。 gauge と sum は集計方法に違いはあるものの、データの形式としてはどちらもいわゆる「一般的なメトリック」です。つまりある時点に対しての値(データポイント)が一つのスカラー値です。

それに対して histogram, exponential histogram のデータポイントは度数分布となっています。度数分布は中学や高校の数学で習ったとおり次のような形式です。

階級 [ms] 度数
(0, 5] 0
(5, 10] 1
(10, 25] 2
(25, 50] 5
(50, 75] 3

histogram と exponential histogram のデータポイントには上記の度数分布とともにデータの数 (count)、合計 (sum)、最大値(max)、最小値(min) といった情報も含まれています。

ヒストグラムメトリックが最も使われているのはおそらく HTTP のレスポンスタイムの計装ではないでしょうか。ウェブアプリケーションではレスポンスタイムのように一つのリクエストに対して計装される数値を記録するときにヒストグラムをつかうのが適しています。

histogram と exponential histogram の違い

OpenTelemetry の規格としての "histogram" は一般的に想像されるヒストグラムです。explicit bucket histogram ともいいます。メトリックを計装するライブラリは、計装した数値をある階級の度数として記録します。階級は各自定義するごとができます(デフォルトは [ 0, 5, 10, 25, 50, 75, 100, 250, 500, 750, 1000, 2500, 5000, 7500, 10000 ])。

この histogram には一つ問題点があります。階級を事前に定義しないといけないというところです。例えばレスポンスタイムが 10 ms ~ 100 ms 程度のアプリケーションをデフォルトの階級を使って計測すると (10, 25] (25, 50] (50, 75] (75, 100] の4つの階級に収まってしまいます。16個もある階級のうち4つしか使っておらず解像度が低いです。階級を適切に設定すれば良いのですが、コンポーネントが増え、記録されるヒストグラムメトリックの種類が増えると設定は大変です。

一方 exponential histogram はこの階級を定義する際の問題がありません。なぜなら階級が自動的に決まるからです。 メトリック計装ライブラリは記録された値をもとに scale を計算します。exponential histgoram の階級はこの scale を階級の index によって冪乗(exponentiation)した値と定義されています。例えば  \mathtt{scale} = sのとき、 \mathtt{index} = i の階級は

 [ (2^{2^{-s}})^i, (2^{2^{-s}})^{i+1} )

と表すことができます。計装ライブラリは記録された値にたいして解像度が高くなるように scale を計算します。詳しい仕組みは省略しますが、 exponential histogram は設定が不要で高解像度のヒストグラムが計装できるメトリックタイプだと捉えればいいでしょう。記事の後半では exponential histogram を使って計装する方法を説明しています。 ただし exponential histogram は比較的あたらしいメトリックタイプなためモニタリングツールによって対応がバラバラです。たとえば Prometheus ではこのブログを執筆した時点(2023/12/18)では まだ expoential histogram のドキュメントが整備されていません。

次の OpenTelemetry のブログには exponential histogram の長所がまとまっています。 opentelemetry.io

Exponential histogram の仕様は次のページで見ることができます。

opentelemetry.io

Mackerel に histogram を投稿する

ベータテストのMackerel では投稿されたヒストグラム (histogram, exponential histogram どちらでも)にたいして、いくつかの代表値が計算をして、その値を保存します。現在は count, sum, max, min p99 (99パーセンタイル), p95, p90 の最大7種のメトリックになります。「最大」というのはメトリック収集の設定によっては sum, max, min の情報がなかったりするからです。 これらのメトリックは [ヒストグラムメトリックの名前] . [suffix (sum や p90など)] の名前をもつメトリックとしてクエリすることができます。

レスポンスタイムを計装する

前回のブログでも登場した otelhttp をつかうとレスポンスタイムがヒストグラムとして計装されます。

rmatsuoka.hatenablog.com

使い方はかんたん。 パッケージ net/http の Handler を関数 otelhttp.NewHandler でラップするだけ。(もちろんメトリックの送信先を Meter Provider によって設定する必要がありますが、ここでは省きます)これだけでレスポンスタイムを計装することができます。

http.ListenAndServe(":8080", otelhttp.NewHandler(&mux, "server"))

Mackerel に投稿したヒストグラムメトリック(レスポンスタイム)をグラフで描画した図

手動で計装する

手動で計装するときは Meter からヒストグラムのカウンターを初期化することで計装できます。 Meter とはメトリックを記録するクラスで、Go では普通パッケージごとひとつだけグローバル変数 meter としてインスタンスを初期化することが多いです。

pkg.go.dev

私は package ごとに次のような meter.go を用意しました。カウンターはプログラム全体で使うためグローバルに定義をしました。 この例では整数 (int64) の値を記録する fooCounter を定義しています。

package foo

import (
    "reflect"

    "go.opentelemetry.io/otel"
    "go.opentelemetry.io/otel/metric"
)

var meter otel.Meter
var fooCounter metric.Int64Histogram

func init() {
    meter = otel.Meter(reflect.TypeOf(t{}).PkgPath())

    fooCounter, err = meter.Int64Histogram("foo metric's name")
    if err != nil {
        otel.Handle(err)
    }
}

数値を記録するときは次のように呼び出します

fooCounter.Record(ctx, int64(n))

exponential histogram を計装する

上記の設定のままでは explicit bucket histogram で計装されます。前述のとおり exponential histogram のほうが便利ですから、そちらに変更しましょう。 OpenTelemetry の metric を計装するライブラリでは View と呼ばれる仕組みが仕様として決められています。これを用いると計装の方法を override してカスタマイズすることができます。 view によって explicit bucket histogram ではなく exponential histogram として計装しましょう。

// histogram をすべて exponential histogram で記録する
view := metric.NewView(
    metric.Instrument{Kind: metric.InstrumentKindHistogram},
    // 160 と 20 はデフォルト値
    metric.Stream{Aggregation: metric.AggregationBase2ExponentialHistogram{MaxSize: 160, MaxScale: 20}},
)

mp := metric.NewMeterProvider(
    metric.WithReader(
        metric.NewPeriodicReader(meterExporter, metric.WithInterval(time.Minute)),
    ),
    metric.WithResource(resources),
    metric.WithView(view),
)

Mackerel で開発中のマイクロサービスを OpenTelemetry のトレースを活用してパフォーマンス改善した

Mackerel Advent Calendar 2023 の2日目の id:rmatsuoka です。

qiita.com

私は今年に新卒としてはてなに入社し、 Mackerel のアプリケーションエンジニアとして開発に携わっています。さて Mackerel では OpenTelemetry のメトリックに対応することが発表されました。詳しくは次のページをご覧ください。

mackerel.io

私はこの OpenTelemetry を受け取ったり、取り出したりするコンポーネントの開発をしています。入社して最初の仕事として OpenTelemetry の トレース を活用し、コンポーネントのパフォーマンスを改善を行いました。 トレース 導入を提案したのは id:lufiabb さんです。最初、私のタスクは OpenTelemetry の トレース をアプリケーションに仕込んで終わりだったのですが、id:lufiabb 曰く「パフォーマンス改善まで rmatsuoka ができそうだから任せた」と言われて頑張りました。

ソフトウェアのパフォーマンスを改善するとき、大切なのが計測をすることです。ソフトウェアエンジニアはどこかで「推測するな、計測せよ」という格言を聞いたことがあるかもしれません。ソフトウェアの処理時間の大半はプログラムの中の数%のボトルネックに集中すると言われています。この部分を見つけることがパフォーマンスの改善の第一歩になります。しかしながらどのように見つければ良いのでしょうか。このブログは OpenTelemetry の トレース を使ってボトルネックを発見し、パフォーマンス改善を進めた体験を書きます。

OpenTelemetry とは

公式のウェブサイト では次のように説明されています。

OpenTelemetry is an Observability framework and toolkit designed to create and manage telemetry data such as traces, metrics, and logs. Crucially, OpenTelemetry is vendor- and tool-agnostic, meaning that it can be used with a broad variety of Observability backends, including open source tools like Jaeger and Prometheus, as well as commercial offerings. OpenTelemetry is a Cloud Native Computing Foundation (CNCF) project.

opentelemetry.io

OpenTelemetry が提供しているライブラリやコレクターは GitHub のリポジトリ から見ることができます。Go や JavaScript など主要な言語でテレメトリーを計装するライブラリが用意されています。このブログの後半で Go アプリケーションを トレース を導入する方法を紹介します。

取得したテレメトリーは Prometheus (metric)や Mackerel (metric), AWS X-Ray (trace)といったモニタリングサービスへ直接送ることもできますが、 OpenTelemetry Collector を経由して送ることが推奨されています。これによってアプリケーションにモニタリングサービスに依存したコードを書く必要がなくなります。さらに collector 自体にもリトライや、テレメトリーをバッチしてモニタリングサービスへおくったり、不要なテレメトリーを除くフィルタリングするといった機能が兼ね備えられていて便利だからです。

Mackerel の OpenTelemetry メトリック対応

PromQL によってメトリックをクエリしている様子。https://mackerel.io へのレスポンスタイムのメトリックをクエリしている。

Mackerel では現在、主に次の機能を開発しています。

  • OTLP/gRPC によるメトリックの受信
  • PromQL によってメトリックをクエリしてグラフに描画

OTLP は OpenTelemetry が策定したテレメトリーを送受信するプロトコルです。 PromQL は OpenSource のメトリックモニタリングツール Prometheus で使われているクエリ言語です。たとえば

httpcheck.duration{http.url="https://mackerel.io"}

といった式によるクエリが可能です。 Mackerel では独自のメトリックデータベースを利用しているため PromQL エンジンを独自に実装して提供します。

これらの機能はマイクロサービスとして設計されています。Go で記述され AWS ECS へデプロイされます。それぞれのサービスの関係は次の図で表すことができます。この図でメトリックは左から右へ流れます。ユーザーのメトリックは OpenTelemetry Collector を経由して、緑色の四角形で表された Otel metric Writer へ送信されデータベースへ保存されます。ユーザーの PromQL によるクエリは Otel metric Reader に送られます。reader は PromQL を評価してメトリックをデータベースから取り出し、レスポンスをユーザーへ返します。

Mackerel の OpenTelemetry 対応のコンポーネントの構成図

もともとこれらのマイクロサービスは設計の方針を確認する PoC で、あまりパフォーマンスを意識した実装ではありませんでした。実際のサーバーから送信されたメトリックの一覧のダッシュボードを見ようとするも重くて使いものになりません。一つのダッシュボードを開くだけでマイクロサービスの CPU が 100%になることもありました。そういうわけでパフォーマンス改善のタスクを行うことになりました。writer と reader のどちらもパフォーマンス改善しましたが、このブログでは reader に焦点を当てて説明します。

Go のアプリケーションでトレースを計装する

つぎのようにして Go のアプリケーションでトレースを計装しました。

1. Tracer の initialize を追加

main 関数あたりでトレースの exporter を初期化します。これによって計装したテレメトリーを外部へ送信する先を指定します。今回は ECS のサイドカーにおいた otel-collector に送信をするので、 otlptracegrpc を exporter としました。

+ traceExporter, err := otlptracegrpc.New(ctx, ...)
+ if err != nil {
+         ...
+ }
+ tp := trace.NewTracerProvider(...)
+ otel.SetTracerProvider(tp)

2. http.Handler を otelhttp でラップ

otelhttp はリクエスト全体のスパンを生成してくれます。reader マイクロサービスは net/http と互換性のある chi によって書かれています。

- handler := newHandler()
+ handler := otelhttp.NewHandler(newHandler(), “servername”, ...)

3. 計装したい関数で span を生成する

処理に時間がかかると思われる関数に span を生成して、処理時間を測定します。

まずはパッケージごとに固有の tracer をグローバル変数で定義します。これによってパッケージとスパンを結びつけることができます。 私はパッケージごとに次のようなコードである trace.go を置きました。

package nicepkg

var tracer = otel.Tracer("example.com/proj/nicepkg")

そして span を生成したい関数に次の2行を追加します。

  func NiceFunction(ctx context.Context) {
+        ctx, span := tracer.Start(ctx, "NiceFunction")
+        defer span.End()
+
          // function body
  }

どの関数で span を生成するかは悩みます。初めはデータベースをクエリしている部分、 PromQL を評価している部分など重いと思われるとこに全部に span を生成して、不要と思った部分を削る方針で進めました。

アプリケーションのトレースは ADOT を用いて AWS X-Ray へと送信しました。

aws-otel.github.io

トレース結果を見て発見した課題と解決方法

マイクロサービス Reader のトレース結果

トレース結果は X-Ray の画面から上のように見ることができます。この結果は一つのリクエストが処理を完了するまでを表しています。一番上の緑の帯は リクエストを受け取る http のハンドラーがかかったのスパンです。幅が処理時間を表しています。このハンドラーが呼び出した関数のスパンが次の行の緑色の帯であり、さらにその関数が呼んだ関数が下に…といったようになっています。

データベースへのクエリの改善

N+1 問題

このトレース結果をみると、同じ関数が何度も呼ばれてその処理に時間がかかっていることがわかります。 これはデータベースへの問い合わせに発生する典型的な問題で N+1問題と呼ばれています。 取り出すメトリック一覧を取得する RDB へのアクセス を1回。それぞれのメトリックの時系列データを Time Series DB から取り出すことをループで N 回実行しています。

これらはまとめて取得をするように変更して N+1 問題は解決しました。

特定のリクエストが遅いことを発見

トレースを眺めていると特定の条件のリクエストだけが遅いことを発見しました。メトリックのメタデータを記録した RDB のテーブルはふたつあります。

  • メトリック (Mackerel のオーガニゼーションの ID や メトリックのタイプなど)
  • メトリックのラベル (メトリックに従属している)

RDBの実行計画をEXPLAIN ANALYZE コマンドで見ると、ラベルテーブルの index の貼り方がマズかったことがわかったので index を修正しました。さらに高速化のためラベルデータのテーブルを非正規化してオーガニゼーションID のカラムを追加しました。

+ ALTER TABLE <ラベルテーブル> ADD COLUMN "org_id" BIGINT;
+ CREATE INDEX <index_name> on <ラベルテーブル> ("org_id", ...);

PromQL の評価が遅い

PromQL の評価 (eval) が遅いことを占めすトレース結果

さらにクエリによっては PromQL を評価する関数が遅いがわかりました。更なる調査でメトリックを長い期間つまりたくさんのデータポイントがあるようなリクエストを発行した時は PromQL の評価が異常に遅くなることがわかりました。 トレースの結果ではなぜこの eval 関数が遅いのかわからないのでGo の プロファイラー pprof を使って更なる調査を行いました。

ループで探していたことを二分探索へ変更

取得したpprof を眺めるとちょっと変わった点を発見しました。時刻の構造体が等しいことを調べる関数 time.(Time).Equal がとても CPU 時間を使っています。この処理自体は重い処理ではないはずです。 さらに詳しく調べたところ、時刻を含む構造体 (dataPoint) のスライス dataPoints から at と一致する時刻をもつ要素を探す時、ループで探していたことを見つけました。この構造体は時刻でソートしていたため、二分探索で行い探索にかかる処理を削減しました。

- for _, dataPoint := range dataPoints {
-         if dataPoint.Time.Equal(at) {
-                 ...
+ idx := sort.Search(len(dataPoints), func(i int) bool {
+         return dataPoints[i].Time.Compare(at) >= 0
+ })

メモリの確保が激しかった

pprof の結果をみるとメモリの確保や解放などのシステムコールを呼び出していることが多いことがわかりました。 更なる調査で入力のたびに毎回正規表現コンパイルしてバリデーションしていました。正規表現を毎回バリデーションするのをやめる手もありますが、今回のケースでは単純なバリデーションだったため、正規表現自体の利用をやめました

  // 制御文字を取り除く
- matched, err := regexp.Match("[ -- set of invalid charactor -- ]", input)
+ matched := strings.ContainsAny(input, invalidChars) // invalidChars = "\x00\x01\x02..."

おわりに

パフォーマンス改善後のトレース結果(上部の改善前のトレース結果の画像と同じリクエストではないため単純比較はできませんが、参考までに)

トレースを導入しパフォーマンス改善をしていく様子を、ブログにしました。 このような施行によりパフォーマンスは改善されています。

現在 Mackerel の OpenTelemetry 対応ベータ版テストの参加募集をしております。リンク先の下記のフォームに進み、内容にご同意いただけましたらベータ版テストへぜひご参加ください。

docs.google.com

Mackerel Advent Calendar 2023、明日 3日目は id:heleeen さんです。

このブログは 11月16日におこなった Hatena Engineer Seminar の発表をブログ記事にしたものです。

developer.hatenastaff.com

最近の macOS の /usr/bin/diff は色をつけることができる

いつからかは分からないが、最近の macOS の /usr/bin/diff は色をつけるオプションが生えた。 記憶が曖昧だが過去のバージョンではこのオプションはなかった気がする。

使い方は簡単。 --color オプションをつけること。

下は macOS (Ventura 13.5.2) の diff の man ページから引っ張ってきたもの。

--color=[when]
       Color the additions green, and removals red, or the value in the DIFFCOLORS environment variable.  The
       possible values of when are “never”, “always” and “auto”.  auto will use color if the output is a tty
       and the COLORTERM environment variable is set to a non-empty string.

GNU diff と同じ文法である。

ちなみに macOSgrep や ls も色をつけることができる。同様に --color をつければよい。 以前のバージョンの macOS では ls に色をつけるのは -G しかなかった記憶。

毎回 --color をつけるのは面倒臭い。こういうときは alias を使う。 私の ~/.zhrc には

alias grep='grep --color=auto'
alias ls='ls -G'
alias diff='diff --color=auto'

と書いてある。