kavo’s diary

備忘録

ISUCON9予選問題の開発環境をGCP上に作る(再整理)

時間が経って忘れてしまったので再度まとめ直した。

TL;DR

GCPでISUCARI(ISUCON9予選問題)を構築する手順。公式の以下の記事をGCPでやるときに、記事に書いてない部分を手順化したもの。

isucon.net

成果物

  • ISUCON9予選問題とベンチマーカーが動くGCPのVM(Ubuntu)

作業リスト

  • GCPコンソール
  • VM設定
    • isuconユーザ作成
    • SSH鍵配置
    • ソフトウェアインストール
  • 構築・疎通
    • rLogin
    • VSCode
    • アプリ
    • ベンチマーカー

作業詳細

GCPコンソール

ファイアウォールルール作成

https://console.cloud.google.com/networking/firewalls/add

ISUCARIで使うポート（5555,7000,8000）、後でnetdataで使う19999を開けておく

f:id:kavohtn:20200627180843p:plain

VM作成

https://console.cloud.google.com/compute/instancesAdd

静的IP作成

https://console.cloud.google.com/networking/addresses/list

動的IPだと書き換えが手間なので発行。有料。 さっき作ったVMを選択する。

f:id:kavohtn:20200627180421p:plain

VM設定

isuconユーザ作成

GCPのVM一覧から、SSH機能を使ってログイン。

sudo adduser isucon
sudo gpasswd -a isucon sudo

SSH鍵配置

ユーザを切り替えてssh鍵作成、配置。 ついでに

su - isucon

ssh-keygen -t rsa -C "isucon" -f isucon
mkdir .ssh
touch .ssh/authorized_keys
cat isucon.pub >> .ssh/authorized_keys
chmod 600 .ssh/authorized_keys
timedatectl set-timezone Asia/Tokyo

sudo visudo #`isucon ALL=NOPASSWD: ALL`
vi ~/.bash_profile # export GOPATH=$HOME/go

ソフトウェアインストール

ISUCARIに使う諸々をインストール。

sudo apt-get update
sudo apt-get install -y gcc make unzip golang mysql-server mysql-client
go get -u github.com/go-sql-driver/mysql
go get -u github.com/gorilla/sessions
go get -u github.com/jmoiron/sqlx
go get -u goji.io
go get -u goji.io/pat
go get -u golang.org/x/crypto/bcrypt
go get -u github.com/morikuni/failure
go get -u github.com/skip2/go-qrcode
sudo apt-get -y install \
    apt-transport-https \
    ca-certificates \
    curl \
    gnupg-agent \
    software-properties-common
curl -fsSL https://download.docker.com/linux/ubuntu/gpg | sudo apt-key add -
sudo apt-key fingerprint 0EBFCD88
sudo add-apt-repository \
   "deb [arch=amd64] https://download.docker.com/linux/ubuntu \
   $(lsb_release -cs) \
   stable"
sudo apt-get install docker-ce docker-ce-cli containerd.io
sudo docker run hello-world

構築・疎通

rLogin

rlogin/telnet/ssh(クライアント)ターミナルソフトを使う。ログインできたらOK。

  • ホスト：GCPで作った静的IP
  • ログインユーザー名：isucon
  • パスフレーズ：***
  • SSH認証鍵：さっき作った秘密鍵をダウンロードして指定

f:id:kavohtn:20200627193551p:plain

VSCode

Developing on Remote Machines using SSH and Visual Studio Codeを使う。サーバのフォルダが見えたらOK。

Host isu9
    HostName 35.221.xx.xx
    User isucon
    IdentityFile C:\Users\xxx\.ssh\isucon

アプリ

ローカル環境でISUCON9予選の問題を動かす : ISUCON公式Blogの外部サービスの起動までを実施。 このままだと購入時にFailed to fetchになる。

以下のようなjsonファイルを作る。

{
  "payment_service_url":"http://35.221.xx.xx:5555",
  "shipment_service_url":"http://35.221.xx.xx:7000"
}

それを使って初期化する。

$ curl -XPOST http://127.0.0.1:8000/initialize -H 'Content-Type: application/json' -d @init.json
{"campaign":0,"language":"Go"}

いちいちこれを実施するのは非常に手間だが、jsonのIPはlocalhostではダメだった。誰か原因がわかる人がいたら教えてほしい。 ブラウザ上で、２ユーザを使って出品・購入・配送して問題なく終わることを確認する。

ベンチマーカー

無事スコアが出たら完成。

{"pass":true,"score":1410,"campaign":0,"language":"Go","messages":[]}

Alipay sandboxを試してみる（失敗）

今後決済系のことをやっていくので、勉強がてらAlipay Documentation Sandboxを試してみる。 AlipayのQRコード決済をテストするための環境が提供されるらしい。とりあえず１回決済を実行してみるところまで行きたい。

Alipay merchant account作成

メールアドレスだけで作成できた。

Alipay sandbox portalログイン

Alipay merchant accountを使ってログイン。MerchantNameとPIDを適当に決める。

Alipay Sandbox Appをスマホにインストール

androidスマホ(Galaxy S10+)にAlipay Sandbox AppのQRコード読み込ませてapkをダウンロード、インストール。 アプリはログインを求められ、何のアカウントか分からなかったがとりあえずAlipay merchant accountの認証を入れてみたがThis account number does not exist.多分別のアカウントだと思われる。

Sign upを選び、Area codeをJapanにして電話番号入れてみたがAttempt failed. Please try again.となる。詰んだ・・・。

日本語情報があんまりなさそう。

ここはAPIの日本語化？でもちょっと古そう。 http://wiki.genexus.jp/hwiki.aspx?Alipay+API

ISUCON9予選問題の開発環境をGCP上に作る（旧）

https://kavo.hatenablog.jp/entry/2020/06/27/203500に書き直した

概要

isucon9-qualify/provisioning at master · isucon/isucon9-qualify · GitHubのプレイブックで練習環境を作ろうとしたメモの続き。

ansibleでwebapp.ymlとdev.ymlとbench.ymlを適用した状態まで行った。

購入操作を試す

この状態で購入操作をしてもFailed to fetchになる。 f:id:kavohtn:20200126214021p:plain

paymentとshipmentは取り敢えず起動しているように見える。切り分けのため、ベンチマーカーがちゃんと動くのか検証する。

$ sudo netstat -ltunp
Active Internet connections (only servers)
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name    
tcp        0      0 127.0.0.1:3306          0.0.0.0:*               LISTEN      12193/mysqld        
tcp        0      0 127.0.0.53:53           0.0.0.0:*               LISTEN      783/systemd-resolve 
tcp        0      0 0.0.0.0:22              0.0.0.0:*               LISTEN      1492/sshd           
tcp        0      0 0.0.0.0:443             0.0.0.0:*               LISTEN      17006/nginx: master 
tcp6       0      0 :::5555                 :::*                    LISTEN      13873/payment       
tcp6       0      0 :::22                   :::*                    LISTEN      1492/sshd           
tcp6       0      0 :::7000                 :::*                    LISTEN      13784/shipment      
tcp6       0      0 :::8000                 :::*                    LISTEN      12275/isucari

ベンチマーカーを動かす

ベンチマーカーを実行してみる。開発用サービスとポート衝突した。

$ /home/isucon/isucari/bin/benchmarker 
2020/01/26 12:10:22 main.go:84: listen tcp :5555: bind: address already in use

停止させる。

sudo systemctl stop payment.service
sudo systemctl stop shipment.service
sudo systemctl list-units --type=service | grep ment

もう一度試す。スコアが出ているので多分ベンチマーカーは正常に動作してる。

$ ./benchmarker 
2020/01/26 12:11:19 shipment.go:188: open initial-data/result/shippings_json.txt: no such file or directory
/home/isucon/isucari$ ./bin/benchmarker 
...
2020/01/26 12:17:33 main.go:180: === final check ===
2020/01/26 12:17:33 main.go:212: 1710 0
{"pass":true,"score":1710,"campaign":0,"language":"Go","messages":[]}

開発用payment.serviceの動作確認

サービスを起動させる。

sudo systemctl start payment.service
sudo systemctl start shipment.service
sudo systemctl list-units --type=service | grep ment

payment.serviceのAPIを叩いてみる。これはちゃんと返ってきている。

$ curl -d '{"shop_id": "11", "card_number": "AAAAAAAA"}' -H "Content-Type: application/json" -X POST localhost:5555/card
{"token":"e7f9bf5caf8f5c950c4cf467bd1169b05e6633c1"}

ブラウザの開発者ツールを開くと少しだけ詳しいエラーメッセージが確認できた。 POST http://localhost:5555/card net::ERR_CONNECTION_REFUSED paymentClient.ts:22とあるが・・・。 f:id:kavohtn:20200127021626p:plain GCPでサーバに5555を許可するポートを開けたが、変わらずFailed to fetchになる。

localhostってもしかしてブラウザ側（つまり自分のPC）になってたりしないかな？と思ってlocalhostをサーバのIPに書き換えてみる。

{
  "payment_service_url":"http://34.68.x.x:5555",
  "shipment_service_url":"http://34.68.x.x:7000"
}

$ curl -XPOST http://127.0.0.1:8000/initialize -H 'Content-Type: application/json' -d @initi
alize2.json
{"campaign":0,"language":"Go"}

ここでようやく購入することができた。 f:id:kavohtn:20200127021937p:plain

ISUCON9予選問題のAnsible構築を試す

概要

isucon9-qualify/provisioning at master · isucon/isucon9-qualify · GitHubのプレイブックで練習環境を作ろうとしたメモ。

環境

ドキュメントに記載されている環境

今回試したこと

  • プラットフォーム：GCP
  • Ansible実行対象サーバ: Ubuntu 18.04 LTS (GCPで選べるubuntu-1804-bionic-v20200108)
  • Ansible実行元サーバ：GCP Cloud Shell(Debian系らしい。)

とにかくエラーにぶつかりまくったので色々試した。

ssh接続設定

  • プライベートIPを指定すると接続が失敗する。パブリックIPならOKだった。
  • ssh時のログイン名がrootかどうかの問題。
ssh-keygen -C "" -f anskey #anskey.pubの中身に「 root」を足し、GCPのVMインスタンスのSSH 認証鍵に貼って保存。
ssh -i anskey root@34.68.25.149 #デフォルト名だとダメ

GCP Cloud Shellからansible 2.2.1で試す。

下記のようにUTC設定するのに失敗したあたりでansibleが古いのが悪いのかなと思い、ansible 2.8.3を入れようとしたがpython関係のエラーで入らないので諦めた。

TASK [user.isucon : Create isucon group] ***************************************
fatal: [x.x.x.x]: FAILED! => {"changed": false, "failed": true, "msg": "groupadd: GID '1001' already exists\n", "name": "isucon"}
...ignoring

TASK [user.isucon : Create isucon user] ****************************************
fatal: [x.x.x.x]: FAILED! => {"changed": false, "failed": true, "msg": "Group ******** does not exist"}
...ignoring

TASK [user.isucon : Add sudoers] ***********************************************
ok: [x.x.x.x]

TASK [bootstrap : Install Dependencies] ****************************************
ok: [x.x.x.x]

TASK [bootstrap : Set timezone UTC] ********************************************
fatal: [x.x.x.x]: FAILED! => {"changed": true, "cmd": ["timedatectl", "set-timezone", "UTC"], "delta": "0:00:00.064019", "end": "2020-01-25 13:45:42.269964", "failed": true, "rc": 1, "start": "2020-01-25 13:45:42.205945", "stderr": "Failed to set time zone: Invalid time zone 'UTC'", "stdout": "", "stdout_lines": [], "warnings": []}
...ignoring

TASK [bootstrap : Setup xbuild] ************************************************
fatal: [x.x.x.x]: FAILED! => {"failed": true, "msg": "Failed to change ownership of the temporary files Ansible needs to create despite connecting as root.  Unprivileged become user would be unable to read the file."}

Ubuntuからansible 2.8.3で試す。

これで2.8.3が入る。aptを使うともっと古いのしか出てこない。

sudo apt-get update
sudo apt-get install make python-pip python-dev -y git
pip install PyYAML jinja2 paramiko
pip install packaging
git clone https://github.com/ansible/ansible.git -b v2.8.3 --depth 1
cd ansible/
sudo make install
ansible --version

hostsファイルでansible_ssh_userも指定しないと今のユーザでsshしようとするので指定する。

[web]
34.68.x.x ansible_ssh_user=root ansible_ssh_private_key_file=~/anskey

ansible疎通。

$ ansible -i hosts web -m ping
34.68.x.x | SUCCESS => {
    "ansible_facts": {
        "discovered_interpreter_python": "/usr/bin/python3"
    }, 
    "changed": false, 
    "ping": "pong"
}
GID/UID衝突

GCPが追加したユーザがansibleで定義されている追加グループID、ユーザIDと衝突している。プレイブックを直すことで通過。

$ getent group
...
ubuntu:x:1000:datalab
google-sudoers:x:1001:datalab,root
datalab:x:1002:

$ cat /etc/passwd
...
ubuntu:x:1000:1000:Ubuntu:/home/ubuntu:/bin/bash
datalab:x:1001:1002::/home/datalab:/bin/bash
initial.sqlがない（手順ミス）
fatal: [34.68.x.x]: FAILED! => {
    "changed": true, 
    "cmd": "mysql < initial.sql", 
    "delta": "0:00:00.002848", 
    "end": "2020-01-25 16:44:48.284014", 
    "invocation": {
        "module_args": {
            "_raw_params": "mysql < initial.sql", 
            "_uses_shell": true, 
            "argv": null, 
            "chdir": "/home/isucon/isucari/webapp/sql", 
            "creates": null, 
            "executable": null, 
            "removes": null, 
            "stdin": null, 
            "stdin_add_newline": true, 
            "strip_empty_ends": true, 
            "warn": true
        }
    }, 
    "msg": "non-zero return code", 
    "rc": 2, 
    "start": "2020-01-25 16:44:48.281166", 
    "stderr": "/bin/sh: 1: cannot open initial.sql: No such file", 
    "stderr_lines": [
        "/bin/sh: 1: cannot open initial.sql: No such file"
    ], 
    "stdout": "", 
    "stdout_lines": []
}

前準備の「初期データの作成」をやってなかった。あと「画像データの展開」も抜かしてたので、サイトの画像が出てなかった。 ローカル環境でISUCON9予選の問題を動かす : ISUCON公式Blog

「初期データの作成」「画像データの展開」を実施後再度ansibleかけて成功。無事画像が表示された。

ISUCON9予選問題をGCP上で構築する

概要

ISUCON9予選問題をGCP上で構築したときのメモ。 やり方はいくつかあると思われるが、下の1→3→2の順に試してみた。

  1. GitHub - isucon/isucon9-qualify: ISUCON9予選のansible playbookを使う
  2. vagrant-isucon/isucon9-qualifier-standalone at master · matsuu/vagrant-isucon · GitHubのvagrant fileを使う
  3. 素ubuntu上に頑張って構築する

1.ansible playbook(断念)

鍵設定を直す必要があるが、面倒そうなので断念。

TASK [setup] *******************************************************************
fatal: [x.x.x.x]: UNREACHABLE! => {"changed": false, "msg": "Failed to connect to the host via ssh: Permission denied (publickey).\r\n", "unreachable": true}

3.素ubuntu上に頑張って構築する

インスタンス作成

必須パッケージのインストール

色々入ってないので入れる。

# とりあえず公式のデータをもってくる
sudo apt-get update #しないとダメ
sudo apt-get install -y git
git clone https://github.com/isucon/isucon9-qualify.git

# makeするのに必要なあれこれを入れる
sudo apt-get install -y make
sudo apt-get install -y gcc make
sudo apt-get install -y golang
export PATH=”/usr/lib/go-1.10/bin:$PATH” #必要なのか不明
sudo apt-get install -y unzip
sudo apt install -y mysql-server mysql-client

#docker関連 from https://docs.docker.com/install/linux/docker-ce/ubuntu/
sudo apt-get install \
    apt-transport-https \
    ca-certificates \
    curl \
    gnupg-agent \
    software-properties-common
curl -fsSL https://download.docker.com/linux/ubuntu/gpg | sudo apt-key add -
sudo apt-key fingerprint 0EBFCD88
sudo add-apt-repository \
   "deb [arch=amd64] https://download.docker.com/linux/ubuntu \
   $(lsb_release -cs) \
   stable"
sudo apt-get install docker-ce docker-ce-cli containerd.io
sudo docker run hello-world

mysql設定

mysql --version
sudo mysql -u root -e 'SHOW databases;' #疎通
sudo mysql -u root -e "set global validate_password_length=6;" #最低文字数はデフォルト8なので減らす
sudo mysql -u root -e "CREATE USER 'isucari'@'localhost' IDENTIFIED BY 'isucari';"

UbuntuにMySQLをインストール - Qiita

公式のインストール手順実施

GitHub - isucon/isucon9-qualify: ISUCON9予選

初期データ作成

cd ~/isucon9-qualify/initial-data/
sudo make #sudo多分必要

初期画像データダウンロード

cd ~/isucon9-qualify/webapp/public/
wget https://github.com/isucon/isucon9-qualify/releases/download/v2/initial.zip
unzip initial.zip
rm -rf upload
mv v3_initial_data upload

ベンチマーク用画像データダウンロード

cd ~/isucon9-qualify/initial-data/
wget https://github.com/isucon/isucon9-qualify/releases/download/v2/bench1.zip
unzip bench1.zip
rm -rf images
mv v3_bench1 images

webapp 起動方法

cd ~/isucon9-qualify/webapp/sql/
sudo mysql -u root < 00_create_database.sql #要sudo
./init.sh
cd ~/isucon9-qualify/webapp/go/

ここでGoでよく見かけるアレに遭遇。

$ make
main.go:18:2: cannot find package "github.com/go-sql-driver/mysql" in any of:
        /usr/lib/go-1.10/src/github.com/go-sql-driver/mysql (from $GOROOT)
        /home/tech150220/go/src/github.com/go-sql-driver/mysql (from $GOPATH)
main.go:19:2: cannot find package "github.com/gorilla/sessions" in any of:
        /usr/lib/go-1.10/src/github.com/gorilla/sessions (from $GOROOT)
        /home/tech150220/go/src/github.com/gorilla/sessions (from $GOPATH)
main.go:20:2: cannot find package "github.com/jmoiron/sqlx" in any of:
        /usr/lib/go-1.10/src/github.com/jmoiron/sqlx (from $GOROOT)
        /home/tech150220/go/src/github.com/jmoiron/sqlx (from $GOPATH)
main.go:21:2: cannot find package "goji.io" in any of:
        /usr/lib/go-1.10/src/goji.io (from $GOROOT)
        /home/tech150220/go/src/goji.io (from $GOPATH)
main.go:22:2: cannot find package "goji.io/pat" in any of:
        /usr/lib/go-1.10/src/goji.io/pat (from $GOROOT)
        /home/tech150220/go/src/goji.io/pat (from $GOPATH)
main.go:23:2: cannot find package "golang.org/x/crypto/bcrypt" in any of:
        /usr/lib/go-1.10/src/golang.org/x/crypto/bcrypt (from $GOROOT)
        /home/tech150220/go/src/golang.org/x/crypto/bcrypt (from $GOPATH)

解消のためライブラリを導入。

go get -u github.com/go-sql-driver/mysql
go get -u github.com/gorilla/sessions
go get -u github.com/jmoiron/sqlx
go get -u goji.io
go get -u goji.io/pat
go get -u golang.org/x/crypto/bcrypt
make
./isucari

接続テスト

curlで簡単に確認。

$ curl localhost:8000
<!doctype html><html lang="ja"><head><meta charset="utf-8"/><link rel="shortcut icon" href="/favicon.png"/><meta name="viewport" content="width=device-width,initial-scale=1"/><meta name="theme-color" content="#f44436"/><link rel="manifest" href="/manifest.json"/><title>ISUCARI</title><

ブラウザでアクセスするために、ファイアウォールで8000番ポートの許可ルールを作る。

f:id:kavohtn:20200124012850p:plain

VMインスタンスにタグ付けする。

f:id:kavohtn:20200124013020p:plain

ブラウザでhttp://x.x.x.x:8000/にアクセスする。

f:id:kavohtn:20200124013340p:plain

細かいところやベンチマーカーまで確認してないが、とりあえずアプリは立ち上がったっぽい。 素のubuntuだと色々入ってなかったり、goのライブラリのエラーやらで結構時間食った。次はベンチマーク計測までやりたい。

2.vagrant fileを使う

vagrant-isucon/isucon9-qualifier-standalone at master · matsuu/vagrant-isucon · GitHubのvagrant fileを使う。

インスタンス作成

必須パッケージのインストール

色々入ってないので入れる。

# とりあえず公式のデータをもってくる
sudo apt-get update
sudo apt-get install -y git
git clone https://github.com/isucon/isucon9-qualify.git

# makeするのに必要なあれこれを入れる
sudo apt-get install -y make gcc
sudo apt-get install -y golang
export PATH=”/usr/lib/go-1.10/bin:$PATH” #必要なのか不明
sudo apt-get install -y unzip
sudo apt install -y mysql-server mysql-client

#docker関連 from https://docs.docker.com/install/linux/docker-ce/ubuntu/
sudo apt-get install -y apt-transport-https ca-certificates curl gnupg-agent software-properties-common
curl -fsSL https://download.docker.com/linux/ubuntu/gpg | sudo apt-key add -
sudo apt-key fingerprint 0EBFCD88
sudo add-apt-repository "deb [arch=amd64] https://download.docker.com/linux/ubuntu $(lsb_release -cs) stable"
sudo apt-get install -y docker-ce docker-ce-cli containerd.io
sudo docker run hello-world

トラブルシューティング

Failed to connect socket to '/var/run/libvirt/libvirt-sock'

単純にsudo vagrant upするとこれになった。多分ソフトウェアインストールが足りない？

Error while connecting to libvirt: Error making a connection to libvirt URI qemu:///system?no_verify=1&keyfile=/home/***/.ssh/id_rsa:
Call to virConnectOpen failed: Failed to connect socket to '/var/run/libvirt/libvirt-sock': No such file or directory

Timed out

このdefault: SSH auth method: private keyがいくつかOS変えて試してみたけど突破できなかった。

==> default: Waiting for machine to boot. This may take a few minutes...
    default: SSH address: 127.0.0.1:2222
    default: SSH username: vagrant
    default: SSH auth method: private key
#<Thread:0x00005627c6868460@/usr/share/rubygems-integration/all/gems/vagrant-2.0.2/lib/vagrant/batch_action.rb:71 run> terminated with exception (report_on_exception is true):
Traceback (most recent call last):

Timed out while waiting for the machine to boot. This means that
Vagrant was unable to communicate with the guest machine within
the configured ("config.vm.boot_timeout" value) time period.

If you look above, you should be able to see the error(s) that
Vagrant had when attempting to connect to the machine. These errors
are usually good hints as to what may be wrong.

If you're using a custom box, make sure that networking is properly
working and you're able to connect to the machine. It is a common
problem that networking isn't setup properly in these boxes.
Verify that authentication configurations are also setup properly,
as well.

If the box appears to be booting properly, you may want to increase
the timeout ("config.vm.boot_timeout") value.

Windows7にVagrantを導入 - 失敗した事 - Qiita

ISUCON8予選問題のメソッド・コードブロック単位の実行時間の解析

ISUCON

概要

ISUCON8予選問題で、GitHub - najeira/measureを使ってメソッド・コードブロック単位で実行時間を取得する手順のメモ。

実行時間の取得

前回、リクエスト単位の解析を行った。ボトルネックの更に具体的な箇所の特定のため、より細かい単位、メソッドやコードブロック単位で時間を測る。

最初はpprofを使おうと思ったが、上手く動かせず挫折した。そこで、死闘の果てに ISUCON 8 予選を全体７位で突破した記録 - Qiitaで紹介されているGitHub - najeira/measureを試してみることに。UsageはREADME.mdに記述がある。

前提：参照実装の構造

ISUCON8予選問題のGoの参照実装では、Echoフレームワークが使われている。

e.GET("/api/users/:id", func(c echo.Context) error {...}, loginRequired)

上記のようにリクエストURIに対応する処理が記述される。alpによる解析で/api/users/*が遅いことが分かっているので、最初はその辺を重点的に見ていく。

計測コード埋め込み

計測コード埋め込み（１）import

import文を書いただけでは、ビルド時にパッケージが見つからない。go getでいちいちインストール的なことをする、というのが普通なんだろうか？Maven以外ほぼ使ったことなかったので、なんだか面倒に感じる。

import (
...
"github.com/najeira/measure"
)

cannot find package "github.com/najeira/measure" in any of:
    /home/isucon/local/go/src/github.com/najeira/measure (from $GOROOT)
    /home/isucon/go/src/github.com/najeira/measure (from $GOPATH)

ちなみにgo get -v github.com/najeira/measureをしても上手く行ってないようで（特にエラーも表示されないが）、cannot find packageは変わらず、上記に表示されているパスにも入っていない。そこで今回はもう直接git cloneした。これで一応解決。

sudo git clone --depth 1 https://github.com/najeira/measure.git $GOPATH/src/github.com/najeira/measure
sudo git clone --depth 1 https://github.com/rcrowley/go-metrics.git $GOPATH/src/github.com/rcrowley/go-metrics

計測コード埋め込み（２）Measure

URI単位の処理とか、関数単位の計測は1文で書ける。

   e.GET("/", func(c echo.Context) error {
        defer measure.Start("GET(/").Stop()

func getEvent(eventID, loginUserID int64) (*Event, error) {
    defer measure.Start("func getEvent").Stop()

さらにmeasure.Startとmeasure.Stopを埋め込んでコード何行目から何行目、という単位でも計測可能。ただし、for文の中のより細かい範囲を分割して測ろうとしたときは上手く行かなかった。実行順序の指定とか上手くやればできるのかも。

計測コード埋め込み（３）Stats部分

まず、Log構造体と、Log構造体を渡してCSVファイルにレンダリングして返してくれる関数を作る。これは参照実装にあったrenderReportCSVの見様見真似。

type Log struct {
    Key   string
    Count   int64
    Sum     float64
    Min     float64
    Max     float64
    Avg     float64
    Rate    float64
    P95     float64
}

func renderLogCSV(c echo.Context, logs []Log) error {

    body := bytes.NewBufferString("key,count,sum,min,max,avg,rate,p95\n")
    for _, s := range logs {
        body.WriteString(fmt.Sprintf("%s,%d,%f,%f,%f,%f,%f,%f\n",
        s.Key, s.Count, s.Sum, s.Min, s.Max, s.Avg, s.Rate, s.P95))
    }

    c.Response().Header().Set("Content-Type", `text/csv; charset=UTF-8`)
    c.Response().Header().Set("Content-Disposition", `attachment; filename="log.csv"`)
    _, err := io.Copy(c.Response(), body)
    return err
}

上記のCSVファイルを取得するエンドポイントを作る。これは参照実装にあったe.GET("/admin/api/reports/sales"の見様見真似。statsのとり方はUsageより。Sumの所でRoundを噛ませているのは、CSVを表示したときに小数が入っていない方がぱっと見で分かりやすいため。

   e.GET("/stats", func(c echo.Context) error{
        stats := measure.GetStats()
        stats.SortDesc("sum")

        var logs []Log
        for _, s := range stats {
            log := Log{
                Key: s.Key,
                Count: s.Count,
                Sum: math.Round(s.Sum),
                Min: s.Min,
                Max: s.Max,
                Avg: s.Avg,
                Rate: s.Rate,
                P95: s.P95,
            }
            logs = append(logs, log)
        }

        return renderLogCSV(c, logs)
    })

結果表示

ブラウザで/statsにアクセスするとCSVファイルがダウンロードできる。

参考実装の初期状態で、ベンチマーク実行後の結果を開いてみると以下のようになる。計測点は全エンドポイント、関数に設定しており、getEventは最大であったため、関数内をさらに分割している。

f:id:kavohtn:20190729020304p:plain

結果のSlack通知

いちいちCSVを開きにいくのも面倒＆後で見返しづらい。

標準入力を適当にまとめてSlackに通知するnotify_slackを作りました - catatsuy - Medium こんな素敵ツールがあったので、使ってみる。GO111MODULEを使うインストール方法は詰まったので普通にバイナリを持ってくることにした。

Slackのアカウント作成、ワークスペース作成、チャンネル作成、https://slack.com/services/new/incoming-webhookからwebhookを作成、レガシートークンも作成（これは必要かよくわかってないが）。

.tomlファイルをhttps://github.com/catatsuy/notify_slackのUsageに従って書く。

CSVをSlackに向けて飛ばしてみる。

curl ${TARGET_SITE_URL}/stats |head -n 10| tr "," "\t" | ./notify_slack

f:id:kavohtn:20190729024625p:plain

無事取得できた。もうちょっと見やすくできるといいが一旦終わり。

ISUCON8予選問題のアクセスログ解析

ISUCON

概要

ISUCON8予選問題の環境で、H2Oサーバのアクセスログをalpに噛ませ、URI単位で重い処理を特定するまでの手順。

計測環境

改善の第一歩は現状把握ということで、色々なものの計測環境を整えていきたい。

  • Webサーバ
  • アプリ
    • プロファイラ（関数単位、行単位）
  • サーバ・NWリソース
    • CPU、メモリ、ディスクIO、NW帯域、ポート...

Webサーバ

特に重要な情報源となるWebサーバのアクセスログ解析のやり方を整理する。今回WebサーバはH2O。 ログ解析ツールにalpを使う。

設定ファイルの特定

サービス一覧を確認、サービス名を特定。

$ systemctl list-units --type=service
~
  h2o.service  loaded active running H2O - the optimized HTTP/1, HTTP/2 server
~

h2o.serviceの状態を確認、設定ファイルのパスを特定。今は/etc/h2o/h2o.confらしい。

$ systemctl status h2o.service
~
           ├─4359 /usr/sbin/h2o -c /etc/h2o/h2o.conf
~

ログ設定の編集

/etc/h2o/h2o.confを編集、アクセスログフォーマットをalp仕様に変更する。

access-log:
  path: /var/log/h2o/access.log
  format: "time:%t\thost:%h\tua:\"%{User-agent}i\"\tstatus:%s\treq:%r\turi:%U\treqtime:%{duration}x\tsize:%b\tmethod:%m\t"

文法チェック。

$ h2o -m test -c /etc/h2o/h2o.conf
configuration OK

h2oをリスタートさせ、ブラウザとかcurlとかでアクセスしてみる。ログが編集した通りのフォーマットになって出てくればOK。

$ sudo systemctl restart h2o.service
$ sudo tail -f /var/log/h2o/access.log

alp実行

資材をダウンロード、展開、実行。表がカラじゃなきゃOK。

$ wget https://github.com/tkuchiki/alp/releases/download/v0.4.0/alp_linux_386.zip
$ unzip alp_linux_386.zip 
$ sudo ./alp -f /var/log/h2o/access.log --sum

ベンチ後にalp実行、ボトルネック処理を特定

ログをカラにしてベンチ実行、alpで解析。このときScoreは800だった。

下図のalp結果はURIごとの累計応答時間を降順に並べている。 全合計が314秒くらいなので、/api/users/*と/だけで2/3近く占めていることが分かった。

$ sudo truncate /var/log/h2o/access.log --size 0
$ bash /home/isucon/torb/bench/tools/do_bench.sh
$ sudo ./alp -f /var/log/h2o/access.log --sum -r --aggregates "/api/users/*"
+-------+--------+-----------------------------------------+---------+
| COUNT | METHOD |                   URI                   |   SUM   |
+-------+--------+-----------------------------------------+---------+
|    12 | GET    | /api/users/*                            | 133.308 |
|    24 | GET    | /                                       |  64.064 |
|     5 | GET    | /admin/                                 |  26.668 |
|    24 | POST   | /api/events/11/actions/reserve          |  22.741 |
|    16 | GET    | /api/events/10                          |  16.836 |
~

これで、とりあえず/api/users/*や/あたりから見ていくのが良さそうなことが分かった。

余談

VSCodeの拡張機能のRemote SSHが便利だった。 図のようにサーバのディレクトリをローカルのようにいじれる感覚が素晴らしい。 f:id:kavohtn:20190630033712p:plain