達人が教える web パフォーマンスチューニング ISUCON から学ぶ高速化の実践

第3章基礎的な負荷試験

private-isu の起動

テスト用の web サービス private-isu をチューニングしてみよう。 AWS で動かしても良いが docker で動かしてみる。まずはアプリケーションサーバーを起動する。

gh repo clone catatsuy/private-isu
cd private-isu

# テーブル初期データセット
cd webapp/sql
curl -L -O github.com/catatsuy/private-isu/releases/download/img/dump.sql.bz2
bunzip2 dump.sql.bz2

# サービス起動
ca webapp
docker compose up

# 動作確認
open localhost

ここで初期データセット忘れてた場合は後から入れないといけない。パスワードは docker-compose に環境変数として宣言されてるのでそれを使う。

docker exec -it webapp-mysql-1 bash
mysql -p < docker-entrypoint-initdb.d/dump.sql

負荷試験の準備

nginx の設定がデフォルトのままなので、まずはアクセスログの設定をしてみる。 nginx.conf を眺めてみる。

user  nginx;
worker_processes  auto;

error_log  /var/log/nginx/error.log notice;
pid        /var/run/nginx.pid;


events {
    worker_connections  1024;
}


http {
    include       /etc/nginx/mime.types;
    default_type  application/octet-stream;

    log_format  main  '$remote_addr - $remote_user [$time_local] "$request" '
                      '$status $body_bytes_sent "$http_referer" '
                      '"$http_user_agent" "$http_x_forwarded_for"';

    access_log  /var/log/nginx/access.log  main;

    sendfile        on;
    #tcp_nopush     on;

    keepalive_timeout  65;

    #gzip  on;

    include /etc/nginx/conf.d/*.conf;
}

情報は最低限で combine 形式のログになっている。実際のログは下のような感じ。

webapp-nginx-1      | 172.18.0.1 - - [10/Jul/2022:00:50:22 +0000] "GET /image/9980.jpg HTTP/1.1" 200 95919 "localhost" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/103.0.0.0 Safari/537.36" "-"

今回は読みやすさ重視でログフォーマットを json にしてみる。 nginx.conf は docker の都合上書き換えずに /etc/nginx/conf.d/default.conf を編集してみる。

log_format json escape=json '{"time": "$time_iso8601",'
    '"host": "$remote_addr",'
    '"port": "$remote_port",'
    '"method": "$request_method",'
    '"uri": "$request_uri",'
    '"status": "$status",'
    '"body_bytes": "$body_bytes_sent",'
    '"referrer": "$http_referer",'
    '"ua": "$http_user_agent",'
    '"request_time": "$request_time",'             # ユーザのリクエストからレスポンス返すまでの時間
    '"response_time": "$upstream_response_time"}'; # nginx のリクエストからアプリケーションサーバーがレスポンス返すまでの時間

server {
    listen 80;

    client_max_body_size 10m;
    root /public/;

    location / {
        proxy_set_header Host $host;
        proxy_pass app:8080;
    }

    access_log /var/log/nginx/access.log json;
}

nginx を再起動する。

docker exec -it webapp-nginx-1 nginx -s reload

下のような感じで json フォーマットに切り替わった。

webapp-nginx-1      | {"time": "2022-07-10T01:19:29+00:00","host": "172.18.0.1","port": "64810","method": "GET","uri": "/favicon.ico","status": "304","body_bytes": "0","referrer": "localhost/@rosa","ua": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/103.0.0.0 Safari/537.36","request_time": "0.000","response_time": "0.001"}

ログを加工したりなんだりする上でログが nginx コンテナの中で閉じていると面倒。標準出力ではなくて docker のボリュームに書き出すようにしたい。 docker-compose.yml を下のような感じで書き換える。

volumes:
  - ./etc/nginx/conf.d:/etc/nginx/conf.d
  - ./public:/public
  - ./logs/nginx:/var/log/nginx

docker compose up を停止してやりなおすとボリュームが割り当てられる。これでホストの logs/nginx/access.log 宛にログが書き出されるようになる。次はログの解析のためのツール alp を入れてみる。

brew install alp
alp json --file logs/nginx/access.log

負荷試験の実行

apache benchmark => ab コマンドを試していたがちょっと面倒くさそうなのでやらないことにした。

パフォーマンスチューニング

性能指標には単位時間に処理できるリクエスト数（スループット）を使うことが多い。ベンチマーク実行中に top コマンドで CPU の利用状態とかをみるといい。一番CPUを消費しているプロセスがボトルネックになっていることが多い。

mysql の設定を変えて、クエリを出してみよう。 etc/my.cnf を編集して下の行を追加。

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

long_query_time が 0 なのはとりあえず全部のクエリを観察してみるという意図。 N+1 クエリとかは見つけやすくなると思う。あとで調整する。mysql を再起動してみよう。でもスロークエリは出ない。ちゃっかりエラーが出ていた。

webapp-mysql-1      | 2022-07-10T02:03:07.368768Z 0 [ERROR] [MY-011263] [Server] Could not use /var/log/mysql/mysql-slow.log for logging (error 2 - No such file or directory). Turning logging off for the server process. To turn it on again: fix the cause, then either restart the query logging by using "SET GLOBAL SLOW_QUERY_LOG=ON" or restart the MySQL server.

どうやらログファイルがなくてエラーになっているようだ。 docker で mysql を動かしていると mysql のプロセスを再起動するのが無理。仕方がないのでこのログファイルも host のボリュームをマウントして事前に作っておくことにする。

mkdir -p logs/mysql
touch logs/mysql/mysql-slow.log

出てるスロークエリの例は下のような感じ。

SELECT * FROM `posts` WHERE `id` = 9979;
# Time: 2022-07-10T02:31:22.342442Z
# User@Host: healthchecker[healthchecker] @ localhost []  Id:    10
# Query_time: 0.000156  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0

第3章 基礎的な負荷試験

private-isu の起動

負荷試験の準備

負荷試験の実行

パフォーマンスチューニング

第3章基礎的な負荷試験