1.準備 2.ベンチの際にログを取る

pprof,nginx,mysql

pprof（プロファイラー）

1. main関数の先頭に以下の設定を追加
2. systemctlからではなくコマンドラインから起動
3. ベンチを走らせて、終了次第ctrl+C

  cpuprofile := "mycpu.prof"
    f, err := os.Create(cpuprofile)
    if err != nil {
      log.Fatal(err)
    }
  pprof.StartCPUProfile(f)
  defer pprof.StopCPUProfile()
  c := make(chan os.Signal, 1)
  signal.Notify(c, os.Interrupt)
  go func() {
    for sig := range c {
      log.Printf("captured %v, stopping profiler and exiting...", sig)
      pprof.StopCPUProfile()
      os.Exit(1)
    }
  }()

プロファイルの仕方

%go tool pprof myprog(goappの名前) mycpu.prof(profファイル)
%pprof>top30 -cum
%pprof>list main.GetIndex

• https://files.slack.com/files-pri/T0A8W0RCL-F0BQZUM6F/-.txt

nginx.confのログフォーマットを編集

https://gist.github.com/edvakf/7340616

    log_format ltsv
      "time:$time_iso8601"
      "\treq_time:$request_time"
      "\tapp_time:$upstream_response_time"
      "\tres_size:$bytes_sent"
      "\tstatus:$status"
      "\tmethod:$request_method"
      "\tpath:$request_uri"
      "\thost:$remote_addr"
      "\tua:$http_user_agent"
      ;

• log_formatの後の"ltsv"は単なる名前なので適宜変更
• user_agent入れると一気に見辛くなる
• req_timeはnginxがリクエストを受け取ってから返すまでの時間
• app_timeはnginxがproxy先にリクエストを投げてから返事がproxy先から帰ってくるまでの時間

kataribeツール

log_format with_time '$remote_addr - $remote_user [$time_local] '
                     '"$request" $status $body_bytes_sent '
                     '"$http_referer" "$http_user_agent" $request_time';
access_log /var/log/nginx/access.log with_time

kataribeバイナリは以下で入手

cd /home/isucon
wget https://github.com/matsuu/kataribe/archive/v0.2.0.zip
unzip v0.2.0.zip
cd /home/isucon/kataribe-0.2.0
GOPATH=/home/isucon/kataribe-0.2.0 GOBIN=$GOPATH go get

実行は以下。kataribe.tomlファイルがカレントディレクトリになければ、場所を指定する。

cat /var/log/nginx/access.log | ./kataribe [-f kataribe.toml] > kataribe.log

my.cnfを編集してslow queryの設定

my.cnfの場所については、isucon5予選だと/etc/mysql/mysql.conf.d/mysqld.cnfがそれっぽい。 設定が反映されているかどうかはmysql>show variables like "%max%とかで確認。

[mysqld]
datadir=/var/lib/mysql
socket=/var/lib/mysql/mysql.sock
symbolic-links=0

max_allowed_packet=300M

# slow query用の設定
## on or off
slow_query_log=1
## queryの発行に0秒以上かかったもの全部記録
long_query_time=0
## index使ってないqueryも記録
log_queries_not_using_indexes=1
slow_query_log_file=/var/log/mysql/mysql-slow.log

解析はpt-query-digestで。yumだとyum localinstall -y http://percona.com/get/percona-toolkit.rpm

sudo apt-get -y install percona-toolkit
pt-query-digest /var/log/mysql/mysql-slow.log > ptq-digest.log

init.shを編集してデータベース初期化の際のクエリがslow-query-logに含まれないようにする

sudo rm -r /var/log/mysql/mysql-slow.log
sudo touch /var/log/mysql/mysql-slow.log
#sudo chown mysql.mysql -R /var/log
#sudo chmod 777 /var/log/mysql/mysql-slow.log
sudo service mysql55-mysqld restart

ベンチマークを実行する際に走らせるコマンド

どれもベンチマーク終了時にctrl+c。下のはどれもファイルに記録するようにしている

dstat

ネットワークIOとかも。

dstat -taf --output dstat.csv 1

top

CPUのプロセス別占有率

top -b -d 1 > top_result.log

iostat

ディスクio

iostat -txn 1 > iostat.log