ISUCONの夏季講習2017をやった

2020年08月02日

ISUCON10に向けた復習として ISUCON 夏季講習 2017 をやりました。ボトルネック発見のための基本的なデータ収集の部分だけまとめています。

環境構築

仮想マシンとしてVirtualBoxを用いて、問題は isucon7の予選問題を利用します。

# プライベートネットワークのIPアドレスを指定
$ vi Vagrantfile
   # Create a private network, which allows host-only access to the machine
   # using a specific IP.
-  config.vm.network "private_network", ip: "192.168.33.10"
+  config.vm.network "private_network", ip: "192.168.33.10"

# 仮想環境を構築
$ g clone https://github.com/matsuu/vagrant-isucon.git
$ cd vagrant-isucon/icuon7-qualifier
$ vagrant up
$ vagrant halt # 初回起動だとimageの仮想マシンでアプリケーションが起動しなかった
$ vagrant up

ベンチマークを実行

最初にアプリケーションサーバーの仮想マシンに割り当てられたIPアドレスを確認する。

$ vagrant ssh image
$ ifconfig 
...
enp0s9    Link encap:Ethernet  HWaddr 08:00:27:4a:09:63
          inet addr:172.28.128.8  Bcast:172.28.128.255  Mask:255.255.255.0
          inet6 addr: fe80::a00:27ff:fe4a:963/64 Scope:Link
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
          RX packets:11 errors:0 dropped:0 overruns:0 frame:0
          TX packets:10 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000
          RX bytes:4968 (4.9 KB)  TX bytes:1332 (1.3 KB)
...

確認したIPアドレスに対してベンチを実行する。

$ vagrant ssh bench
$ cd /home/isucon/isubata/bench
$ bin/bench -remotes 172.28.128.8 # imageマシンのIPアドレスを指定
[isu7q-bench] 2020/07/26 09:33:46.171614 dataset.go:37: datapath ./data
[isu7q-bench] 2020/07/26 09:33:47.656776 bench.go:472: Remotes [172.28.128.8]
[isu7q-bench] 2020/07/26 09:33:47.656810 bench.go:346: State.Init()
[isu7q-bench] 2020/07/26 09:33:47.663825 bench.go:348: State.Init() Done
[isu7q-bench] 2020/07/26 09:33:47.663853 bench.go:350: requestInitialize()
[isu7q-bench] 2020/07/26 09:33:47.756337 bench.go:358: requestInitialize() Done
[isu7q-bench] 2020/07/26 09:33:47.756358 bench.go:363: preTest()
[isu7q-bench] 2020/07/26 09:33:58.556061 bench.go:371: preTest() Done
[isu7q-bench] 2020/07/26 09:33:58.556186 bench.go:380: validationMain()
[isu7q-bench] 2020/07/26 09:33:59.560581 bench.go:267: Increase Load Level.
[isu7q-bench] 2020/07/26 09:34:00.557278 bench.go:263: Cannot increase Load Level. Reason: SlowPath /message Before 11.790899ms
[isu7q-bench] 2020/07/26 09:34:01.557413 bench.go:263: Cannot increase Load Level. Reason: SlowPath /profile/yamaoka_shinsuke Before 415.740187ms
[isu7q-bench] 2020/07/26 09:34:02.557313 bench.go:260: Cannot increase Load Level. Reason: RecentErr 2020-07-26 09:34:02.336753948 +0000 UTC m=+16.304791155 リクエストがタイムアウトしました (POST /message ) Before 220.553901ms

アプリケーションの動作確認

ブラウザで http://192.168.33.10 にアクセスすれば動作確認ができます。ベンチマーク実行前の場合はデータが無く動作確認がやり辛いので、ベンチマークを先に実行しておく事をオススメします。アカウントは適当に新規登録してログインしてください。

仮想環境のMySQLに接続する

sshの設定を確認する。MySQLの接続情報は ansibleの設定ファイルを参照しました。

$ vagrant ssh-config image
Host image
  HostName 127.0.0.1
  User vagrant
  Port 2222
  UserKnownHostsFile /dev/null
  StrictHostKeyChecking no
  PasswordAuthentication no
  IdentityFile /Users/tomohiro/workspace/isucon/vagrant-isucon/isucon7-qualifier/.vagrant/machines/image/virtualbox/private_key
  IdentitiesOnly yes
  LogLevel FATAL

MySQLクライアントで次の設定でMySQLに接続します。

MySQLホスト: 127.0.0.1
ユーザー名: isucon
パスワード: isucon
データベース: isubata
SSHホスト: 192.168.33.10
SSHユーザー: vagrant
秘密鍵: ~/isucon7-qualifier/.vagrant/machines/image/virtualbox/private_key

実装言語を変更する

ISUCONでは複数の言語から自分たちが好きな言語を利用できます。ここでは、JavaScript(Node.js)に実装言語を変更します。参考実装の切り替えは、ISUCON7 予選マニュアルを参照しました。

# アプリケーションサーバーで作業
$ vagrant ssh image

# サービスの一覧を確認
$ ls -l /etc/systemd/system/ | grep isubata
-rw-r--r-- 1 root root  331 Jul 26 09:01 isubata.golang.service
-rw-r--r-- 1 root root  363 Jul 26 09:01 isubata.nodejs.service
-rw-r--r-- 1 root root  367 Jul 26 09:01 isubata.perl.service
-rw-r--r-- 1 root root  386 Jul 26 09:01 isubata.php.service
-rw-r--r-- 1 root root  386 Jul 26 09:01 isubata.python.service
-rw-r--r-- 1 root root  382 Jul 26 09:01 isubata.ruby.service

# 実行中の参考実装を確認
vagrant@ubuntu-xenial:~$ systemctl list-unit-files --type=service | grep isubata
isubata.golang.service                     disabled
isubata.nodejs.service                     disabled
isubata.perl.service                       disabled
isubata.php.service                        disabled
isubata.python.service                     enabled
isubata.ruby.service                       disabled

# 参考実装の言語を変更
$ sudo systemctl stop isubata.python.service
$ sudo systemctl disable isubata.python.service
$ sudo systemctl start isubata.nodejs.service
$ sudo systemctl enable isubata.nodejs.service

起動を確認する。

$ service isubata.nodejs status
● isubata.nodejs.service - isucon7 qualifier main application in nodejs
   Loaded: loaded (/etc/systemd/system/isubata.nodejs.service; enabled; vendor preset: enabled)
   Active: active (running) since Sun 2020-07-26 12:24:52 UTC; 2min 59s ago
 Main PID: 5901 (node)
   CGroup: /system.slice/isubata.nodejs.service
           └─5901 /home/isucon/local/node/bin/node /home/isucon/isubata/webapp/nodejs

ボトルネック計測

監視ツールのインストール

以下のツールから好きなのを選んでインストールします。

htop
dstat
glances
netdata

$ sudo apt install htop
$ sudo apt isntall dstat
$ sudo apt install glances
$ bash <(curl -Ss https://my-netdata.io/kickstart-static64.sh)

監視ツール実行の様子

ベンチマーク実行中のCPUやメモリなどのリソース状況を可視化できます。

glances

$ glances
ubuntu-xenial (Ubuntu 16.04 64bit / Linux 4.4.0-184-generic)                                                     Uptime: 3:06:11

CPU      99.7%  nice:     0.2%             LOAD    2-core             MEM     53.6%  active:    1.51G             SWAP      0.0%
user:    74.7%  irq:      0.0%             1 min:    7.61             total:  1.95G  inactive:   262M             total:       0
system:  23.1%  iowait:   0.2%             5 min:    6.71             used:   1.05G  buffers:   54.1M             used:        0
idle:     0.3%  steal:    0.0%             15 min:   3.86             free:    928M  cached:     779M             free:        0

NETWORK     Rx/s   Tx/s   TASKS 123 (228 thr), 1 run, 122 slp, 0 oth sorted automatically by cpu_percent, flat view
enp0s3       6Kb    6Kb
enp0s8        0b     0b     CPU%  MEM%  VIRT   RES   PID USER        NI S    TIME+ IOR/s IOW/s Command
enp0s9     133Kb 40.1Mb    179.3  20.1 1.52G  402M  1225 mysql        0 S 20:15.77     0     0 /usr/sbin/mysqld
lo         550Mb  550Mb     12.8  22.8 1.53G  456M  5901 isucon       0 S  1:12.94     0     0 /home/isucon/local/node/bin/node
                             2.9   1.4 89.8M 27.6M  6345 vagrant      0 R  0:00.83     0     0 /usr/bin/python3 /usr/bin/glances
DISK I/O     R/s    W/s
sda1           0   359K
sdb            0      0   Warning or critical alerts (lasts 4 entries)
                          2020-07-26 12:38:07 (ongoing) - CPU_SYSTEM (99.7)
FILE SYS    Used  Total   2020-07-26 12:37:55 (ongoing) - CPU_USER (74.8)
/ (sda1)   3.68G  9.63G   2020-07-26 12:37:51 (0:00:04) - WARNING on CPU_SYSTEM (81.2)
2020-07-26 12:38:07       2020-07-26 12:37:36 (ongoing) - LOAD (1.9)

netdata

ブラウザで http://<imageマシンのIPアドレス>:19999 にアクセスします。今回の場合は、http://172.28.128.8:19999/ にアクセスすれば確認ができます。

netdata

alpでアクセスログを解析

alpをインストール

$ wget https://github.com/tkuchiki/alp/releases/download/v1.0.3/alp_linux_amd64.zip
$ sudo apt install unzip
$ unzip alp_linux_amd64.zip
$ sudo install ./alp /usr/local/bin

nginxにalp用の出力を追加

$ sudo vi /etc/nginx/nginx.conf
http {
        ...

        ##
        # Logging Settings
        ##

        log_format ltsv "time:$time_local"
                        "\thost:$remote_addr"
                        "\tforwardedfor:$http_x_forwarded_for"
                        "\treq:$request"
                        "\tstatus:$status"
                        "\tmethod:$request_method"
                        "\turi:$request_uri"
                        "\tsize:$body_bytes_sent"
                        "\treferer:$http_referer"
                        "\tua:$http_user_agent"
                        "\treqtime:$request_time"
                        "\tcache:$upstream_http_x_cache"
                        "\truntime:$upstream_http_x_runtime"
                        "\tapptime:$upstream_response_time"
                        "\tvhost:$host";

        access_log /var/log/nginx/access.log ltsv;
        error_log /var/log/nginx/error.log;

$ sudo rm /var/log/nginx/access.log && sudo systemctl reload nginx

alpでアクセスログを解析

ベンチマークを実行後にalpでアクセスログを集計して計測結果を見てみます。処理時間の合計で降順ソートした結果を見てみると、 /message と /fetch へのアクセスに時間を要しています。また、 /icons 配下の画像のレスポンスも気になりますね。
ここで修正した気持ちをグッと抑えて次はMySQLのクエリ解析を実施していきます。

$ alp ltsv -r --sort sum --file /var/log/nginx/access.log
+-------+-----+-----+-----+-----+-----+--------+------------------------------------------------------+-------+--------+---------+--------+--------+--------+--------+--------+------------+------------+--------------+------------+
| COUNT | 1XX | 2XX | 3XX | 4XX | 5XX | METHOD |                         URI                          |  MIN  |  MAX   |   SUM   |  AVG   |   P1   |  P50   |  P99   | STDDEV | MIN(BODY)  | MAX(BODY)  |  SUM(BODY)   | AVG(BODY)  |
+-------+-----+-----+-----+-----+-----+--------+------------------------------------------------------+-------+--------+---------+--------+--------+--------+--------+--------+------------+------------+--------------+------------+
|    90 |   0 |  60 |   0 |  30 |   0 | GET    | /message                                             | 0.002 | 10.216 | 397.354 |  4.415 |  0.003 |  3.236 | 10.084 |  4.455 |      5.000 |  52648.000 |  1261915.000 |  14021.278 |
|    44 |   0 |   7 |   0 |  37 |   0 | GET    | /fetch                                               | 0.002 | 10.085 | 350.770 |  7.972 |  0.002 | 10.001 |  0.002 |  3.769 |      0.000 |   3098.000 |    21687.000 |    492.886 |
|    18 |   0 |   5 |   0 |  13 |   0 | GET    | /icons/7598595abd317f5ae637300a27f95e3c700376a7.png  | 0.820 | 10.028 | 143.519 |  7.973 |  0.820 | 10.002 |  7.973 |  2.878 |      0.000 | 437319.000 |  2186261.000 | 121458.944 |
|    17 |   0 |   6 |   0 |  11 |   0 | GET    | /icons/c434098fec37fd0d2c1e646d104220f6ffabbea7.png  | 0.132 | 10.009 | 137.344 |  8.079 |  0.132 | 10.005 |  7.973 |  2.903 |      0.000 | 103218.000 |   619208.000 |  36424.000 |
|    17 |   0 |   5 |   0 |  12 |   0 | GET    | /icons/61463cd868570a29cc1b74232000e84d3276e315.png  | 0.228 | 10.130 | 136.311 |  8.018 |  0.228 | 10.015 | 10.000 |  3.084 |      0.000 | 381286.000 |  1905666.000 | 112098.000 |
|    18 |   0 |   6 |   0 |  12 |   0 | GET    | /icons/5e981ef46ec0f47bdc2f188673325b85078f5235.png  | 0.144 | 10.043 | 135.467 |  7.526 |  0.144 | 10.000 |  9.019 |  2.927 |      0.000 | 769314.000 |  4613375.000 | 256298.611 |
|    17 |   0 |   7 |   0 |  10 |   0 | GET    | /icons/158fa9df919970ac8bc3bc2724ed5b02fe30968d.png  | 0.140 | 10.047 | 125.555 |  7.386 |  0.140 | 10.047 |  9.999 |  3.542 |      0.000 | 115188.000 |   806284.000 |  47428.471 |
|    14 |   0 |   3 |   0 |  11 |   0 | GET    | /icons/0614f0cea1b70fb71b4c3b88545a42327157a41e.jpg  | 4.715 | 10.138 | 125.212 |  8.944 |  4.958 | 10.021 | 10.047 |  2.104 |      0.000 | 559681.000 |  1678461.000 | 119890.071 |
|    14 |   0 |   5 |   0 |   9 |   0 | GET    | /icons/ba2d2384f825a83862f3b61302468b2e07f0a0f7.png  | 3.736 | 10.026 | 119.459 |  8.533 |  3.736 | 10.026 | 10.025 |  2.271 |      0.000 | 294773.000 |  1473311.000 | 105236.500 |
|    14 |   0 |   4 |   0 |  10 |   0 | GET    | /icons/65ea5a70b1fcf8f5f816b01b87f2aca2251315b0.png  | 2.330 | 10.039 | 117.397 |  8.386 |  2.330 | 10.039 |  9.191 |  2.362 |      0.000 | 299543.000 |  1197726.000 |  85551.857 |

MySQLのクエリ解析

スロークエリログの出力設定を追加して、改めてベンチマークを実行してログを出力します。設定が正常に完了していれば、 /var/log/mysql/mysql-slow.log が出力されます。

$ sudo vi /etc/mysql/mysql.conf.d/mysqld.cnf
[mysqld]
slow_query_log = 1
log_slow_queries = /var/log/mysql/mysql-slow.log
long_query_time = 0

$ sudo systemctl restart mysql
$ sudo sytemtctl restart isubata.nodejs.service

pt-query-digestのインストール

pt-query-digest はMySQLのクエリログを集計するサポートツールです。

apt 経由でインストールするとパッケージのバージョンが古くバグが存在するので注意してください。
mariadb - Pipeline process 5 (iteration) caused an error: Redundant argument in sprintf at /usr/bin/pt-query-digest line 2556 - Stack Overflow

$ wget percona.com/get/percona-toolkit.tar.gz
$ tar xf percona-toolkit.tar.gz
$ cd percona-toolkit-3.2.0
$ perl Makefile.PL && make && sudo make install
$ sudo pt-query-digest --help

スロークエリのログを見る

pt-query-digest でスロークエリログを見ていきます。

SELECT * FROM image WHERE name = 'c434098fec37fd0d2c1e646d104220f6ffabbea7.png'\G の実行が非常に時間が掛かってるっぽいですね。

$ sudo pt-query-digest --limit 10 /var/log/mysql/mysql-slow.log
# Profile
# Rank Query ID                      Response time  Calls R/Call V/M   Ite
# ==== ============================= ============== ===== ====== ===== ===
#    1 0x086EF2D69E0CA10C16A13978... 989.3391 93.5%   751 1.3174  0.09 SELECT image
#    2 0xB36405B8C0D2F0C74866C96B...  47.8231  4.5%  4012 0.0119  0.02 SELECT message
#    3 0x23E986FD32D530D2691DE3FA...   5.1509  0.5%  5077 0.0010  0.02 SELECT user
#    4 0xDF664753A9FC79D32CF41F09...   3.3720  0.3%  4000 0.0008  0.01 SELECT haveread
#    5 0xE8390778DC20D4CC04FE01C5...   2.6107  0.2% 11863 0.0002  0.01 ADMIN PING
#    6 0xEC97B582BC15F46A85799218...   2.4980  0.2%    89 0.0281  0.04 SELECT message
#    7 0x6CB85ADF7C155CAA91283C30...   2.0849  0.2%    49 0.0425  0.03 SELECT message
#    8 0xE1F097E42A11604ECA5E8124...   0.9187  0.1%    17 0.0540  0.02 INSERT image
#    9 0x34E80BA8226FB17741883793...   0.8466  0.1%   268 0.0032  0.07 SELECT user
#   10 0x98584C6216E0B67546AAE7D3...   0.7411  0.1%    89 0.0083  0.02 INSERT UPDATE haveread
# MISC 0xMISC                          2.2539  0.2%   838 0.0027   0.0 <16 ITEMS>

# Query 1: 11.92 QPS, 15.70x concurrency, ID 0x086EF2D69E0CA10C16A13978F3B7FCFA at byte 13991086
# Scores: V/M = 0.09
# Time range: 2020-08-02T06:11:47 to 2020-08-02T06:12:50
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          2     751
# Exec time     93    989s   121ms      3s      1s      2s   338ms      1s
# Lock time      6   154ms    23us    35ms   205us   287us     1ms    76us
# Rows sent     25  11.77k       1      25   16.04   22.53    3.89   15.25
# Rows examine   1 745.91k    1001    1018 1017.06 1012.63    8.50 1012.63
# Query size     0  57.81k      46      80   78.83   76.28    2.31   76.28
# String:
# Databases    isubata
# Hosts        localhost
# Users        isucon
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms  #######
#    1s  ################################################################
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `isubata` LIKE 'image'\G
#    SHOW CREATE TABLE `isubata`.`image`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM image WHERE name = 'c434098fec37fd0d2c1e646d104220f6ffabbea7.png'\G

...