SODA Engineering Blog
🪑

pprotein でボトルネックを探して ISUCON で優勝する

2023/12/06に公開

スニダンを開発しているSODA inc.の Advent Calendar 6日目の記事です!!!/

昨日は @decoch718 さんによる「エンジニアブログを開設して1年で取り組んだことを公開」でした!
組織としてのアウトプットがドンドン増えていてすごい!

明日は @KosukeSaigusa さんによる「Dart のドキュメンテーションについて」の予定です!
お楽しみに!

https://qiita.com/advent-calendar/2023/soda-inc

はじめに

推測するな、計測せよ

Rule 1. You can't tell where a program is going to spend its time. Bottlenecks occur in surprising places, so don't try to second guess and put in a speed hack until you've proven that's where the bottleneck is.
Rule 2. Measure. Don't tune for speed until you've measured, and even then don't unless one part of the code overwhelms the rest.

Rob Pike, "Notes on Programming in C" (1989), https://www.lysator.liu.se/c/pikestyle.html

https://www.lysator.liu.se/c/pikestyle.html

Rob Pike氏が最初にそれらしいことを言った原典をカッコつけて持ってきました。
皆さん、パフォーマンス改善をするときは推測せずに計測していきましょう。

ISUCONでは特に、「計測→改善→計測→…」のサイクルをどれだけ高速に回せるかがとっても重要です。

pproteinで計測せよ

https://github.com/kaz/pprotein

3大計測ポイント(?)であるプロファイル、スロークエリログ、アクセスログをまとめて計測して可視化してくれる神ツールです。
pproteinがないと、ログのローテートをしたり、ログを手元に持ってきてalpなどで分析したり、 go tool pprof で毎回計測を走らせたり、それらの計測結果をチームメンバーに共有したり、と色々なことをしないといけなくて大変です。

ISUCON13終了直後の現在は、優勝チームのメンバーの1人である とーふとふさん が自チームで使っていたpproteinを公開してくれています。
これを見ればどんなツールかのイメージは簡単につくでしょう。
そしてこのツールは同じチームのメンバーである sekaiさん が作ったツールです。ありがたや。

https://pprotein.isucon13.to-hutohu.com/#/group/

pproteinの使い方をご紹介します

本記事ではpproteinの使い方をご紹介します。
リポジトリにREADMEが置かれておらず、インターネット上にも使い方をまとめたページなどが見当たらず、初めて使うときは少し大変でした。
Goで書かれてて読みやすかったこともあり、pproteinのコードを全部読んで理解しました()

計測対象の準備

まずは計測ができるよう各サーバで準備していきましょう。

Goアプリケーションのpprof

これは echov4.EnableDebugHandler(e)main 関数に置くだけで簡単です。
pprof を単体で使う場合は net/http/pprof をBlank importしたり、6060番ポートを自分で開放したり、が必要ですが、そのあたりに相当することはいい感じに内部でやってくれています。

https://github.com/rinchsan/isucon13-final/blob/2a77f2ab583ed28dd7d74473c2db2a855718d891/webapp/go/main.go#L131

https://github.com/rinchsan/isucon13-final/commit/2a77f2ab583ed28dd7d74473c2db2a855718d891#diff-871eb89e86e63e7eca84f0075cba1a75574a11341cd89d39c7891864d2b085b9

gin など他のWebフレームワークにも対応していて便利です。

https://github.com/kaz/pprotein/blob/master/integration/gin/integrate.go

フレームワークの種類は気にせずに standalone.Integrate(":19000") のように19000番ポートで公開するのもよいでしょう。

https://github.com/kaz/pprotein/blob/master/integration/standalone/integrate.go

MySQLのスロークエリログ

スロークエリログが出力されるように設定します。
Ansible でいい感じに適用できるようにしておくと便利です。

https://github.com/rinchsan/isucon13-final/blob/d20043cd58fafc6e9e7f257d04c169126e069412/ansible/roles/mysql/files/etc/mysql/mysql.conf.d/mysqld.cnf#L65-L67

https://github.com/rinchsan/isucon13-final/commit/d20043cd58fafc6e9e7f257d04c169126e069412

ログの読み込みがPermission Deniedになる場合は chmod しちゃいましょう。

sudo chmod +rx /var/log/mysql/
sudo chmod +r /var/log/mysql/mysql-slow.log

MySQLを別サーバに分離しても大丈夫

だって pprotein-agent があるのだから。

途中でMySQLを別サーバに逃がして複数台構成にすると、当たり前ですがGoアプリケーションがスロークエリログを直接取得できなくなってしまいます。
その場合は pprotein-agent というプロセスをMySQLが起動しているサーバで稼働させることでpproteinがログを取得できるようにします。
詳細は後述の「pprotein-agentのserviceを起動」にて。

Nginxのアクセスログ

アクセスログがltsv形式で出力されるように設定します。
こちらも Ansible でいい感じに適用できるようにしておくと便利です。

https://github.com/rinchsan/isucon13-final/blob/397a82463177e828090b3224bc1ad1b8de9e2e59/ansible/roles/nginx/files/etc/nginx/nginx.conf#L43-L59

https://github.com/rinchsan/isucon13-final/commit/397a82463177e828090b3224bc1ad1b8de9e2e59

ログの読み込みがPermission Deniedになる場合は chmod しちゃいましょう(これもAnsibleでやると便利です)。

sudo chmod +r /var/log/nginx/access.log

Nginxを別サーバに分離しても大丈夫

だって pprotein-agent があるのだから。

MySQLと同じくNginxを別サーバに逃がす場合もGoアプリケーションからアクセスログを直接取得できなくなってしまいます。
この場合も pprotein-agent をNginxサーバで稼働させることで解決します。

pproteinの準備

ここからpprotein本体の準備に入ります(ワクワク)。

CloudFormationでサーバ起動

CloudFormationを利用して、計測対象サーバと同じVPC、同じSubnetにpprotein用のサーバを起動します。
ISUCON13では一応競技用サーバと同じAMIでEC2を起動しましたが、別のAMIでも問題ないでしょう。

https://github.com/rinchsan/isucon13-final/blob/0c242ccd085cefd7f5544201b3101b0cb59b7fb6/provisioning/cf_pprotein.yaml

https://github.com/rinchsan/isucon13-final/commit/0c242ccd085cefd7f5544201b3101b0cb59b7fb6

CloudFormationのParametersでVPCとSubnetを指定できるように用意しておくと便利です。
また、競技用サーバのSecurity Groupは変更してしまうと失格になるのですが、pprotein用のサーバは変更して問題ないので、9000番ポートを開放しておきます。

周辺ツールのインストール

次に、pproteinを動かすのに必要なツール群をバンバン入れていきましょう。

pprofのグラフ描画に使うgraphviz

sudo apt install -y graphviz gv

スロークエリログの分析に使うslp

wget https://github.com/tkuchiki/slp/releases/download/v0.2.0/slp_linux_amd64.tar.gz
tar -xvf slp_linux_amd64.tar.gz
sudo mv slp /usr/local/bin/slp

アクセスログの分析に使うalp

wget https://github.com/tkuchiki/alp/releases/download/v1.0.21/alp_linux_amd64.tar.gz
tar -xvf alp_linux_amd64.tar.gz
sudo mv alp /usr/local/bin/alp

pprotein本体

wget https://github.com/kaz/pprotein/releases/download/v1.2.3/pprotein_1.2.3_linux_amd64.tar.gz
tar -xvf pprotein_1.2.3_linux_amd64.tar.gz

pproteinのserviceを起動

pprotein用サーバで /etc/systemd/system/pprotein.service を作って起動しましょう。
起動に成功すると http://{pprotein用サーバのPublic IP}:9000 でpproteinのWeb UIにアクセスできるようになっているはずです。

/etc/systemd/system/pprotein.service
[Unit]
Description=pprotein service

[Service]
ExecStart=/home/isucon/pprotein
WorkingDirectory=/home/isucon
Environment=PATH=$PATH:/usr/local/bin
Restart=always
User=root

[Install]
WantedBy=multi-user.target
sudo systemctl start pprotein

pprotein-agentのserviceを起動

MySQLが別サーバの場合は、そのサーバで /etc/systemd/system/pprotein-agent.service を作って起動しましょう。
起動に成功すると19000番ポートでスロークエリログが取得できるエンドポイントが公開されているはずです。
/var/log/mysql/mysql-slow.log などログファイルのPermissionにご注意を。

wget https://github.com/kaz/pprotein/releases/download/v1.2.3/pprotein_1.2.3_linux_amd64.tar.gz
tar -xvf pprotein_1.2.3_linux_amd64.tar.gz
/etc/systemd/system/pprotein-agent.service
[Unit]
Description=pprotein-agent service

[Service]
ExecStart=/home/isucon/pprotein-agent
WorkingDirectory=/home/isucon
Environment=PATH=$PATH:/usr/local/bin
Restart=always
User=root

[Install]
WantedBy=multi-user.target
sudo systemctl start pprotein-agent

group/targets の設定

pproteinのWeb UI上にある setting からログ収集に関するを設定を変更します。

group/targets は基本的には計測対象サーバのPrivate IPとログを取得できるエンドポイントが公開されているポートを設定していくだけでOKです。
ここで standalone.Integrate を使っているとすべてのポートを19000番にできるので脳内メモリを節約することができますね。
ちなみに、ここでの設定内容はpprotein用サーバ上の /home/isucon/data/targets.json に保存されます。

group/targetsの例
[
  {
    "Type": "pprof",
    "Label": "webapp",
    "URL": "http://192.168.0.11:8080/debug/pprof/profile",
    "Duration": 60
  },
  {
    "Type": "httplog",
    "Label": "nginx",
    "URL": "http://192.168.0.11:8080/debug/log/httplog",
    "Duration": 60
  },
  {
    "Type": "slowlog",
    "Label": "mysql",
    "URL": "http://192.168.0.12:19000/debug/log/slowlog",
    "Duration": 60
  }
]

httplog/config の設定

httplog/config はPath Parameterを受け取るエンドポイントを正規表現でいい感じにまとめる設定を書きます。
ちなみに、ここでの設定内容はpprotein用サーバ上の /home/isucon/data/alp.yml に保存されます。

httplog/configの例
matching_groups:
    - ^/api/user/[0-9a-zA-Z_-]+/theme$
    - ^/api/user/[0-9a-zA-Z_-]+/livestream$
    - ^/api/livestream/[0-9a-f_-]+$
    - ^/api/livestream/[0-9a-f_-]+/livecomment$
    - ^/api/livestream/[0-9a-f_-]+/reaction$
    - ^/api/livestream/[0-9a-f_-]+/report$
    - ^/api/livestream/[0-9a-f_-]+/ngwords$
    - ^/api/livestream/[0-9a-f_-]+/livecomment/[0-9a-f_-]+/report$
    - ^/api/livestream/[0-9a-f_-]+/moderate$
    - ^/api/livestream/[0-9a-f_-]+/enter$
    - ^/api/livestream/[0-9a-f_-]+/exit$
    - ^/api/user/[0-9a-zA-Z_-]+$
    - ^/api/user/[0-9a-zA-Z_-]+/statistics$
    - ^/api/user/[0-9a-zA-Z_-]+/icon$
    - ^/api/livestream/[0-9a-f_-]+/statistics$

いざ計測

ISUCONのベンチマーカーはまず最初にinitialize処理をして初期データ作ったりしています。
そのinitialize処理の最後にpproteinでの計測を自動でスタートするようにすると便利です。

https://github.com/rinchsan/isucon13-final/blob/837b95d24f3a42b24f02b69728846c06f99a7ccf/webapp/go/main.go#L114-L118

https://github.com/rinchsan/isucon13-final/commit/837b95d24f3a42b24f02b69728846c06f99a7ccf

メモ機能もあるので、ベンチのログやスコアを計測結果に紐づけて残しておくと便利でしょう(と、優勝チームのpproteinを見て思いました(小並感))。

おわりに

優勝できませんでした!!!
が、初出場でも頑張れたのはpproteinのおかげです!!!

https://zenn.dev/team_soda/articles/20231126195358

GitHubで編集を提案
SODA Engineering Blog
SODA Engineering Blog

Discussion