Unengineered Weblog

PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND

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'

と書いてある。

Linux でファイルがどのファイルシステムにあるのか調べるのは簡単ではなかった

GNU/Linux で df の挙動を見てみよう。引数に(デバイスファイルではなく、普通の)ファイル名を渡すと、それが保存してあるファイルシステムを探してきて、デバイスファイルやマウントポイントなどそのファイルシステムの情報を表示する。

$ df Makefile
Filesystem      1K-blocks       Used  Available Use% Mounted on
/dev/sda1       477514616  106381680  346803108  24%  /

実はこの挙動「ファイルが保存されてあるファイルシステムを返す」をするシステムコールは無い。 df はマウントしているファイルシステムの一覧がある /etc/mtab から探しているのである。

/etc/mtab は次のようなファイルだ

sysfs /sys sysfs rw,nosuid,nodev,noexec,relatime 0 0
proc /proc proc rw,nosuid,nodev,noexec,relatime 0 0
...
/dev/sdb2 / ext4 rw,relatime 0 0
/dev/sda1 /home/ ext4 rw,relatime 0 0
...

マウントしているファイルシステムが一行ごとに書いてある。一行には左からスペース区切りで、ファイルシステムの名前(デバイスファイル)、マウントしてあるディレクトリ(マウントポイント)、あとは細かい情報(いまからの説明に関係がないので端折る)が書いてある。 ちなみに文法は /etc/fstab と同じである。

それでは df がどのようにファイルシステムを探しているのか見てみよう。 GNU のコードを読むのは大変なので、 busybox のコードを読んでみよう。まさにファイルがどのファイルシステムにあるのか調べる関数 find_mount_point という関数がある。これはファイル名を渡すと、それがあるファイルシステムの情報を構造体 のポインタ struct mntent* を返す。この構造体は /etc/mtab の一行をパースしただけである。

github.com

アルゴリズムを端折って説明すると、ファイルの stat から得られるデバイス ID (st_dev) と一致するマウントポイントのディレクトリを /etc/mtab から一行一行読んで探し、そこからファイルシステムを特定している。

なんて泥臭いんだ! 「ファイルが保存されてあるファイルシステムを探す」ためのシステムコールがあると思っていた僕は面食らってしまった。タイトルどおり簡単ではなかった。まあ難しくもないが。

ちなみに macOS では statfs システムコールを使えば一発でわかる。

Bash が環境変数を勝手に変えてくる!

ネタバレ

犯人は BASH_ENV

私がシェルスクリプトを書いていたとき、 bash が勝手に環境変数を変えてくるという謎の挙動をした。なぜなのか調べた。

どんなことが起こったのか

私が書いていたシェルスクリプトは複雑で本題とは関係ない。話を簡単にするために、次のシェルスクリプト hello を書いていたとしよう。 環境変数 NAME へ挨拶するスクリプトだ。

#!/bin/bash
echo "hello, $NAME"

そして次のように実行した。すると意図しない挙動をする。

$ NAME=alice ./hello
hello, bob
🤔

環境変数 NAME は alice だったはず! なぜ bash環境変数を勝手に変えてくるのだろうか。

状況はどうであったか

このシェルの環境変数を見てみると怪しいものがある。

$ printenv
...
BASH_ENV=/path/to/name
....

そして気になる /path/to/name の中身は次の通り。

NAME=bob

BASH_ENV とは

BASH_ENV

If this variable is set when Bash is invoked to execute a shell script, its value is expanded and used as the name of a startup file to read before executing the script.

www.gnu.org

環境変数 BASH_ENV がセットしていたとき、bash スクリプトが実行されると、スクリプトが実行される前にファイル BASH_ENV が読まれるそうだ。

つまり、上の name スクリプトは /path/to/name によって環境変数 NAME が上書きされてしまったのである。

BASH_ENV を unset したら意図した挙動になった。

$ unset BASH_ENV
$ NAME=alice ./hello
hello, alice

なぜ BASH_ENV がセットされていたのか

ある GitHub リポジトリにあった Dockerfile で BASH_ENV が使われていたのをよくわからずにコピペして動かしていたから。よくわからないものをコピペして動かすのはよくないね。

入力ソースを切り替えるキーバインドを ctrl + space に変えよう(と思ったが…)

入力モードを切り替えるキーバインドは何を設定していますか?

私はこれまで ctrl + \ で入力ソースを切り替えていたが、ターミナルで STOP シグナルを送るキーバインドとかぶっていることに気づいた。 普段 STOP シグナルを送ることはあまりないが、このような被りは誤操作を引き起こしそうだと考えてキーバインドをタイトルのように変更した。

そもそも ctrl + spaceMac のデフォルト設定なのだから、それに戻しただけである。 わざわざ変えていた理由は Emacs だ。 Emacs では ctrl + space は範囲選択に、ctrl + \Emacs の 入力ソースを切り替えになっていたのだ。 Emacs に干渉しないように設定したというわけである。

でも最近は Emacs を使わないから Mac のデフォルト設定に戻してしまおう。 Ubuntu もそれにあわせよう。めでたしめでたし

と思ったんだが…

この続きを読むには
購入して全文を読む

環境変数$SHELLの使い方を間違っていませんか?

要約

いま動いているインタラクティブシェルを知る方法に環境変数$SHELLを読むのが広く知られているが、これはこの環境変数の誤った使い方である。 $SHELLはユーザーのお気に入りのシェルを指定するものである($EDITORに近い)。 シェルは起動時に$SHELLの値をいまのシェルにセットするわけではない。 いま動いているシェルを知るには

ps -o comm= -p $$

とするのが良さそうだ。

Googleで「現在のシェル 確認」と検索すると

google:現在のシェル 確認

echo $SHELLでわかると書いてあるページが多い。たまにecho $SHELLではなくecho $0とやれと書いてある記事もある。

POSIXの説明

SHELL

This variable shall represent a pathname of the user's preferred command language interpreter. If this interpreter does not conform to the Shell Command Language in XCU Shell Command Language, utilities may behave differently from those described in POSIX.1-2017.

pubs.opengroup.org

この説明からわかるように$SHELLは現在の動いているシェルを表すものでは無い。

試してみる

簡単な実験で$SHELLが現在走っているシェルを示さないことがわかる。

# いまは zsh です。
% uname -a
Darwin Ryuichis-MacBook-Pro.local 22.4.0 Darwin Kernel Version 22.4.0: Mon Mar  6 20:59:58 PST 2023; root:xnu-8796.101.5~3/RELEASE_ARM64_T6020 arm64
% echo $SHELL
/bin/zsh
%
% bash # bashを起動するも、
$ echo $SHELL # $SHELLの値は変わらない。
/bin/zsh
$
$ ksh
$ echo $SHELL
/bin/zsh

このようにbashksh環境変数$SHELL/bin/bashに上書きしてくれるわけでは無い。 このようにいま動いているシェルと$SHELLが異なる状態で$SHELLからいま動いているシェルを知ろうとする(行儀の悪い)スクリプトsource.で読むとおかしい挙動をしたりする。

だったらどうやっていまのシェルを調べればよいのだろう。

$0は罠がある

$0C言語でのargv[0]を示すので、インタラクティブシェルでは$0は現在のシェルのパスを表す(シェルスクリプトでは起動したファイルの名前を表す)。

# bash
$ echo $0
bash

# ksh
$ echo $0
ksh

# sh
$ echo $0
sh

# dash
$ echo $0
dash

# zsh
% echo $0
-zsh

(最後のzshのようにログインシェルはprefixに-がついている。)

「これでいまのシェルを知ればいいじゃん」と思うじゃん? zshだけは起動ファイル~/.zshrc.でファイルを読んだ時にそのファイル名を表してしまう。

# echo0.source
echo $0
# bash
$ . ./echo0.source 
bash

# ksh
$ . ./echo0.source
ksh

# sh
$ . ./echo0.source
sh

# dash
$ . ./echo0.source
dash

# zsh だけ違う出力をする!
% . ./echo0.source
./echo0.source

こういった挙動の違いは.bashrc.zshrcを共通のファイルにしている人(そんなにいないかも🤔)にとっては困る。

どんなシェルでも同じ方法でいまのシェルを知る方法が欲しい。

いまのシェル名はpsから取得しよう

僕が思いついた方法はpsを使うことだ。 インターネットで調べると同じようにpsを使っていまのシェルを知る方法を紹介しているページがいくつか見つかる。

ps -o comm= -p $$
# or
ps -o args= -p $$
$ bash -i
$ ps -o comm= -p $$
bash
$ ps -o args= -p $$
bash -i

-o args=の場合は起動時の引数も表示するという違いがある。

これはPOSIXに規定されているコマンドオプションのみなのでLinuxmacOS、確認してないがほかのUnixでも動くだろう。 細かいオプションの説明はしないのでPOSIXのページでも見てほしい。

pubs.opengroup.org

ちなみに$$はシェルが展開する変数だ。だから例えばGoのos/execパッケージはシェルを経由しないで実行するので

exec.Command("ps", "-o", "comm=", "-p", "$$")

とやっても動かない(シェルが展開するグロブや変数を知らない人を稀によく観察する)。

実はps -o comm= -p $$が動かない環境がある。

busyboxのpsは-pオプションがない。 だから上の方法はAlpine Linuxでは動かない。 だから

ps -o pid=,comm= | awk -v pid=$$ '$1 == pid { print $2 }'

となるかなぁ。ちょっとめんどくさいね。

Goでスライスなどを無理やり比較する

Goには比較可能ではない型がある
  • スライス
  • 関数値
  • 上記のものを含んだ構造体など
package main

import (
	"fmt"
)

func main() {
	a := []int{1, 2, 3}
	b := []int{1, 2, 3}

	fmt.Println(a == b)
}
$ go run x.go
# command-line-arguments
./x.go:11:14: invalid operation: a == b (slice can only be compared to nil)

雑に使い捨てコードを書いているときにいちいちスライスの要素を一つ一つ比較する関数を書くのはめんどくさい。

無理やり比較する
package main

import (
	"fmt"
)

func main() {
	a := []int{1, 2, 3}
	b := []int{1, 2, 3}

	fmt.Printf("# %q == %q\n", a, b)
	fmt.Println(fmt.Sprintf("%q", a) == fmt.Sprintf("%q", b))
}
 go run x.go
# ['\x01' '\x02' '\x03'] == ['\x01' '\x02' '\x03']
true

比較したい値をSprintfによって文字列にする。その文字列の比較によってその値が等しいかを調べてしまう。

注意点

ただのハックなのでちゃんとしたコードを書く場面では使わないほうがいいだろう。