private-isu

2.計測

CPU・メモリ使用率

1. ベンチマーカーを実行
2. 実行中にlinuxコマンドを利用してモニタリングする
   • CPU使用率を計測：topコマンド
   • メモリ使用率：freeコマンド
3. 使用率が高いところに対してアプローチ

平常時：

ベンチマーク実行時：

• ベンチマーク実行時にCPU利用率が大きく上がっていることがわかる
• 一方でメモリ使用率は平常時とほとんど変わっていなかった
• ->CPUリソースがボトルネックになっていると判断できる。
• 特にMySQLのプロセスが高い使用率になっているので、DBに対してアプローチが必要だと判断できる。

スロークエリログの取得

• /etc/mysql/mysql.cnf.d/mysqld.cnf(Dockerならwebapp/mysql/conf.d/my.cnf)の設定を変更することでスロークエリログの有効化ができる
• 設定を反映させるためにはsystemctl restart mysqlで再起動すること

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

スロークエリログの集計(簡易的に確認したい時)

• そのままだと膨大すぎるので、mysqldumpslowコマンドで集計する
• logファイルの閲覧ができるユーザーで実行すること(rootなど)
• ソート機能を使ってクエリ時間順に並べたりもできる

一例：

$ mysqldumpslow t /var/log/mysql/mysql-slow.log 
Count: 924  Time=0.07s (61s)  Lock=0.00s (0s)  Rows=2.8 (2586), isuconp[isuconp]@localhost
  SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N

• -aオプションでクエリログの詳細を見ることができる(ログが膨大なときは使わないほうがいいかも)
• -sオプションでソート方法の指定ができる。ここではt(実行時間)でソートしている。
• ` SELECT * FROM ~`が発行されたクエリ

スロークエリログの解析(こちらがメイン)

• pt-query-digestを用いて解析する
• pt-query-digest /var/log/mysql/mysql-slow.logでログを解析できる
• teeコマンドを使ってファイルに書き込むこともできる

インストール(Debian/Ubuntu)：

sudo apt update
sudo apt install percona-toolkit

インストール(Red Hat)：

sudo yum install https://repo.percona.com/yum/percona-release-latest.noarch.rpm
sudo yum install percona-toolkit

使用例：

# 標準出力させる場合
pt-query-digest /var/log/mysql/mysql-slow.log
# ファイル出力させるとき
pt-query-digest /var/log/mysql/mysql-slow.log | tee /home/isucon/private_isu/digest_$(date +%Y%m%d%H%M).txt

結果の見方：

• 全体として3部構成になっている
  • 全体的な統計
  • ランキング
  • 各クエリの詳細

まずはランキングから見ていく

• 主なチューニング対象は次の2つ：
  • 実行回数が少ないのに、1回あたりのクエリの負荷が高く、上位に食い込むもの
  • 1回あたりのクエリの負荷は小さいが、実行回数が多く、上位に食い込むもの

    # Profile
    # Rank Query ID                      Response time Calls R/Call V/M   Item
    # ==== ============================= ============= ===== ====== ===== ====
    #    1 0x624863D30DAC59FA16849282... 61.8901 71.2%   924 0.0670  0.00 SELECT comments
    #    2 0x422390B42D4DD86C7539A5F4... 20.8125 23.9%   935 0.0223  0.00 SELECT comments
    # MISC 0xMISC                         4.2685  4.9% 15408 0.0003   0.0 <23 ITEMS>
    

次に、ランキング上位のクエリの詳細を見ていく

• クエリの実行回数は924回、実行時間は62秒かかっている
  • Lock timeが小さいため、他のスレッドの影響は受けていなさそう
  • Rows sentとRows examineに着目すると、2000行返すのに、8800万行も読み込んでいることがわかる
  • クエリにはLIMIT 3がついており、最大でも3行しか返さないのに、毎回10万行近く読み込んでいる
  • -> インデックスを付与して、読み込む行数を減らすように改善する

    # Query 1: 10.38 QPS, 0.70x concurrency, ID 0x624863D30DAC59FA16849282195BE09F at byte 2929867
    # This item is included in the report because it matches --limit.
    # Scores: V/M = 0.00
    # Time range: 2023-10-16T01:51:19 to 2023-10-16T01:52:48
    # Attribute    pct   total     min     max     avg     95%  stddev  median
    # ============ === ======= ======= ======= ======= ======= ======= =======
    # Count          5     924
    # Exec time     71     62s    65ms   138ms    67ms    68ms     3ms    65ms
    # Lock time     18     3ms     2us    35us     3us     3us     1us     2us
    # Rows sent      0   2.53k       0       3    2.80    2.90    0.73    2.90
    # Rows examine  48  88.12M  97.66k  97.66k  97.66k  97.04k       0  97.04k
    # Query size     3  74.08k      80      83   82.09   80.10    0.18   80.10
    # String:
    # Databases    isuconp
    # Hosts        localhost
    # Users        isuconp
    # Query_time distribution
    #   1us
    #  10us
    # 100us
    #   1ms
    #  10ms  ################################################################
    # 100ms  #
    #    1s
    #  10s+
    # Tables
    #    SHOW TABLE STATUS FROM `isuconp` LIKE 'comments'\G
    #    SHOW CREATE TABLE `isuconp`.`comments`\G
    # EXPLAIN /*!50100 PARTITIONS*/
    SELECT * FROM `comments` WHERE `post_id` = 9981 ORDER BY `created_at` DESC LIMIT 3\G
    

参考

• ISUCON本
• https://blog.bitjourney.com/entry/2017/11/09/101740