ISUCON8 の予選問題を復習した

今年もISUCONには参加する予定で、チームメンバーを集めるところまでは進めていたのですが、日程が 別のイベント と重なってしまい、参加できませんでした。。。

ISUCONの問題は取り組んでいてワクワクしてくる良問が出ているので、ネタバレを食らう前に復習しようと思いました。

復習するまで参加記や講評などは読まないようにしていたのですが、Twitterを見ているだけでも情報が流れてきてしまったので、以下の情報は知ってしまっていたことを予め申し上げておきます。

  • OSはCentOS 7
  • 複数台構成
  • HTTPサーバーはH2O

OSとネットワークの準備

この記事を書いている間にConoHaでISUCON8のイメージが公開されました。新しく利用される方はそちらを利用するのが賢明かと思います。

www.conoha.jp

予選問題のリポジトリが公式に公開されていたので、それを利用しました。

GitHub - isucon/isucon8-qualify

サーバーはVagrantで構築してもよいのですが、なるべく本番と同じスコアを再現したかったのでVPSを借りました。本番でどこのサービスのサーバーが使われたのか分からないのでエスパーするしか無いのですが、今年はサーバーの提供がGMOインターネットだったので、ConoHaのメモリ1GBのコース を使いました。1GBのコースはvCPUが2つであるなど、スペック的にも README に書いてあるものと近いので、たぶん合っているんじゃないかと思います。

サーバーは競技用3台＋ベンチマーク1台の合計4台を契約して、プライベートネットワークで接続しました。

f:id:kujira16:20181016225037p:plain

プライベートネットワークを構築すると、以下の eth1 のようなインターフェースが生えます。

[isucon@150-95-191-226 ~]$ ip a
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
       valid_lft forever preferred_lft forever
    inet6 ::1/128 scope host
       valid_lft forever preferred_lft forever
2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP group default qlen 1000
    link/ether 02:01:96:5f:bf:e2 brd ff:ff:ff:ff:ff:ff
    inet 150.95.191.226/23 brd 150.95.191.255 scope global noprefixroute dynamic eth0
       valid_lft 86327sec preferred_lft 86327sec
    inet6 2400:8500:1302:847:150:95:191:226/128 scope global noprefixroute dynamic
       valid_lft 7429sec preferred_lft 7129sec
    inet6 fe80::1:96ff:fe5f:bfe2/64 scope link noprefixroute
       valid_lft forever preferred_lft forever
3: eth1: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP group default qlen 1000
    link/ether fa:16:3e:b7:d7:68 brd ff:ff:ff:ff:ff:ff
    inet6 fe80::3d00:ea4a:4342:9f10/64 scope link noprefixroute
       valid_lft forever preferred_lft forever
[isucon@150-95-191-226 ~]$

よく見るとわかるように、インターフェースは認識されているのですが、IPアドレスは振られていません。IPアドレスの振り方はConoHaの公式サイトに書いてあるのでそれに従いました。RHEL7からNetworkManagerというものを使うのが推奨されているのですが、凝った設定をするわけではないのでConoHa公式サイトに載っている方法で進めました。

www.conoha.jp

プライベートネットワークのセグメントを 192.168.0.0/27 に設定したので、設定ファイルはこんな感じでしょうか。

$ cat <<EOF | sudo tee /etc/sysconfig/network-scripts/ifcfg-eth1
TYPE="Ethernet"
BOOTPROTO="none"
IPADDR="192.168.0.X"
NETMASK="255.255.255.224"
DEVICE="eth1"
ONBOOT="yes"
EOF
$ sudo service network restart

全台に設定するとちゃんと繋がりました。親切なマニュアルが用意されていてよいですね。

[isucon@isucon8-1 ~]$ ping -c 1 192.168.0.2
PING 192.168.0.2 (192.168.0.2) 56(84) bytes of data.
64 bytes from 192.168.0.2: icmp_seq=1 ttl=64 time=0.649 ms

--- 192.168.0.2 ping statistics ---
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = 0.649/0.649/0.649/0.000 ms
[isucon@isucon8-1 ~]$ ping -c 1 192.168.0.3
PING 192.168.0.3 (192.168.0.3) 56(84) bytes of data.
64 bytes from 192.168.0.3: icmp_seq=1 ttl=64 time=3.53 ms

--- 192.168.0.3 ping statistics ---
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = 3.537/3.537/3.537/0.000 ms
[isucon@isucon8-1 ~]$ ping -c 1 192.168.0.4
PING 192.168.0.4 (192.168.0.4) 56(84) bytes of data.
64 bytes from 192.168.0.4: icmp_seq=1 ttl=64 time=2.98 ms

--- 192.168.0.4 ping statistics ---
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = 2.981/2.981/2.981/0.000 ms
[isucon@isucon8-1 ~]$

ちなみに、iperfで帯域を測ったところ730Mbpsほど出ていました。プライベートネットワークは1Gbpsとのことなので、こんなものでしょう。

プロビジョニング

初期実装のプロビジョニングをするためのAnsibleスクリプトが用意されているのですが、使い方に関して誤った解釈をしてしまい、余計な時間がかかってしまいました。

isucon8-qualify/provisioning at master · isucon/isucon8-qualify · GitHub

何を間違っていたかというと、Ansibleでプロビジョニングをする前に、isuconユーザーを作成してwheelグループに参加させるという手順を行ってしまっていたことです。isuconユーザーの作成などを行うタスクがprovisioning/roles/common/tasks/main.ym の中で定義されているので、手動でユーザーを作成後にプロビジョニングしようとすると不整合が生じて失敗してしまいました。ユーザーの作成もAnsibleに任せるのが正しかったようです… 私は provisioning/roles/common/tasks/main.ym を編集してユーザー作成に関するタスクを削除することで乗り切りました。

プロビジョニングをする際にお勧めしたいのは、使用する予定がない言語のインストールをスキップすることです。私は Python だけ使う予定だったので、Go, NodeJS, Perl, PHP, Ruby のインストールをスキップするように設定を修正しました。このとき webapp-*.yml から isntall_* を削除するだけでは不十分で、これでは prepare_webapp で npm install などの処理を行おうとしたときに npm, carton, composer, bundler などを使った依存ライブラリのインストールに失敗してしまいます。これに関してもファイルの編集で対応しました。

diff --git a/provisioning/roles/prepare_webapp/tasks/main.yml b/provisioning/roles/prepare_webapp/tasks/main.yml
index fde4e67..2481266 100644
--- a/provisioning/roles/prepare_webapp/tasks/main.yml
+++ b/provisioning/roles/prepare_webapp/tasks/main.yml
@@ -79,38 +79,6 @@
     src: torb.ruby.service
     dest: /etc/systemd/system/torb.ruby.service

-- name: Install for torb.nodejs
-  become: yes
-  become_user: isucon
-  args:
-    chdir: /home/isucon/torb/webapp/nodejs
-  shell: |
-    bash -lc "/home/isucon/local/node/bin/npm install"
-
-- name: Install for torb.go
-  become: yes
-  become_user: isucon
-  args:
-    chdir: /home/isucon/torb/webapp/go
-  shell: |
-    bash -lc "make clean && make deps && make"
-
-- name: Install for torb.perl
-  become: yes
-  become_user: isucon
-  args:
-    chdir: /home/isucon/torb/webapp/perl
-  shell: |
-    bash -lc "carton install"
-
-- name: Install for torb.php
-  become: yes
-  become_user: isucon
-  args:
-    chdir: /home/isucon/torb/webapp/php
-  shell: |
-    bash -lc "composer install"
-
 - name: Install for torb.python
   become: yes
   become_user: isucon
@@ -118,11 +86,3 @@
     chdir: /home/isucon/torb/webapp/python
   shell: |
     bash -lc "sh setup.sh"
-
-- name: Install for torb.ruby
-  become: yes
-  become_user: isucon
-  args:
-    chdir: /home/isucon/torb/webapp/ruby
-  shell: |
-    bash -lc "bundle install --path=.bundle"
diff --git a/provisioning/webapp1.yml b/provisioning/webapp1.yml
index cfca84d..b85205f 100644
--- a/provisioning/webapp1.yml
+++ b/provisioning/webapp1.yml
@@ -4,12 +4,7 @@
     - common
     - install_h2o
     - install_mariadb
-    - install_go
-    - install_nodejs
-    - install_perl
-    - install_php
     - install_python
-    - install_ruby
     - deploy_webapp
     - prepare_webapp
     - initialize_db
diff --git a/provisioning/webapp2.yml b/provisioning/webapp2.yml
index 381717a..8d5fa41 100644
--- a/provisioning/webapp2.yml
+++ b/provisioning/webapp2.yml
@@ -4,12 +4,7 @@
     - common
     - install_h2o
     - install_mariadb
-    - install_go
-    - install_nodejs
-    - install_perl
-    - install_php
     - install_python
-    - install_ruby
     - deploy_webapp
     - prepare_webapp
     - initialize_db
diff --git a/provisioning/webapp3.yml b/provisioning/webapp3.yml
index 98dd7a0..770947a 100644
--- a/provisioning/webapp3.yml
+++ b/provisioning/webapp3.yml
@@ -4,12 +4,7 @@
     - common
     - install_h2o
     - install_mariadb
-    - install_go
-    - install_nodejs
-    - install_perl
-    - install_php
     - install_python
-    - install_ruby
     - deploy_webapp
     - prepare_webapp
     - initialize_db

競技開始

3台のサーバーを使うことができますが、最初から複数台構成でチューニングするのは大変なので、最初は1台構成でチューニングを行い、満足いくまでチューニングしてから複数台構成に変更する方針で進めました。

Pythonの初期実装でベンチマークを実行すると 567点 でした。

Initial commit: 567 · arosh/isucon8-qual@24e0aba · GitHub

ボトルネックが分からないとどうしようもないので、まずはHTTPサーバーのアクセスログにレスポンスタイムを記録する設定を加えました。Twitterで流れてきたネタバレによるとHTTPサーバーはH2Oとのことだったのですが、知らなかった体で一応確認しました。

[isucon@isucon8-1 python]$ sudo netstat -antup
Active Internet connections (servers and established)
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name
tcp        0      0 0.0.0.0:3306            0.0.0.0:*               LISTEN      5230/mysqld
tcp        0      0 127.0.0.1:8080          0.0.0.0:*               LISTEN      6210/python3
tcp        0      0 0.0.0.0:80              0.0.0.0:*               LISTEN      5418/perl
tcp        0      0 0.0.0.0:22              0.0.0.0:*               LISTEN      1152/sshd
（略）
[isucon@isucon8-1 python]$

80番ポートで待ち受けているのはPerlのスクリプトから動いている何かのようですね。ほかには8080番ポートでアプリケーションのPythonが待ち受けているのとMySQLも動いているのが確認できます。

プロセス番号を指定して ps コマンドで調べると以下のようになりました。

[isucon@isucon8-1 python]$ ps uwwp 5418
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root      5418  0.0  0.0 148548     0 ?        Ss   16:31   0:00 perl -x /usr/share/h2o/start_server --pid-file=/var/run/h2o/h2o.pid --log-file=/var/log/h2o/error.log --port=0.0.0.0:80 -- /usr/sbin/h2o -c /etc/h2o/h2o.conf
[isucon@isucon8-1 python]$

これが噂のH2Oですか！ ご丁寧にも設定ファイルの場所まで表示されています。

設定ファイルの内容は以下のような状態でした。

user: isucon

access-log: /var/log/h2o/access.log
error-log: /var/log/h2o/error.log
pid-file: /var/run/h2o/h2o.pid

hosts:
  "localhost:80":
    listen:
      port: 80
      host: 0.0.0.0
    paths:
      "/favicon.ico":
        file.file: /home/isucon/torb/webapp/static/favicon.ico
      "/css":
        file.dir: /home/isucon/torb/webapp/static/css
      "/img":
        file.dir: /home/isucon/torb/webapp/static/img
      "/js":
        file.dir: /home/isucon/torb/webapp/static/js
      "/":
        proxy.reverse.url: http://127.0.0.1:8080/
        proxy.preserve-host: ON

H2Oの設定ファイルは初めて見たのですが、すでに静的ファイル配信の設定も行われているようですね。例年のISUCONでは、最初に取り除くボトルネックは静的ファイルの配信のことが多いですが、今回はその部分はスキップしてもよさそうです。

続いてHTTPエンドポイントごとの処理時間を調べるため、アクセスログ解析ツールに必要な設定をH2Oの設定に組み入れます。アクセスログの解析にはいつも Kataribe を使っています。ISUCON8の予選当日の時点ではH2O向けの設定ファイルの書き方のサンプルがREADMEに載っていなかったようなのですが、予選後にH2O向けのサンプルが追加されたのでコピペするだけで使えます。

Merge pull request #17 from shiimaxx/h2o-example · matsuu/kataribe@63877a5 · GitHub

知らなかったふりゲームをするのも不毛な気がするので、このサンプルを使わせていただきました。初期実装のアクセスログを解析してみると以下のようになりました。

Top 20 Sort By Total
Count   Total      Mean    Min    Max  2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
   51  92.174  1.807328  0.003  9.132   49    0    2    0        2480         34         48         57  POST /api/actions/login HTTP/1.1
   17  54.580  3.210590  0.583  7.678   17    0    0    0      253267      14513      14898      14923  GET / HTTP/1.1
    7  32.911  4.701528  1.172  9.441    7    0    0    0      100730      11440      14390      22045  GET /admin/ HTTP/1.1
   17  29.954  1.761998  0.284  5.039   17    0    0    0     1002838      58988      58990      59002  GET /api/events/10 HTTP/1.1
   23  21.658  0.941646  0.002  3.823   17    0    6    0        1111         34         48         81  POST /admin/api/actions/login HTTP/1.1
    5  16.534  3.306896  0.003  7.725    4    0    1    0         211         23         42         47  POST /api/users HTTP/1.1
   10  13.411  1.341117  0.001  4.935    8    0    2    0         458         25         45         51  POST /api/events/11/actions/reserve HTTP/1.1
（略）

静的ファイルの配信が上位に来ていないので、HTTPサーバーの設定改善はあまり頑張らなくてもよさそうだということが分かりました。

次に dstat でシステムのリソースを調べてみると50%ほどIdleになっていることが分かりました。

[isucon@isucon8-1 webapp]$ dstat -tclmdrn
----system---- ----total-cpu-usage---- ---load-avg--- ------memory-usage----- -dsk/total- --io/total- -net/total-
     time     |usr sys idl wai hiq siq| 1m   5m  15m | used  buff  cach  free| read  writ| read  writ| recv  send
13-10 17:33:16| 11   3  85   0   0   0|   0 0.05 0.10| 271M 20.0M  187M  513M| 747k 1234k|26.5  27.9 |   0     0
13-10 17:33:17|  0   0 100   0   0   0|   0 0.04 0.10| 271M 20.0M  187M  513M|   0     0 |   0     0 |1156B   90B
13-10 17:33:18|  0   0 100   0   0   0|   0 0.04 0.10| 271M 20.0M  187M  513M|   0  8192B|   0  1.00 | 390B  394B
13-10 17:33:19|  0   0 100   0   0   0|   0 0.04 0.10| 271M 20.0M  187M  513M|   0     0 |   0     0 | 592B  146B
13-10 17:33:20|  0   0 100   0   0   0|   0 0.04 0.10| 271M 20.0M  187M  513M|   0     0 |   0     0 | 800B  122B
13-10 17:33:21|  6   2  92   1   0   0|   0 0.04 0.10| 281M 20.0M  187M  504M|  64k  468k|2.00  44.0 | 853B  246B
13-10 17:33:22| 46   3  48   3   0   0|   0 0.04 0.10| 289M 20.2M  188M  494M| 560k   31M|20.0   290 | 352B  106B
13-10 17:33:23| 47   3  49   2   0   0|   0 0.04 0.10| 278M 20.2M  188M  506M| 448k   35M|14.0   147 |4747B  233k
13-10 17:33:24| 38   9  50   1   0   2|   0 0.04 0.10| 282M 20.2M  188M  502M| 192k 2876k|6.00  20.0 |5126B  179k
13-10 17:33:25| 40   7  50   0   0   3|   0 0.04 0.10| 282M 20.2M  188M  501M|   0     0 |   0     0 | 472B  146B
13-10 17:33:26| 40   8  50   0   0   3|   0 0.04 0.10| 282M 20.2M  188M  501M|   0     0 |   0     0 | 860B  154B
13-10 17:33:27| 39   9  50   0   0   3|0.08 0.06 0.11| 282M 20.2M  188M  501M|   0     0 |   0     0 | 712B  114B
13-10 17:33:28| 40   9  50   0   0   2|0.08 0.06 0.11| 282M 20.2M  188M  501M|   0  8192B|   0  2.00 | 546B  106B
13-10 17:33:29| 39   7  51   0   0   3|0.08 0.06 0.11| 282M 20.2M  188M  501M|   0    36k|   0  2.00 |1386B   22k
13-10 17:33:30| 37  11  50   0   0   3|0.08 0.06 0.11| 282M 20.2M  188M  502M|  32k  268k|1.00  21.0 |2273B 2081B
13-10 17:33:31| 38   9  51   0   0   2|0.08 0.06 0.11| 282M 20.2M  188M  502M|   0  8192B|   0  4.00 |6599B   33k
13-10 17:33:32| 39   9  51   0   0   3|0.16 0.08 0.11| 282M 20.2M  188M  502M|   0    12k|   0  4.00 |2616B   43k
13-10 17:33:33| 39   9  50   0   0   2|0.16 0.08 0.11| 282M 20.2M  188M  502M|   0  4096B|   0  2.00 | 592B  122B
13-10 17:33:34| 45   5  50   0   0   1|0.16 0.08 0.11| 282M 20.2M  188M  502M|   0  4096B|   0  2.00 | 806B  254B

この結果からアプリケーションのワーカーの数が適切でないことが示唆されました。そのため、ワーカーの数を増やしてベンチマークを再度とったところ 848点 になりました。

Increase python worker: 848 · arosh/isucon8-qual@4e632bd · GitHub

CPUのIdle時間が減ったところで、topコマンドでどのプロセスがCPUを多く使っているのか調べました。

 5230 mysql     20   0 1565008 163696   3224 S 123.3 16.1   3:37.35 mysqld
 7720 isucon    20   0  331044  28260   4736 R  39.5  2.8   0:18.44 gunicorn
 7721 isucon    20   0  449372 146044   4752 R  34.6 14.4   0:14.55 gunicorn

MySQLですね。innodb_buffer_pool_size の設定をしたり、スロークエリログの設定をしてボトルネックを見つける必要がありそうです。

CentOS系のMySQLの設定ファイルの場所が分からなかったので mysql --help で調べると以下のような行が含まれていました。

Default options are read from the following files in the given order:
/etc/mysql/my.cnf /etc/my.cnf ~/.my.cnf

/etc/mysql/my.cnf が見つからなかったので /etc/my.cnf の中身を見ると /etc/my.cnf.d の中を include していることが分かりました。/etc/my.cnf.d/server.conf を見ると以下のような状態でした。

#
# These groups are read by MariaDB server.
# Use it for options that only the server (but not clients) should see
#
# See the examples of server my.cnf files in /usr/share/mysql/
#

# this is read by the standalone daemon and embedded servers
[server]

# this is only for the mysqld standalone daemon
[mysqld]

# this is only for embedded server
[embedded]

# This group is only read by MariaDB-5.5 servers.
# If you use the same .cnf file for MariaDB of different versions,
# use this group for options that older servers don't understand
[mysqld-5.5]

# These two groups are only read by MariaDB servers, not by MySQL.
# If you use the same .cnf file for MySQL and MariaDB,
# you can put MariaDB-only options here
[mariadb]

[mariadb-5.5]

設定されていなくて実質空ファイルですね。さらにMySQLではなくMariaDBで、バージョンも5.5ということで古めでした。5.5だとMySQLとほとんど差分が無かったんでしたっけ？昔のことなので忘れました…

設定はスロークエリログを書き出す設定と、innodb_buffer_pool_size, innodb_log_file_size, innodb_flush_log_at_trx_commit = 0 などの設定を行いました（ISUCON以外では innodb_flush_log_at_trx_commit = 0 は絶対にダメです…）。最終的な状態は以下のファイルをご覧ください。

isucon8-qual/server.cnf at master · arosh/isucon8-qual · GitHub

やたらと遅い /api/actions/login を見てみました。これの中身は以下のようなものでした。

def get_login_user():
    （略）
    cur.execute("SELECT id, nickname FROM users WHERE id = %s", [user_id])
    return cur.fetchone()

@app.route('/api/actions/login', methods=['POST'])
def post_login():
    （略）
    cur.execute('SELECT * FROM users WHERE login_name = %s', [login_name])
    user = cur.fetchone()
    cur.execute('SELECT SHA2(%s, 256) AS pass_hash', [password])
    pass_hash = cur.fetchone()
    if not user or pass_hash['pass_hash'] != user['pass_hash']:
        return res_error("authentication_failed", 401)

    flask.session['user_id'] = user["id"]
    user = get_login_user()
    return flask.jsonify(user)

遅い原因として予想されるのは

  1. users.login_name にインデックスが付けられていない
  2. MariaDBの中でSHA-256を計算するのが遅い
  3. get_login_user() の中のSQLにある users.id にインデックスが付けられていない
  4. JSONにシリアライズするのが遅い

などです。実際にはこの中で1と3はハズレで、既にインデックスが付けられていました。2のSHA-256の計算が遅いというのが有力かな？と思って以下のように修正しました。

def sha256(s):
    if isinstance(s, str):
      s = s.encode('UTF-8')
    m = hashlib.sha256()
    m.update(s)
    return m.hexdigest()

def post_login():
  # 略
  pass_hash = {'pass_hash': sha256(password)}
  # 略

これには全く効果がありませんでした。結局のところ /api/actions/login が遅いのは最後まで修正することができませんでした。

遅い関数をエスパーするのは不毛なので、Werkzeug の WSGI Application Profiler を導入しました。gprof2dot を使うと、プロファイル結果をコールグラフの形で時間のかかっている処理を関数単位で見つけることができます。

実際にプロファイルを取ってみると get_events() と get_event() が重いことが分かりました。get_events() の初期実装は以下のようなものでした。

def get_events(filter=lambda e: True):
    （略）
    cur.execute("SELECT * FROM events ORDER BY id ASC")
    rows = cur.fetchall()
    event_ids = [row['id'] for row in rows if filter(row)]
    events = []
    for event_id in event_ids:
        event = get_event(event_id)
        for sheet in event['sheets'].values():
            del sheet['detail']
        events.append(event)
    （略）
    return events

この実装の改善できるところとして

  • get_events() で id 一覧を取得してから、それぞれの id について get_event() の中で詳細情報を取得している（つまりN+1）
  • get_event() で sheet['detail'] の中身をかなり頑張って作っているのに、get_events() から呼ばれた時には捨てている

という点に気づきました。最小限の手間で行える改善を考えたところ、get_event() の引数に need_detail というオプション引数を足しておいて、need_detail=False のときには sheet['detail'] の中身を作らないという方針を考えました。

実装を進める前に get_events() で返されるデータがどのようなものなのか確認しておくと役に立ちそうだと思ったので、調べてみました。

[isucon@isucon8-1 webapp]$ curl 127.0.0.1/api/events | jq '.'
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100  1251  100  1251    0     0   1133      0  0:00:01  0:00:01 --:--:--  1133
[
  {
    "id": 10,
    "title": "平成狐合戦バブル経済",
    "total": 1000,
    "remains": 0,
    "sheets": {
      "S": {
        "total": 50,
        "remains": 0,
        "price": 7000
      },
      "A": {
        "total": 150,
        "remains": 0,
        "price": 5000
      },
      "B": {
        "total": 300,
        "remains": 0,
        "price": 3000
      },
      "C": {
        "total": 500,
        "remains": 0,
        "price": 2000
      }
    }
  },
  （略）

要するに、各イベントについてランクごとの総座席数 (total) 、残り座席数 (remains)、価格 (price) を計算しているようです。total と remains に関しては、get_event() の初期実装では

cur.execute("SELECT * FROM sheets ORDER BY `rank`, num")
sheets = cur.fetchall()
for sheet in sheets:
  （略）

のようにして、各座席についてループを回して、座席数を += 1 のようにして数えているのですが、SQLで GROUP BY を使って集計することができそうですね。

また price に関しては、イベントの基本価格 event['price'] と、座席のランクごとの価格 sheet['price'] の合計で計算されていて、それぞれをデータベースから取得する処理を行っています。ところが、座席のランクごとの価格 sheet['price'] に関しては、価格を変更する機能がアプリケーションに含まれていないので、データベースから取得するのを省いてアプリケーションに埋め込んでしまうことができそうです。

need_detail=False の場合の処理を分岐して以下のように変更しました。

ranks = ["S", "A", "B", "C"]
sheet_price = {'S': 5000, 'A': 3000, 'B': 1000, 'C': 0}
for rank in ranks:
    event['sheets'][rank] = {'price': event['price'] + sheet_price[rank]}
# ランクごとの総座席数を計算する
cur.execute('SELECT `rank`, COUNT(*) AS total FROM sheets GROUP BY `rank`')
totals = cur.fetchall()
for total in totals:
    event['sheets'][total['rank']]['total'] = total['total']
    event['sheets'][total['rank']]['remains'] = total['total']
# ランクごとの予約済みの座席数を計算する
cur.execute('SELECT sheets.`rank`, COUNT(*) AS reserved FROM reservations INNER JOIN sheets ON reservations.sheet_id = sheets.id WHERE event_id = %s AND canceled_at IS NULL GROUP BY sheets.`rank`', [event['id']])
reserved = cur.fetchall()
# 総座席数 - 予約済み座席数 = 残り座席数
for rank in reserved:
    event['sheets'][rank['rank']]['remains'] -= rank['reserved']
for rank in ranks:
    event['total'] += event['sheets'][rank]['total']
    event['remains'] += event['sheets'][rank]['remains']

この変更でスコアが 1725点 と倍近くに上がりました。

Fix get_event: 1725 · arosh/isucon8-qual@b08569f · GitHub

get_events() に関してはかなりマシになりましたが、プロファイルの結果 get_event() がまだ遅いことが分かりました。need_detail=False の場合は改善されたので、次は need_detail=True の場合を改善する必要がありそうです。

get_event() の need_detail=True の場合の処理を抜粋すると以下のような箇所があります。

cur.execute("SELECT * FROM sheets ORDER BY `rank`, num")
sheets = cur.fetchall()
for sheet in sheets:
    （略）
    cur.execute(
        "SELECT * FROM reservations WHERE event_id = %s AND sheet_id = %s AND canceled_at IS NULL GROUP BY event_id, sheet_id HAVING reserved_at = MIN(reserved_at)",
        [event['id'], sheet['id']])
    reservation = cur.fetchone()
    if reservation:
        if login_user_id and reservation['user_id'] == login_user_id:
            sheet['mine'] = True
        sheet['reserved'] = True
        sheet['reserved_at'] = int(reservation['reserved_at'].replace(tzinfo=timezone.utc).timestamp())
    else:
        event['remains'] += 1
        event['sheets'][sheet['rank']]['remains'] += 1

    event['sheets'][sheet['rank']]['detail'].append(sheet)
    （略）

座席 (sheet) の一覧を取ってから、それぞれの座席の予約 (reservation) の詳細情報を取得しています。つまりN+1です。N+1は id 一覧を取ってくるときに JOIN 区で詳細情報をまとめて取ってくる方針で改善することが多いですが、いくつか懸念事項がありました。

  • 座席 (sheet) に対応する予約 (reservation) は存在しない場合がある（if reservation の else 句）。INNER JOIN ではなく LEFT OUTER JOIN を使わなければ sheet が欠損してしまう。
  • 予約 (reservation) の詳細情報を取ってくるときのSQLに HAVING reserved_at = MIN(reserved_at) という謎の句がある。同じ座席について複数の予約を取ってしまった場合の処置のようだ。予約の処理のトランザクション処理が正しく行えていれば不要なはずなので、これは消そう。

以下のようなSQL文に変更することで改善することができました。

SELECT sheets.id AS id, sheets.`rank` AS `rank`, sheets.num AS num, sheets.price AS price, reservations.user_id AS user_id, reservations.reserved_at AS reserved_at
FROM sheets LEFT OUTER JOIN reservations ON sheets.id = reservations.sheet_id
AND reservations.event_id = %s
AND reservations.canceled_at IS NULL
ORDER BY sheets.`rank`, sheets.num

この改善によりスコアが 11111点 にまで上がりました。

SQLに詳しい方ならこんな間違いはしないと思うのですが、reservations.event_id = %s と reservations.canceled_at IS NULL を書く場所について間違った理解をしていて、時間を無駄にしてしまいました。今回の場合は、これらの条件は LEFT OUTER JOIN の ON 句の中に書くのが正しく、WHERE 句の中に書くと結果が違ってしまいます。

Fix N+1: 11111 · arosh/isucon8-qual@d7b4798 · GitHub

この段階でプロファイルを取ってみると get_users() が遅いのが気になりました。よく見ると get_events() と同じで get_event() の結果の sheet['detail'] を使っていないことが分かったので need_detail=False を付けました。これで 16482点 まで上がりました。

Improve get_users: 16482 · arosh/isucon8-qual@d9ba3f9 · GitHub

次に気になったのは top コマンドの結果です。used のカラムを見ていると、まれにメモリをたくさん使っている瞬間があることに気づきました。

     time     |usr sys idl wai hiq siq| 1m   5m  15m | used  buff  cach  free| read  writ| read  writ| recv  send
14-10 20:51:17|  0   0 100   0   0   0|   0 0.22 0.63| 591M 11.0M  319M 70.5M|   0     0 |   0     0 | 694B   66B
14-10 20:51:18|  1   0  99   0   0   0|   0 0.21 0.62| 591M 11.0M  319M 70.2M|  32k   56k|1.00  2.00 | 676B  370B
14-10 20:51:19|  2   0  99   0   0   0|   0 0.21 0.62| 591M 11.0M  319M 70.2M|   0   112k|   0  24.0 |1999B   12k
14-10 20:51:20|  0   0 100   0   0   0|   0 0.21 0.62| 591M 11.0M  319M 70.2M|   0     0 |   0     0 | 840B   11k
14-10 20:51:21|  9   0  91   0   0   0|   0 0.21 0.62| 591M 11.0M  319M 70.2M|   0     0 |   0     0 |1293B  376B
14-10 20:51:22| 36  18  46   0   0   0|   0 0.21 0.62| 593M 10.3M  322M 66.6M|  12k  174M|3.00   397 | 514B   54B
14-10 20:51:23| 39  15  46   0   0   0|0.16 0.24 0.63| 621M 6684k  106M  258M|4096B  117M|1.00   351 | 506B  114B
14-10 20:51:24| 48   3  50   0   0   0|0.16 0.24 0.63| 682M 6684k  106M  197M|   0     0 |   0     0 | 910B  458B
14-10 20:51:25| 47   3  50   0   0   0|0.16 0.24 0.63| 757M 6684k  106M  122M|   0     0 |   0     0 | 896B   66B
14-10 20:51:26| 48   2  50   0   0   0|0.16 0.24 0.63| 821M 6684k  106M 59.0M|   0     0 |   0     0 | 320B  130B
14-10 20:51:27| 49   2  50   0   0   0|0.16 0.24 0.63| 827M 5132k 96.7M 62.5M|   0   560k|   0  9.00 | 836B  444B
14-10 20:51:28| 17   3  80   0   0   0|0.23 0.26 0.63| 595M 5132k 96.7M  295M|   0     0 |   0     0 |  45k 8721k
14-10 20:51:29|  0   1  99   0   0   0|0.23 0.26 0.63| 567M 5132k 96.7M  323M|   0     0 |   0     0 |  15k 3509k
14-10 20:51:30|  2   1  97   1   0   1|0.23 0.26 0.63| 569M 5132k 96.7M  321M|  20k    0 |1.00     0 |2772B 3279B
14-10 20:51:31|  0   0 100   0   0   0|0.23 0.26 0.63| 569M 5132k 96.7M  321M|   0     0 |   0     0 | 728B  204B
14-10 20:51:32|  1   1  99   0   0   0|0.23 0.26 0.63| 571M 5132k 96.8M  319M|   0     0 |   0     0 |2538B 2725B
14-10 20:51:33|  1   1  99   0   0   0|0.21 0.25 0.63| 569M 5140k 96.8M  320M|   0    48k|   0  2.00 |1384B  798B

プロファイルの結果 get_admin_sales() が1回のレスポンス時間が長いことが分かったのですが、よく見ると reservations を全件取得して CSV 形式で書き出していることが分かりました。CSV に書き出す処理は以下のようになっています。

def render_report_csv(reports):
    reports = sorted(reports, key=lambda x: x['sold_at'])

    keys = ["reservation_id", "event_id", "rank", "num", "price", "user_id", "sold_at", "canceled_at"]

    body = []
    body.append(keys)
    for report in reports:
        body.append([report[key] for key in keys])

    f = StringIO()
    writer = csv.writer(f)
    writer.writerows(body)
    res = flask.make_response()
    res.data = f.getvalue()
    res.headers['Content-Type'] = 'text/csv'
    res.headers['Content-Disposition'] = 'attachment; filename=report.csv'
    return res

StringIO にすべて書き出しているのは改善できそうですね。Flask の機能でストリーム的にデータを送ることができた記憶があったので調べてみると、ドキュメントに Streaming Contents という項目がありました。これを参考に render_report_csv() を改善した結果が以下のものです。

def render_report_csv(reports):
    keys = ["reservation_id", "event_id", "rank", "num", "price", "user_id", "sold_at", "canceled_at"]

    def generate():
        yield ','.join(keys) + '\n'
        for report in reports:
            yield ','.join([str(report[key]) for key in keys]) + '\n'

    headers = {}
    headers['Content-Type'] = 'text/csv'
    headers['Content-Disposition'] = 'attachment; filename=report.csv'

    return flask.Response(generate(), headers=headers)

この改善に加えて reservations を全件取得する際に cur.fetchall() するのではなく、逐次的に読み込むためのイテレータを render_report_csv() の引数 reports として渡すように変更しました。これにより 17517点 になりました。思ったより改善しませんでしたね。。。

Stream: 17517 · arosh/isucon8-qual@b5afe34 · GitHub

次は、また get_event() が遅いのが気になってきました。今度は need_detail=False の場合の高速化が必要な気がします。need_detail=False の場合の処理を抜粋すると、以下のようなものでした（再掲）。

ranks = ["S", "A", "B", "C"]
sheet_price = {'S': 5000, 'A': 3000, 'B': 1000, 'C': 0}
for rank in ranks:
    event['sheets'][rank] = {'price': event['price'] + sheet_price[rank]}
# ランクごとの総座席数を計算する
cur.execute('SELECT `rank`, COUNT(*) AS total FROM sheets GROUP BY `rank`')
totals = cur.fetchall()
for total in totals:
    event['sheets'][total['rank']]['total'] = total['total']
    event['sheets'][total['rank']]['remains'] = total['total']
# ランクごとの予約済みの座席数を計算する
cur.execute('SELECT sheets.`rank`, COUNT(*) AS reserved FROM reservations INNER JOIN sheets ON reservations.sheet_id = sheets.id WHERE event_id = %s AND canceled_at IS NULL GROUP BY sheets.`rank`', [event['id']])
reserved = cur.fetchall()
# 総座席数 - 予約済み座席数 = 残り座席数
for rank in reserved:
    event['sheets'][rank['rank']]['remains'] -= rank['reserved']
for rank in ranks:
    event['total'] += event['sheets'][rank]['total']
    event['remains'] += event['sheets'][rank]['remains']

よく考えると、総座席数はイベントごとに変わらないので、sheet_price と同じようにアプリに埋め込んでおくことができます。埋め込むように変更することで 17475点 になりました。あまり変わりませんね。

Improve get_event: 17475 · arosh/isucon8-qual@10790dd · GitHub

mysqldumpslow の結果を見てみると

SELECT sheets.`rank`, COUNT(*) AS reserved FROM reservations INNER JOIN sheets ON reservations.sheet_id = sheets.id WHERE event_id = %s AND canceled_at IS NULL GROUP BY sheets.`rank`

が遅いことに気づきました。これは、あるイベントに関して座席のランクごとの予約の数を数えるSQLです。これは別のテーブルを作って結果をキャッシュしておくことができます。ただし、予約が行われた時にはインクリメントして、予約がキャンセルされた時にはデクリメントしてやるなど、大きな改修が必要です。

まず /initialize の中で以下のようなテーブルを作成しました。カラムの型は既存のものをパクりました。

CREATE TABLE IF NOT EXISTS sheet_reserved (
    id          INTEGER UNSIGNED PRIMARY KEY AUTO_INCREMENT,
    event_id    INTEGER UNSIGNED NOT NULL,
    `rank`      VARCHAR(128)     NOT NULL,
    reserved    INTEGER UNSIGNED NOT NULL,
    UNIQUE KEY event_id_rank_uniq (event_id, `rank`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4

このテーブルに適切にキャッシュしておけば

SELECT `rank`, reserved FROM sheet_reserved WHERE event_id = %s

というSQLで前述のSQLを置き換えることができます。適切にキャッシュしておくために reservations テーブルを INSERT, UPDATE, DELETE している箇所を探すと、以下の部分に変更が必要だとわかりました。

  • 初期データを投入している部分 (get_initialize()) で、初期データの reservations についての sheet_reserved を更新する
  • 予約を追加する部分 (post_reserve()) で sheet_reserved をインクリメントする
  • 予約をキャンセルする部分 (delete_reserve()) で sheet_reserved をデクリメントする
  • イベントを追加する部分 (post_admin_events_api()) で sheet_reserved に 0 をセットする

この変更によって 29107点 まで上がりました。かなり上がってうれしいですね。

Cache sheet_reserved: 29107 · arosh/isucon8-qual@765cfba · GitHub

ソースコードを眺めていると get_event() を呼び出すときに need_detail=False にしてしまって問題ない箇所がいくつかあったので変更しました。また、reservations の全件取得でメモリ爆食い容疑のある get_admin_sales() について、オブジェクトの生成数を減らせる方法があったので変更しました。これにより 32865点 まで上がりました。

More need_detail=False: 32865 · arosh/isucon8-qual@38bb549 · GitHub

また get_event() の改善に戻ります。今度は need_detail=True の場合です。N+1を改善するために使った以下のSQLがmysqldumpslowで上位に来てしまっていました（再掲）。

SELECT sheets.id AS id, sheets.`rank` AS `rank`, sheets.num AS num, sheets.price AS price, reservations.user_id AS user_id, reservations.reserved_at AS reserved_at
FROM sheets LEFT OUTER JOIN reservations ON sheets.id = reservations.sheet_id
AND reservations.event_id = %s
AND reservations.canceled_at IS NULL
ORDER BY sheets.`rank`, sheets.num

LEFT OUTER JOINを使っているのは、予約が無い座席についても、座席番号と座席のランクの情報が必要なためでした。ところで、座席の数や座席のランクは変化することが無いのですが、LEFT OUTER JOINを使う必要があるのでしょうか？ アプリにデータを埋め込んでおくことで reservations.sheet_id から座席番号と座席のランクは計算できます。すると、予約がない座席についてのデータを取得する必要がなくなるので、LEFT OUTER JOINを使う必要がなくなります。SQL文は

SELECT sheet_id, user_id, reserved_at
FROM reservations
WHERE event_id = %s AND canceled_at IS NULL
ORDER BY sheet_id

のようにシンプルになります。その代わり、

def convert(sheet_id):
    if sheet_id <= 50:
        return ('S', sheet_id)
    if sheet_id <= 200:
        return ('A', sheet_id - 50)
    if sheet_id <= 500:
        return ('B', sheet_id - 200)
    return ('C', sheet_id - 500)

のようにして sheet_id から座席のランクと座席番号を計算しなければならなくなったのと、予約が無い座席についても欠損を埋めてやる必要が出てきてしまいました。この変更は面倒ですが、負荷をデータベースからアプリに移すことができるようになったので、複数台構成に変更したときに大きな効果が見込めます。

この変更によって 35554点 になりました。

Improve get_event: 35554 · arosh/isucon8-qual@b736900 · GitHub

ここまでで、単体構成で改善できそうな内容が無くなってきたので、複数台構成に変更することにしました。h2oでロードバランシングする方法は知らなかったのですが、/etc/hosts に複数台のホストのIPアドレスを指定すればよいようですね。

Proxy Directives - Configure - H2O - the optimized HTTP/2 server

netstat を見ていると TIME_WAIT で埋め尽くされていたのでカーネルパラメータを変更しました。パラメータの意味はよく分かっていないので、Fluentdのドキュメントに載っている値をコピペしました（ちゃんと勉強したい…）

Before Installing Fluentd | Fluentd

H2O、DB、アプリのワーカーの配置の構成はいろいろ試したのですが、H2O+DBのホストが1台、ワーカーを2つ起動したホストが2台の構成が最もスコアが安定しました。最高スコアは 52856点 です。ベンチマークのログは以下のようになりました。

[  info ] [isu8q-bench] 2018/10/16 01:19:57.549293 bench.go:378: ----- Request counts -----
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549315 bench.go:381: POST|/api/actions/login 3022
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549327 bench.go:381: GET|/js/fetch.min.js 2324
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549339 bench.go:381: GET|/js/jquery-3.3.1.slim.min.js 2324
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549349 bench.go:381: GET|/css/layout.css 2324
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549360 bench.go:381: GET|/css/admin.css 2324
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549370 bench.go:381: GET|/js/app.js 2324
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549380 bench.go:381: GET|/css/bootstrap.min.css 2324
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549389 bench.go:381: GET|/js/bootstrap.bundle.min.js 2324
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549399 bench.go:381: GET|/favicon.ico 2324
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549408 bench.go:381: GET|/js/vue.min.js 2324
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549418 bench.go:381: GET|/js/bootstrap-waitingfor.min.js 2324
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549428 bench.go:381: GET|/js/admin.js 2324
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549441 bench.go:381: GET|/ 2268
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549450 bench.go:381: GET|/api/events/* 2237
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549460 bench.go:381: POST|/api/events/*/actions/reserve 2060
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549470 bench.go:381: DELETE|/api/events/*/sheets/*/*/reservation 621
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549481 bench.go:381: POST|/admin/api/actions/login 52
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549490 bench.go:381: GET|/admin/api/reports/events/*/sales 37
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549500 bench.go:381: GET|/api/users/* 29
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549517 bench.go:381: GET|/admin/ 28
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549528 bench.go:381: POST|/api/users 24
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549537 bench.go:381: GET|/admin/api/events/* 12
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549551 bench.go:381: POST|/admin/api/events/*/actions/edit 8
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549567 bench.go:381: POST|/admin/api/events 7
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549585 bench.go:381: POST|/api/actions/logout 6
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549602 bench.go:381: POST|/admin/api/actions/logout 6
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549617 bench.go:381: GET|/admin/api/reports/sales 2
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549630 bench.go:384: ----- Other counts ------
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549647 bench.go:388: staticfile-200 25531
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549664 bench.go:388: load-level-up 9
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549680 bench.go:391: -------------------------
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549826 bench.go:510: get 30177
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549844 bench.go:511: post 5185
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549855 bench.go:512: delete 621
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549886 bench.go:513: static 25531
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549897 bench.go:514: top 2268
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549908 bench.go:515: reserve 2060
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549919 bench.go:516: cancel 621
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549929 bench.go:517: get_event 2237
[  info ] [isu8q-bench] 2018/10/16 01:19:57.549939 bench.go:518: score 52856

Kataribeで集計したエンドポイントごとの時間は以下のようになりました。/api/actions/login が一番遅いのが気になりますが、WSGI Application Profilerで何も出てこないところから考えて、ワーカーが空くのを待っている時間がそのまま計上されている可能性が高いと考えています。この部分だけ H2O+DB を動かしているホストに逃がしてみるという方法を検討しても良かったかもしれません。

Top 20 Sort By Total
Count      Total      Mean     Min     Max    2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
17200  11945.441  0.694502   0.004   5.376  17142    0   58    0      849768         34         49         63  POST /api/actions/login HTTP/1.1
11020   9133.275  0.828791   0.004   5.374  10964    0   56    0   644742015         22      58506      59030  GET /api/events/*
11399   9030.855  0.792250   0.008   5.367  11399    0    0    0   183479922      14440      16096      17422  GET / HTTP/1.1
10940   8168.320  0.746647   0.002   5.264  10858    0   82    0      552419         25         50         51  POST /api/events/*/actions/reserve
 3617   2615.991  0.723249   0.002   5.256   3506    0  111    0        2886          0          0         27  DELETE /api/events/*/sheets/*/*/reservation
  268    277.131  1.034073   0.493   5.445    268    0    0    0      813519        113       3035       3334  GET /api/users/*
   32    252.734  7.897946   5.105  13.156     32    0    0    0   397957946   12403378   12436185   12517753  GET /admin/api/reports/sales HTTP/1.1
  324    150.378  0.464129   0.005   3.933    324    0    0    0    57680848         67     178027     826499  GET /admin/api/reports/events/*/sales
  429    131.878  0.307407   0.005   5.230    344    0   85    0       21120         30         49         81  POST /admin/api/actions/login HTTP/1.1
  327     94.422  0.288752   0.005   3.325    297    0   30    0       15765         23         48         59  POST /api/users HTTP/1.1
  264     89.595  0.339373   0.002   3.112    264    0    0    0     4182721      11440      15843      24832  GET /admin/ HTTP/1.1
  112     22.893  0.204401   0.002   1.868     56    0   56    0      786648         22       7023      14024  GET /admin/api/events/*
   84     18.222  0.216934   0.002   1.503     28    0   56    0      394080         22       4691      14023  POST /admin/api/events/*/actions/edit
    7     17.633  2.518975   2.454   2.557      7    0    0    0           0          0          0          0  GET /initialize HTTP/1.1
   61     14.246  0.233536   0.002   3.541     33    0   28    0      463590         33       7599      14024  POST /admin/api/events HTTP/1.1
   58     13.711  0.236404   0.001   5.226     29    0   29    0         957          0         16         33  POST /admin/api/actions/logout HTTP/1.1
   60     11.122  0.185373   0.002   2.498     31    0   29    0         783          0         13         27  POST /api/actions/logout HTTP/1.1
11639      0.571  0.000049   0.000   0.013  11639    0    0    0  1640284270     140930     140930     140930  GET /css/bootstrap.min.css HTTP/1.1
11636      0.098  0.000008   0.000   0.013  11636    0    0    0  1005955472      86452      86452      86452  GET /js/vue.min.js HTTP/1.1
11639      0.000  0.000000   0.000   0.000  11639    0    0    0    12709788       1092       1092       1092  GET /favicon.ico HTTP/1.1

そのほかの取り組み

MySQL 8.0

MariaDB 5.5 から MySQL 8.0 にアップグレードすればオプティマイザが改善されているはずなのでスコアが上がるのではと思ってやってみましたが、逆にスコアが下がりました。設定のデフォルト値の変更や、クエリキャッシュの機能削除などいろいろな要因が考えられます。

Fail2ban

/var/log/secure を確認しているとSSHでログインを試みてくる悪い人が沢山いることに気づきました。精神衛生上悪いので Fail2ban をインストールして、ログイン失敗を繰り返しているIPアドレスをブロックする設定を行ったのですが、Fail2ban を設定するとMariaDBへのアクセスにも何らかのチェックが行われるようで、スコアがかなり下がってしまいました。ISUCONではアンインストールしたほうが良いかもしれません。

tmux

複数台を同時に制御したいときは tmux の synchronized pane が便利でした。

複数のpaneを開いた後、C-b → ':' でコンソールっぽいものに入力できるようになるので

set-window-option synchronize-panes on

を実行すると複数paneに同じキー入力を送れるようになります。

追加で、複数paneの縦幅を均等にするにはtmuxのコンソールで以下のコマンドを実行します。

select-layout even-vertical

dstat

dstat のオプションは以下のものが気に入っています。

dstat -tcmsdn --tcp

お好みで -f をつけてもよいですが、横幅の大きいディスプレイでないと使いにくいでしょう。

まとめ

競技時間的には本番の倍くらいの時間をかけましたが 52856点 が出せたので良い練習になりました。来年は本番に出られるように頑張ります！

過去の参加記

kujira16.hateblo.jp

kujira16.hateblo.jp

kujira16.hateblo.jp