Zenn
Open13

private-isu作業集

euryopaeuryopa

mysqlのスロークエリログ設定

/etc/mysql/mysql.conf.d/mysql.cnf

[mysqld]
slow_query_log = 1
slow_query_log_file = /var/log/mysql/mysql-slow.log
long_query_time = 0

systemctl restart mysql
euryopaeuryopa

インデックス作成

alter table comments add index post_id_idx(post_id, created_at desc);
euryopaeuryopa

アプリケーションの並列数を変更

webapp/ruby/unicorn_config.rbを編集

worker_processes 4

goではたぶんこれ

func main() {
    // CPUコア数を取得
    numCPU := runtime.NumCPU()
    
    // 使用するCPUコア数を設定
    runtime.GOMAXPROCS(numCPU)
    
    // または、固定のコア数を指定したい場合
    // runtime.GOMAXPROCS(4) // 例えば、4コアを使用する場合

    // 以下、アプリケーションの処理
}
euryopaeuryopa

alpでアクセスログ出力

alp json \
--sort sum -r \
-m "/posts/[0-9]+,/@\w+,/image/\d+" \
-o count,method,uri,min,avg,max,sum \
< /var/log/nginx/access.log
euryopaeuryopa
  • スコアが上昇して、ベンチマーカーが大量のリクエストを送るようになると開けるファイルディスクリプタの上限数を超えてしまうことがある。too many open filesが発生したときはベンチマーカーのインスタンスで/etc/security/limits.confに以下を追記し、ログインしなおして設定を反映。ulimit -nコマンドで設定確認
isucon hard nofile 10000
isucon soft nofile 10000
euryopaeuryopa

ISUCON本でのprivate-isuの大まかな流れ

  1. まずは初期状態でベンチマーカーを実行し、topコマンドでCPU利用率を調査
  2. mysqlのCPU消費率が約100％でボトルネック
  3. DB操作に問題がありそうなので、スロークエリログを解析 pt-query-digest, mysqldumpslow
  4. クエリの問題箇所に応じてインデックス貼ったりする
  5. 再度topコマンドで確認
  6. CPU利用率がコアごとに偏っていて並列で使えていない
  7. アプリケーションのworkerプロセスを4にして改善されていることを確認
  8. alpでアクセス集計ログを確認
  9. ボトルネックが大きい箇所から対応 (静的ファイル配信など)
  10. ボトルネック解消→alpでアクセスログ確認したりpt-query-digestでスロークエリを確認したりexplainで実行計画調べて対処、の繰り返し
  11. アプリケーションコードやsqlのチューニング以外にも、DBの最大接続数やプリペアドステートメントの改善(interpolateParams=true)、dbコミット時のログ書かないようしたり、ネットワークのコネクションのオーバーヘッドやカーネルやハードウェアの設定変更したりするのも忘れずに
euryopaeuryopa

1回目のベンチマーカー実行

スコア

{"pass":true,"score":2200,"success":2153,"fail":2,"messages":["リクエストがタイムアウトしました (GET /)","リクエストがタイムアウトしました (POST /login)"]}

top 見るとmysqlが〜200％ボトルネック
mysqlがボトルネックになる原因

  • クエリが非効率(インデックス貼っていないなど)

スロークエリをpt-query-digestで調査

# Profile
# Rank Query ID                      Response time  Calls R/Call V/M   Ite
# ==== ============================= ============== ===== ====== ===== ===
#    1 0x624863D30DAC59FA16849282... 478.9479 68.8%  1845 0.2596  0.02 SELECT comments
#    2 0x422390B42D4DD86C7539A5F4... 158.7321 22.8%  1978 0.0802  0.01 SELECT comments
#    3 0x100EC8B5C400F34381F9D7F7...  38.2365  5.5%   133 0.2875  0.01 SELECT comments
# MISC 0xMISC                         20.6842  3.0% 37694 0.0005   0.0 <23 ITEMS>

上から順に解決して、ベンチマーカーを回してみることにする

euryopaeuryopa

1つ目のボトルネックの解消：インデックス作成

ボトルネックとなるクエリ

SELECT * FROM `comments` WHERE `post_id` = 9998 ORDER BY `created_at` DESC LIMIT 3\G

post_idで選択した後、created_atでソートしているので、(post_id, created_at desc)で複合インデックスを貼って試してみる

alter table comments add index post_id_idx (post_id, created_at desc);

CPU利用率めっちゃ下がって効いてそう。アプリケーションにもCPUが割かれている

スコアも〜20000点

{"pass":true,"score":19365,"success":18248,"fail":0,"messages":[]}

ボトルネック解消後のpt-query-digestの結果を見てみる

# Profile
# Rank Query ID                     Response time  Calls  R/Call V/M   Ite
# ==== ============================ ============== ====== ====== ===== ===
#    1 0x624863D30DAC59FA1684928... 493.0000 48.4%  54101 0.0091  0.25 SELECT comments
#    2 0x422390B42D4DD86C7539A5F... 171.5244 16.8%  56848 0.0030  0.07 SELECT comments
#    3 0x4858CF4D8CAA743E839C127... 123.6508 12.1%   2009 0.0615  0.01 SELECT posts
#    4 0x19759A5557089FD5B718D44...  42.4770  4.2%  36129 0.0012  0.02 SELECT posts
#    5 0x100EC8B5C400F34381F9D7F...  39.3179  3.9%   2747 0.0143  0.26 SELECT comments
#    6 0xDA556F9115773A1A99AA016...  35.0950  3.4% 305842 0.0001  0.00 ADMIN PREPARE
#    7 0x396201721CD58410E070DA9...  30.0628  3.0% 151084 0.0002  0.00 SELECT users
#    8 0x7A12D0C8F433684C3027353...  29.8516  2.9%    426 0.0701  0.01 SELECT posts
#    9 0xCDEB1AFF2AE2BE51B2ED5CF...  25.2236  2.5%    443 0.0569  0.01 SELECT comments
# MISC 0xMISC                        28.2069  2.8% 339371 0.0001   0.0 <34 ITEMS>

一番上のクエリに関して、R/Callが0.26→0.09になっており効率化ができている。
select commentsの呼び出し件数がめっちゃ多くなっている。N＋1問題が発生している可能性あり。
その解消に行く前に定番のADMIN PREPAREを解消する

おまけにpost_idだけにインデックス貼った時のスコアがこちら

{"pass":true,"score":18973,"success":17894,"fail":0,"messages":[]}

複合インデックスじゃなくてもよさそう？

euryopaeuryopa

2つ目のボトルネック解消：ADMIN PREPAREの解消

これは定番のやつ。
アプリケーションのDB接続箇所にinterpolateParams=trueを追記する。

        dsn := fmt.Sprintf(
-                "%s:%s@tcp(%s:%s)/%s?charset=utf8mb4&parseTime=true&loc=Local",
+                "%s:%s@tcp(%s:%s)/%s?charset=utf8mb4&parseTime=true&loc=Local&interpolateParams=true",

スコア下がった

euryopaeuryopa

3つ目：N+1の解消

select commentがめっちゃ実行されているので、N+1が発生している可能性。
アプリケーションのコードを見に行く。

euryopaeuryopa

pprotein導入手順
基本はこれ：
https://hackmd.io/@to-hutohu/pprotein-getting-started
https://zenn.dev/team_soda/articles/20231206000000

importに

"github.com/kaz/pprotein/integration/standalone"
// 省略

func main() {
    go func() {
    standalone.Integrate(":19000")
}()
// 省略
}

起動したらインスタンスではなくローカルのPCからこれ

ssh -i "private-isu.pem" ubuntu@{ipアドレス} -fNL 9000:localhost:9000

pproteinのsettingのhttpのところ

[
  {
    "Type": "pprof",
    "Label": "localhost",
    "URL": "http://localhost:19000/debug/pprof/profile",
    "Duration": 60
  },
  {
    "Type": "httplog",
    "Label": "localhost",
    "URL": "http://localhost:19000/debug/log/httplog",
    "Duration": 60
  },
  {
    "Type": "slowlog",
    "Label": "localhost",
    "URL": "http://localhost:19000/debug/log/slowlog",
    "Duration": 60
  }
]