はじめに

本記事では、ISUCON9の予選問題をローカル環境で実行しながら振り返りを行います。言語はrubyで行います。

環境構築

環境構築には以下のリポジトリのVagrantfileを使用します。
https://github.com/matsuu/vagrant-isucon

本番との違いはREADME.mdにも記載のある通り、スペックと台数です。

初期実装のスコア

実装をrubyに切り替えてベンチマークを実行します。

実装の切り替え

$ sudo systemctl stop    isucari.golang.service
$ sudo systemctl disable isucari.golang.service
$ sudo systemctl start   isucari.ruby.service
$ sudo systemctl enable  isucari.ruby.service

ベンチマークの実行

ベンチマークは本番と同様にNginxを通して実行したいので、target_urlを指定して実行します。

$ ./bin/benchmarker -target-url https://127.0.0.1

実行結果は以下の通りです。

{"pass":true,"score":2010,"campaign":0,"language":"ruby","messages":[]}

アクセスログを解析する

alp v0.4.0を使用してアクセスログの解析をします。
https://github.com/tkuchiki/alp

v1.0.0もありますが、事前準備の段階でv1.0.0が上手く動かなかったため、v0.4.0を使用しました。

$ sudo wget https://github.com/tkuchiki/alp/releases/download/v0.4.0/alp_linux_amd64.zip
$ sudo unzip alp_linux_amd64.zip
$ sudo mv alp /usr/bin/

Nginxのログをalpで解析できる形式にします。
nginx.confを修正したらNginxを再起動する必要があります。

nginx.conf

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;

この状態で改めてベンチマークを実行し、アクセスログを解析します。
集計の正規表現はalpの結果を見ながら適当に足して行きました。

$ sudo cat /var/log/nginx/access.log | alp --aggregates="/users/\d+.json","/items/\d+.json","/new_items/\d+.json","/upload/.+.jpg","/transactions/\d+.png"

結果は以下のように表示されます。
大きな時間を取っているGET /users/transactions.jsonやGET /new_items/\d+.jsonから対応していく方針になります。

+-------+--------+-------------------------------------+-----+------+-----+-----+-----+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+
| COUNT | METHOD |                 URI                 | 1XX | 2XX  | 3XX | 4XX | 5XX |  MIN  |  MAX  |   SUM   |  AVG  |  P1   |  P50  |  P99  | STDDEV | MIN(BODY)  | MAX(BODY)  |  SUM(BODY)   | AVG(BODY)  |
+-------+--------+-------------------------------------+-----+------+-----+-----+-----+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+
|     1 | GET    | /static/js/runtime~main.a8a9905a.js |   0 |    1 |   0 |   0 |   0 | 0.008 | 0.008 |   0.008 | 0.008 | 0.008 | 0.008 | 0.008 |  0.000 |   1502.000 |   1502.000 |     1502.000 |   1502.000 |
|    34 | GET    | /transactions/\d+.png               |   0 |   22 |   0 |  12 |   0 | 0.004 | 0.012 |   0.124 | 0.004 | 0.000 | 0.004 | 0.000 |  0.004 |     32.000 |    626.000 |    13945.000 |    410.147 |
|     1 | GET    | /reports.json                       |   0 |    1 |   0 |   0 |   0 | 0.012 | 0.012 |   0.012 | 0.012 | 0.012 | 0.012 | 0.012 |  0.000 |  94019.000 |  94019.000 |    94019.000 |  94019.000 |
|     1 | GET    | /static/js/2.ff6e1067.chunk.js      |   0 |    1 |   0 |   0 |   0 | 0.032 | 0.032 |   0.032 | 0.032 | 0.032 | 0.032 | 0.032 |  0.000 | 508459.000 | 508459.000 |   508459.000 | 508459.000 |
|     9 | POST   | /items/edit                         |   0 |    3 |   0 |   6 |   0 | 0.004 | 0.052 |   0.092 | 0.010 | 0.004 | 0.008 | 0.012 |  0.015 |     57.000 |     92.000 |      615.000 |     68.333 |
|     1 | GET    | /static/css/main.19393e92.chunk.css |   0 |    1 |   0 |   0 |   0 | 0.052 | 0.052 |   0.052 | 0.052 | 0.052 | 0.052 | 0.052 |  0.000 |    994.000 |    994.000 |      994.000 |    994.000 |
|    57 | GET    | /upload/.+.jpg                      |   0 |   57 |   0 |   0 |   0 | 0.004 | 0.128 |   1.644 | 0.029 | 0.008 | 0.024 | 0.004 |  0.025 |  51229.000 | 130127.000 |  4362729.000 |  76539.105 |
|    13 | POST   | /bump                               |   0 |   13 |   0 |   0 |   0 | 0.004 | 0.352 |   0.756 | 0.058 | 0.076 | 0.068 | 0.008 |  0.092 |     90.000 |     91.000 |     1171.000 |     90.077 |
|     1 | GET    | /static/js/main.babc3d4d.chunk.js   |   0 |    1 |   0 |   0 |   0 | 0.452 | 0.452 |   0.452 | 0.452 | 0.452 | 0.452 | 0.452 |  0.000 |  90365.000 |  90365.000 |    90365.000 |  90365.000 |
|    53 | GET    | /settings                           |   0 |   53 |   0 |   0 |   0 | 0.012 | 0.488 |   6.173 | 0.116 | 0.048 | 0.092 | 0.000 |  0.125 |   3086.000 |   3100.000 |   163919.000 |   3092.811 |
|  2207 | GET    | /items/\d+.json                     |   0 | 2206 |   0 |   1 |   0 | 0.005 | 0.517 |  16.024 | 0.007 | 0.008 | 0.004 | 0.012 |  0.019 |      0.000 |   4041.000 |  4840278.000 |   2193.148 |
|    61 | POST   | /login                              |   0 |   53 |   0 |   8 |   0 | 0.060 | 0.781 |  18.730 | 0.307 | 0.124 | 0.389 | 0.060 |  0.183 |     72.000 |    266.000 |    14293.000 |    234.311 |
|    52 | POST   | /sell                               |   0 |   34 |   0 |  18 |   0 | 0.004 | 0.820 |   5.281 | 0.102 | 0.080 | 0.000 | 0.008 |  0.204 |     12.000 |    105.000 |     1836.000 |     35.308 |
|    40 | POST   | /ship_done                          |   0 |   22 |   0 |  18 |   0 | 0.816 | 0.824 |  19.747 | 0.494 | 0.020 | 0.000 | 0.000 |  0.392 |     28.000 |     82.000 |     1602.000 |     40.050 |
|    21 | POST   | /complete                           |   0 |   20 |   0 |   1 |   0 | 0.004 | 0.876 |  14.621 | 0.696 | 0.008 | 0.828 | 0.832 |  0.287 |      0.000 |     33.000 |      660.000 |     31.429 |
|    38 | POST   | /ship                               |   0 |   26 |   0 |  12 |   0 | 0.808 | 0.937 |  19.301 | 0.508 | 0.020 | 0.820 | 0.828 |  0.398 |     28.000 |     60.000 |     1944.000 |     51.158 |
|   267 | GET    | /users/\d+.json                     |   0 |  267 |   0 |   0 |   0 | 0.008 | 1.325 |  53.977 | 0.202 | 0.168 | 0.072 | 0.120 |  0.199 |     97.000 |  23995.000 |  3711121.000 |  13899.330 |
|    51 | POST   | /buy                                |   0 |   27 |   0 |  24 |   0 | 0.000 | 2.029 |  48.036 | 0.942 | 0.004 | 1.613 | 1.640 |  0.809 |     28.000 |     48.000 |     1809.000 |     35.471 |
|   130 | GET    | /new_items.json                     |   0 |  130 |   0 |   0 |   0 | 0.048 | 2.045 |  51.348 | 0.395 | 0.508 | 0.097 | 0.188 |  0.320 |  23011.000 |  23940.000 |  3043699.000 |  23413.069 |
|   700 | GET    | /new_items/\d+.json                 |   0 |  698 |   0 |   2 |   0 | 0.028 | 2.061 | 167.766 | 0.240 | 0.088 | 0.088 | 0.148 |  0.217 |      0.000 |  24044.000 | 16387888.000 |  23411.269 |
|     1 | POST   | /initialize                         |   0 |    1 |   0 |   0 |   0 | 7.156 | 7.156 |   7.156 | 7.156 | 7.156 | 7.156 | 7.156 |  0.000 |     32.000 |     32.000 |       32.000 |     32.000 |
|   160 | GET    | /users/transactions.json            |   0 |  151 |   0 |   9 |   0 | 0.028 | 7.467 | 450.698 | 2.817 | 0.384 | 2.613 | 3.492 |  1.551 |      0.000 |  30441.000 |  3087209.000 |  19295.056 |
+-------+--------+-------------------------------------+-----+------+-----+-----+-----+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+

categoriesのオンメモリ化

GET /users/transactions.jsonやGET /new_items/\d+.jsonの実装を確認すると、get_user_simple_by_id()とget_category_by_id()が非常に気軽に呼ばれていることに気がつきます。
このうち、get_category_by_id()についてはcategoriesテーブルの更新が無いため、メモリに乗せることができます。

def get_category_by_id(category_id)
  category = categories.find{|item| item[:id] == category_id}

  return if category.nil?

  parent_category_name = if category[:parent_id] != 0
    parent_category = get_category_by_id(category[:parent_id])

    return if parent_category.nil?

    parent_category['category_name']
  end

  {
    'id' => category[:id],
    'parent_id' => category[:parent_id],
    'category_name' => category[:category_name],
    'parent_category_name' => parent_category_name
  }
end

def categories
  [
    {:id => 1, :parent_id => 0, :category_name => "ソファー"},
    {:id => 2, :parent_id => 1, :category_name => "一人掛けソファー"},
    {:id => 3, :parent_id => 1, :category_name => "二人掛けソファー"},
    {:id => 4, :parent_id => 1, :category_name => "コーナーソファー"},
    {:id => 5, :parent_id => 1, :category_name => "二段ソファー"},
    {:id => 6, :parent_id => 1, :category_name => "ソファーベッド"},
    {:id => 10, :parent_id => 0, :category_name => "家庭用チェア"},
    {:id => 11, :parent_id => 10, :category_name => "スツール"},
    {:id => 12, :parent_id => 10, :category_name => "クッションスツール"},
    {:id => 13, :parent_id => 10, :category_name => "ダイニングチェア"},
    {:id => 14, :parent_id => 10, :category_name => "リビングチェア"},
    {:id => 15, :parent_id => 10, :category_name => "カウンターチェア"},
    {:id => 20, :parent_id => 0, :category_name => "キッズチェア"},
    {:id => 21, :parent_id => 20, :category_name => "学習チェア"},
    {:id => 22, :parent_id => 20, :category_name => "ベビーソファ"},
    {:id => 23, :parent_id => 20, :category_name => "キッズハイチェア"},
    {:id => 24, :parent_id => 20, :category_name => "テーブルチェア"},
    {:id => 30, :parent_id => 0, :category_name => "オフィスチェア"},
    {:id => 31, :parent_id => 30, :category_name => "デスクチェア"},
    {:id => 32, :parent_id => 30, :category_name => "ビジネスチェア"},
    {:id => 33, :parent_id => 30, :category_name => "回転チェア"},
    {:id => 34, :parent_id => 30, :category_name => "リクライニングチェア"},
    {:id => 35, :parent_id => 30, :category_name => "投擲用椅子"},
    {:id => 40, :parent_id => 0, :category_name => "折りたたみ椅子"},
    {:id => 41, :parent_id => 40, :category_name => "パイプ椅子"},
    {:id => 42, :parent_id => 40, :category_name => "木製折りたたみ椅子"},
    {:id => 43, :parent_id => 40, :category_name => "キッチンチェア"},
    {:id => 44, :parent_id => 40, :category_name => "アウトドアチェア"},
    {:id => 45, :parent_id => 40, :category_name => "作業椅子"},
    {:id => 50, :parent_id => 0, :category_name => "ベンチ"},
    {:id => 51, :parent_id => 50, :category_name => "一人掛けベンチ"},
    {:id => 52, :parent_id => 50, :category_name => "二人掛けベンチ"},
    {:id => 53, :parent_id => 50, :category_name => "アウトドア用ベンチ"},
    {:id => 54, :parent_id => 50, :category_name => "収納付きベンチ"},
    {:id => 55, :parent_id => 50, :category_name => "背もたれ付きベンチ"},
    {:id => 56, :parent_id => 50, :category_name => "ベンチマーク"},
    {:id => 60, :parent_id => 0, :category_name => "座椅子"},
    {:id => 61, :parent_id => 60, :category_name => "和風座椅子"},
    {:id => 62, :parent_id => 60, :category_name => "高座椅子"},
    {:id => 63, :parent_id => 60, :category_name => "ゲーミング座椅子"},
    {:id => 64, :parent_id => 60, :category_name => "ロッキングチェア"},
    {:id => 65, :parent_id => 60, :category_name => "座布団"},
    {:id => 66, :parent_id => 60, :category_name => "空気椅子"}
  ]
end

get_user_simple_by_idを削除

get_user_simple_by_id()もget_category_by_id()と同様に非常に多く呼ばれています。
こちらはオンメモリ化は難しいので、JOINして取得するようにします。
以下に、一例としてgetNewItemsのクエリを掲載します。

SELECT
  t1.*
  ,t2.`account_name`
  ,t2.`num_sell_items`
FROM
  `items` AS t1
  INNER JOIN `users` AS t2 ON
    t1.`seller_id` = t2.`id`
WHERE
  t1.`status` IN (?, ?)
ORDER BY
  t1.`created_at` DESC, t1.`id` DESC
LIMIT
  #{ITEMS_PER_PAGE + 1}

getTransactionsのAPI呼び出し

ここからは当日できなかった修正です。
api_client.shipment_statusはtransaction_evidenceのstatusがdoneの時には呼び出す必要が無いそうです。
修正後のスコアは以下の通りです。

{"pass":true,"score":3740,"campaign":0,"language":"ruby","messages":[]}

この時点でのalpの結果は以下のようになります。

+-------+--------+-------------------------------------+-----+------+-----+-----+-----+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+
| COUNT | METHOD |                 URI                 | 1XX | 2XX  | 3XX | 4XX | 5XX |  MIN  |  MAX  |   SUM   |  AVG  |  P1   |  P50  |  P99  | STDDEV | MIN(BODY)  | MAX(BODY)  |  SUM(BODY)   | AVG(BODY)  |
+-------+--------+-------------------------------------+-----+------+-----+-----+-----+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+
|     1 | GET    | /static/js/2.ff6e1067.chunk.js      |   0 |    1 |   0 |   0 |   0 | 0.016 | 0.016 |   0.016 | 0.016 | 0.016 | 0.016 | 0.016 |  0.000 | 508459.000 | 508459.000 |   508459.000 | 508459.000 |
|     1 | GET    | /static/js/runtime~main.a8a9905a.js |   0 |    1 |   0 |   0 |   0 | 0.024 | 0.024 |   0.024 | 0.024 | 0.024 | 0.024 | 0.024 |  0.000 |   1502.000 |   1502.000 |     1502.000 |   1502.000 |
|     1 | GET    | /reports.json                       |   0 |    1 |   0 |   0 |   0 | 0.032 | 0.032 |   0.032 | 0.032 | 0.032 | 0.032 | 0.032 |  0.000 | 143390.000 | 143390.000 |   143390.000 | 143390.000 |
|    50 | GET    | /transactions/\d+.png               |   0 |   40 |   0 |  10 |   0 | 0.008 | 0.080 |   0.544 | 0.011 | 0.008 | 0.012 | 0.012 |  0.015 |     32.000 |    623.000 |    24890.000 |    497.800 |
|    11 | POST   | /items/edit                         |   0 |    6 |   0 |   5 |   0 | 0.004 | 0.116 |   0.304 | 0.028 | 0.028 | 0.000 | 0.048 |  0.033 |     57.000 |     92.000 |      835.000 |     75.909 |
|    56 | GET    | /upload/.+.jpg                      |   0 |   56 |   0 |   0 |   0 | 0.004 | 0.180 |   2.994 | 0.053 | 0.084 | 0.068 | 0.008 |  0.043 |  51574.000 | 146187.000 |  4706042.000 |  84036.464 |
|     1 | GET    | /static/css/main.19393e92.chunk.css |   0 |    1 |   0 |   0 |   0 | 0.192 | 0.192 |   0.192 | 0.192 | 0.192 | 0.192 | 0.192 |  0.000 |    994.000 |    994.000 |      994.000 |    994.000 |
|     1 | GET    | /static/js/main.babc3d4d.chunk.js   |   0 |    1 |   0 |   0 |   0 | 0.520 | 0.520 |   0.520 | 0.520 | 0.520 | 0.520 | 0.520 |  0.000 |  90365.000 |  90365.000 |    90365.000 |  90365.000 |
|    13 | POST   | /bump                               |   0 |   13 |   0 |   0 |   0 | 0.004 | 0.529 |   1.821 | 0.140 | 0.156 | 0.028 | 0.080 |  0.164 |     89.000 |     91.000 |     1168.000 |     89.846 |
|    52 | GET    | /settings                           |   0 |   52 |   0 |   0 |   0 | 0.008 | 0.568 |   7.472 | 0.144 | 0.044 | 0.320 | 0.040 |  0.153 |   3086.000 |   3103.000 |   160855.000 |   3093.365 |
|    60 | POST   | /login                              |   0 |   52 |   0 |   8 |   0 | 0.100 | 0.740 |  22.886 | 0.381 | 0.576 | 0.452 | 0.184 |  0.190 |     72.000 |    269.000 |    14063.000 |    234.383 |
|    55 | POST   | /ship_done                          |   0 |   39 |   0 |  16 |   0 | 0.004 | 0.896 |  33.709 | 0.613 | 0.016 | 0.004 | 0.853 |  0.360 |      0.000 |     82.000 |     2017.000 |     36.673 |
|    65 | POST   | /sell                               |   0 |   50 |   0 |  15 |   0 | 0.004 | 0.936 |   8.002 | 0.123 | 0.068 | 0.016 | 0.080 |  0.208 |     12.000 |    105.000 |     1790.000 |     27.538 |
|   390 | GET    | /users/\d+.json                     |   0 |  386 |   0 |   4 |   0 | 0.007 | 0.944 |  94.877 | 0.243 | 0.144 | 0.280 | 0.225 |  0.153 |      0.000 |  23864.000 |  5174034.000 |  13266.754 |
|    50 | POST   | /ship                               |   0 |   40 |   0 |  10 |   0 | 0.004 | 0.948 |  31.514 | 0.630 | 0.016 | 0.829 | 0.849 |  0.361 |     28.000 |     60.000 |     2720.000 |     54.400 |
|    38 | POST   | /complete                           |   0 |   37 |   0 |   1 |   0 | 0.008 | 1.117 |  30.578 | 0.805 | 0.192 | 0.844 | 0.888 |  0.228 |      0.000 |     33.000 |     1221.000 |     32.132 |
|   128 | GET    | /new_items.json                     |   0 |  128 |   0 |   0 |   0 | 0.212 | 1.509 |  69.956 | 0.547 | 0.212 | 0.372 | 0.369 |  0.185 |  22988.000 |  23744.000 |  2994285.000 |  23392.852 |
|   788 | GET    | /new_items/\d+.json                 |   0 |  785 |   0 |   3 |   0 | 0.044 | 1.857 | 214.928 | 0.273 | 0.044 | 0.112 | 0.296 |  0.148 |      0.000 |  24021.000 | 18454159.000 |  23418.984 |
|  2932 | GET    | /items/\d+.json                     |   0 | 2932 |   0 |   0 |   0 | 0.008 | 1.857 |  37.309 | 0.013 | 0.080 | 0.004 | 0.012 |  0.040 |   1851.000 |   4052.000 |  6539101.000 |   2230.253 |
|    61 | POST   | /buy                                |   0 |   41 |   0 |  20 |   0 | 0.076 | 1.865 |  70.834 | 1.161 | 0.040 | 1.725 | 1.657 |  0.754 |     28.000 |     48.000 |     2118.000 |     34.721 |
|   414 | GET    | /users/transactions.json            |   0 |  409 |   0 |   5 |   0 | 0.024 | 2.341 | 256.159 | 0.619 | 0.216 | 1.160 | 0.340 |  0.411 |      0.000 |  27197.000 |  8797561.000 |  21250.147 |
|     1 | POST   | /initialize                         |   0 |    1 |   0 |   0 |   0 | 8.213 | 8.213 |   8.213 | 8.213 | 8.213 | 8.213 | 8.213 |  0.000 |     32.000 |     32.000 |       32.000 |     32.000 |
+-------+--------+-------------------------------------+-----+------+-----+-----+-----+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+

INDEXを張る

itemsテーブルのseller_id、buyer_id、created_atにINDEXを張ってみます。

還元率を変更してみる

当日はルールへの理解が足りず着手しなかったのですが、postInitializeのレスポンスにあるcampaignの数値を変更することで負荷が上がるようです。
試しに0 → 1に変更してベンチマークを実行した結果が以下のものです。

{
  "pass": true,
  "score": 7240,
  "campaign": 1,
  "language": "ruby",
  "messages": [
    "GET /new_items.json: リクエストに失敗しました（タイムアウトしました）",
    "GET /users/transactions.json リクエストに失敗しました (user_id: 3197)（タイムアウトしました）",
    "POST /login: リクエストに失敗しました（タイムアウトしました）",
    "POST /ship: リクエストに失敗しました (item_id: 50041)（タイムアウトしました）"
  ]
}

タイムアウトが増えますが、スコアは上がっています。

まとめ

1台構成ですが、予選通過ラインに肉薄するスコアが出るようになってきました。
本番の8時間でこれらを実施するのは大変ですが、来年は予選通過できるよう精進したいと思います。