euglena1215/isucon4q20190904

Kataribe

Nginx/Apache/Varnishncsa Log Profiler

Prerequisites

Apache

Add %D to LogFormat.

LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-agent}i\" %D" with_time
CustomLog logs/access_log with_time

Nginx

Add $request_time to log_format.

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

Varnishncsa

Add %D to varnishncsa -F option.

varnishncsa -a -w $logfile -D -P $pidfile -F '%h %l %u %t "%r" %s %b "%{Referer}i" "%{User-agent}i" %D'

Rack

Add Rack::CommonLogger to config.ru.

logger = Logger.new("/tmp/app.log")
use Rack::CommonLogger, logger

Usage

• Download release file
• Edit kataribe.toml
• Pass access log to kataribe by stdin

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

Example

Sort By Count
Count   Total      Mean    Stddev    Min    P50    P90    P95    P99    Max    2xx   3xx  4xx  5xx  Request
17238   0.000  0.000000  0.000000  0.000  0.000  0.000  0.000  0.000  0.000  17238     0    0    0  GET /stylesheets/*
 5746   0.000  0.000000  0.000000  0.000  0.000  0.000  0.000  0.000  0.000   5746     0    0    0  GET /images/*
 5198  12.449  0.002395  0.002292  0.001  0.002  0.003  0.005  0.009  0.069   5198     0    0    0  GET / HTTP/1.1
 2873  22.753  0.007920  0.007529  0.004  0.006  0.011  0.015  0.035  0.193      0  2873    0    0  POST /login HTTP/1.1
  548   2.851  0.005203  0.004015  0.003  0.004  0.007  0.009  0.021  0.066    548     0    0    0  GET /mypage HTTP/1.1
    1   0.303  0.303000  0.000000  0.303  0.303  0.303  0.303  0.303  0.303      0     0    0    1  GET /report HTTP/1.1

Sort By Total
Count   Total      Mean    Stddev    Min    P50    P90    P95    P99    Max    2xx   3xx  4xx  5xx  Request
 2873  22.753  0.007920  0.007529  0.004  0.006  0.011  0.015  0.035  0.193      0  2873    0    0  POST /login HTTP/1.1
 5198  12.449  0.002395  0.002292  0.001  0.002  0.003  0.005  0.009  0.069   5198     0    0    0  GET / HTTP/1.1
  548   2.851  0.005203  0.004015  0.003  0.004  0.007  0.009  0.021  0.066    548     0    0    0  GET /mypage HTTP/1.1
    1   0.303  0.303000  0.000000  0.303  0.303  0.303  0.303  0.303  0.303      0     0    0    1  GET /report HTTP/1.1
17238   0.000  0.000000  0.000000  0.000  0.000  0.000  0.000  0.000  0.000  17238     0    0    0  GET /stylesheets/*
 5746   0.000  0.000000  0.000000  0.000  0.000  0.000  0.000  0.000  0.000   5746     0    0    0  GET /images/*

Sort By Mean
Count   Total      Mean    Stddev    Min    P50    P90    P95    P99    Max    2xx   3xx  4xx  5xx  Request
    1   0.303  0.303000  0.000000  0.303  0.303  0.303  0.303  0.303  0.303      0     0    0    1  GET /report HTTP/1.1
 2873  22.753  0.007920  0.007529  0.004  0.006  0.011  0.015  0.035  0.193      0  2873    0    0  POST /login HTTP/1.1
  548   2.851  0.005203  0.004015  0.003  0.004  0.007  0.009  0.021  0.066    548     0    0    0  GET /mypage HTTP/1.1
 5198  12.449  0.002395  0.002292  0.001  0.002  0.003  0.005  0.009  0.069   5198     0    0    0  GET / HTTP/1.1
17238   0.000  0.000000  0.000000  0.000  0.000  0.000  0.000  0.000  0.000  17238     0    0    0  GET /stylesheets/*
 5746   0.000  0.000000  0.000000  0.000  0.000  0.000  0.000  0.000  0.000   5746     0    0    0  GET /images/*

Sort By Standard Deviation
Count   Total      Mean    Stddev    Min    P50    P90    P95    P99    Max    2xx   3xx  4xx  5xx  Request
 2873  22.753  0.007920  0.007529  0.004  0.006  0.011  0.015  0.035  0.193      0  2873    0    0  POST /login HTTP/1.1
  548   2.851  0.005203  0.004015  0.003  0.004  0.007  0.009  0.021  0.066    548     0    0    0  GET /mypage HTTP/1.1
 5198  12.449  0.002395  0.002292  0.001  0.002  0.003  0.005  0.009  0.069   5198     0    0    0  GET / HTTP/1.1
    1   0.303  0.303000  0.000000  0.303  0.303  0.303  0.303  0.303  0.303      0     0    0    1  GET /report HTTP/1.1
17238   0.000  0.000000  0.000000  0.000  0.000  0.000  0.000  0.000  0.000  17238     0    0    0  GET /stylesheets/*
 5746   0.000  0.000000  0.000000  0.000  0.000  0.000  0.000  0.000  0.000   5746     0    0    0  GET /images/*

Sort By Maximum(100 Percentile)
Count   Total      Mean    Stddev    Min    P50    P90    P95    P99    Max    2xx   3xx  4xx  5xx  Request
    1   0.303  0.303000  0.000000  0.303  0.303  0.303  0.303  0.303  0.303      0     0    0    1  GET /report HTTP/1.1
 2873  22.753  0.007920  0.007529  0.004  0.006  0.011  0.015  0.035  0.193      0  2873    0    0  POST /login HTTP/1.1
 5198  12.449  0.002395  0.002292  0.001  0.002  0.003  0.005  0.009  0.069   5198     0    0    0  GET / HTTP/1.1
  548   2.851  0.005203  0.004015  0.003  0.004  0.007  0.009  0.021  0.066    548     0    0    0  GET /mypage HTTP/1.1
17238   0.000  0.000000  0.000000  0.000  0.000  0.000  0.000  0.000  0.000  17238     0    0    0  GET /stylesheets/*
 5746   0.000  0.000000  0.000000  0.000  0.000  0.000  0.000  0.000  0.000   5746     0    0    0  GET /images/*

TOP 37 Slow Requests
 1  0.303  GET /report HTTP/1.1
 2  0.193  POST /login HTTP/1.1
 3  0.149  POST /login HTTP/1.1
 4  0.108  POST /login HTTP/1.1
 5  0.105  POST /login HTTP/1.1
 6  0.101  POST /login HTTP/1.1
 7  0.084  POST /login HTTP/1.1
 8  0.080  POST /login HTTP/1.1
 9  0.080  POST /login HTTP/1.1
10  0.069  GET / HTTP/1.1
11  0.066  GET /mypage HTTP/1.1
12  0.063  POST /login HTTP/1.1
13  0.063  POST /login HTTP/1.1
14  0.057  POST /login HTTP/1.1
15  0.056  POST /login HTTP/1.1
16  0.056  GET / HTTP/1.1
17  0.054  POST /login HTTP/1.1
18  0.054  POST /login HTTP/1.1
19  0.048  POST /login HTTP/1.1
20  0.046  GET /mypage HTTP/1.1
21  0.045  POST /login HTTP/1.1
22  0.045  POST /login HTTP/1.1
23  0.044  POST /login HTTP/1.1
24  0.042  POST /login HTTP/1.1
25  0.041  GET / HTTP/1.1
26  0.040  POST /login HTTP/1.1
27  0.039  GET / HTTP/1.1
28  0.038  POST /login HTTP/1.1
29  0.038  GET / HTTP/1.1
30  0.037  POST /login HTTP/1.1
31  0.037  POST /login HTTP/1.1
32  0.036  GET / HTTP/1.1
33  0.036  POST /login HTTP/1.1
34  0.036  GET / HTTP/1.1
35  0.036  POST /login HTTP/1.1
36  0.035  POST /login HTTP/1.1
37  0.035  POST /login HTTP/1.1

License

Apache-2.0

Author

matsuu

isucon4q20190904's Issues

score

• 当日のマニュアル
  https://gist.github.com/mirakui/e394ed543415852d34a6#benchmarker

kataribe

走らせ方

# access_logを空にする(ベンチを走らせる前にやる)
sudo cp /dev/null /var/log/nginx/access.log

## 整形して出力
sudo cat /var/log/nginx/access.log | ~/kataribe -f ~/kataribe.toml

# kataribeで整形して出力、timestampをつけてファイルとして保存
sudo cat /var/log/nginx/access.log | ~/kataribe -f ~/kataribe.toml > ~/kataribe-`date "+%H%M%S"`.log

データベース調査

mysqlチートシート

• ログイン
  username = rootの時
  mysql -uroot

• 基本的な操作

show databases;
use isutomo;
desc tweets;desc users;

• インデックスの確認

show index from tweets;show index from users;

• 容量の確認

SELECT table_name, engine, table_rows, avg_row_length, floor((data_length+index_length)/1024/1024) as allMB, floor((data_length)/1024/1024) as dMB, floor((index_length)/1024/1024) as iMB FROM information_schema.tables WHERE table_schema=database() ORDER BY (data_length+index_length) DESC;

• スロークエリログの設定

show variables like "%slow%"

Indexの貼り方

CREATE INDEX post_id_index ON comments(post_id)

myprofiler

基本スペック

[isucon@ip-172-31-24-5 ec2-user]$ grep processor /proc/cpuinfo | wc -l
2
[isucon@ip-172-31-24-5 ec2-user]$ free -m
             total       used       free     shared    buffers     cached
Mem:          3768        679       3088          0         31        199
-/+ buffers/cache:        448       3319
Swap:            0          0          0