去年のnonyleneくんのブログを読んだ僕の、一年越しの回答です。
nonylene.hatenablog.jp
poyo.hatenablog.jp
ISUCON13に参加し、最高107000点くらい 106457点をマークしましたがfailしたチーム ツナ缶です。来年は優勝します。
公式から全チームのスコアおよび結果が出ました。failしていなければ最低でも16位くらいだったと思われ、大変無念です。
ISUCON13 受賞チームおよび全チームスコア : ISUCON公式Blog
今回は割とよい分析基盤が出来たかなと思ったので紹介します。
メンバー紹介:
Grafana Cloudとは
詳しくは↓を参照
poyo.hatenablog.jp
2ヶ月ほど前に家の監視基盤をGrafana Cloudに移したのは、ISUCONに向けた素振りをするためでもありました。Grafana Cloudで基盤を作ると良さそうと感じたのは主に以下の点でした。
ログの閲覧ができる
ログをパースしてメトリクスとして集計して可視化できる
メトリクスを送信することでサーバの負荷状況を同じプラットフォームで可視化できる
Goのpprofに対応した継続的プロファイリングにより、フレームグラフを同じプラットフォームで閲覧できる
上記を全て単一のAgentでアプリにほとんど手を入れずに実現できる←ここ重要
他にも仕事でGrafanaやPrometheus、Lokiとは仲良くしているので、これらを使った解析基盤は自分の知見が活かせるのでは(そして仕事でも使えるのでは)という思惑がありました。
できたもの
API エンドポイントごとの解析
エンドポイントごとのレスポンスタイムの解析
alp相当の解析ができるダッシュ ボードです。nginxのアクセスログ をパースしてAPI エンドポイント・メソッド・レスポンスタイムの情報を頑張って組み立てています。各テーブルヘッダをクリックすることでインタラクティブ にソートできるので、見たい人が見たい順に並べ直すことができます。
各URI はリンクになっており、各エンドポイントごとの詳細を別ダッシュ ボードで閲覧できるようになっています。
あるエンドポイントに関する詳細の解析
これらは全てグラフや右上の日時指定ボタンから指定日時のデータを見ることができるため、何時頃の結果、などを解析することも可能です*1
ログの閲覧・検索
アプリケーション・nginxのログの横断閲覧および検索
時間範囲を指定して、アプリケーションやnginxのログを一つの画面で横断検索できるようにしました。ページ上部のドロップダウンメニューから見るインスタンス (全てまとめてみることも可)を、検索ボックスに任意文字列を入れて絞り込みなどができるようになっています。これらは自分はベンチマーク のfail時などによく確認していました。
またエンドポイントごとの詳細画面では、エンドポイントの正規表現 を使ってログをフィルタし、特定のエンドポイントのアクセスログ だけを引っ張って来るなどもしていました。
エンドポイントごとのログの閲覧
MySQL でスロークエリログを有効化した場合、それも収集するようにしていました。これの数はかなり膨大で結構大変な事になっていたと思います。
スロークエリログの閲覧および検索
指定した時間範囲で指定した秒数以上かかったクエリを表示することができます*2 。ロック時間などで並び替えることも出来るようになっています。
各インスタンス ではNode Exporterが動作しており*3 、各ホストの状況のメトリクスを送っていました。今回は15秒に一回送信することにしていましたが、もう少し解像度が高い方がISUCONという競技では使いやすかったなと思います。
Node Exporterのダッシュ ボード
フレームグラフの表示
Grafana LabsがPyroscopeを買収したことにより実現した機能です。Grafana Agentが定期的に /debug/pprof/profile
などを叩くことで、Grafana Cloudへこれらのプロファイリングデータを送信して可視化しています。
Goアプリケーションのフレームグラフ
各関数にフォーカスして拡大することもでき、検索ボックスから特定の関数を調べることも可能です。go tool pprof
を使って閲覧するのと変わらないような使い勝手で、しかもこちらが実施することは最初のGrafana Agentのセットアップと、Goアプリケーションでのpprof対応だけでした。セットアップはAnsibleで自動化済み、pprof対応はlabstack/echoでは依存足して1行書き足すだけだったので、ほぼ労力ゼロでこれが使えるのはかなり良いと思いました。
ログ・メトリクス・プロファイルが全て単一のプラットフォームで見れるため、他のツールの使い方を覚えたりログインを使い分ける必要がありません。また、当日に追加で行った変更は以下のような、Grafana Cloudを用いなくてもやっているいつものことだけです。
nginxのログ形式の変更
MySQL のスロークエリログの有効化
Goアプリケーションのpprof対応
API エンドポイントを識別する正規表現 の記述
これらの対応を全て終えてISUCON本番で完全に動作し始め、ベンチマーク 結果を解析出来るようになったのはおおよそ競技開始から40分後くらいでした。その間もtaxioにはマニュアルの読み込みやUIを触って理解を深めてもらうなどをやってもらっており、初動としてはそこまで悪くないかなと思っています。
さらに、そこから先で解析基盤に手を入れることはほとんどありませんでした。撤退も単にGrafana Agentを消す、pprof対応を消す、ログを出さないようにするだけで良いので非常に簡単でした。
構築編
Grafana CloudはSaaS なので、自分でセルフホストする必要がありません。収集対象のインスタンス にエージェントを入れるだけで使えます。
Grafana Agent Flowのインストール
Grafana Cloudへのログやメトリクス、プロファイルデータの送信にはGrafana Agentというエージェントを利用します。これはstatic mode (YAML で設定を書ける)とflow mode (HCLみたいなriver という設定言語で書ける)の2種類のモードがありますが、プロファイルデータを送れるのがflow modeだけなので今回はflow modeを使います。
GitHub Releasesでdebパッケージが公開されている ので単にこれをダウンロードしてきて各ホストに入れます。自分はAnsibleで全ホストにサクッと入れられるようにしておきました。
また、送信に必要なのでGrafana CloudのAPI キーを各ホストに撒いておきます。適当なところにファイルに書いて置いておきました。Grafana CloudではAPI キーのExpire dateを設定できるので、翌日とかにしておくと安心です。
メトリクスを収集する
flow modeではriverで設定ファイルを書くのですが、これはモジュール化出来るようになっています。今回は以下の様なモジュールを書いていました。
argument "write_to" {
comment = "remote write target"
}
prometheus.exporter.unix "default" {
include_exporter_metrics = false
set_collectors = [
"cpu" , "diskstats" , "filefd" , "filesystem" , "loadavg" , "meminfo" , "netclass" , "netdev" , "vmstat" , "sockstat" ,
]
filesystem {
fs_types_exclude = "^(autofs|binfmt_misc|bpf|cgroup2?|configfs|debugfs|devpts|devtmpfs|tmpfs|fusectl|hugetlbfs|iso9660|mqueue|nsfs|overlay|proc|procfs|pstore|rpc_pipefs|securityfs|selinuxfs|squashfs|sysfs|tracefs)$"
}
netclass {
ignored_devices = "^(veth.*|cali.*|[a-f0-9]{15})$"
}
netdev {
device_exclude = "^(veth.*|cali.*|[a-f0-9]{15})$"
}
}
prometheus.scrape "unix" {
targets = prometheus.exporter.unix.default.targets
forward_to = [ argument.write_to.value]
scrape_interval = "15s"
}
このモジュールを使う側では、以下の様に宣言するだけです。
local.file "api_key" {
filename = "/etc/grafana-agent-api-key"
is_secret = true
}
prometheus.remote_write "grafanacloud" {
endpoint {
url = "REMOTE WRITE URL"
basic_auth {
username = "BASIC AUTH USER"
password = local.file.api_key.content
}
}
}
prometheus.relabel "replace_instance" {
forward_to = [ prometheus.remote_write.grafanacloud.receiver]
rule {
action = "replace"
target_label = "instance"
replacement = "{{ inventory_hostname }}"
}
}
module.file "nodeexporter" {
filename = "/etc/grafana-agent/rivers/nodeexporter.river"
arguments {
write_to = prometheus.relabel.replace_instance.receiver
}
}
ログを収集する
ISUCONではログの収集パターンは主に2つだと考えていました。
journaldのログ(journalctl -u ~~
などで見る物)
ローカルにあるファイルに書かれるログ
Grafana Agentではどちらも対応可能です。まずはjournal logの収集から。
argument "write_to" {
comment = "Loki remote write url"
}
loki.relabel "journallog" {
forward_to = []
rule {
source_labels = [ "__journal__systemd_unit" ]
target_label = "app"
}
rule {
source_labels = [ "__journal_priority_keyword" ]
target_label = "level"
}
}
loki.source.journal "journallog" {
forward_to = [ argument.write_to.value]
max_age = "10m"
relabel_rules = loki.relabel.journallog.rules
labels = {
job = "loki.source.journal" ,
}
}
このモジュールを使ってGrafana Cloudに送信する設定は以下
loki.write "grafanacloud" {
endpoint {
url = "REMOTE WRITE URL"
basic_auth {
username = "BASIC AUTH USER"
password = local.file.api_key.content
}
}
}
loki.process "drop_abnormals" {
forward_to = [ loki.write.grafanacloud.receiver]
stage.drop {
longer_than = "255KB"
drop_counter_reason = "too long"
}
stage.drop {
older_than = "1h"
drop_counter_reason = "too old"
}
}
loki.relabel "replace_instance" {
forward_to = [ loki.process.drop_abnormals.receiver]
rule {
action = "replace"
target_label = "instance"
replacement = "{{ inventory_hostname }}"
}
}
loki.relabel "filter_app" {
forward_to = [ loki.relabel.replace_instance.receiver]
rule {
source_labels = [ "app" ]
regex = "^isupipe-go.*$"
action = "keep"
}
}
module.file "journallog" {
filename = "/etc/grafana-agent/rivers/journallog.river"
arguments {
write_to = loki.relabel.filter_app.receiver
}
}
次にファイルからのログを収集します。単純なログであれば以下の様に書けば収集できます。
argument "write_to" {
comment = "Loki remote write target"
}
loki.process "error" {
forward_to = [ argument.write_to.value]
stage.static_labels {
values = {
app = "mysql" ,
type = "error" ,
}
}
stage.label_drop {
values = [ "filename" ]
}
}
local.file_match "errorlog" {
path_targets = [{ "__path__" = "/var/log/mysql/error.log.*" }]
}
loki.source.file "error" {
targets = local.file_match.errorlog.targets
forward_to = [ loki.process.error.receiver]
tail_from_end = true
}
先述したようにriverでは様々なモジュール同士の接続を自由に書けるので、このモジュールとjournallogモジュールはログの処理フェーズを共有できます。
module.file "mysql_error_log" {
filename = "/etc/grafana-agent/rivers/mysql_error_log.river"
arguments {
write_to = loki.relabel.replace_instance.receiver
}
}
nginxのアクセスログ を元にダッシュ ボードを表示したいのですが、通常はパスにパラメータなどが入っており統計処理に向いていません。同様のことにnonyleneくんも気付いており、収集時に正規化するという方法を取っていました。
nonylene.hatenablog.jp
Grafana Agentにおいても同様の処理を行います。前提としてnginxのログ形式は以下の様になっているとします。
log_format main "time:$time_local"
"\thost:$remote_addr"
"\tforwardedfor:$http_x_forwarded_for"
"\treq:$request"
"\tstatus:$status"
"\tmethod:$request_method"
"\turi:$request_uri"
"\tsize:$body_bytes_sent"
"\treferer:$http_referer"
"\tua:$http_user_agent"
"\treqtime:$request_time"
"\tcache:$upstream_http_x_cache"
"\truntime:$upstream_http_x_runtime"
"\tapptime:$upstream_response_time"
"\tvhost:$host"
"\trequest_id:$request_id";
access_log /var/log/nginx/access.log main;
まずは前処理としてnginxのログをパースします。
loki.process "access" {
forward_to = [ loki.relabel.access.receiver]
stage.static_labels {
values = {
app = "nginx" ,
type = "access" ,
}
}
stage.label_drop {
values = [ "filename" ]
}
stage.regex {
expression = "^time:(?P<time>.*)\\thost:(?P<host>.*)\\tforwardedfor:(?P<forwardedfor>.*)\\treq:(?P<request>.*)\\tstatus:(?P<status>.*)\\tmethod:(?P<method>.*)\\turi:(?P<uri>.*)\\tsize:(?P<body_bytes_sent>.*)\\treferer:(?P<http_referer>.*)\\tua:(?P<http_user_agent>.*)\\treqtime:(?P<request_time>.*)\\tcache:(?P<upstream_http_x_cache>.*)\\truntime:(?P<upstream_http_x_runtime>.*)\\tapptime:(?P<upstream_response_time>.*)\\tvhost:(?P<vhost>.*)\\trequest_id:(?P<request_id>.*)$"
}
stage.timestamp {
source = "time"
format = "02/Jan/2006:15:04:05 -0700"
}
stage.labels {
values = {
status_normalized = "status" ,
uri_normalized = "uri" ,
}
}
}
local.file_match "accesslog" {
path_targets = [{ "__path__" = "/var/log/nginx/access.log.*" }]
}
loki.source.file "access" {
targets = local.file_match.accesslog.targets
forward_to = [ loki.process.access.receiver]
tail_from_end = true
}
後は実際に本番で実装されているエンドポイントに合わせて設定ファイルを書いて正規化させるだけです。
loki.relabel "access" {
forward_to = [ argument.write_to.value]
rule {
source_labels = [ "status_normalized" ]
regex = "^([0-9])[0-9]+$"
replacement = "$ { 1 } XX"
target_label = "status_normalized"
}
rule {
source_labels = [ "uri_normalized" ]
regex = "^(.*)\\?(.+)$"
replacement = "$1"
target_label = "uri_normalized"
}
rule {
source_labels = [ "uri_normalized" ]
regex = "^/api/user/[a-zA-Z0-9]+$"
replacement = "/api/user/[a-zA-Z0-9]+"
target_label = "uri_normalized"
}
}
Grafanaのダッシュ ボードではこの送信されたログを再度同じ正規表現 でパースし直してレスポンスタイムを取りだし、ラベルとして付与された uri_normalized
などを元に行数をカウントしたり最悪レスポンス時間を取り出したりしています。
スロークエリログの収集
MySQL のスロークエリログは、一行ごとに結果が出るのではなく複数行にわたっています。こういったログも設定を書くことで収集できます。
loki.process "slowquery" {
forward_to = [ argument.write_to.value]
stage.static_labels {
values = {
app = "mysql" ,
type = "slowquery" ,
}
}
stage.label_drop {
values = [ "filename" ]
}
stage.multiline {
firstline = "^#\\sTime:.*$"
}
stage.regex {
expression = "#\\s*Time:\\s*(?P<timestamp>.*)\\n#\\s*User@Host:\\s*(?P<user>[^\\[]+).*@\\s*(?P<host>.*]).*Id:\\s*(?P<id>\\d+)\\n#\\s*Query_time:\\s*(?P<query_time>\\d+\\.\\d+)\\s*Lock_time:\\s*(?P<lock_time>\\d+\\.\\d+)\\s*Rows_sent:\\s*(?P<rows_sent>\\d+)\\s*Rows_examined:\\s*(?P<rows_examined>\\d+)\\n(?P<query>(?s:.*))$"
}
stage.timestamp {
source = "timestamp"
format = "RFC3339Nano"
}
}
local.file_match "slowquery" {
path_targets = [{ "__path__" = "/tmp/slow_query.log*" }]
}
loki.source.file "slowquery" {
targets = local.file_match.slowquery.targets
forward_to = [ loki.process.slowquery.receiver]
tail_from_end = true
}
これは生データのみしか収集できないので、pt-query-digest等も組み合わせることを検討すべきかも知れません。自分たちのチームではpt-query-digestはそれは別途ベンチの度に走らせてリポジトリ のIssueに結果を書いており、それで済ませていました。
ベンチマーク 実行ごとに投稿されるコメント
プロファイルデータの取得
Goアプリケーション自体が /debug/pprof エンドポイントを実装していれば、Grafana Agentが書くことはたったこれだけです。実際にはインスタンス 名やサービス名、アクセス先のポート番号などは全てAnsibleで動的に埋めています。
pyroscope.write "grafanacloud" {
endpoint {
url = "REMOTE WRITE URL"
basic_auth {
username = "BASIC AUTH USER"
password = local.file.api_key.content
}
}
}
pyroscope.scrape "pprof" {
targets = [
{ "__address__" = "localhost:8080" , "instance" = "{{ inventory_hostname }}" , "service_name" = "isupipe" } ,
]
forward_to = [ pyroscope.write.grafanacloud.receiver]
scrape_interval = "15s"
}
ハマったところ
何でもログのラベルに付与すると死ぬ
Grafana Cloudのログ収集機能には max_global_streams_per_user
というハードリミットがかかっています。値は5000です。
grafana.com
これは送信するログに付与するラベルの値の組み合わせの数が相当します。つまり、インスタンス の数が5つあり、それぞれ3種類の値を取るラベルが2つあるとすると、5 × 2 × 3 = 30
のactive streamとなります。
当初、nginxのアクセスログ をパースして全てラベルとして付与していましたが、練習の段階でGrafana Agentがこのリミットに引っかかったというエラーを吐いていました。当然です。レスポンスタイムの値、正規化していないURLのパスなどがそのまま入ると、あっという間に5000通りくらいの組み合わせに到達します。
一度に全ログが取得できるわけではない
Grafanaのダッシュ ボードではTransformという取得したメトリクスを加工する機能が存在しています。そこでGROUP BYしてカウントしたりも可能です。最初期のダッシュ ボードではLogQLを使ってnginxのアクセスログ を全行取ってきてTransform機能でカウントしようとしていましたが、デフォルトでは1000行まで、最大でも5000行までしか一度に取得できず不完全な解析となってしまいました。
最終的には以下の様にLogQLでメトリクスを取ってきて、Transformは最低限になっています。
エンドポイントごとの解析に使われているクエリ
エンドポイントごとの解析画面のTransform
メトリクスのDPM
送信するログ量自体は競技時間全てを合わせても無料枠を超えませんが、メトリクスをどの頻度で取得するかによって課金額に影響するDPMというパラメータがあります。
grafana.com
これは Data points per minute
の略で、Grafana Agentのscrape intervalのデフォルト60秒が1DPMです。これがGrafana Cloud FreeおよびProアカウントのデフォルトです。これを超えた場合、課金額に影響があります。ISUCONでは60秒ごとでは遅すぎるので、競技中のみ15秒に一回スクレイプするようにしました。おそらくこれくらいなら大丈夫ですが、長期間使うインスタンス では辞めておくべきでしょう。
競技終盤はアクセス数が増えて解析が遅い
これは正規表現 でアクセスログ をパースしていたことによる可能性を拭えないのですが、競技終盤になるとエンドポイントごとの解析画面は結果の表示に数十秒かかるようになってしまいました。フレームグラフは見れるので、とりあえず開いてクエリを走らせている間にフレームグラフを見るといた感じにしていました。
一位のNaruseJunのチームだとおそらく中盤当たりで使い物にならなくなっていた可能性があります。とはいえほとんどのチームでは自分たちが捌いていたくらいのアクセス数に収まっていると思うので、十分実用的と言えるのではないでしょうか。
完全に同じログ行は重複排除で消える
今回前提としたnginxのログの形式は実はalpのREADMEに書かれているLTSV形式そのままではなく、末尾にrequest_idを追加しています。これはGrafana CloudというかおそらくそのバックエンドになっているLokiのQuerierの制約を回避するためです。
QuerierはLogQLを元に、データを問い合わせて返すコンポーネント です。
https://grafana.com/docs/loki/latest/get-started/components/#querier
the querier internally deduplicates data that has the same nanosecond timestamp, label set, and log message.
これには冗長化 のために重複しているログを排除するという機能が実装されています。nginxのログのタイムスタンプの精度は秒単位のため、アクセス数の多いエンドポイントでは容易に全く同じログが吐かれてしまうことがあり、alpの結果とGrafanaダッシュ ボード上での結果が一致しないことが起きていました。
ログ行自体が完全に一致しなければ異なるログ行として扱われるため、request_id(リクエス トごとに一意な値)を出力することで、重複排除によって消えないようにしています。
本番でやったこと・感想
自分が本番でやったことです。
~10:40:環境構築・解析基盤の準備
~12:00:icon画像をDBから剥がしてX-Accel-Redirectでnginxにサーブさせ、sha256のチェックサム をオンメモリにキャッシュ
~13:30:ミドルウェア のチューニングや、moderateHandlerの高速化
~15:30:DNS 水責め対策に奮闘したが失敗
~17:00:DBのレプリケーション をしてリードレプリカを使うようにしたが整合性チェックが通らず失敗
~17:30:最終的な複数台構成にした。(nginx, app, pdns)、(DB for app)、(DB for DNS )という構成。
~18:00:全ての解析系を止めて再起動試験をし、キャッシュ実装がダメでfailすることに気付く
途中ベンチマーク の不具合で大きな変更がちゃんと通るかどうかを検証できず、競技時間伸びないかなとちょっと期待していました。それは叶わず残念。
taxio、shanpuがあらゆるものをメモリに載せようと奮闘している間に自分はDNS 水責めの対策をしていました。正直に言ってDNS の知見があまりに乏しく、PowerDNSの設定を変えてDBの向き先を変更してアプリのDBの負荷を減らすのが限界でした。しかし、これも最善手だったとは思っていません。DNS を正しく捌いてしまうことでむしろアプリの負荷が増えていた可能性があります。DNS サーバを自前実装する可能性を一瞬検討し、理解と実装に半日はかかると踏んでDNS を切り捨てる判断をしました。チャレンジすべきだったのかなぁと後悔はつきません。
今回のアプリケーションはread heavyなワークロードなのでリードレプリカが効くかと思ったのですが、自分が途中でミスってレプリケーション そのものに時間がかかったこと、組んだ構成が整合性チェックでどうしても通らなかったことで諦めたのも時間的には痛かったです。後から思えば、もっとオンメモリで処理できました。これは仕事ではないのでSREとしての自分を捨てるべきでした。
あとはキャッシュ実装が速さを優先するあまり初期化や再起動後の状態への意識を失っており、おそらく参加して初のfailでの終了となりました。これはあまりにも痛いです。いくら高スコアを記録しても、failしていては改善しないのと同じです。
良かったところを言うと、自分の役目は基本的に解析基盤を整え、アプリ担当が1コマンドで本番に変更を反映出来る状況にした時点で終わっていると言えなくもないです。後はX-Accel-Redirectでnginxに静的ファイルを捌く処理を移す改善を午前で終わらせられ、午後の余裕がなかったタイミングで取り組む必要が無かったのは心理的 に非常に効きました。自分の経験値がまだまだだということがよく分かったので、参加して良かったです。運営の方々、今年もありがとうございました。
まとめ
Grafana Cloudはアプリケーションにできるだけ手を入れず、いつも通りの構成のままインフラ担当が裏から手を回して基盤を構築出来る便利なSaaS です。アプリ本体に手を入れれば、OpenTelemetryで分散トレーシングも可能です。無料枠も大きいので事前の練習などで使うのもおすすめです。
ISUCON12で初の本選出場を果たし、ISUCON13は逆にfailして失格しました。ラノベ のセオリーとしては次は優勝のはずなので、来年も頑張ります。