Webアプリケーション初心者が ISUCON 4 予選を通じてパフォーマンスの測定改善をした話 / newcomers of web application improvements in performance measurement through ISUCON 4 qualifying

Webアプリケーション初心者が ISUCON 4 予選を通じてパフォーマンスの測定改善をした話

Transcript

1. Webアプリケーション初心者が ISUCON 4 予選を通じて パフォーマンスの測定/改善をした話 Kosen10s LT#13 do-su-0805
2. はじめに：アジェンダ • まえがき • 概要 • ISUCON とは • 解いて見た話
3. まえがき • ISUCON解いたぜ！！！という話ではない ◦ 予選突破レベルまで点数が届いてない • レイヤーの違うところから初心者として入った私の経験の話 • ISUCON 出たことある人とか、パフォーマンスを見てきた人は片目にどうぞ • 進むごとに「あらかじめ見とけよ！」的なものが増えます ◦ 学んでいっているんだなと生暖かい目で見守っていただければ幸い
4. 概要 • SRE として社内サービスを運用していくための研修としてスタート ◦ サービスを運用するための 観点・経験・手法を学んでほしい ◦ 「多分これで早くなるべ」「なんか知らんけど早くなった」という目的ではない ▪ 「スコアがここまで上がりました！」というのを望んでいるわけではない ◦ 「こう観測し、こう考えたので、こうアプローチし、こういう結果になった」 • サービスを構成する要素を体感する研修としてもスタート ◦ 1つのWebサービスという意味での経験はなかった • 今回はライトにファーストステップのみ紹介
5. ISUCONとは • Iikanjini Speed Up CONtest • 1つ/複数 のサーバ上で起動している Web サービスを高速化するコンテスト ◦ 予選だと 1つ / 本戦だと複数？ • benchmarker が想定するリクエストを発行し、捌いた件数などから採点 • ISUCON 4 予選の題材では、「いすこん銀行」のサイトを想定 ◦ ログイン画面があり、ログインが成功すれば残高照会ができる ◦ 失敗すれば想定されるエラーメッセージが表示され、ページ遷移はなし ◦ /report にアクセスすることで ban した IP など、レポートが照会できる
6. 初期構成 • ISUCON 4 予選はサーバ1台 ◦ AWS EC2 m3.xlarge (EBS最適化なし) ◦ magnetic Disk • システム構成 ◦ benchmarker が nginx(localhost:80) へアクセス ◦ nginx が unicorn(localhost:8080) へ upstream ◦ unicorn/ruby から MySQL(localhost:3306) へ必要に応じ接続 Front (Nginx) App (Ruby / unicorn) DB (MySQL) BenchMarker TCP:3306 TCP:8080 TCP:80 EC2 (m3.large)
7. とりあえず benchmark をしてみる
8. とりあえず benchmark をしてみる <= スコア
9. ここからなにをするのか • とりあえず Speed Up しないといけない ◦ が、残念ながら私には数値感覚が一切ない • まずは現状を把握する ◦ サーバの負荷状況を見る ◦ アクセスログを読む ◦ MySQL のクエリサマリー的なのを出す
10. サーバの負荷状況などは？ • top コマンド ◦ top -- display and update sorted information about processes ◦ サーバ上で稼働するプロセスの状況を確認できる ◦ htop や vmstat などいろいろあるが、シンプルに • top -as -c で起動後、「1」を押すといい感じ ◦ メモリ利用順に表示し (a) ▪ ここについては、メモリ利用順にだしても CPU利用率とは大差はないだろうという ◦ セキュアモード（一般ユーザでプロセス kill できない）になって (s) ◦ プロセスをフルパスで表示し (c) ◦ CPUごとの負荷状況がわかるようになる (1)
11. サーバの負荷状況などは？ • CPU は 4 core ◦ 負荷はバラバラ、偏りがある ◦ 総じて暇そう • プロセス状況 ◦ MySQL プロセスが CPU 消費 (75%) ◦ それ以外が暇そう ◦ MySQL で詰まっていそう？ • 理想 ◦ CPU 使い切りたい!!
12. アクセスログを読む • access.log を awk で・・・ • alp という便利ツールがあるので恩恵に預かる ◦ https://github.com/tkuchiki/alp ◦ papix さんの紹介記事 なども • “alp is Access Log Profiler for Labeled Tab-separated Values(LTSV).” ◦ LTSV形式のログをプロファイリングしてくれる便利なツール
13. https://github.com/tkuchiki/alp “tkuchiki/alp”
14. https://papix.hatenablog.com/entry/2015/09/28/094310 “ISUCON 5でalpを使ってNginxのログを解析した話”
15. アクセスログを読むために 1. https://github.com/tkuchiki/alp/releases から持ってくる 2. nginx のログフォーマットを指定のものに変更 3.
16. alp の出力を見てみる • なんとなく見て意味のわかる配置 ◦ 何回 (COUNT) ◦ どれくらいの時間をかけて (MIN / MAX / SUM / AVG) ▪ 1/50/99パーセンタイルと標準偏差も出る ◦ どれくらいの容量で (MIN(BODY) / MAX(BODY) / SUM(BODY)) ◦ どのメソッドで (METHOD) ◦ どのURIが叩かれたか (URI)
17. alp の出力を見てみて思うこと • /login へのアクセス時間のばらつきが大きい ◦ 早くて 0.004 秒なのに 遅くて 0.579 秒 ◦ コンテンツの性質的にここが遅いのは問題 • 静的ファイルの配信時間/容量が気になる ◦ 問題の /login が早くて 0.004 秒なのに、付属品に 0.01X 秒かかっているのは :thinking_face: ◦ ここはアクセス数が増えればリニアに響くはず
18. MySQL のクエリサマリー的なのを出す • slowquery を出せば良い？ ◦ slowquery は特定時間以上かかったクエリーを出してくれる MySQL の機能 ◦ が、人間の目には優しくない • pt-query-digest という便利ツールがあるので恩恵に預かる ◦ PERCONA 社の PERCONA Toolkit に入っている ▪ The Database Performance Experts なすごい人たちのツール ◦ slow-query をまとめてくれる pt-query-digest 以外にも多々の便利ツールがある ◦ (どうやら tcpdump や mysql の processlist からもまとめてくれるらしい・・・ )
19. https://www.percona.com/doc/percona-toolkit/LATEST/pt-query-digest.html “pt-query-digest”
20. MySQL のクエリサマリー的なのを出すために 1. installation.html を参考に percona-toolkit を導入 2. my.cnf に slowquery を出すための設定を記載 ◦ 全クエリをサマりたいので、 long_query_time を 0 にすることで全クエリを slow 判定させる 3. 　 ◦ 長くなるので、 less などでみる
21. MySQL のクエリサマリー的なのを見てみる • 最初はこんな感じ • 実行時間 (Exec time) ◦ 早くて 1us ◦ 遅くて 4s ◦ 平均 10ms • Profile の 80%程度 が SELECT ◦ 支配的 ◦ login_log table への SELECT がほとんど ◦ INSERT より時間を使う
22. MySQL のクエリサマリー的なのを見てみる • 最初の画面の Rank1 の詳細 • 実行時間 (Exec time) ◦ 早くて 150us ◦ 遅くて 65ms ◦ 平均 36ms • Query_time distribution(分布) ◦ 100us ラインが 1/7 程度 ◦ 10ms ラインが 6/7 程度 ◦ 遅い方へのブレが大きい ▪ 100倍も違う • 一番下の行はサンプルクエリ ◦ こんな感じのクエリが叩かれる
23. MySQL のクエリサマリー的なのを見てみる • 最初の画面の Rank2 の詳細 • 実行時間 (Exec time) ◦ 早くて 82us ◦ 遅くて 24ms ◦ 平均 4ms • Query_time distribution(分布) ◦ 10us ラインが少し ◦ 100us ラインが 半数程度 ◦ 1ms ラインが 1/6 程度 ◦ 10ms ラインが 1/3 程度 ◦ Rank1 ほどブレは大きくない ▪ が、相変わらずブレはある • 一番下の行はサンプルクエリ ◦ こんな感じのクエリが叩かれる
24. MySQL の実行計画を見てみる • EXPLAIN 文で見ることができる ◦ さっきの例として出てきたクエリに対して EXPLAIN を先頭におくと出してくれる ◦ どういう考えを MySQL が持って実行したか、がわかる ◦ 見方などは MySQLのEXPLAINを徹底解説!! などが詳しい • 例 ◦ ◦ この場合、PRIMARY のクエリが、範囲検索で「約 35149件くらい」舐めるんじゃないと想定
25. MySQL の実行計画を見てみる • Rank 2 の場合(都合によりこっちを先に) ◦ possible_keys が PRIMARY 、 range / Using where ▪ id は主キーのため PRIMARY INDEX があるため、範囲を絞るのは全探索せずに済む • id については重複を許さないため、左から索引がなくても綺麗に並んでる • イメージとしては、右から舐めていくと 1 ~ 3234 ,3235 ~ MAX となっており、 隣接データへのポインタがあるので、順方向、逆方向については早く取れる ▪ user_id については、 INDEX を使えておらず、範囲内を全探索している • id が 3235 ~ MAX の実データについてのポインタがあり、そこからデータを見ていって いるイメージ（のため、 3235 ~ MAX までのデータを全部見ている ) ◦ user_id : id な索引を作って、user_id 順に並べてあげると、すぐに見つかる
26. MySQL の実行計画を見てみる • Rank 1 の場合 ◦ possible_keys が PRIMARY / NULL 、 Using where ▪ SUBQUERY 1. ip が 127.1.0.95 で全スキャン … 70000レコードから？ 2. succeeded が 1 なものを出す … succeeded が 1 なんてわからないから全探索 3. id 順に並び替えて、先頭 1つを出す … ここまでやったのに？ ▪ PRIMARY 1. ip が 127.1.0.95 なものを全スキャン … 70000 レコードから？ 2. id が SUBQUERY の結果 ( NULL なら 0 ) より大きいものを返す (まだいい) ◦ ip : id な索引を作って、ip 順に並べてあげる とすぐに見つかる
27. ここまでのまとめ 1. CPU は MySQL が食ってて、それ以外が暇そうだしリソースに余裕がある ◦ MySQL で突っかかっていそう = MySQL がボトルネックのようだ 2. アクセスログを見ると、動的っぽい場所での時間のばらつきが大きい 3. MySQL のクエリを見ると、login_log を参照するクエリで最適化されてない MySQL の面倒を見てあげると良さそう！
28. MySQL の INDEX を貼る • 先行調査で、 ip と user_id について index を貼るという方針 • 初期化スクリプトに、ALTER 文を仕込む ◦ これで、ip:id と、 user_id:id な INDEX が作成される
29. INDEX 適応後の EXPLAIN を確かめる • type = ref で Using index になった ◦ type = ref は、UNIQUE でないが INDEX を使えているということ ◦ rows も減った (特に後者は 35149 -> 4 なので、8787 倍！)
30. 改めて benchmark 1221 -> 4748 と向上したことを確認 <= スコア
31. 改めてサーバの負荷状況を確認 • CPU は 4 core ◦ 負荷は均一に ◦ 総じて暇そう • プロセス状況 ◦ MySQL プロセスの負荷が激減 ◦ benchmarker の負荷が目立つように ◦ unicorn も平均して 10% くらいを 全プロセスで食うように
32. 改めて alp • アクセス数が向上していることを確認 • /login についてはまだ遅い時があるが、AVG が 0.075 -> 0.007 と高速化
33. 改めて pt-query-digest (全体) • INSERT の時間が支配的に変わった • total / avg の Exec time が短くなった ◦ 実行回数増えてるのに total が減ったあたりに INDEX の効果を計り知れる
34. 改めて pt-query-digest (改善前での Rank1) • 実行回数が 4 倍に増えた ( 565 -> 2198 ) • 合計実行時間が 1/50 まで減った ( 20s -> 474ms ) • 最大/ 平均実行時間 も大幅に減った ( 65ms -> 392us , 36ms -> 215us) • ばらつきも減り、全部 100us オーダーに収まるようになった
35. 改めて pt-query-digest (改善前での Rank2) • 合計実行時間が 約 1/50 まで減った ( 18s -> 394ms ) • 最大/ 平均実行時間 も大幅に減った ( 24ms -> 142us , 4ms -> 93us) • ばらつきも減り、大半が 10us オーダーに収まり、遅くても 100us オーダー
36. ここからの話 • 並列数をあげたら too many connection が・・・ ◦ netstat を while で叩いてグラフを書いて、負荷状況を観察して、 unicorn を unix domain socketにしたり・・ • nginx から静的ファイルは配信するようにしたりなどしてました