ISUCON 12 予選にいつもの id:utgwkk, id:wass80 と :old_noto_innocent: チームで参戦した*1。
結果は 50696 点で本選出場！
ここ数回と同様、自分はインフラと分析・観測を担当していた。ただ、毎年似たようなことをやっていてあまり貢献できていないなあという課題感があったので、今回はログやメトリクスの分析環境をしっかり作ることにした。目標は毎回ベンチ終了のたびにコマンドを叩くのをやめること！
App 周りについてはチームメイトの記事を参照。
Elastic Stack でアクセスログ・スローログ可視化
ログを集約・可視化する代表的なアーキテクチャとして、Elastic Stack がある。 もともと Elasticsearch + Logstash + Kibana の組み合わせの "ELK Stack" が有名だが、最近は軽量ログシッパーである Filebeat も合わせて Elastic Stack というらしい。
↑ヘラジカの漫画が自己を見つめ直す話でよかったです。
Loki + Promtail + Grafana とどちらにしようか迷った結果、あんまり使ったことのない Elastic Stack を使ってみることにした。 あと Kibana って語感が好き。
ダッシュボード 最高便利
Filebeat から Nginx のログ、 app ログ、 MySQL スローログを Elasticsearch に投げ、それを Kibana で Log stream やダッシュボードで見れる環境を作った（構築については後述）。
Nginx はパスごとのアクセス数とそのレスポンスタイムの装合計、MySQL はスローログのクエリとその時間の総合計などを出すようにしている。
特にダッシュボードが便利で、アクセスログやスローログを見るときに特定の時間で絞り込んだ集計が簡単にできる*2ため、ベンチを回す → 集計結果を見る という流れがとてもスムーズにできた。
ログは結局 journalctcl で見るのが早いのであまり使わなかった気がする。次はダッシュボードでエラーログもサクッと見れるようにしてもいいかもしれない。
Google Cloud でトレーシング & プロファイリング
トレーシングやプロファイリングは Google Cloud を使うことにした。Google アカウントは誰でも持っているので、チームメイトへの権限が簡単に配れてオススメ。
Trace
前回は OSS の Jaeger を使ったが、 UI が使いにくかったりインメモリだと遅かったりで微妙だったので、ちゃんとマネージドサービスを使うことにした。
Google Cloud Trace は OpenTelemetry に対応しているので、サードパーティの Trace library を使って構築できて便利だった。予選では MySQL と HTTP リクエストに対してトレースを仕込んだ。
Profiler
Google Cloud Profiler は
- 導入がとても簡単
- go ファイルの最初にちょろっと書くだけ
- コンソールが見やすい
- 無料！！
という3拍子揃った神サービスだった。
バージョン番号を変えてデプロイし続けていたら競技途中で1日のデプロイ数 quota （75）に引っかかったので、そこは注意。
やってよかった
…このように今回は色々リアルタイム可視化グッズを用意して挑んでみた。
ISUCON でのこのような集計は pt-query-digest や kataribe / alp や pprof を使うのが定番だが、今回はインストールだけはしたものの一度も使わずに済んだ。コマンドだとどうしても
ログ退避 → ベンチ → 集計コマンド発行 → 結果の共有 → テキストベースの解読
といった作業が必要になるが、 Kibana や GCP コンソールでそれを一気に省略できたのが大きかった。集計結果が Slack チャンネルに流れていかず、チームメイトが見たいときに自分で操作して確認できるのも良いことだと思う。
当日ダッシュボードを触ったりと付け焼き刃なところもあったが、チームメイトからも好評だったので準備したかいがあった。
ちなみに、これらの分析のオーバーヘッドはそこそこある。echo のデバッグモードなども行っていたのでどれが原因かは分からないが、全てを外してベンチを回すと 36k だったスコアが 50k ぐらいになって盛り上がった。
構築編
Elasticsaerch + Kibana 準備
個人の GKE クラスタに強めのノードをたてて*3、そこに Elasticsearch と Kibana を立ち上げた。
Elasticsearch には elastic と kibana_system ユーザー向けのパスワードを設定する *4。
実際にはこんな感じ。
↓ elastic のパスワード
↓ kibana_system のパスワード
- name: password image: curlimages/curl command: ["sh", "-c", "until curl -X POST -u elastic:${ELASTIC_PASSWORD} -H 'Content-Type: application/json' -k http://elasticsearch:9200/_security/user/kibana_system/_password -d \"{\\\"password\\\":\\\"${KIBANA_PASSWORD}\\\"}\" | grep -q '^{}'; do sleep 10; done;"]
Kibana へのアクセスはちょっとめんどくさくて、
- 人間が見る用のパス
- Filebeat から叩く用のパス
- ダッシュボードの自動構築などで使われる
がある。人間が叩く用のパスは OIDC を使うのが正規ルート だろうが、今回は既に構築していた oauth2-proxy 背後にしていたので Kibana 自体は anonymous でアクセスできるように した。
ただ、oauth2-proxy 背後だと Filebeat からのアクセスができなくなるので、別途 Basic Auth 付きの endpoint を用意して Filebeat からはそれを叩かせるようにした*5。こうやってポコポコ endpoint 生やせるのは k8s のいいところ。
その他、各種データは永続化する必要がある。今回は Node Pool がスケーリングしないように設定した上で hostPath を使う超雑ソリューションをしてしまった…。作ったダッシュボードとかエクスポートするまでこのインスタンス落とせないじゃん…*6。本選までには PV 使うようにしたい。
Filebeat
Filebeat は競技インスタンスにインストールする。モジュールやプラグインが充実していて、数行設定を変更するだけで journald、 Nginx、 MySQL log それぞれの収集 & メトリック化を有効化できて楽だった。
一点、 Nginx でレスポンスタイムを記録するためには、 Nginx ログフォーマットの変更 + Filebeat のパース設定の変更を行う必要がある。 kataribe 互換のログフォーマット（デフォルトフォーマットの末尾にレスポンスタイムを追加する）の場合、以下のリンクの通りにすると nginx.response.time がメトリクスとして上がるようになった。
追記（Nginx）
予選・本選で試してみたところ各種 id が入ったパスが分散して表示されてしまう課題があったので、 Filebeat の Nginx module の設定を触って集約して表示できるようにした。
追記（MySQL）
本選時は init 時の MySQL スロークエリが大きすぎて Filebeat がメモりを食って OOM になる問題があった。 init 関係のクエリは頑張って記録する必要はないので、 max_bytes で一行あたりの最大長を調整し、大きすぎるログはスキップするようにすることで解決した*7。
- module: mysql ... slowlog: enabled: true input: max_bytes: 100000 # Limit up to 100k bytes
スローログそのままだと本戦ではいくつか問題が出てきたので、pt-query-digest の結果を出せるようにもしてみた。詳しくは↓を参照。発展編って感じ。
ダッシュボード
今回 Elastic Stack を選んで最も良かった点は、ダッシュボードが簡単に構築できたこと。 Filebeat と Kibana の連携が整っており、Filebeat のセットアップコマンドで Kibana ダッシュボードを自動生成してくれる。
この機能があったおかげで、自動生成されたダッシュボードを Clone & 参考にすることができ、 Nginx, MySQL のダッシュボードを高速に設定できた。
（参考） ダッシュボードを export したものは以下。
個人的には、 Grafana よりも Kibana のほうが編集画面の UI がしっかりしていてビギナーでも使いやすいと思う。オススメ。
タイムライン
最後に、準備と当日やったことの記録。
前々日
- 全然準備やってないことに気づく :old_noto_innocent:
- Elastic Stack のドキュメントを眺め、 Elasticsearch と Kibana の連携までやって力尽きる
前日
- Filebeat の検証
- nginx と journal が取れることを確認した
- nginx のレスポンスタイムと MySQL スローログは当日の課題とした :old_noto_innocent:
- Kibana でのログ閲覧やダッシュボードの準備
- トレーシングやプロファイラの試行 w/ チームメイト
当日
だいたいいつも通りで、サーバーの水やり当番をしていた。
- 30分前に起きて、20分前からライブが始まることを知る
- カーネル起動パラメーターを変更する
- 起動しなくなったら最悪なので最初に
- いつものサーバーもろもろ整備
- サーバー眺めて不要そうなプロセス止める
- sysctl チューニングしたり、max open files 変えたり
- netdata 入れる
- これはいつもどおり役に立った。ベンチマーク中のリアルタイムな負荷傾向を見るにはこれが一番。
- filebeat 入れて各種設定
- ダッシュボード整備（付け焼き刃ポイント）
- MySQL のメモリ調整
- 富豪的に設定していたらメモリがなくなってホストへの疎通が失われることが数回あったので、やや控えめに
- 分割した後は上げといてもよかった。最後余ってたから大差ないだろうけど
- 富豪的に設定していたらメモリがなくなってホストへの疎通が失われることが数回あったので、やや控えめに
- クエリキャシュ目当てに MySQL 5.7 に戻そうとしたが無理だったので諦める
- Ubuntu 22.04 に対応したパッケージがなかった
- MySQL 別ホスト移行、垂直分割準備
- 今回は初めから
%のユーザーがあったので bind 変更するだけだった
- 今回は初めから
- Nginx キャッシュ
- 今回は多分関係ない
- GOGC の調整
- GOGC=off にしたらメモリを食いまくってホストが死んだ（当たり前すぎる）
- 最終的に 300 に。1000点分くらいの効果はあった
- 最後にトレーシングとか全部 purge して、再起動試験
- Filebeat が purge してもゾンビのように生きていてこわかった（
systemctl disableした）
- Filebeat が purge してもゾンビのように生きていてこわかった（
- 競技終了後に MySQL スローログを切り忘れたのに気づく
最終的に nginx + App 1台、MySQL 2 台の構成になった。App がカツカツだったので、もっと時間があったら or スコアに余裕がなかったら App を増やす作業をしていたと思う。
感想
今回も楽しかったです！SQLite を知ったときはウケました。 本選も楽しみ！！
毎年 id:utgwkk id:wass80 がアプリやクエリ周り見てくれるので大感謝 :pray: 今回もアプリのコードは3分くらいしか見ていないので自分だけだと絶対ムリそう。
サーバー周りは年々整備されていてやらないといけないことが減っている印象があって、サーバー触り担当としてはこういう基盤まわりで貢献していきたいところ。今後の課題としては基盤周りのブラッシュアップと、Redis や Varnish をサクッと触れるようにすることかな。セッション周りも Sticky module に頼った分散から脱却したいと思ったり…。
その他
最近ピノキオピーのデラシネをめっちゃ聞いてます。構築中ずっと流してました。今も流してます。電子音最高です。
*1:Slack に登録している :innocent: が Noto emoji だったころのグリフを使った絵文字
*2:アクセス数のグラフを出しておくと、いつベンチが回ったかすぐに分かる。そこでドラッグすると時間の設定が可能
*3:e2-standard-2
*4:kibana_system については、手作業でやるなら Enrollment Token を使えば良さそう。k8s で立ててるとコンテナが作り直されたりするので固定パスワードを設定した https://www.elastic.co/guide/en/elasticsearch/reference/master/create-enrollment-token.html
*5:実際はさらに複雑で、Filebeat から Kibana の API を叩くには Anonymous user だとできなかったので、ingress-nginx で set_proxy_header を行い Filebeat から来たリクエストの Basic auth credential を elastic ユーザーのものに上書きする処理を行っている。
*6:Kibana のダッシュボードなどのデータは Elasticsearch に保存されているので、正確には Elasticsearch の乗ったインスタンスを落とすまで。
*7:本選後に
