ISUCONでログの可視化と分析をやってみた話

2022/03/27 #traP_LT にて発表
https://connpass.com/event/242713/

Transcript

1. @nagatech 2022 年03 月27 日( 日) traP LT 2022 ISUCON でログの分析と可視化を やってみた話 2022/03/27 traP LT 2022 #traP_LT
2. nagatech( ながてち) Twitter: @_nagatech ex-traQ サーバー管理者 4 月から社会人3 年目 都内でサーバーエンジニアやってます 最近DJ 始めました Twitch(@nagatea_p) で配信してる フォローしてくれ！！！ 自己紹介 2022/03/27 traP LT 2022 #traP_LT
3. 今日話すこと ISUCON とは システムの紹介 デモンストレーション ハマったところ ISUCON で競技中リアルタイムにベンチマークのロ グを収集し結果を分析できるシステムを構築し予選 を戦ったので、詳細と運用した顛末を紹介します。 “ “ 2022/03/27 traP LT 2022 #traP_LT
4. ISUCON とは ISUCON 8, 9 は本選出場 ISUCON 10, 11 は予選落ちました お題となるWeb アプリケーションを時間内にいかに高速化できるか を競うコンテスト 高速化手法は( レギュレーションを守れば) なんでもやっていい 1 〜3 人1 チームで600 チーム予選参加→30 チームが本戦出場 2022/03/27 traP LT 2022 #traP_LT
5. ISUCON において大事なこと なんでしょう？ ISUCON LINE スタンプ発売中！ 2022/03/27 traP LT 2022 #traP_LT
6. ISUCON において大事なこと 答え ISUCON LINE スタンプ発売中！ 2022/03/27 traP LT 2022 #traP_LT
7. ISUCON において大事なこと 推測するな計測せよ 計測した結果に基づいて高速化を検討しようということ あなたはプログラムがどこで時間を消費しているか を理解していない。ボトルネックは予想外のところ にある。推測するな。どこにボトルネックがあるか 証明されるまで高速化するな。 計測せよ。計測するまで高速化するな。計測して、 コードの一部分が他の部分より圧倒的に時間を消費 しているのでなければ、高速化をするな。 “ “ 2022/03/27 traP LT 2022 #traP_LT 　引用: https://scrapbox.io/nishio/ 推測するな、計測せよ
8. 計測手段とツールいろいろ( 一例) kataribe リクエストログからリクエスト数や処理時間を計測 myprofiler MySQL の実行計画からクエリの実行回数を計測 pt-query-digest MySQL のスロークエリログから遅いクエリを計測 dstat CPU 使用率等のパフォーマンスを計測 2022/03/27 traP LT 2022 #traP_LT
9. 計測手段とツールいろいろ( 一例) ISUCON 10 ではMakefile で一連のコマンドを叩いて 結果をSlack に投稿するまで自動化してた 各ツールを毎回実行して見比べるのは大変 いつのベンチマークの結果か分からなくなる 2022/03/27 traP LT 2022 #traP_LT
10. ログ分析システムを構築した 2022/03/27 traP LT 2022 #traP_LT
11. 2022/03/27 traP LT 2022 #traP_LT
12. kataribe をイメージして作成 fluentd のnginx プラグインを使 用して収集 データを正規表現で置換して 定量化 例: /view/isu/123 → /view/isu/* リクエストログの分析 2022/03/27 traP LT 2022 #traP_LT
13. myprofiler をイメージして作成 fluentd のnata2 プラグインを使 用して収集 データを正規表現で置換して 定量化 MySQL スロークエリログの分析 例: SELECT * FROM isu_condition WHERE jia_isu_uuid = "hoge" LIMIT 10 → SELECT * FROM isu_condition WHERE jia_isu_uuid = S LIMIT N 2022/03/27 traP LT 2022 #traP_LT
14. よくみるやつ CPU 、メモリ、帯域etc... fluentd のdstat プラグインを使 用して収集 パフォーマンスモニタリングだ けでなく、負荷が大きいプロセ スを記録して分析できるように した サーバーパフォーマンスの分析 2022/03/27 traP LT 2022 #traP_LT
15. 環境のセットアップ 分析側( ながてちサーバー) docker で「elasticsearch 」と 「kibana 」のイメージを立ち 上げる ログ送信側( 競技サーバー) fluentd とプラグインをインストール 各サーバーに設定ファイルを配置 事前に仕込んでおいたMakefile でコマンド一発 2022/03/27 traP LT 2022 #traP_LT
16. デモンストレーション システムとデータがまだ残ってたので実際に動かしながら ISUCON 11 初回ベンチマークの様子を見せたいと思います お題のWeb アプリケーション IoT デバイス記録& 閲覧アプリ「ISUCONDITION 」 ISU のコンディションを記録するWeb サービス IoT デバイスから送られてくるデータとトレンドの閲覧を いかに捌くかがポイントだった 2022/03/27 traP LT 2022 #traP_LT
17. パフォーマンスモニタリングが動かなかった なぜかfluentd がエラーを吐いてログが送信されない 2022/03/27 traP LT 2022 #traP_LT
18. 原因その1 Ubuntu20.04LTS で apt でインストールできるdstat で dstat --output log.csv がエラーで実行できない isucon@ip-192-168-0-11:~$ dstat --output tmp.csv You did not select any stats, using -cdngy by default. Traceback (most recent call last): File "/usr/bin/dstat", line 2847, in <module> main() File "/usr/bin/dstat", line 2687, in main scheduler.run() [.. 省略] if isinstance(self.val[name], types.ListType) or isinstance(self.val[name], types.TupleType): NameError: name 'types' is not defined 2022/03/27 traP LT 2022 #traP_LT
19. 原因その2 dstat --output log.csv がプロセスを終了するまで log.csv に結果を書き込まないようにコードが変更されていた 結論として dstat のバグだった システムを構築した際に気づかなかったのは、ISUCON 10 予選 のイメージ(Ubuntu18.04LTS) で検証していたため dstat のバージョンが違う そしてdstat は開発が終了している... 直そうにも無理 後継は直っているぽいがプラグインが依存している... 2022/03/27 traP LT 2022 #traP_LT
20. まとめ ログを可視化して分析できるシステムを構築しました 構成自体はよくある 今後レギュが変わる場合もあるから注意してね バグってうまく活用できなかった バグってても競技中に直そうとしてはいけない 原因は特定できたので来年は活用できる 来年こそは予選突破するぞ！！！！！ 2022/03/27 traP LT 2022 #traP_LT
21. その他余談 本番中はインスタンスのメモリそこそこにしないと まともに動かない 戻し忘れないようにしましょう( 一敗) 2022/03/27 traP LT 2022 #traP_LT