okashoi / isucon-practice-20200718

2 stars 0 forks source link

はやくする #1

Open okashoi opened 4 years ago

yamachu commented 4 years ago

とりあえず初回ベンチ

[isucon@ip-172-31-23-17 isucon3-mod]$  make bench
sudo /opt/isucon3-mod/bench/bench benchmark --workload 1 --init ./init.sh
2020/07/18 03:40:31 <<<DEBUG build>>>
2020/07/18 03:40:31 benchmark mode
2020/07/18 03:40:31 initialize data...
2020/07/18 03:40:36 run ./init.sh timeout 60 sec...
2020/07/18 03:40:36 done
2020/07/18 03:40:36 sleeping 5 sec...
2020/07/18 03:40:41 run benchmark workload: 1
2020/07/18 03:41:43 done benchmark
Result:   SUCCESS
RawScore: 2556.4
Fails:    0
Score:    2556.4

傾向

okashoi commented 4 years ago

最初の30秒でWriteが100MiB/s で張り付いてる

これはおそらく初期化処理(データの初期化等)かな、ベンチのスコアには影響しない気がする

yamachu commented 4 years ago
mysql> show create table memos;
+-------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Table | Create Table                                                                                                                                                                                                                                                                                                                                                          |
+-------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| memos | CREATE TABLE `memos` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `user` int(11) NOT NULL,
  `content` text,
  `is_private` tinyint(4) NOT NULL DEFAULT '0',
  `created_at` datetime NOT NULL,
  `updated_at` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=41176 DEFAULT CHARSET=utf8 |
+-------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

mysql> show create table users;
+-------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Table | Create Table                                                                                                                                                                                                                                                                                                                               |
+-------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| users | CREATE TABLE `users` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `username` varchar(255) NOT NULL,
  `password` varchar(255) NOT NULL,
  `salt` varchar(255) NOT NULL,
  `last_access` datetime DEFAULT NULL,
  PRIMARY KEY (`id`),
  UNIQUE KEY `users_username_idx` (`username`)
) ENGINE=InnoDB AUTO_INCREMENT=401 DEFAULT CHARSET=utf8 |
+-------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

mysql> 
okashoi commented 4 years ago

アプリケーション仕様

メモ(ブログ?)アプリ

ページ構成

その他メモ

yamachu commented 4 years ago

計測前に気になったポイント

okashoi commented 4 years ago

memosusers の 2 テーブルのみ

CREATE TABLE `memos` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `user` int(11) NOT NULL,
  `content` text,
  `is_private` tinyint(4) NOT NULL DEFAULT '0',
  `created_at` datetime NOT NULL,
  `updated_at` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=41176 DEFAULT CHARSET=utf8
CREATE TABLE `users` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `username` varchar(255) NOT NULL,
  `password` varchar(255) NOT NULL,
  `salt` varchar(255) NOT NULL,
  `last_access` datetime DEFAULT NULL,
  PRIMARY KEY (`id`),
  UNIQUE KEY `users_username_idx` (`username`)
) ENGINE=InnoDB AUTO_INCREMENT=401 DEFAULT CHARSET=utf8
okashoi commented 4 years ago

@yamachu

計測前に気になったポイント

これ、1 個 1 個 issue にしてもらえるとたすかる!

yamachu commented 4 years ago

Markdownパースするやつしたら

[isucon@ip-172-31-23-17 isucon3-mod]$ make bench
sudo /opt/isucon3-mod/bench/bench benchmark --workload 1 --init ./init.sh
2020/07/18 06:30:15 <<<DEBUG build>>>
2020/07/18 06:30:15 benchmark mode
2020/07/18 06:30:15 initialize data...
2020/07/18 06:30:21 run ./init.sh timeout 60 sec...
2020/07/18 06:30:21 done
2020/07/18 06:30:21 sleeping 5 sec...
2020/07/18 06:30:26 run benchmark workload: 1
2020/07/18 06:31:27 done benchmark
Result:   SUCCESS
RawScore: 3546.9
Fails:    0
Score:    3546.9
okashoi commented 4 years ago

pprof による Flame Graph

http://18.183.182.156/torch-IMESTAMP.svg

okashoi commented 4 years ago
$ sudo mysqldumpslow /var/lib/mysql/mysql-slow.log

Reading mysql slow query log from /var/lib/mysql/mysql-slow.log
Count: 1  Time=0.13s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), isucon[isucon]@localhost
  #

Count: 483  Time=0.10s (47s)  Lock=0.00s (0s)  Rows=100.0 (48300), isucon[isucon]@localhost
  SELECT * FROM memos WHERE is_private=N ORDER BY created_at DESC, id DESC LIMIT N OFFSET N

Count: 497  Time=0.07s (32s)  Lock=0.00s (0s)  Rows=100.0 (49700), isucon[isucon]@localhost
  SELECT * FROM memos WHERE is_private=N ORDER BY created_at DESC, id DESC LIMIT N

Count: 198  Time=0.06s (12s)  Lock=0.00s (0s)  Rows=54.7 (10822), isucon[isucon]@localhost
  SELECT id, content, is_private, created_at, updated_at FROM memos WHERE user=N AND is_private=N ORDER BY created_at

Count: 199  Time=0.06s (11s)  Lock=0.00s (0s)  Rows=107.5 (21392), isucon[isucon]@localhost
  SELECT id, content, is_private, created_at, updated_at FROM memos WHERE user=N ORDER BY created_at DESC

Count: 1077  Time=0.05s (57s)  Lock=0.00s (0s)  Rows=108.8 (117171), isucon[isucon]@localhost
  SELECT id, content, is_private, created_at, updated_at FROM memos WHERE user=N  ORDER BY created_at

Count: 980  Time=0.04s (38s)  Lock=0.00s (0s)  Rows=1.0 (980), isucon[isucon]@localhost
  SELECT count(*) AS c FROM memos WHERE is_private=N

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), 0users@0hosts
  administrator command: Prepare

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), 0users@0hosts
> explain SELECT * FROM memos WHERE is_private=0 ORDER BY created_at DESC, id DESC;

+----+-------------+-------+------------+------+---------------+------+---------+------+-------+----------+-----------------------------+
| id | select_type | table | partitions | type | possible_keys | key  | key_len | ref  | rows  | filtered | Extra                       |
+----+-------------+-------+------------+------+---------------+------+---------+------+-------+----------+-----------------------------+
|  1 | SIMPLE      | memos | NULL       | ALL  | NULL          | NULL | NULL    | NULL | 32387 |    10.00 | Using where; Using filesort |
+----+-------------+-------+------------+------+---------------+------+---------+------+-------+----------+-----------------------------+
FuwariSprit commented 4 years ago

18

okashoi commented 4 years ago
$ make bench
sudo /opt/isucon3-mod/bench/bench benchmark --workload 1 --init ./init.sh
2020/07/18 07:21:32 <<<DEBUG build>>>
2020/07/18 07:21:32 benchmark mode
2020/07/18 07:21:32 initialize data...
2020/07/18 07:21:37 run ./init.sh timeout 60 sec...
2020/07/18 07:21:38 done
2020/07/18 07:21:38 sleeping 5 sec...
2020/07/18 07:21:43 run benchmark workload: 1
2020/07/18 07:22:43 done benchmark
Result:   SUCCESS 
RawScore: 4667.2
Fails:    0
Score:    4667.2
$ sudo mysqldumpslow /var/lib/mysql/mysql-slow.log

Reading mysql slow query log from /var/lib/mysql/mysql-slow.log
Count: 1  Time=0.15s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), isucon[isucon]@localhost
  #

Count: 331  Time=0.13s (42s)  Lock=0.00s (0s)  Rows=100.0 (33100), isucon[isucon]@localhost
  SELECT * FROM memos WHERE is_private=N ORDER BY created_at DESC, id DESC LIMIT N OFFSET N

Count: 117  Time=0.07s (8s)  Lock=0.00s (0s)  Rows=100.0 (11700), isucon[isucon]@localhost
  SELECT * FROM memos WHERE is_private=N ORDER BY created_at DESC, id DESC LIMIT N

Count: 44  Time=0.06s (2s)  Lock=0.00s (0s)  Rows=115.1 (5063), isucon[isucon]@localhost
  SELECT id, content, is_private, created_at, updated_at FROM memos WHERE user=N ORDER BY created_at DESC

Count: 36  Time=0.06s (2s)  Lock=0.00s (0s)  Rows=58.9 (2120), isucon[isucon]@localhost
  SELECT id, content, is_private, created_at, updated_at FROM memos WHERE user=N AND is_private=N ORDER BY created_at

Count: 254  Time=0.06s (14s)  Lock=0.00s (0s)  Rows=111.9 (28414), isucon[isucon]@localhost
  SELECT id, content, is_private, created_at, updated_at FROM memos WHERE user=N  ORDER BY created_at

Count: 1189  Time=0.03s (41s)  Lock=0.00s (0s)  Rows=1.0 (1189), isucon[isucon]@localhost
  SELECT count(*) AS c FROM memos WHERE is_private=N

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), 0users@0hosts
  administrator command: Prepare

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), 0users@0hosts

Flame Graph

http://18.183.182.156/torch-20200718072450.svg

Kataribe

Top 20 Sort By Count
Count   Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max   2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
 1856  23.018  0.0124  0.0227  0.000  0.003  0.045  0.067  0.106  0.134  1716    0  140    0     7548979         10       4067      58970  get memo
 1548   1.069  0.0007  0.0013  0.000  0.000  0.001  0.003  0.007  0.013  1548    0    0    0   144129636      93107      93107      93107  GET /js/jquery.min.js HTTP/1.1
 1548   1.061  0.0007  0.0014  0.000  0.000  0.001  0.003  0.007  0.017  1548    0    0    0   164111220     106015     106015     106015  GET /css/bootstrap.min.css HTTP/1.1
 1548   0.985  0.0006  0.0014  0.000  0.000  0.001  0.003  0.007  0.020  1548    0    0    0    44320788      28631      28631      28631  GET /js/bootstrap.min.js HTTP/1.1
 1548   0.838  0.0005  0.0013  0.000  0.000  0.001  0.002  0.006  0.019  1548    0    0    0    26082252      16849      16849      16849  GET /css/bootstrap-responsive.min.css HTTP/1.1
  647  51.043  0.0789  0.0421  0.024  0.068  0.136  0.172  0.222  0.279   646    0    1    0     9572869        157      14795      15768  GET / HTTP/1.1
  262   0.772  0.0029  0.0022  0.001  0.002  0.005  0.007  0.015  0.019     0  262    0    0           0          0          0          0  POST /memo HTTP/1.1
  262   0.166  0.0006  0.0010  0.000  0.000  0.001  0.002  0.005  0.006     0  262    0    0           0          0          0          0  POST /signout HTTP/1.1
  262   0.917  0.0035  0.0100  0.001  0.002  0.005  0.007  0.011  0.162     0  262    0    0           0          0          0          0  POST /signin HTTP/1.1
  262   0.140  0.0005  0.0011  0.000  0.000  0.001  0.002  0.006  0.011   262    0    0    0      349508       1334       1334       1334  GET /signin HTTP/1.1
  262   5.042  0.0192  0.0283  0.001  0.008  0.059  0.089  0.128  0.177   262    0    0    0     3981807       1920      15197      28164  GET /mypage HTTP/1.1
   41   8.334  0.2033  0.0570  0.086  0.192  0.285  0.295  0.362  0.362    41    0    0    0      561794      13182      13702      13975  GET /recent/205 HTTP/1.1
   40   9.171  0.2293  0.0697  0.128  0.216  0.355  0.388  0.397  0.397    40    0    0    0      558415      13722      13960      14098  GET /recent/204 HTTP/1.1
    7   1.083  0.1547  0.0405  0.066  0.162  0.197  0.197  0.197  0.197     7    0    0    0       96218      13558      13745      13947  GET /recent/165 HTTP/1.1
    7   0.700  0.1000  0.0289  0.070  0.087  0.159  0.159  0.159  0.159     7    0    0    0      100011      14195      14287      14340  GET /recent/92 HTTP/1.1
    7   0.376  0.0537  0.0145  0.037  0.044  0.076  0.076  0.076  0.076     7    0    0    0       96809      13562      13829      14325  GET /recent/8 HTTP/1.1
    6   1.185  0.1975  0.0880  0.097  0.164  0.319  0.319  0.319  0.319     6    0    0    0       84511      13982      14085      14292  GET /recent/110 HTTP/1.1
    6   0.578  0.0963  0.0439  0.044  0.098  0.172  0.172  0.172  0.172     6    0    0    0       88749      14677      14791      14952  GET /recent/37 HTTP/1.1
    6   1.078  0.1797  0.0755  0.071  0.162  0.303  0.303  0.303  0.303     6    0    0    0       82760      13341      13793      13987  GET /recent/164 HTTP/1.1
    6   0.271  0.0452  0.0195  0.029  0.038  0.088  0.088  0.088  0.088     6    0    0    0       87985      14133      14664      14968  GET /recent/4 HTTP/1.1

Top 20 Sort By Total
Count   Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max   2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
  647  51.043  0.0789  0.0421  0.024  0.068  0.136  0.172  0.222  0.279   646    0    1    0     9572869        157      14795      15768  GET / HTTP/1.1
 1856  23.018  0.0124  0.0227  0.000  0.003  0.045  0.067  0.106  0.134  1716    0  140    0     7548979         10       4067      58970  get memo
   40   9.171  0.2293  0.0697  0.128  0.216  0.355  0.388  0.397  0.397    40    0    0    0      558415      13722      13960      14098  GET /recent/204 HTTP/1.1
   41   8.334  0.2033  0.0570  0.086  0.192  0.285  0.295  0.362  0.362    41    0    0    0      561794      13182      13702      13975  GET /recent/205 HTTP/1.1
  262   5.042  0.0192  0.0283  0.001  0.008  0.059  0.089  0.128  0.177   262    0    0    0     3981807       1920      15197      28164  GET /mypage HTTP/1.1
    6   1.185  0.1975  0.0880  0.097  0.164  0.319  0.319  0.319  0.319     6    0    0    0       84511      13982      14085      14292  GET /recent/110 HTTP/1.1
    7   1.083  0.1547  0.0405  0.066  0.162  0.197  0.197  0.197  0.197     7    0    0    0       96218      13558      13745      13947  GET /recent/165 HTTP/1.1
    6   1.078  0.1797  0.0755  0.071  0.162  0.303  0.303  0.303  0.303     6    0    0    0       82760      13341      13793      13987  GET /recent/164 HTTP/1.1
 1548   1.069  0.0007  0.0013  0.000  0.000  0.001  0.003  0.007  0.013  1548    0    0    0   144129636      93107      93107      93107  GET /js/jquery.min.js HTTP/1.1
 1548   1.061  0.0007  0.0014  0.000  0.000  0.001  0.003  0.007  0.017  1548    0    0    0   164111220     106015     106015     106015  GET /css/bootstrap.min.css HTTP/1.1
    5   1.041  0.2082  0.1384  0.065  0.178  0.465  0.465  0.465  0.465     5    0    0    0       72926      14403      14585      14660  GET /recent/86 HTTP/1.1
 1548   0.985  0.0006  0.0014  0.000  0.000  0.001  0.003  0.007  0.020  1548    0    0    0    44320788      28631      28631      28631  GET /js/bootstrap.min.js HTTP/1.1
    5   0.945  0.1890  0.0282  0.170  0.173  0.244  0.244  0.244  0.244     5    0    0    0       67635      13391      13527      13713  GET /recent/197 HTTP/1.1
  262   0.917  0.0035  0.0100  0.001  0.002  0.005  0.007  0.011  0.162     0  262    0    0           0          0          0          0  POST /signin HTTP/1.1
    4   0.874  0.2185  0.0702  0.111  0.254  0.301  0.301  0.301  0.301     4    0    0    0       57338      14213      14334      14450  GET /recent/157 HTTP/1.1
    5   0.864  0.1728  0.0533  0.122  0.143  0.239  0.239  0.239  0.239     5    0    0    0       70913      13985      14182      14304  GET /recent/100 HTTP/1.1
 1548   0.838  0.0005  0.0013  0.000  0.000  0.001  0.002  0.006  0.019  1548    0    0    0    26082252      16849      16849      16849  GET /css/bootstrap-responsive.min.css HTTP/1.1
    4   0.837  0.2092  0.0803  0.112  0.288  0.289  0.289  0.289  0.289     4    0    0    0       56512      13955      14128      14340  GET /recent/142 HTTP/1.1
    3   0.791  0.2637  0.0745  0.160  0.299  0.332  0.332  0.332  0.332     3    0    0    0       43584      14288      14528      14650  GET /recent/124 HTTP/1.1
    5   0.775  0.1550  0.0488  0.093  0.131  0.225  0.225  0.225  0.225     5    0    0    0       68996      13616      13799      14210  GET /recent/129 HTTP/1.1

Top 20 Sort By Mean
Count  Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max  2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
    2  0.667  0.3335  0.0645  0.269  0.398  0.398  0.398  0.398  0.398    2    0    0    0       27848      13472      13924      14376  GET /recent/175 HTTP/1.1
    2  0.557  0.2785  0.0255  0.253  0.304  0.304  0.304  0.304  0.304    2    0    0    0       27566      13783      13783      13783  GET /recent/162 HTTP/1.1
    1  0.278  0.2780  0.0000  0.278  0.278  0.278  0.278  0.278  0.278    1    0    0    0       14200      14200      14200      14200  GET /recent/133 HTTP/1.1
    3  0.791  0.2637  0.0745  0.160  0.299  0.332  0.332  0.332  0.332    3    0    0    0       43584      14288      14528      14650  GET /recent/124 HTTP/1.1
    1  0.261  0.2610  0.0000  0.261  0.261  0.261  0.261  0.261  0.261    1    0    0    0       13893      13893      13893      13893  GET /recent/177 HTTP/1.1
    1  0.242  0.2420  0.0000  0.242  0.242  0.242  0.242  0.242  0.242    1    0    0    0       13889      13889      13889      13889  GET /recent/68 HTTP/1.1
    2  0.478  0.2390  0.1560  0.083  0.395  0.395  0.395  0.395  0.395    2    0    0    0       28738      14307      14369      14431  GET /recent/185 HTTP/1.1
    1  0.238  0.2380  0.0000  0.238  0.238  0.238  0.238  0.238  0.238    1    0    0    0       14600      14600      14600      14600  GET /recent/140 HTTP/1.1
    3  0.701  0.2337  0.0571  0.160  0.242  0.299  0.299  0.299  0.299    3    0    0    0       40245      13316      13415      13543  GET /recent/179 HTTP/1.1
   40  9.171  0.2293  0.0697  0.128  0.216  0.355  0.388  0.397  0.397   40    0    0    0      558415      13722      13960      14098  GET /recent/204 HTTP/1.1
    3  0.684  0.2280  0.0128  0.211  0.231  0.242  0.242  0.242  0.242    3    0    0    0       41400      13650      13800      13887  GET /recent/176 HTTP/1.1
    1  0.227  0.2270  0.0000  0.227  0.227  0.227  0.227  0.227  0.227    1    0    0    0       14124      14124      14124      14124  GET /recent/1 HTTP/1.1
    3  0.673  0.2243  0.0491  0.155  0.257  0.261  0.261  0.261  0.261    3    0    0    0       41897      13874      13965      14026  GET /recent/114 HTTP/1.1
    3  0.670  0.2233  0.0718  0.148  0.202  0.320  0.320  0.320  0.320    3    0    0    0       41588      13740      13862      13987  GET /recent/161 HTTP/1.1
    1  0.223  0.2230  0.0000  0.223  0.223  0.223  0.223  0.223  0.223    1    0    0    0       13487      13487      13487      13487  GET /recent/202 HTTP/1.1
    3  0.662  0.2207  0.1295  0.115  0.144  0.403  0.403  0.403  0.403    3    0    0    0       43590      14376      14530      14685  GET /recent/174 HTTP/1.1
    4  0.874  0.2185  0.0702  0.111  0.254  0.301  0.301  0.301  0.301    4    0    0    0       57338      14213      14334      14450  GET /recent/157 HTTP/1.1
    1  0.216  0.2160  0.0000  0.216  0.216  0.216  0.216  0.216  0.216    1    0    0    0     1238659    1238659    1238659    1238659  GET /kataribe.txt HTTP/1.1
    1  0.215  0.2150  0.0000  0.215  0.215  0.215  0.215  0.215  0.215    1    0    0    0       14051      14051      14051      14051  GET /recent/145 HTTP/1.1
    3  0.630  0.2100  0.1477  0.066  0.151  0.413  0.413  0.413  0.413    3    0    0    0       41696      13752      13898      14167  GET /recent/195 HTTP/1.1

Top 20 Sort By Standard Deviation
Count  Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max  2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
    2  0.478  0.2390  0.1560  0.083  0.395  0.395  0.395  0.395  0.395    2    0    0    0       28738      14307      14369      14431  GET /recent/185 HTTP/1.1
    3  0.630  0.2100  0.1477  0.066  0.151  0.413  0.413  0.413  0.413    3    0    0    0       41696      13752      13898      14167  GET /recent/195 HTTP/1.1
    5  1.041  0.2082  0.1384  0.065  0.178  0.465  0.465  0.465  0.465    5    0    0    0       72926      14403      14585      14660  GET /recent/86 HTTP/1.1
    3  0.662  0.2207  0.1295  0.115  0.144  0.403  0.403  0.403  0.403    3    0    0    0       43590      14376      14530      14685  GET /recent/174 HTTP/1.1
    2  0.376  0.1880  0.1180  0.070  0.306  0.306  0.306  0.306  0.306    2    0    0    0       27381      13668      13690      13713  GET /recent/152 HTTP/1.1
    2  0.406  0.2030  0.1130  0.090  0.316  0.316  0.316  0.316  0.316    2    0    0    0       27600      13754      13800      13846  GET /recent/191 HTTP/1.1
    2  0.334  0.1670  0.1110  0.056  0.278  0.278  0.278  0.278  0.278    2    0    0    0       27924      13448      13962      14476  GET /recent/97 HTTP/1.1
    2  0.388  0.1940  0.1000  0.094  0.294  0.294  0.294  0.294  0.294    2    0    0    0       28311      14153      14155      14158  GET /recent/147 HTTP/1.1
    3  0.504  0.1680  0.0974  0.087  0.112  0.305  0.305  0.305  0.305    3    0    0    0       41242      13425      13747      14093  GET /recent/198 HTTP/1.1
    3  0.602  0.2007  0.0960  0.124  0.142  0.336  0.336  0.336  0.336    3    0    0    0       42482      14087      14160      14253  GET /recent/116 HTTP/1.1
    2  0.333  0.1665  0.0895  0.077  0.256  0.256  0.256  0.256  0.256    2    0    0    0       27361      13656      13680      13705  GET /recent/168 HTTP/1.1
    6  1.185  0.1975  0.0880  0.097  0.164  0.319  0.319  0.319  0.319    6    0    0    0       84511      13982      14085      14292  GET /recent/110 HTTP/1.1
    3  0.308  0.1027  0.0837  0.043  0.044  0.221  0.221  0.221  0.221    3    0    0    0       43018      14158      14339      14586  GET /recent/45 HTTP/1.1
    4  0.837  0.2092  0.0803  0.112  0.288  0.289  0.289  0.289  0.289    4    0    0    0       56512      13955      14128      14340  GET /recent/142 HTTP/1.1
    6  1.078  0.1797  0.0755  0.071  0.162  0.303  0.303  0.303  0.303    6    0    0    0       82760      13341      13793      13987  GET /recent/164 HTTP/1.1
    3  0.791  0.2637  0.0745  0.160  0.299  0.332  0.332  0.332  0.332    3    0    0    0       43584      14288      14528      14650  GET /recent/124 HTTP/1.1
    4  0.656  0.1640  0.0739  0.085  0.207  0.263  0.263  0.263  0.263    4    0    0    0       56082      13809      14020      14492  GET /recent/135 HTTP/1.1
    4  0.690  0.1725  0.0735  0.102  0.201  0.280  0.280  0.280  0.280    4    0    0    0       56376      14015      14094      14161  GET /recent/184 HTTP/1.1
    3  0.670  0.2233  0.0718  0.148  0.202  0.320  0.320  0.320  0.320    3    0    0    0       41588      13740      13862      13987  GET /recent/161 HTTP/1.1
    2  0.275  0.1375  0.0715  0.066  0.209  0.209  0.209  0.209  0.209    2    0    0    0       28391      13957      14195      14434  GET /recent/171 HTTP/1.1

Top 20 Sort By Maximum(100 Percentile)
Count  Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max  2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
    5  1.041  0.2082  0.1384  0.065  0.178  0.465  0.465  0.465  0.465    5    0    0    0       72926      14403      14585      14660  GET /recent/86 HTTP/1.1
    3  0.630  0.2100  0.1477  0.066  0.151  0.413  0.413  0.413  0.413    3    0    0    0       41696      13752      13898      14167  GET /recent/195 HTTP/1.1
    3  0.662  0.2207  0.1295  0.115  0.144  0.403  0.403  0.403  0.403    3    0    0    0       43590      14376      14530      14685  GET /recent/174 HTTP/1.1
    2  0.667  0.3335  0.0645  0.269  0.398  0.398  0.398  0.398  0.398    2    0    0    0       27848      13472      13924      14376  GET /recent/175 HTTP/1.1
   40  9.171  0.2293  0.0697  0.128  0.216  0.355  0.388  0.397  0.397   40    0    0    0      558415      13722      13960      14098  GET /recent/204 HTTP/1.1
    2  0.478  0.2390  0.1560  0.083  0.395  0.395  0.395  0.395  0.395    2    0    0    0       28738      14307      14369      14431  GET /recent/185 HTTP/1.1
   41  8.334  0.2033  0.0570  0.086  0.192  0.285  0.295  0.362  0.362   41    0    0    0      561794      13182      13702      13975  GET /recent/205 HTTP/1.1
    3  0.602  0.2007  0.0960  0.124  0.142  0.336  0.336  0.336  0.336    3    0    0    0       42482      14087      14160      14253  GET /recent/116 HTTP/1.1
    3  0.791  0.2637  0.0745  0.160  0.299  0.332  0.332  0.332  0.332    3    0    0    0       43584      14288      14528      14650  GET /recent/124 HTTP/1.1
    3  0.670  0.2233  0.0718  0.148  0.202  0.320  0.320  0.320  0.320    3    0    0    0       41588      13740      13862      13987  GET /recent/161 HTTP/1.1
    6  1.185  0.1975  0.0880  0.097  0.164  0.319  0.319  0.319  0.319    6    0    0    0       84511      13982      14085      14292  GET /recent/110 HTTP/1.1
    2  0.406  0.2030  0.1130  0.090  0.316  0.316  0.316  0.316  0.316    2    0    0    0       27600      13754      13800      13846  GET /recent/191 HTTP/1.1
    2  0.376  0.1880  0.1180  0.070  0.306  0.306  0.306  0.306  0.306    2    0    0    0       27381      13668      13690      13713  GET /recent/152 HTTP/1.1
    3  0.504  0.1680  0.0974  0.087  0.112  0.305  0.305  0.305  0.305    3    0    0    0       41242      13425      13747      14093  GET /recent/198 HTTP/1.1
    2  0.557  0.2785  0.0255  0.253  0.304  0.304  0.304  0.304  0.304    2    0    0    0       27566      13783      13783      13783  GET /recent/162 HTTP/1.1
    6  1.078  0.1797  0.0755  0.071  0.162  0.303  0.303  0.303  0.303    6    0    0    0       82760      13341      13793      13987  GET /recent/164 HTTP/1.1
    4  0.874  0.2185  0.0702  0.111  0.254  0.301  0.301  0.301  0.301    4    0    0    0       57338      14213      14334      14450  GET /recent/157 HTTP/1.1
    3  0.701  0.2337  0.0571  0.160  0.242  0.299  0.299  0.299  0.299    3    0    0    0       40245      13316      13415      13543  GET /recent/179 HTTP/1.1
    2  0.388  0.1940  0.1000  0.094  0.294  0.294  0.294  0.294  0.294    2    0    0    0       28311      14153      14155      14158  GET /recent/147 HTTP/1.1
    4  0.837  0.2092  0.0803  0.112  0.288  0.289  0.289  0.289  0.289    4    0    0    0       56512      13955      14128      14340  GET /recent/142 HTTP/1.1

TOP 37 Slow Requests
 1  0.465  GET /recent/86 HTTP/1.1
 2  0.413  GET /recent/195 HTTP/1.1
 3  0.403  GET /recent/174 HTTP/1.1
 4  0.398  GET /recent/175 HTTP/1.1
 5  0.397  GET /recent/204 HTTP/1.1
 6  0.395  GET /recent/185 HTTP/1.1
 7  0.388  GET /recent/204 HTTP/1.1
 8  0.371  GET /recent/204 HTTP/1.1
 9  0.362  GET /recent/205 HTTP/1.1
10  0.355  GET /recent/204 HTTP/1.1
11  0.336  GET /recent/116 HTTP/1.1
12  0.332  GET /recent/124 HTTP/1.1
13  0.330  GET /recent/205 HTTP/1.1
14  0.329  GET /recent/204 HTTP/1.1
15  0.320  GET /recent/161 HTTP/1.1
16  0.319  GET /recent/110 HTTP/1.1
17  0.318  GET /recent/110 HTTP/1.1
18  0.316  GET /recent/191 HTTP/1.1
19  0.308  GET /recent/204 HTTP/1.1
20  0.306  GET /recent/152 HTTP/1.1
21  0.305  GET /recent/198 HTTP/1.1
22  0.304  GET /recent/162 HTTP/1.1
23  0.303  GET /recent/204 HTTP/1.1
24  0.303  GET /recent/164 HTTP/1.1
25  0.301  GET /recent/157 HTTP/1.1
26  0.299  GET /recent/124 HTTP/1.1
27  0.299  GET /recent/179 HTTP/1.1
28  0.295  GET /recent/205 HTTP/1.1
29  0.294  GET /recent/147 HTTP/1.1
30  0.289  GET /recent/142 HTTP/1.1
31  0.288  GET /recent/205 HTTP/1.1
32  0.288  GET /recent/142 HTTP/1.1
33  0.288  GET /recent/204 HTTP/1.1
34  0.285  GET /recent/205 HTTP/1.1
35  0.284  GET /recent/204 HTTP/1.1
36  0.280  GET /recent/184 HTTP/1.1
37  0.280  GET /recent/204 HTTP/1.1
okashoi commented 4 years ago

エンドポイント単位では recent が重い

okashoi commented 4 years ago
(pprof) list .recentHandler
ROUTINE ======================== main.recentHandler in /opt/isucon3-mod/app/src/app.go                                                                                         
         0      1.65s (flat, cum) 23.17% of Total                                                                                                                              
         .          .    290:   }()                                                                                                                                            
         .          .    291:   user := getUser(w, r, dbConn, session)                                                                                                         
         .          .    292:   vars := mux.Vars(r)                                                                                                                            
         .          .    293:   page, _ := strconv.Atoi(vars["page"])                                                                                                          
         .          .    294:                                                                                                                                                  
         .       20ms    295:   rows, err := dbConn.Query("SELECT count(*) AS c FROM memos WHERE is_private=0")                                                                
         .          .    296:   if err != nil {                                                                                                                                
         .          .    297:           serverError(w, err)                                                                                                                    
         .          .    298:           return                                                                                                                                 
         .          .    299:   }                                                                                                                                              
         .          .    300:   var totalCount int                                                                                                                             
         .          .    301:   if rows.Next() {                                                                                                                               
         .          .    302:           rows.Scan(&totalCount)                                                                                                                 
         .          .    303:   }                                                                                                                                              
         .          .    304:   rows.Close()                                                                                                                                   
         .          .    305:                                                                                                                                                  
         .       20ms    306:   rows, err = dbConn.Query("SELECT * FROM memos WHERE is_private=0 ORDER BY created_at DESC, id DESC LIMIT ? OFFSET ?", memosPerPage, memosPerPag
e*page)                                                                                                                                                                        
         .          .    307:   if err != nil {                                                                                                                                
         .          .    308:           serverError(w, err)                                                                                                                    
         .          .    309:           return
         .          .    310:   }
         .          .    311:   memos := make(Memos, 0)
         .       20ms    312:   stmtUser, err := dbConn.Prepare("SELECT username FROM users WHERE id=?")
         .          .    313:   defer stmtUser.Close()
         .          .    314:   if err != nil {
         .          .    315:           serverError(w, err)
         .          .    316:           return
         .          .    317:   }
         .       90ms    318:   for rows.Next() {
         .          .    319:           memo := Memo{}
         .       60ms    320:           rows.Scan(&memo.Id, &memo.User, &memo.Content, &memo.IsPrivate, &memo.CreatedAt, &memo.UpdatedAt)
         .      790ms    321:           stmtUser.QueryRow(memo.User).Scan(&memo.Username)
         .       10ms    322:           memos = append(memos, &memo)
         .          .    323:   }
         .          .    324:   if len(memos) == 0 {
         .          .    325:           notFound(w)
         .          .    326:           return
         .          .    327:   }
         .          .    328:
         .          .    329:   v := &View{
         .          .    330:           Total:     totalCount,
         .          .    331:           Page:      page,
         .          .    332:           PageStart: memosPerPage*page + 1,
         .          .    333:           PageEnd:   memosPerPage * (page + 1),
         .          .    334:           Memos:     &memos,
         .          .    335:           User:      user,
         .          .    336:           Session:   session,
         .          .    337:   }
         .      620ms    338:   if err = tmpl.ExecuteTemplate(w, "index", v); err != nil {
         .          .    339:           serverError(w, err)
         .          .    340:   }
         .       20ms    341:}
         .          .    342:
         .          .    343:func signinHandler(w http.ResponseWriter, r *http.Request) {
         .          .    344:   session, err := loadSession(w, r)
         .          .    345:   if err != nil {
         .          .    346:           serverError(w, err)
yamachu commented 4 years ago
[isucon@ip-172-31-23-17 isucon3-mod]$ make bench
sudo /opt/isucon3-mod/bench/bench benchmark --workload 1 --init ./init.sh
2020/07/18 08:55:18 <<<DEBUG build>>>
2020/07/18 08:55:18 benchmark mode
2020/07/18 08:55:18 initialize data...
2020/07/18 08:55:24 run ./init.sh timeout 60 sec...
2020/07/18 08:55:24 done
2020/07/18 08:55:24 sleeping 5 sec...
2020/07/18 08:55:29 run benchmark workload: 1
2020/07/18 08:56:30 done benchmark
Result:   SUCCESS
RawScore: 4777.9
Fails:    0
Score:    4777.9
[isucon@ip-172-31-23-17 isucon3-mod]$
[isucon@ip-172-31-23-17 isucon3-mod]$ sudo mysqldumpslow /var/lib/mysql/mysql-slow.log

Reading mysql slow query log from /var/lib/mysql/mysql-slow.log
Count: 337  Time=0.12s (41s)  Lock=0.00s (0s)  Rows=100.0 (33700), isucon[isucon]@localhost
  SELECT * FROM memos WHERE is_private=N ORDER BY created_at DESC, id DESC LIMIT N OFFSET N

Count: 112  Time=0.08s (8s)  Lock=0.00s (0s)  Rows=100.0 (11200), isucon[isucon]@localhost
  SELECT * FROM memos WHERE is_private=N ORDER BY created_at DESC, id DESC LIMIT N

Count: 42  Time=0.07s (2s)  Lock=0.00s (0s)  Rows=51.7 (2170), isucon[isucon]@localhost
  SELECT id, content, is_private, created_at, updated_at FROM memos WHERE user=N AND is_private=N ORDER BY created_at

Count: 40  Time=0.06s (2s)  Lock=0.00s (0s)  Rows=111.2 (4446), isucon[isucon]@localhost
  SELECT id, content, is_private, created_at, updated_at FROM memos WHERE user=N ORDER BY created_at DESC

Count: 235  Time=0.06s (14s)  Lock=0.00s (0s)  Rows=111.5 (26208), isucon[isucon]@localhost
  SELECT id, content, is_private, created_at, updated_at FROM memos WHERE user=N  ORDER BY created_at

Count: 1202  Time=0.03s (40s)  Lock=0.00s (0s)  Rows=1.0 (1202), isucon[isucon]@localhost
  SELECT count(*) AS c FROM memos WHERE is_private=N

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), 0users@0hosts

Flame Graph

http://18.183.182.156/torch-20200718085526.svg

Kataribe

[isucon@ip-172-31-23-17 isucon3-mod]$ sudo cat /var/log/nginx/access.log | kataribe
Top 20 Sort By Count
Count   Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max   2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
 1862  23.376  0.0126  0.0245  0.000  0.003  0.046  0.072  0.116  0.160  1727    0  135    0     7911571         10       4248      58971  get memo
 1550   1.006  0.0006  0.0013  0.000  0.000  0.001  0.002  0.006  0.017  1550    0    0    0   144315850      93107      93107      93107  GET /js/jquery.min.js HTTP/1.1
 1550   0.814  0.0005  0.0011  0.000  0.000  0.001  0.002  0.005  0.012  1550    0    0    0    26115950      16849      16849      16849  GET /css/bootstrap-responsive.min.css HTTP/1.1
 1550   0.907  0.0006  0.0015  0.000  0.000  0.001  0.002  0.006  0.037  1550    0    0    0    44378050      28631      28631      28631  GET /js/bootstrap.min.js HTTP/1.1
 1550   1.007  0.0006  0.0013  0.000  0.000  0.001  0.002  0.006  0.019  1550    0    0    0   164323250     106015     106015     106015  GET /css/bootstrap.min.css HTTP/1.1
  651  51.691  0.0794  0.0474  0.026  0.064  0.150  0.189  0.247  0.268   651    0    0    0     9474095      13492      14553      15290  GET / HTTP/1.1
  262   4.606  0.0176  0.0258  0.001  0.008  0.056  0.080  0.120  0.129   262    0    0    0     3872645       2029      14781      28493  GET /mypage HTTP/1.1
  262   0.788  0.0030  0.0023  0.001  0.002  0.005  0.008  0.012  0.015     0  262    0    0           0          0          0          0  POST /memo HTTP/1.1
  262   0.172  0.0007  0.0014  0.000  0.000  0.001  0.001  0.008  0.016     0  262    0    0           0          0          0          0  POST /signout HTTP/1.1
  262   0.121  0.0005  0.0013  0.000  0.000  0.001  0.001  0.006  0.017   262    0    0    0      349508       1334       1334       1334  GET /signin HTTP/1.1
  262   1.057  0.0040  0.0104  0.001  0.002  0.005  0.008  0.080  0.116     0  262    0    0           0          0          0          0  POST /signin HTTP/1.1
   43   9.369  0.2179  0.0874  0.102  0.180  0.359  0.401  0.428  0.428    43    0    0    0      599323      13532      13937      14099  GET /recent/204 HTTP/1.1
   42   7.928  0.1888  0.0625  0.075  0.182  0.290  0.320  0.344  0.344    42    0    0    0      577479      13326      13749      13975  GET /recent/205 HTTP/1.1
    8   0.767  0.0959  0.0675  0.037  0.081  0.223  0.223  0.223  0.223     8    0    0    0      110607      13704      13825      14106  GET /recent/31 HTTP/1.1
    7   0.962  0.1374  0.0433  0.101  0.107  0.217  0.217  0.217  0.217     7    0    0    0       97456      13775      13922      14285  GET /recent/123 HTTP/1.1
    7   0.889  0.1270  0.0589  0.047  0.099  0.231  0.231  0.231  0.231     7    0    0    0       97478      13585      13925      14348  GET /recent/41 HTTP/1.1
    6   0.799  0.1332  0.0561  0.055  0.169  0.205  0.205  0.205  0.205     6    0    0    0       87065      14476      14510      14565  GET /recent/80 HTTP/1.1
    6   0.907  0.1512  0.0700  0.070  0.144  0.280  0.280  0.280  0.280     6    0    0    0       86399      13883      14399      14796  GET /recent/109 HTTP/1.1
    6   1.050  0.1750  0.1018  0.068  0.169  0.387  0.387  0.387  0.387     6    0    0    0       81767      13363      13627      13825  GET /recent/165 HTTP/1.1
    6   0.535  0.0892  0.0208  0.050  0.100  0.115  0.115  0.115  0.115     6    0    0    0       85025      14031      14170      14360  GET /recent/34 HTTP/1.1

Top 20 Sort By Total
Count   Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max   2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
  651  51.691  0.0794  0.0474  0.026  0.064  0.150  0.189  0.247  0.268   651    0    0    0     9474095      13492      14553      15290  GET / HTTP/1.1
 1862  23.376  0.0126  0.0245  0.000  0.003  0.046  0.072  0.116  0.160  1727    0  135    0     7911571         10       4248      58971  get memo
   43   9.369  0.2179  0.0874  0.102  0.180  0.359  0.401  0.428  0.428    43    0    0    0      599323      13532      13937      14099  GET /recent/204 HTTP/1.1
   42   7.928  0.1888  0.0625  0.075  0.182  0.290  0.320  0.344  0.344    42    0    0    0      577479      13326      13749      13975  GET /recent/205 HTTP/1.1
  262   4.606  0.0176  0.0258  0.001  0.008  0.056  0.080  0.120  0.129   262    0    0    0     3872645       2029      14781      28493  GET /mypage HTTP/1.1
  262   1.057  0.0040  0.0104  0.001  0.002  0.005  0.008  0.080  0.116     0  262    0    0           0          0          0          0  POST /signin HTTP/1.1
    6   1.050  0.1750  0.1018  0.068  0.169  0.387  0.387  0.387  0.387     6    0    0    0       81767      13363      13627      13825  GET /recent/165 HTTP/1.1
 1550   1.007  0.0006  0.0013  0.000  0.000  0.001  0.002  0.006  0.019  1550    0    0    0   164323250     106015     106015     106015  GET /css/bootstrap.min.css HTTP/1.1
 1550   1.006  0.0006  0.0013  0.000  0.000  0.001  0.002  0.006  0.017  1550    0    0    0   144315850      93107      93107      93107  GET /js/jquery.min.js HTTP/1.1
    7   0.962  0.1374  0.0433  0.101  0.107  0.217  0.217  0.217  0.217     7    0    0    0       97456      13775      13922      14285  GET /recent/123 HTTP/1.1
    5   0.924  0.1848  0.0474  0.113  0.175  0.238  0.238  0.238  0.238     5    0    0    0       70093      13853      14018      14223  GET /recent/111 HTTP/1.1
 1550   0.907  0.0006  0.0015  0.000  0.000  0.001  0.002  0.006  0.037  1550    0    0    0    44378050      28631      28631      28631  GET /js/bootstrap.min.js HTTP/1.1
    6   0.907  0.1512  0.0700  0.070  0.144  0.280  0.280  0.280  0.280     6    0    0    0       86399      13883      14399      14796  GET /recent/109 HTTP/1.1
    6   0.906  0.1510  0.0726  0.075  0.163  0.252  0.252  0.252  0.252     6    0    0    0       84136      13704      14022      14415  GET /recent/82 HTTP/1.1
    5   0.903  0.1806  0.0347  0.153  0.166  0.249  0.249  0.249  0.249     5    0    0    0       69273      13660      13854      14035  GET /recent/176 HTTP/1.1
    7   0.889  0.1270  0.0589  0.047  0.099  0.231  0.231  0.231  0.231     7    0    0    0       97478      13585      13925      14348  GET /recent/41 HTTP/1.1
    5   0.860  0.1720  0.0450  0.104  0.166  0.243  0.243  0.243  0.243     5    0    0    0       70054      13951      14010      14067  GET /recent/136 HTTP/1.1
    5   0.848  0.1696  0.0839  0.092  0.145  0.328  0.328  0.328  0.328     5    0    0    0       68740      13610      13748      13872  GET /recent/102 HTTP/1.1
 1550   0.814  0.0005  0.0011  0.000  0.000  0.001  0.002  0.005  0.012  1550    0    0    0    26115950      16849      16849      16849  GET /css/bootstrap-responsive.min.css HTTP/1.1
    6   0.799  0.1332  0.0561  0.055  0.169  0.205  0.205  0.205  0.205     6    0    0    0       87065      14476      14510      14565  GET /recent/80 HTTP/1.1

Top 20 Sort By Mean
Count  Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max  2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
    1  0.332  0.3320  0.0000  0.332  0.332  0.332  0.332  0.332  0.332    1    0    0    0       13831      13831      13831      13831  GET /recent/183 HTTP/1.1
    2  0.580  0.2900  0.0860  0.204  0.376  0.376  0.376  0.376  0.376    2    0    0    0       28247      13978      14123      14269  GET /recent/187 HTTP/1.1
    1  0.284  0.2840  0.0000  0.284  0.284  0.284  0.284  0.284  0.284    1    0    0    0       13513      13513      13513      13513  GET /recent/54 HTTP/1.1
    1  0.251  0.2510  0.0000  0.251  0.251  0.251  0.251  0.251  0.251    1    0    0    0       14334      14334      14334      14334  GET /recent/178 HTTP/1.1
    2  0.492  0.2460  0.1040  0.142  0.350  0.350  0.350  0.350  0.350    2    0    0    0       28067      13955      14033      14112  GET /recent/174 HTTP/1.1
    3  0.710  0.2367  0.0731  0.153  0.226  0.331  0.331  0.331  0.331    3    0    0    0       43059      14281      14353      14432  GET /recent/185 HTTP/1.1
    1  0.233  0.2330  0.0000  0.233  0.233  0.233  0.233  0.233  0.233    1    0    0    0       14112      14112      14112      14112  GET /recent/164 HTTP/1.1
    3  0.678  0.2260  0.0675  0.138  0.238  0.302  0.302  0.302  0.302    3    0    0    0       42133      13900      14044      14173  GET /recent/151 HTTP/1.1
    1  0.224  0.2240  0.0000  0.224  0.224  0.224  0.224  0.224  0.224    1    0    0    0       13795      13795      13795      13795  GET /recent/182 HTTP/1.1
    2  0.441  0.2205  0.0345  0.186  0.255  0.255  0.255  0.255  0.255    2    0    0    0       27199      13350      13599      13849  GET /recent/179 HTTP/1.1
   43  9.369  0.2179  0.0874  0.102  0.180  0.359  0.401  0.428  0.428   43    0    0    0      599323      13532      13937      14099  GET /recent/204 HTTP/1.1
    3  0.641  0.2137  0.0751  0.123  0.211  0.307  0.307  0.307  0.307    3    0    0    0       41426      13342      13808      14103  GET /recent/172 HTTP/1.1
    1  0.211  0.2110  0.0000  0.211  0.211  0.211  0.211  0.211  0.211    1    0    0    0       14628      14628      14628      14628  GET /recent/87 HTTP/1.1
    1  0.205  0.2050  0.0000  0.205  0.205  0.205  0.205  0.205  0.205    1    0    0    0       13576      13576      13576      13576  GET /recent/202 HTTP/1.1
    1  0.204  0.2040  0.0000  0.204  0.204  0.204  0.204  0.204  0.204    1    0    0    0       14028      14028      14028      14028  GET /recent/195 HTTP/1.1
    2  0.407  0.2035  0.0705  0.133  0.274  0.274  0.274  0.274  0.274    2    0    0    0       28047      14019      14023      14028  GET /recent/125 HTTP/1.1
    2  0.394  0.1970  0.0580  0.139  0.255  0.255  0.255  0.255  0.255    2    0    0    0       26916      13439      13458      13477  GET /recent/166 HTTP/1.1
    2  0.390  0.1950  0.0830  0.112  0.278  0.278  0.278  0.278  0.278    2    0    0    0       28833      14100      14416      14733  GET /recent/138 HTTP/1.1
    3  0.583  0.1943  0.0565  0.119  0.209  0.255  0.255  0.255  0.255    3    0    0    0       42799      14162      14266      14460  GET /recent/113 HTTP/1.1
    3  0.579  0.1930  0.0854  0.091  0.188  0.300  0.300  0.300  0.300    3    0    0    0       41531      13486      13843      14357  GET /recent/189 HTTP/1.1

Top 20 Sort By Standard Deviation
Count  Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max  2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
    3  0.536  0.1787  0.1187  0.076  0.115  0.345  0.345  0.345  0.345    3    0    0    0       41642      13803      13880      13962  GET /recent/162 HTTP/1.1
    3  0.531  0.1770  0.1063  0.076  0.131  0.324  0.324  0.324  0.324    3    0    0    0       43952      14472      14650      14763  GET /recent/108 HTTP/1.1
    2  0.492  0.2460  0.1040  0.142  0.350  0.350  0.350  0.350  0.350    2    0    0    0       28067      13955      14033      14112  GET /recent/174 HTTP/1.1
    6  1.050  0.1750  0.1018  0.068  0.169  0.387  0.387  0.387  0.387    6    0    0    0       81767      13363      13627      13825  GET /recent/165 HTTP/1.1
    2  0.265  0.1325  0.1015  0.031  0.234  0.234  0.234  0.234  0.234    2    0    0    0       27514      13691      13757      13823  GET /recent/8 HTTP/1.1
    2  0.306  0.1530  0.0880  0.065  0.241  0.241  0.241  0.241  0.241    2    0    0    0       27714      13686      13857      14028  GET /recent/161 HTTP/1.1
   43  9.369  0.2179  0.0874  0.102  0.180  0.359  0.401  0.428  0.428   43    0    0    0      599323      13532      13937      14099  GET /recent/204 HTTP/1.1
    3  0.374  0.1247  0.0865  0.060  0.067  0.247  0.247  0.247  0.247    3    0    0    0       42464      14015      14154      14360  GET /recent/145 HTTP/1.1
    2  0.580  0.2900  0.0860  0.204  0.376  0.376  0.376  0.376  0.376    2    0    0    0       28247      13978      14123      14269  GET /recent/187 HTTP/1.1
    3  0.579  0.1930  0.0854  0.091  0.188  0.300  0.300  0.300  0.300    3    0    0    0       41531      13486      13843      14357  GET /recent/189 HTTP/1.1
    5  0.848  0.1696  0.0839  0.092  0.145  0.328  0.328  0.328  0.328    5    0    0    0       68740      13610      13748      13872  GET /recent/102 HTTP/1.1
    2  0.390  0.1950  0.0830  0.112  0.278  0.278  0.278  0.278  0.278    2    0    0    0       28833      14100      14416      14733  GET /recent/138 HTTP/1.1
    3  0.514  0.1713  0.0814  0.086  0.147  0.281  0.281  0.281  0.281    3    0    0    0       40497      13446      13499      13558  GET /recent/66 HTTP/1.1
    3  0.429  0.1430  0.0813  0.053  0.126  0.250  0.250  0.250  0.250    3    0    0    0       41649      13744      13883      14154  GET /recent/57 HTTP/1.1
    2  0.380  0.1900  0.0760  0.114  0.266  0.266  0.266  0.266  0.266    2    0    0    0       27919      13793      13959      14126  GET /recent/163 HTTP/1.1
    3  0.535  0.1783  0.0758  0.098  0.157  0.280  0.280  0.280  0.280    3    0    0    0       42314      13876      14104      14223  GET /recent/142 HTTP/1.1
    3  0.641  0.2137  0.0751  0.123  0.211  0.307  0.307  0.307  0.307    3    0    0    0       41426      13342      13808      14103  GET /recent/172 HTTP/1.1
    3  0.710  0.2367  0.0731  0.153  0.226  0.331  0.331  0.331  0.331    3    0    0    0       43059      14281      14353      14432  GET /recent/185 HTTP/1.1
    6  0.906  0.1510  0.0726  0.075  0.163  0.252  0.252  0.252  0.252    6    0    0    0       84136      13704      14022      14415  GET /recent/82 HTTP/1.1
    2  0.407  0.2035  0.0705  0.133  0.274  0.274  0.274  0.274  0.274    2    0    0    0       28047      14019      14023      14028  GET /recent/125 HTTP/1.1

Top 20 Sort By Maximum(100 Percentile)
Count   Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max  2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
   43   9.369  0.2179  0.0874  0.102  0.180  0.359  0.401  0.428  0.428   43    0    0    0      599323      13532      13937      14099  GET /recent/204 HTTP/1.1
    6   1.050  0.1750  0.1018  0.068  0.169  0.387  0.387  0.387  0.387    6    0    0    0       81767      13363      13627      13825  GET /recent/165 HTTP/1.1
    2   0.580  0.2900  0.0860  0.204  0.376  0.376  0.376  0.376  0.376    2    0    0    0       28247      13978      14123      14269  GET /recent/187 HTTP/1.1
    2   0.492  0.2460  0.1040  0.142  0.350  0.350  0.350  0.350  0.350    2    0    0    0       28067      13955      14033      14112  GET /recent/174 HTTP/1.1
    3   0.536  0.1787  0.1187  0.076  0.115  0.345  0.345  0.345  0.345    3    0    0    0       41642      13803      13880      13962  GET /recent/162 HTTP/1.1
   42   7.928  0.1888  0.0625  0.075  0.182  0.290  0.320  0.344  0.344   42    0    0    0      577479      13326      13749      13975  GET /recent/205 HTTP/1.1
    1   0.332  0.3320  0.0000  0.332  0.332  0.332  0.332  0.332  0.332    1    0    0    0       13831      13831      13831      13831  GET /recent/183 HTTP/1.1
    3   0.710  0.2367  0.0731  0.153  0.226  0.331  0.331  0.331  0.331    3    0    0    0       43059      14281      14353      14432  GET /recent/185 HTTP/1.1
    5   0.848  0.1696  0.0839  0.092  0.145  0.328  0.328  0.328  0.328    5    0    0    0       68740      13610      13748      13872  GET /recent/102 HTTP/1.1
    3   0.531  0.1770  0.1063  0.076  0.131  0.324  0.324  0.324  0.324    3    0    0    0       43952      14472      14650      14763  GET /recent/108 HTTP/1.1
    3   0.641  0.2137  0.0751  0.123  0.211  0.307  0.307  0.307  0.307    3    0    0    0       41426      13342      13808      14103  GET /recent/172 HTTP/1.1
    3   0.678  0.2260  0.0675  0.138  0.238  0.302  0.302  0.302  0.302    3    0    0    0       42133      13900      14044      14173  GET /recent/151 HTTP/1.1
    3   0.579  0.1930  0.0854  0.091  0.188  0.300  0.300  0.300  0.300    3    0    0    0       41531      13486      13843      14357  GET /recent/189 HTTP/1.1
    1   0.284  0.2840  0.0000  0.284  0.284  0.284  0.284  0.284  0.284    1    0    0    0       13513      13513      13513      13513  GET /recent/54 HTTP/1.1
    3   0.514  0.1713  0.0814  0.086  0.147  0.281  0.281  0.281  0.281    3    0    0    0       40497      13446      13499      13558  GET /recent/66 HTTP/1.1
    6   0.907  0.1512  0.0700  0.070  0.144  0.280  0.280  0.280  0.280    6    0    0    0       86399      13883      14399      14796  GET /recent/109 HTTP/1.1
    3   0.535  0.1783  0.0758  0.098  0.157  0.280  0.280  0.280  0.280    3    0    0    0       42314      13876      14104      14223  GET /recent/142 HTTP/1.1
    2   0.390  0.1950  0.0830  0.112  0.278  0.278  0.278  0.278  0.278    2    0    0    0       28833      14100      14416      14733  GET /recent/138 HTTP/1.1
    2   0.407  0.2035  0.0705  0.133  0.274  0.274  0.274  0.274  0.274    2    0    0    0       28047      14019      14023      14028  GET /recent/125 HTTP/1.1
  651  51.691  0.0794  0.0474  0.026  0.064  0.150  0.189  0.247  0.268  651    0    0    0     9474095      13492      14553      15290  GET / HTTP/1.1

TOP 37 Slow Requests
 1  0.428  GET /recent/204 HTTP/1.1
 2  0.408  GET /recent/204 HTTP/1.1
 3  0.401  GET /recent/204 HTTP/1.1
 4  0.387  GET /recent/165 HTTP/1.1
 5  0.382  GET /recent/204 HTTP/1.1
 6  0.376  GET /recent/187 HTTP/1.1
 7  0.359  GET /recent/204 HTTP/1.1
 8  0.350  GET /recent/174 HTTP/1.1
 9  0.345  GET /recent/162 HTTP/1.1
10  0.344  GET /recent/205 HTTP/1.1
11  0.341  GET /recent/205 HTTP/1.1
12  0.332  GET /recent/183 HTTP/1.1
13  0.331  GET /recent/185 HTTP/1.1
14  0.328  GET /recent/102 HTTP/1.1
15  0.325  GET /recent/204 HTTP/1.1
16  0.324  GET /recent/108 HTTP/1.1
17  0.320  GET /recent/205 HTTP/1.1
18  0.310  GET /recent/204 HTTP/1.1
19  0.307  GET /recent/172 HTTP/1.1
20  0.307  GET /recent/205 HTTP/1.1
21  0.302  GET /recent/151 HTTP/1.1
22  0.300  GET /recent/189 HTTP/1.1
23  0.290  GET /recent/204 HTTP/1.1
24  0.290  GET /recent/205 HTTP/1.1
25  0.288  GET /recent/205 HTTP/1.1
26  0.287  GET /recent/204 HTTP/1.1
27  0.284  GET /recent/54 HTTP/1.1
28  0.281  GET /recent/66 HTTP/1.1
29  0.280  GET /recent/109 HTTP/1.1
30  0.280  GET /recent/142 HTTP/1.1
31  0.278  GET /recent/138 HTTP/1.1
32  0.276  GET /recent/204 HTTP/1.1
33  0.274  GET /recent/125 HTTP/1.1
34  0.272  GET /recent/204 HTTP/1.1
35  0.268  GET / HTTP/1.1
36  0.266  GET /recent/163 HTTP/1.1
37  0.265  GET /recent/204 HTTP/1.1
(pprof) list .memoHandler
Total: 6.92s
ROUTINE ======================== main.memoHandler in /opt/isucon3-mod/app/src/app.go
      10ms      730ms (flat, cum) 10.55% of Total
         .          .    494:       serverError(w, err)
         .          .    495:   }
         .          .    496:}
         .          .    497:
         .          .    498:func memoHandler(w http.ResponseWriter, r *http.Request) {
         .       80ms    499:   session, err := loadSession(w, r)
         .          .    500:   if err != nil {
         .          .    501:       serverError(w, err)
         .          .    502:       return
         .          .    503:   }
         .          .    504:   prepareHandler(w, r)
         .          .    505:   vars := mux.Vars(r)
         .          .    506:   memoId := vars["memo_id"]
         .          .    507:   dbConn := <-dbConnPool
         .          .    508:   defer func() {
         .          .    509:       dbConnPool <- dbConn
         .          .    510:   }()
         .       30ms    511:   user := getUser(w, r, dbConn, session)
         .          .    512:
         .       20ms    513:   rows, err := dbConn.Query("SELECT id, user, content, is_private, created_at, updated_at FROM memos WHERE id=?", memoId)
         .          .    514:   if err != nil {
         .          .    515:       serverError(w, err)
         .          .    516:       return
         .          .    517:   }
         .          .    518:   memo := &Memo{}
         .          .    519:   if rows.Next() {
         .          .    520:       rows.Scan(&memo.Id, &memo.User, &memo.Content, &memo.IsPrivate, &memo.CreatedAt, &memo.UpdatedAt)
         .          .    521:       rows.Close()
         .          .    522:   } else {
         .          .    523:       notFound(w)
         .          .    524:       return
         .          .    525:   }
         .          .    526:   if memo.IsPrivate == 1 {
         .          .    527:       if user == nil || user.Id != memo.User {
         .          .    528:           notFound(w)
         .          .    529:           return
         .          .    530:       }
         .          .    531:   }
         .       40ms    532:   rows, err = dbConn.Query("SELECT username FROM users WHERE id=?", memo.User)
         .          .    533:   if err != nil {
         .          .    534:       serverError(w, err)
         .          .    535:       return
         .          .    536:   }
         .          .    537:   if rows.Next() {
         .          .    538:       rows.Scan(&memo.Username)
         .       20ms    539:       rows.Close()
         .          .    540:   }
         .          .    541:
         .          .    542:   var cond string
         .          .    543:   if user != nil && user.Id == memo.User {
         .          .    544:       cond = ""
         .          .    545:   } else {
         .          .    546:       cond = "AND is_private=0"
         .          .    547:   }
         .       50ms    548:   rows, err = dbConn.Query("SELECT id, content, is_private, created_at, updated_at FROM memos WHERE user=? "+cond+" ORDER BY created_at", memo.User)
         .          .    549:   if err != nil {
         .          .    550:       serverError(w, err)
         .          .    551:       return
         .          .    552:   }
         .          .    553:   memos := make(Memos, 0)
         .      120ms    554:   for rows.Next() {
         .       10ms    555:       m := Memo{}
      10ms      100ms    556:       rows.Scan(&m.Id, &m.Content, &m.IsPrivate, &m.CreatedAt, &m.UpdatedAt)
         .          .    557:       memos = append(memos, &m)
         .          .    558:   }
         .          .    559:   rows.Close()
         .          .    560:   var older *Memo
         .          .    561:   var newer *Memo
         .          .    562:   for i, m := range memos {
         .          .    563:       if m.Id == memo.Id {
         .          .    564:           if i > 0 {
         .          .    565:               older = memos[i-1]
         .          .    566:           }
         .          .    567:           if i < len(memos)-1 {
         .          .    568:               newer = memos[i+1]
         .          .    569:           }
         .          .    570:       }
         .          .    571:   }
         .          .    572:
         .          .    573:   v := &View{
         .          .    574:       User:     user,
         .          .    575:       Memo:     memo,
         .          .    576:       Older:    older,
         .          .    577:       Newer:    newer,
         .          .    578:       Session:  session,
         .          .    579:       Url_for:  _Url_for(),
         .          .    580:       My_token: _My_token(session),
         .      130ms    581:       Markdown: _gen_markdown(memo.Content),
         .          .    582:   }
         .      130ms    583:   if err = tmpl.ExecuteTemplate(w, "memo", v); err != nil {
         .          .    584:       serverError(w, err)
         .          .    585:   }
         .          .    586:}
         .          .    587:
         .          .    588:func memoPostHandler(w http.ResponseWriter, r *http.Request) {
(pprof) list .topHandler
Total: 6.92s
ROUTINE ======================== main.topHandler in /opt/isucon3-mod/app/src/app.go
         0      1.60s (flat, cum) 23.12% of Total
         .          .    253:       return
         .          .    254:   }
         .          .    255:   if rows.Next() {
         .          .    256:       rows.Scan(&totalCount)
         .          .    257:   }
         .       10ms    258:   rows.Close()
         .          .    259:
         .       20ms    260:   rows, err = dbConn.Query("SELECT * FROM memos WHERE is_private=0 ORDER BY created_at DESC, id DESC LIMIT ?", memosPerPage)
         .          .    261:   if err != nil {
         .          .    262:       serverError(w, err)
         .          .    263:       return
         .          .    264:   }
         .          .    265:   memos := make(Memos, 0)
         .       10ms    266:   stmtUser, err := dbConn.Prepare("SELECT username FROM users WHERE id=?")
         .          .    267:   defer stmtUser.Close()
         .          .    268:   if err != nil {
         .          .    269:       serverError(w, err)
         .          .    270:       return
         .          .    271:   }
         .       70ms    272:   for rows.Next() {
         .          .    273:       memo := Memo{}
         .       50ms    274:       rows.Scan(&memo.Id, &memo.User, &memo.Content, &memo.IsPrivate, &memo.CreatedAt, &memo.UpdatedAt)
         .      750ms    275:       stmtUser.QueryRow(memo.User).Scan(&memo.Username)
         .       10ms    276:       memos = append(memos, &memo)
         .          .    277:   }
         .          .    278:   rows.Close()
         .          .    279:
         .          .    280:   v := &View{
         .          .    281:       Total:             totalCount,
         .          .    282:       Page:              0,
         .          .    283:       PageStart:         1,
         .          .    284:       PageEnd:           memosPerPage,
         .          .    285:       Memos:             &memos,
         .          .    286:       User:              user,
         .          .    287:       Session:           session,
         .          .    288:       Url_for:           _Url_for(),
         .          .    289:       My_token:          _My_token(session),
         .       20ms    290:       Memos_first_lines: _to_first_line(&memos),
         .          .    291:   }
         .      650ms    292:   if err = tmpl.ExecuteTemplate(w, "index", v); err != nil {
         .          .    293:       serverError(w, err)
         .          .    294:   }
         .       10ms    295:}
         .          .    296:
         .          .    297:func recentHandler(w http.ResponseWriter, r *http.Request) {
         .          .    298:   session, err := loadSession(w, r)
         .          .    299:   if err != nil {
         .          .    300:       serverError(w, err)
(pprof)
(pprof) list .recentHandler
Total: 6.92s
ROUTINE ======================== main.recentHandler in /opt/isucon3-mod/app/src/app.go
      10ms      1.59s (flat, cum) 22.98% of Total
         .          .    293:       serverError(w, err)
         .          .    294:   }
         .          .    295:}
         .          .    296:
         .          .    297:func recentHandler(w http.ResponseWriter, r *http.Request) {
         .       10ms    298:   session, err := loadSession(w, r)
         .          .    299:   if err != nil {
         .          .    300:       serverError(w, err)
         .          .    301:       return
         .          .    302:   }
         .          .    303:   prepareHandler(w, r)
         .          .    304:   dbConn := <-dbConnPool
         .          .    305:   defer func() {
         .          .    306:       dbConnPool <- dbConn
         .          .    307:   }()
         .          .    308:   user := getUser(w, r, dbConn, session)
         .          .    309:   vars := mux.Vars(r)
         .          .    310:   page, _ := strconv.Atoi(vars["page"])
         .          .    311:
         .       10ms    312:   rows, err := dbConn.Query("SELECT count(*) AS c FROM memos WHERE is_private=0")
         .          .    313:   if err != nil {
         .          .    314:       serverError(w, err)
         .          .    315:       return
         .          .    316:   }
         .          .    317:   var totalCount int
         .          .    318:   if rows.Next() {
         .          .    319:       rows.Scan(&totalCount)
         .          .    320:   }
         .          .    321:   rows.Close()
         .          .    322:
         .       30ms    323:   rows, err = dbConn.Query("SELECT * FROM memos WHERE is_private=0 ORDER BY created_at DESC, id DESC LIMIT ? OFFSET ?", memosPerPage, memosPerPage*page)
         .          .    324:   if err != nil {
         .          .    325:       serverError(w, err)
         .          .    326:       return
         .          .    327:   }
         .          .    328:   memos := make(Memos, 0)
         .          .    329:   stmtUser, err := dbConn.Prepare("SELECT username FROM users WHERE id=?")
         .          .    330:   defer stmtUser.Close()
         .          .    331:   if err != nil {
         .          .    332:       serverError(w, err)
         .          .    333:       return
         .          .    334:   }
         .       40ms    335:   for rows.Next() {
         .       10ms    336:       memo := Memo{}
         .       90ms    337:       rows.Scan(&memo.Id, &memo.User, &memo.Content, &memo.IsPrivate, &memo.CreatedAt, &memo.UpdatedAt)
         .      750ms    338:       stmtUser.QueryRow(memo.User).Scan(&memo.Username)
      10ms       10ms    339:       memos = append(memos, &memo)
         .          .    340:   }
         .          .    341:   if len(memos) == 0 {
         .          .    342:       notFound(w)
         .          .    343:       return
         .          .    344:   }
         .          .    345:
         .          .    346:   v := &View{
         .          .    347:       Total:             totalCount,
         .          .    348:       Page:              page,
         .          .    349:       PageStart:         memosPerPage*page + 1,
         .          .    350:       PageEnd:           memosPerPage * (page + 1),
         .          .    351:       Memos:             &memos,
         .          .    352:       User:              user,
         .          .    353:       Session:           session,
         .          .    354:       Url_for:           _Url_for(),
         .          .    355:       My_token:          _My_token(session),
         .      110ms    356:       Memos_first_lines: _to_first_line(&memos),
         .          .    357:   }
         .      530ms    358:   if err = tmpl.ExecuteTemplate(w, "index", v); err != nil {
         .          .    359:       serverError(w, err)
         .          .    360:   }
         .          .    361:}
         .          .    362:
         .          .    363:func signinHandler(w http.ResponseWriter, r *http.Request) {
FuwariSprit commented 4 years ago

ベンチ結果 Result: SUCCESS RawScore: 3015.0 Fails: 0 Score: 3015.0

pprof http://18.183.182.156/torch-20200718092552.svg

kataribe

Top 20 Sort By Count
Count   Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max   2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
 1476   0.805  0.0005  0.0014  0.000  0.000  0.001  0.002  0.006  0.026  1475    1    0    0    24852275          0      16837      16849  GET /css/bootstrap-responsive.min.css HTTP/1.1
 1476   0.826  0.0006  0.0011  0.000  0.000  0.001  0.002  0.006  0.016  1475    1    0    0   156372125          0     105943     106015  GET /css/bootstrap.min.css HTTP/1.1
 1476   0.847  0.0006  0.0011  0.000  0.000  0.001  0.002  0.007  0.011  1475    1    0    0   137332825          0      93043      93107  GET /js/jquery.min.js HTTP/1.1
 1476   0.804  0.0005  0.0012  0.000  0.000  0.001  0.002  0.006  0.013  1475    1    0    0    42230725          0      28611      28631  GET /js/bootstrap.min.js HTTP/1.1
 1253  21.736  0.0173  0.0287  0.000  0.004  0.062  0.086  0.127  0.186  1174    0   79    0     4519537         10       3606      58970  get memo
  466  72.886  0.1564  0.0599  0.043  0.149  0.239  0.266  0.342  0.422   466    0    0    0     6699481      13485      14376      15680  GET / HTTP/1.1
  181   0.863  0.0048  0.0107  0.001  0.002  0.007  0.011  0.040  0.133     0  181    0    0           0          0          0          0  POST /signin HTTP/1.1
  181   0.115  0.0006  0.0009  0.000  0.001  0.001  0.001  0.005  0.005     0  181    0    0           0          0          0          0  POST /signout HTTP/1.1
  181   0.108  0.0006  0.0012  0.000  0.000  0.001  0.001  0.005  0.013   181    0    0    0      241454       1334       1334       1334  GET /signin HTTP/1.1
  181   4.417  0.0244  0.0314  0.001  0.011  0.077  0.096  0.136  0.168   181    0    0    0     2794436       1920      15438      28501  GET /mypage HTTP/1.1
  181   0.756  0.0042  0.0045  0.001  0.002  0.009  0.012  0.031  0.031     0  181    0    0           0          0          0          0  POST /memo HTTP/1.1
   33  46.607  1.4123  0.7333  0.134  1.649  2.152  2.298  2.479  2.479    33    0    0    0      460489      13800      13954      14079  GET /recent/204 HTTP/1.1
   23  35.129  1.5273  0.3096  1.050  1.552  2.014  2.052  2.384  2.384    23    0    0    0      313692      13159      13638      13899  GET /recent/205 HTTP/1.1
    3   0.712  0.2373  0.0654  0.159  0.234  0.319  0.319  0.319  0.319     3    0    0    0       41345      13646      13781      13856  GET /recent/176 HTTP/1.1
    3   1.870  0.6233  0.6759  0.105  0.187  1.578  1.578  1.578  1.578     3    0    0    0       42829      14183      14276      14347  GET /recent/200 HTTP/1.1
    3   2.079  0.6930  0.7356  0.114  0.234  1.731  1.731  1.731  1.731     3    0    0    0       41197      13695      13732      13776  GET /recent/129 HTTP/1.1
    3   3.121  1.0403  0.7253  0.106  1.141  1.874  1.874  1.874  1.874     3    0    0    0       42983      14260      14327      14384  GET /recent/199 HTTP/1.1
    3   0.532  0.1773  0.1115  0.094  0.103  0.335  0.335  0.335  0.335     3    0    0    0       40687      13431      13562      13752  GET /recent/180 HTTP/1.1
    2   0.330  0.1650  0.0590  0.106  0.224  0.224  0.224  0.224  0.224     2    0    0    0       28962      14481      14481      14481  GET /recent/170 HTTP/1.1
    2   0.095  0.0475  0.0135  0.034  0.061  0.061  0.061  0.061  0.061     2    0    0    0       27184      13563      13592      13621  GET /recent/8 HTTP/1.1

Top 20 Sort By Total
Count   Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max   2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
  466  72.886  0.1564  0.0599  0.043  0.149  0.239  0.266  0.342  0.422   466    0    0    0     6699481      13485      14376      15680  GET / HTTP/1.1
   33  46.607  1.4123  0.7333  0.134  1.649  2.152  2.298  2.479  2.479    33    0    0    0      460489      13800      13954      14079  GET /recent/204 HTTP/1.1
   23  35.129  1.5273  0.3096  1.050  1.552  2.014  2.052  2.384  2.384    23    0    0    0      313692      13159      13638      13899  GET /recent/205 HTTP/1.1
 1253  21.736  0.0173  0.0287  0.000  0.004  0.062  0.086  0.127  0.186  1174    0   79    0     4519537         10       3606      58970  get memo
  181   4.417  0.0244  0.0314  0.001  0.011  0.077  0.096  0.136  0.168   181    0    0    0     2794436       1920      15438      28501  GET /mypage HTTP/1.1
    3   3.121  1.0403  0.7253  0.106  1.141  1.874  1.874  1.874  1.874     3    0    0    0       42983      14260      14327      14384  GET /recent/199 HTTP/1.1
    2   2.859  1.4295  0.0415  1.388  1.471  1.471  1.471  1.471  1.471     2    0    0    0       28092      14037      14046      14055  GET /recent/85 HTTP/1.1
    2   2.399  1.1995  0.0135  1.186  1.213  1.213  1.213  1.213  1.213     2    0    0    0       27880      13807      13940      14073  GET /recent/71 HTTP/1.1
    2   2.371  1.1855  1.0685  0.117  2.254  2.254  2.254  2.254  2.254     2    0    0    0       28063      13997      14031      14066  GET /recent/147 HTTP/1.1
    2   2.096  1.0480  0.3780  0.670  1.426  1.426  1.426  1.426  1.426     2    0    0    0       27144      13523      13572      13621  GET /recent/182 HTTP/1.1
    3   2.079  0.6930  0.7356  0.114  0.234  1.731  1.731  1.731  1.731     3    0    0    0       41197      13695      13732      13776  GET /recent/129 HTTP/1.1
    2   1.988  0.9940  0.8770  0.117  1.871  1.871  1.871  1.871  1.871     2    0    0    0       28537      14232      14268      14305  GET /recent/60 HTTP/1.1
    1   1.902  1.9020  0.0000  1.902  1.902  1.902  1.902  1.902  1.902     1    0    0    0       14028      14028      14028      14028  GET /recent/99 HTTP/1.1
    3   1.870  0.6233  0.6759  0.105  0.187  1.578  1.578  1.578  1.578     3    0    0    0       42829      14183      14276      14347  GET /recent/200 HTTP/1.1
    1   1.796  1.7960  0.0000  1.796  1.796  1.796  1.796  1.796  1.796     1    0    0    0       13814      13814      13814      13814  GET /recent/93 HTTP/1.1
    1   1.655  1.6550  0.0000  1.655  1.655  1.655  1.655  1.655  1.655     1    0    0    0       14107      14107      14107      14107  GET /recent/132 HTTP/1.1
    1   1.570  1.5700  0.0000  1.570  1.570  1.570  1.570  1.570  1.570     1    0    0    0       14162      14162      14162      14162  GET /recent/117 HTTP/1.1
    1   1.505  1.5050  0.0000  1.505  1.505  1.505  1.505  1.505  1.505     1    0    0    0       13537      13537      13537      13537  GET /recent/193 HTTP/1.1
    1   1.434  1.4340  0.0000  1.434  1.434  1.434  1.434  1.434  1.434     1    0    0    0       13693      13693      13693      13693  GET /recent/6 HTTP/1.1
    1   1.422  1.4220  0.0000  1.422  1.422  1.422  1.422  1.422  1.422     1    0    0    0       13749      13749      13749      13749  GET /recent/17 HTTP/1.1

Top 20 Sort By Mean
Count   Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max  2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
    1   1.902  1.9020  0.0000  1.902  1.902  1.902  1.902  1.902  1.902    1    0    0    0       14028      14028      14028      14028  GET /recent/99 HTTP/1.1
    1   1.796  1.7960  0.0000  1.796  1.796  1.796  1.796  1.796  1.796    1    0    0    0       13814      13814      13814      13814  GET /recent/93 HTTP/1.1
    1   1.655  1.6550  0.0000  1.655  1.655  1.655  1.655  1.655  1.655    1    0    0    0       14107      14107      14107      14107  GET /recent/132 HTTP/1.1
    1   1.570  1.5700  0.0000  1.570  1.570  1.570  1.570  1.570  1.570    1    0    0    0       14162      14162      14162      14162  GET /recent/117 HTTP/1.1
   23  35.129  1.5273  0.3096  1.050  1.552  2.014  2.052  2.384  2.384   23    0    0    0      313692      13159      13638      13899  GET /recent/205 HTTP/1.1
    1   1.505  1.5050  0.0000  1.505  1.505  1.505  1.505  1.505  1.505    1    0    0    0       13537      13537      13537      13537  GET /recent/193 HTTP/1.1
    1   1.434  1.4340  0.0000  1.434  1.434  1.434  1.434  1.434  1.434    1    0    0    0       13693      13693      13693      13693  GET /recent/6 HTTP/1.1
    2   2.859  1.4295  0.0415  1.388  1.471  1.471  1.471  1.471  1.471    2    0    0    0       28092      14037      14046      14055  GET /recent/85 HTTP/1.1
    1   1.422  1.4220  0.0000  1.422  1.422  1.422  1.422  1.422  1.422    1    0    0    0       13749      13749      13749      13749  GET /recent/17 HTTP/1.1
    1   1.414  1.4140  0.0000  1.414  1.414  1.414  1.414  1.414  1.414    1    0    0    0       13748      13748      13748      13748  GET /recent/66 HTTP/1.1
   33  46.607  1.4123  0.7333  0.134  1.649  2.152  2.298  2.479  2.479   33    0    0    0      460489      13800      13954      14079  GET /recent/204 HTTP/1.1
    1   1.394  1.3940  0.0000  1.394  1.394  1.394  1.394  1.394  1.394    1    0    0    0       14216      14216      14216      14216  GET /recent/157 HTTP/1.1
    1   1.363  1.3630  0.0000  1.363  1.363  1.363  1.363  1.363  1.363    1    0    0    0       14205      14205      14205      14205  GET /recent/144 HTTP/1.1
    1   1.342  1.3420  0.0000  1.342  1.342  1.342  1.342  1.342  1.342    1    0    0    0       14448      14448      14448      14448  GET /recent/21 HTTP/1.1
    2   2.399  1.1995  0.0135  1.186  1.213  1.213  1.213  1.213  1.213    2    0    0    0       27880      13807      13940      14073  GET /recent/71 HTTP/1.1
    2   2.371  1.1855  1.0685  0.117  2.254  2.254  2.254  2.254  2.254    2    0    0    0       28063      13997      14031      14066  GET /recent/147 HTTP/1.1
    1   1.132  1.1320  0.0000  1.132  1.132  1.132  1.132  1.132  1.132    1    0    0    0       14400      14400      14400      14400  GET /recent/97 HTTP/1.1
    1   1.130  1.1300  0.0000  1.130  1.130  1.130  1.130  1.130  1.130    1    0    0    0       14641      14641      14641      14641  GET /recent/80 HTTP/1.1
    1   1.103  1.1030  0.0000  1.103  1.103  1.103  1.103  1.103  1.103    1    0    0    0       14131      14131      14131      14131  GET /recent/1 HTTP/1.1
    2   2.096  1.0480  0.3780  0.670  1.426  1.426  1.426  1.426  1.426    2    0    0    0       27144      13523      13572      13621  GET /recent/182 HTTP/1.1

Top 20 Sort By Standard Deviation
Count   Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max  2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
    2   2.371  1.1855  1.0685  0.117  2.254  2.254  2.254  2.254  2.254    2    0    0    0       28063      13997      14031      14066  GET /recent/147 HTTP/1.1
    2   1.988  0.9940  0.8770  0.117  1.871  1.871  1.871  1.871  1.871    2    0    0    0       28537      14232      14268      14305  GET /recent/60 HTTP/1.1
    3   2.079  0.6930  0.7356  0.114  0.234  1.731  1.731  1.731  1.731    3    0    0    0       41197      13695      13732      13776  GET /recent/129 HTTP/1.1
   33  46.607  1.4123  0.7333  0.134  1.649  2.152  2.298  2.479  2.479   33    0    0    0      460489      13800      13954      14079  GET /recent/204 HTTP/1.1
    3   3.121  1.0403  0.7253  0.106  1.141  1.874  1.874  1.874  1.874    3    0    0    0       42983      14260      14327      14384  GET /recent/199 HTTP/1.1
    3   1.870  0.6233  0.6759  0.105  0.187  1.578  1.578  1.578  1.578    3    0    0    0       42829      14183      14276      14347  GET /recent/200 HTTP/1.1
    2   1.407  0.7035  0.6415  0.062  1.345  1.345  1.345  1.345  1.345    2    0    0    0       28095      14043      14047      14052  GET /recent/54 HTTP/1.1
    2   1.372  0.6860  0.6250  0.061  1.311  1.311  1.311  1.311  1.311    2    0    0    0       27835      13756      13917      14079  GET /recent/186 HTTP/1.1
    2   1.323  0.6615  0.5805  0.081  1.242  1.242  1.242  1.242  1.242    2    0    0    0       28329      14161      14164      14168  GET /recent/24 HTTP/1.1
    2   1.226  0.6130  0.4550  0.158  1.068  1.068  1.068  1.068  1.068    2    0    0    0       28781      14373      14390      14408  GET /recent/159 HTTP/1.1
    2   1.299  0.6495  0.3795  0.270  1.029  1.029  1.029  1.029  1.029    2    0    0    0       27997      13880      13998      14117  GET /recent/123 HTTP/1.1
    2   2.096  1.0480  0.3780  0.670  1.426  1.426  1.426  1.426  1.426    2    0    0    0       27144      13523      13572      13621  GET /recent/182 HTTP/1.1
   23  35.129  1.5273  0.3096  1.050  1.552  2.014  2.052  2.384  2.384   23    0    0    0      313692      13159      13638      13899  GET /recent/205 HTTP/1.1
    2   0.602  0.3010  0.2550  0.046  0.556  0.556  0.556  0.556  0.556    2    0    0    0       28247      14033      14123      14214  GET /recent/114 HTTP/1.1
    3   0.532  0.1773  0.1115  0.094  0.103  0.335  0.335  0.335  0.335    3    0    0    0       40687      13431      13562      13752  GET /recent/180 HTTP/1.1
    2   0.282  0.1410  0.0760  0.065  0.217  0.217  0.217  0.217  0.217    2    0    0    0       27436      13714      13718      13722  GET /recent/158 HTTP/1.1
    3   0.712  0.2373  0.0654  0.159  0.234  0.319  0.319  0.319  0.319    3    0    0    0       41345      13646      13781      13856  GET /recent/176 HTTP/1.1
  466  72.886  0.1564  0.0599  0.043  0.149  0.239  0.266  0.342  0.422  466    0    0    0     6699481      13485      14376      15680  GET / HTTP/1.1
    2   0.330  0.1650  0.0590  0.106  0.224  0.224  0.224  0.224  0.224    2    0    0    0       28962      14481      14481      14481  GET /recent/170 HTTP/1.1
    2   0.351  0.1755  0.0545  0.121  0.230  0.230  0.230  0.230  0.230    2    0    0    0       28986      14484      14493      14502  GET /recent/96 HTTP/1.1

Top 20 Sort By Maximum(100 Percentile)
Count   Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max  2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
   33  46.607  1.4123  0.7333  0.134  1.649  2.152  2.298  2.479  2.479   33    0    0    0      460489      13800      13954      14079  GET /recent/204 HTTP/1.1
   23  35.129  1.5273  0.3096  1.050  1.552  2.014  2.052  2.384  2.384   23    0    0    0      313692      13159      13638      13899  GET /recent/205 HTTP/1.1
    2   2.371  1.1855  1.0685  0.117  2.254  2.254  2.254  2.254  2.254    2    0    0    0       28063      13997      14031      14066  GET /recent/147 HTTP/1.1
    1   1.902  1.9020  0.0000  1.902  1.902  1.902  1.902  1.902  1.902    1    0    0    0       14028      14028      14028      14028  GET /recent/99 HTTP/1.1
    3   3.121  1.0403  0.7253  0.106  1.141  1.874  1.874  1.874  1.874    3    0    0    0       42983      14260      14327      14384  GET /recent/199 HTTP/1.1
    2   1.988  0.9940  0.8770  0.117  1.871  1.871  1.871  1.871  1.871    2    0    0    0       28537      14232      14268      14305  GET /recent/60 HTTP/1.1
    1   1.796  1.7960  0.0000  1.796  1.796  1.796  1.796  1.796  1.796    1    0    0    0       13814      13814      13814      13814  GET /recent/93 HTTP/1.1
    3   2.079  0.6930  0.7356  0.114  0.234  1.731  1.731  1.731  1.731    3    0    0    0       41197      13695      13732      13776  GET /recent/129 HTTP/1.1
    1   1.655  1.6550  0.0000  1.655  1.655  1.655  1.655  1.655  1.655    1    0    0    0       14107      14107      14107      14107  GET /recent/132 HTTP/1.1
    3   1.870  0.6233  0.6759  0.105  0.187  1.578  1.578  1.578  1.578    3    0    0    0       42829      14183      14276      14347  GET /recent/200 HTTP/1.1
    1   1.570  1.5700  0.0000  1.570  1.570  1.570  1.570  1.570  1.570    1    0    0    0       14162      14162      14162      14162  GET /recent/117 HTTP/1.1
    1   1.505  1.5050  0.0000  1.505  1.505  1.505  1.505  1.505  1.505    1    0    0    0       13537      13537      13537      13537  GET /recent/193 HTTP/1.1
    2   2.859  1.4295  0.0415  1.388  1.471  1.471  1.471  1.471  1.471    2    0    0    0       28092      14037      14046      14055  GET /recent/85 HTTP/1.1
    1   1.434  1.4340  0.0000  1.434  1.434  1.434  1.434  1.434  1.434    1    0    0    0       13693      13693      13693      13693  GET /recent/6 HTTP/1.1
    2   2.096  1.0480  0.3780  0.670  1.426  1.426  1.426  1.426  1.426    2    0    0    0       27144      13523      13572      13621  GET /recent/182 HTTP/1.1
    1   1.422  1.4220  0.0000  1.422  1.422  1.422  1.422  1.422  1.422    1    0    0    0       13749      13749      13749      13749  GET /recent/17 HTTP/1.1
    1   1.414  1.4140  0.0000  1.414  1.414  1.414  1.414  1.414  1.414    1    0    0    0       13748      13748      13748      13748  GET /recent/66 HTTP/1.1
    1   1.394  1.3940  0.0000  1.394  1.394  1.394  1.394  1.394  1.394    1    0    0    0       14216      14216      14216      14216  GET /recent/157 HTTP/1.1
    1   1.363  1.3630  0.0000  1.363  1.363  1.363  1.363  1.363  1.363    1    0    0    0       14205      14205      14205      14205  GET /recent/144 HTTP/1.1
    2   1.407  0.7035  0.6415  0.062  1.345  1.345  1.345  1.345  1.345    2    0    0    0       28095      14043      14047      14052  GET /recent/54 HTTP/1.1

TOP 37 Slow Requests
 1  2.479  GET /recent/204 HTTP/1.1
 2  2.384  GET /recent/205 HTTP/1.1
 3  2.298  GET /recent/204 HTTP/1.1
 4  2.254  GET /recent/147 HTTP/1.1
 5  2.204  GET /recent/204 HTTP/1.1
 6  2.152  GET /recent/204 HTTP/1.1
 7  2.137  GET /recent/204 HTTP/1.1
 8  2.087  GET /recent/204 HTTP/1.1
 9  2.071  GET /recent/204 HTTP/1.1
10  2.058  GET /recent/204 HTTP/1.1
11  2.052  GET /recent/205 HTTP/1.1
12  2.014  GET /recent/205 HTTP/1.1
13  1.995  GET /recent/204 HTTP/1.1
14  1.962  GET /recent/204 HTTP/1.1
15  1.902  GET /recent/99 HTTP/1.1
16  1.887  GET /recent/204 HTTP/1.1
17  1.874  GET /recent/199 HTTP/1.1
18  1.871  GET /recent/60 HTTP/1.1
19  1.817  GET /recent/204 HTTP/1.1
20  1.796  GET /recent/93 HTTP/1.1
21  1.757  GET /recent/204 HTTP/1.1
22  1.747  GET /recent/204 HTTP/1.1
23  1.731  GET /recent/129 HTTP/1.1
24  1.715  GET /recent/204 HTTP/1.1
25  1.693  GET /recent/205 HTTP/1.1
26  1.683  GET /recent/204 HTTP/1.1
27  1.666  GET /recent/205 HTTP/1.1
28  1.660  GET /recent/205 HTTP/1.1
29  1.655  GET /recent/132 HTTP/1.1
30  1.649  GET /recent/204 HTTP/1.1
31  1.649  GET /recent/205 HTTP/1.1
32  1.649  GET /recent/205 HTTP/1.1
33  1.631  GET /recent/204 HTTP/1.1
34  1.617  GET /recent/205 HTTP/1.1
35  1.611  GET /recent/204 HTTP/1.1
36  1.594  GET /recent/204 HTTP/1.1
37  1.578  GET /recent/200 HTTP/1.1

slowquerylog

Reading mysql slow query log from sudo /var/lib/mysql/mysql-slow.log
Can't open sudo: No such file or directory at /bin/mysqldumpslow line 97.
Count: 162  Time=0.81s (130s)  Lock=0.00s (0s)  Rows=100.0 (16200), isucon[isucon]@localhost
  SELECT memos.id, user, content, is_private, memos.created_at, memos.updated_at, username FROM memos INNER JOIN users ON memos.user = users.id WHERE is_private=N ORDER BY created_at DESC, memos.id DESC LIMIT N OFFSET N

Count: 2  Time=0.13s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), isucon[isucon]@localhost
  #

Count: 628  Time=0.10s (60s)  Lock=0.00s (0s)  Rows=1.0 (628), isucon[isucon]@localhost
  SELECT count(*) AS c FROM memos WHERE is_private=N

Count: 38  Time=0.07s (2s)  Lock=0.00s (0s)  Rows=67.5 (2564), isucon[isucon]@localhost
  SELECT id, content, is_private, created_at, updated_at FROM memos WHERE user=N AND is_private=N ORDER BY created_at

Count: 107  Time=0.07s (7s)  Lock=0.00s (0s)  Rows=100.0 (10700), isucon[isucon]@localhost
  SELECT * FROM memos WHERE is_private=N ORDER BY created_at DESC, id DESC LIMIT N

Count: 42  Time=0.07s (2s)  Lock=0.00s (0s)  Rows=126.1 (5295), isucon[isucon]@localhost
  SELECT id, content, is_private, created_at, updated_at FROM memos WHERE user=N ORDER BY created_at DESC

Count: 228  Time=0.06s (13s)  Lock=0.00s (0s)  Rows=134.3 (30628), isucon[isucon]@localhost
  SELECT id, content, is_private, created_at, updated_at FROM memos WHERE user=N  ORDER BY created_at

Count: 2  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), 0users@0hosts
  administrator command: Prepare

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), 0users@0hosts
FuwariSprit commented 4 years ago

pprof recentHandler

Time: Jul 18, 2020 at 9:25am (UTC)
Duration: 30.08s, Total samples = 4.57s (15.19%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) list .recentHandler
Total: 4.57s
ROUTINE ======================== main.recentHandler in /opt/isucon3-mod/app/src/app.go
         0      340ms (flat, cum)  7.44% of Total
         .          .    303:   prepareHandler(w, r)
         .          .    304:   dbConn := <-dbConnPool
         .          .    305:   defer func() {
         .          .    306:       dbConnPool <- dbConn
         .          .    307:   }()
         .       10ms    308:   user := getUser(w, r, dbConn, session)
         .          .    309:   vars := mux.Vars(r)
         .          .    310:   page, _ := strconv.Atoi(vars["page"])
         .          .    311:
         .          .    312:   rows, err := dbConn.Query("SELECT count(*) AS c FROM memos WHERE is_private=0")
         .          .    313:   if err != nil {
         .          .    314:       serverError(w, err)
         .          .    315:       return
         .          .    316:   }
         .          .    317:   var totalCount int
         .          .    318:   if rows.Next() {
         .          .    319:       rows.Scan(&totalCount)
         .          .    320:   }
         .          .    321:   rows.Close()
         .          .    322:
         .       20ms    323:   rows, err = dbConn.Query("SELECT memos.id, user, content, is_private, memos.created_at, memos.updated_at, username FROM memos INNER JOIN users ON memos.user = users.id WHERE is_private=0 ORDER BY created_at DESC, memos.id DESC LIMIT ? OFFSET ?", memosPerPage, memosPerPage*page)
         .          .    324:   if err != nil {
         .          .    325:       serverError(w, err)
         .          .    326:       return
         .          .    327:   }
         .          .    328:   memos := make(Memos, 0)
         .       20ms    329:   for rows.Next() {
         .          .    330:       memo := Memo{}
         .       20ms    331:       rows.Scan(&memo.Id, &memo.User, &memo.Content, &memo.IsPrivate, &memo.CreatedAt, &memo.UpdatedAt, &memo.Username)
         .          .    332:       memos = append(memos, &memo)
         .          .    333:   }
         .          .    334:   if len(memos) == 0 {
         .          .    335:       notFound(w)
         .          .    336:       return
         .          .    337:   }
         .          .    338:
         .          .    339:   v := &View{
         .          .    340:       Total:             totalCount,
         .          .    341:       Page:              page,
         .          .    342:       PageStart:         memosPerPage*page + 1,
         .          .    343:       PageEnd:           memosPerPage * (page + 1),
         .          .    344:       Memos:             &memos,
         .          .    345:       User:              user,
         .          .    346:       Session:           session,
         .          .    347:       Url_for:           _Url_for(),
         .          .    348:       My_token:          _My_token(session),
         .       10ms    349:       Memos_first_lines: _to_first_line(&memos),
         .          .    350:   }
         .      260ms    351:   if err = tmpl.ExecuteTemplate(w, "index", v); err != nil {
         .          .    352:       serverError(w, err)
         .          .    353:   }
         .          .    354:}
         .          .    355:
         .          .    356:func signinHandler(w http.ResponseWriter, r *http.Request) {
FuwariSprit commented 4 years ago

ベンチ結果 Result: SUCCESS RawScore: 1302.9 Fails: 0 Score: 1302.9

pprof http://18.183.182.156/torch-20200718100030.svg

kataribe

Top 20 Sort By Count
Count    Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max   2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
 1390    0.677  0.0005  0.0010  0.000  0.000  0.001  0.001  0.005  0.017  1390    0    0    0   147360850     106015     106015     106015  GET /css/bootstrap.min.css HTTP/1.1
 1390    0.630  0.0005  0.0010  0.000  0.000  0.001  0.001  0.005  0.014  1390    0    0    0    23420110      16849      16849      16849  GET /css/bootstrap-responsive.min.css HTTP/1.1
 1390    0.685  0.0005  0.0010  0.000  0.000  0.001  0.001  0.004  0.013  1390    0    0    0    39797090      28631      28631      28631  GET /js/bootstrap.min.js HTTP/1.1
 1390    0.693  0.0005  0.0011  0.000  0.000  0.001  0.001  0.005  0.016  1390    0    0    0   129418730      93107      93107      93107  GET /js/jquery.min.js HTTP/1.1
  507   14.417  0.0284  0.0364  0.000  0.007  0.081  0.104  0.143  0.181   463    0   44    0     2236844         10       4411      58970  get memo
  184  253.058  1.3753  1.0006  0.046  1.909  2.486  2.557  2.651  2.739   184    0    0    0     2567221      13478      13952      14559  GET / HTTP/1.1
   76    0.581  0.0076  0.0101  0.002  0.003  0.023  0.034  0.044  0.044     0   76    0    0           0          0          0          0  POST /signin HTTP/1.1
   76    0.674  0.0089  0.0102  0.001  0.004  0.023  0.031  0.049  0.049     0   76    0    0           0          0          0          0  POST /memo HTTP/1.1
   76    0.033  0.0004  0.0008  0.000  0.000  0.001  0.001  0.005  0.005    76    0    0    0      101384       1334       1334       1334  GET /signin HTTP/1.1
   76    3.550  0.0467  0.0562  0.001  0.025  0.132  0.178  0.245  0.245    76    0    0    0     1064942       1940      14012      27358  GET /mypage HTTP/1.1
   76    0.064  0.0008  0.0015  0.000  0.001  0.002  0.002  0.011  0.011     0   76    0    0           0          0          0          0  POST /signout HTTP/1.1
   20   35.542  1.7771  0.9593  0.068  2.212  2.729  2.782  2.782  2.782    20    0    0    0      277989      13671      13899      13992  GET /recent/204 HTTP/1.1
    2    1.966  0.9830  0.9070  0.076  1.890  1.890  1.890  1.890  1.890     2    0    0    0       26802      13270      13401      13532  GET /recent/11 HTTP/1.1
    2    0.312  0.1560  0.0150  0.141  0.171  0.171  0.171  0.171  0.171     2    0    0    0       28241      14084      14120      14157  GET /recent/72 HTTP/1.1
    2    2.533  1.2665  1.1495  0.117  2.416  2.416  2.416  2.416  2.416     2    0    0    0       28843      14418      14421      14425  GET /recent/121 HTTP/1.1
    2    4.999  2.4995  0.2625  2.237  2.762  2.762  2.762  2.762  2.762     2    0    0    0       28091      13972      14045      14119  GET /recent/107 HTTP/1.1
    2    2.445  1.2225  1.0495  0.173  2.272  2.272  2.272  2.272  2.272     2    0    0    0       27272      13454      13636      13818  GET /recent/165 HTTP/1.1
    2    0.262  0.1310  0.0580  0.073  0.189  0.189  0.189  0.189  0.189     2    0    0    0       27865      13884      13932      13981  GET /recent/88 HTTP/1.1
    2    0.986  0.4930  0.4390  0.054  0.932  0.932  0.932  0.932  0.932     2    0    0    0       28568      14262      14284      14306  GET /recent/142 HTTP/1.1
    2    0.317  0.1585  0.0865  0.072  0.245  0.245  0.245  0.245  0.245     2    0    0    0       27858      13811      13929      14047  GET /recent/109 HTTP/1.1

Top 20 Sort By Total
Count    Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max  2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
  184  253.058  1.3753  1.0006  0.046  1.909  2.486  2.557  2.651  2.739  184    0    0    0     2567221      13478      13952      14559  GET / HTTP/1.1
   20   35.542  1.7771  0.9593  0.068  2.212  2.729  2.782  2.782  2.782   20    0    0    0      277989      13671      13899      13992  GET /recent/204 HTTP/1.1
  507   14.417  0.0284  0.0364  0.000  0.007  0.081  0.104  0.143  0.181  463    0   44    0     2236844         10       4411      58970  get memo
    2    4.999  2.4995  0.2625  2.237  2.762  2.762  2.762  2.762  2.762    2    0    0    0       28091      13972      14045      14119  GET /recent/107 HTTP/1.1
   76    3.550  0.0467  0.0562  0.001  0.025  0.132  0.178  0.245  0.245   76    0    0    0     1064942       1940      14012      27358  GET /mypage HTTP/1.1
    1    2.969  2.9690  0.0000  2.969  2.969  2.969  2.969  2.969  2.969    1    0    0    0       13993      13993      13993      13993  GET /recent/135 HTTP/1.1
    2    2.730  1.3650  1.3130  0.052  2.678  2.678  2.678  2.678  2.678    2    0    0    0       27698      13801      13849      13897  GET /recent/93 HTTP/1.1
    1    2.632  2.6320  0.0000  2.632  2.632  2.632  2.632  2.632  2.632    1    0    0    0       13519      13519      13519      13519  GET /recent/202 HTTP/1.1
    1    2.564  2.5640  0.0000  2.564  2.564  2.564  2.564  2.564  2.564    1    0    0    0       14236      14236      14236      14236  GET /recent/106 HTTP/1.1
    1    2.549  2.5490  0.0000  2.549  2.549  2.549  2.549  2.549  2.549    1    0    0    0       14458      14458      14458      14458  GET /recent/23 HTTP/1.1
    1    2.545  2.5450  0.0000  2.545  2.545  2.545  2.545  2.545  2.545    1    0    0    0       14363      14363      14363      14363  GET /recent/145 HTTP/1.1
    2    2.533  1.2665  1.1495  0.117  2.416  2.416  2.416  2.416  2.416    2    0    0    0       28843      14418      14421      14425  GET /recent/121 HTTP/1.1
    1    2.518  2.5180  0.0000  2.518  2.518  2.518  2.518  2.518  2.518    1    0    0    0       14296      14296      14296      14296  GET /recent/92 HTTP/1.1
    1    2.499  2.4990  0.0000  2.499  2.499  2.499  2.499  2.499  2.499    1    0    0    0       14302      14302      14302      14302  GET /recent/153 HTTP/1.1
    1    2.473  2.4730  0.0000  2.473  2.473  2.473  2.473  2.473  2.473    1    0    0    0       14116      14116      14116      14116  GET /recent/1 HTTP/1.1
    2    2.445  1.2225  1.0495  0.173  2.272  2.272  2.272  2.272  2.272    2    0    0    0       27272      13454      13636      13818  GET /recent/165 HTTP/1.1
    1    2.365  2.3650  0.0000  2.365  2.365  2.365  2.365  2.365  2.365    1    0    0    0       14164      14164      14164      14164  GET /recent/133 HTTP/1.1
    1    2.345  2.3450  0.0000  2.345  2.345  2.345  2.345  2.345  2.345    1    0    0    0       14200      14200      14200      14200  GET /recent/55 HTTP/1.1
    1    2.334  2.3340  0.0000  2.334  2.334  2.334  2.334  2.334  2.334    1    0    0    0       14711      14711      14711      14711  GET /recent/120 HTTP/1.1
    1    2.187  2.1870  0.0000  2.187  2.187  2.187  2.187  2.187  2.187    1    0    0    0       13954      13954      13954      13954  GET /recent/70 HTTP/1.1

Top 20 Sort By Mean
Count    Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max  2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
    1    2.969  2.9690  0.0000  2.969  2.969  2.969  2.969  2.969  2.969    1    0    0    0       13993      13993      13993      13993  GET /recent/135 HTTP/1.1
    1    2.632  2.6320  0.0000  2.632  2.632  2.632  2.632  2.632  2.632    1    0    0    0       13519      13519      13519      13519  GET /recent/202 HTTP/1.1
    1    2.564  2.5640  0.0000  2.564  2.564  2.564  2.564  2.564  2.564    1    0    0    0       14236      14236      14236      14236  GET /recent/106 HTTP/1.1
    1    2.549  2.5490  0.0000  2.549  2.549  2.549  2.549  2.549  2.549    1    0    0    0       14458      14458      14458      14458  GET /recent/23 HTTP/1.1
    1    2.545  2.5450  0.0000  2.545  2.545  2.545  2.545  2.545  2.545    1    0    0    0       14363      14363      14363      14363  GET /recent/145 HTTP/1.1
    1    2.518  2.5180  0.0000  2.518  2.518  2.518  2.518  2.518  2.518    1    0    0    0       14296      14296      14296      14296  GET /recent/92 HTTP/1.1
    2    4.999  2.4995  0.2625  2.237  2.762  2.762  2.762  2.762  2.762    2    0    0    0       28091      13972      14045      14119  GET /recent/107 HTTP/1.1
    1    2.499  2.4990  0.0000  2.499  2.499  2.499  2.499  2.499  2.499    1    0    0    0       14302      14302      14302      14302  GET /recent/153 HTTP/1.1
    1    2.473  2.4730  0.0000  2.473  2.473  2.473  2.473  2.473  2.473    1    0    0    0       14116      14116      14116      14116  GET /recent/1 HTTP/1.1
    1    2.365  2.3650  0.0000  2.365  2.365  2.365  2.365  2.365  2.365    1    0    0    0       14164      14164      14164      14164  GET /recent/133 HTTP/1.1
    1    2.345  2.3450  0.0000  2.345  2.345  2.345  2.345  2.345  2.345    1    0    0    0       14200      14200      14200      14200  GET /recent/55 HTTP/1.1
    1    2.334  2.3340  0.0000  2.334  2.334  2.334  2.334  2.334  2.334    1    0    0    0       14711      14711      14711      14711  GET /recent/120 HTTP/1.1
    1    2.187  2.1870  0.0000  2.187  2.187  2.187  2.187  2.187  2.187    1    0    0    0       13954      13954      13954      13954  GET /recent/70 HTTP/1.1
    1    2.038  2.0380  0.0000  2.038  2.038  2.038  2.038  2.038  2.038    1    0    0    0       14508      14508      14508      14508  GET /recent/140 HTTP/1.1
    1    1.966  1.9660  0.0000  1.966  1.966  1.966  1.966  1.966  1.966    1    0    0    0       14168      14168      14168      14168  GET /recent/74 HTTP/1.1
    1    1.957  1.9570  0.0000  1.957  1.957  1.957  1.957  1.957  1.957    1    0    0    0       13740      13740      13740      13740  GET /recent/129 HTTP/1.1
   20   35.542  1.7771  0.9593  0.068  2.212  2.729  2.782  2.782  2.782   20    0    0    0      277989      13671      13899      13992  GET /recent/204 HTTP/1.1
    1    1.552  1.5520  0.0000  1.552  1.552  1.552  1.552  1.552  1.552    1    0    0    0       14016      14016      14016      14016  GET /recent/9 HTTP/1.1
  184  253.058  1.3753  1.0006  0.046  1.909  2.486  2.557  2.651  2.739  184    0    0    0     2567221      13478      13952      14559  GET / HTTP/1.1
    2    2.730  1.3650  1.3130  0.052  2.678  2.678  2.678  2.678  2.678    2    0    0    0       27698      13801      13849      13897  GET /recent/93 HTTP/1.1

Top 20 Sort By Standard Deviation
Count    Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max   2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
    2    2.730  1.3650  1.3130  0.052  2.678  2.678  2.678  2.678  2.678     2    0    0    0       27698      13801      13849      13897  GET /recent/93 HTTP/1.1
    2    2.533  1.2665  1.1495  0.117  2.416  2.416  2.416  2.416  2.416     2    0    0    0       28843      14418      14421      14425  GET /recent/121 HTTP/1.1
    2    2.445  1.2225  1.0495  0.173  2.272  2.272  2.272  2.272  2.272     2    0    0    0       27272      13454      13636      13818  GET /recent/165 HTTP/1.1
  184  253.058  1.3753  1.0006  0.046  1.909  2.486  2.557  2.651  2.739   184    0    0    0     2567221      13478      13952      14559  GET / HTTP/1.1
   20   35.542  1.7771  0.9593  0.068  2.212  2.729  2.782  2.782  2.782    20    0    0    0      277989      13671      13899      13992  GET /recent/204 HTTP/1.1
    2    1.966  0.9830  0.9070  0.076  1.890  1.890  1.890  1.890  1.890     2    0    0    0       26802      13270      13401      13532  GET /recent/11 HTTP/1.1
    2    0.986  0.4930  0.4390  0.054  0.932  0.932  0.932  0.932  0.932     2    0    0    0       28568      14262      14284      14306  GET /recent/142 HTTP/1.1
    2    4.999  2.4995  0.2625  2.237  2.762  2.762  2.762  2.762  2.762     2    0    0    0       28091      13972      14045      14119  GET /recent/107 HTTP/1.1
    2    0.317  0.1585  0.0865  0.072  0.245  0.245  0.245  0.245  0.245     2    0    0    0       27858      13811      13929      14047  GET /recent/109 HTTP/1.1
    2    0.262  0.1310  0.0580  0.073  0.189  0.189  0.189  0.189  0.189     2    0    0    0       27865      13884      13932      13981  GET /recent/88 HTTP/1.1
   76    3.550  0.0467  0.0562  0.001  0.025  0.132  0.178  0.245  0.245    76    0    0    0     1064942       1940      14012      27358  GET /mypage HTTP/1.1
  507   14.417  0.0284  0.0364  0.000  0.007  0.081  0.104  0.143  0.181   463    0   44    0     2236844         10       4411      58970  get memo
    2    0.226  0.1130  0.0350  0.078  0.148  0.148  0.148  0.148  0.148     2    0    0    0       28294      14074      14147      14220  GET /recent/124 HTTP/1.1
    2    0.312  0.1560  0.0150  0.141  0.171  0.171  0.171  0.171  0.171     2    0    0    0       28241      14084      14120      14157  GET /recent/72 HTTP/1.1
   76    0.674  0.0089  0.0102  0.001  0.004  0.023  0.031  0.049  0.049     0   76    0    0           0          0          0          0  POST /memo HTTP/1.1
   76    0.581  0.0076  0.0101  0.002  0.003  0.023  0.034  0.044  0.044     0   76    0    0           0          0          0          0  POST /signin HTTP/1.1
   76    0.064  0.0008  0.0015  0.000  0.001  0.002  0.002  0.011  0.011     0   76    0    0           0          0          0          0  POST /signout HTTP/1.1
 1390    0.693  0.0005  0.0011  0.000  0.000  0.001  0.001  0.005  0.016  1390    0    0    0   129418730      93107      93107      93107  GET /js/jquery.min.js HTTP/1.1
 1390    0.677  0.0005  0.0010  0.000  0.000  0.001  0.001  0.005  0.017  1390    0    0    0   147360850     106015     106015     106015  GET /css/bootstrap.min.css HTTP/1.1
 1390    0.685  0.0005  0.0010  0.000  0.000  0.001  0.001  0.004  0.013  1390    0    0    0    39797090      28631      28631      28631  GET /js/bootstrap.min.js HTTP/1.1

Top 20 Sort By Maximum(100 Percentile)
Count    Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max  2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
    1    2.969  2.9690  0.0000  2.969  2.969  2.969  2.969  2.969  2.969    1    0    0    0       13993      13993      13993      13993  GET /recent/135 HTTP/1.1
   20   35.542  1.7771  0.9593  0.068  2.212  2.729  2.782  2.782  2.782   20    0    0    0      277989      13671      13899      13992  GET /recent/204 HTTP/1.1
    2    4.999  2.4995  0.2625  2.237  2.762  2.762  2.762  2.762  2.762    2    0    0    0       28091      13972      14045      14119  GET /recent/107 HTTP/1.1
  184  253.058  1.3753  1.0006  0.046  1.909  2.486  2.557  2.651  2.739  184    0    0    0     2567221      13478      13952      14559  GET / HTTP/1.1
    2    2.730  1.3650  1.3130  0.052  2.678  2.678  2.678  2.678  2.678    2    0    0    0       27698      13801      13849      13897  GET /recent/93 HTTP/1.1
    1    2.632  2.6320  0.0000  2.632  2.632  2.632  2.632  2.632  2.632    1    0    0    0       13519      13519      13519      13519  GET /recent/202 HTTP/1.1
    1    2.564  2.5640  0.0000  2.564  2.564  2.564  2.564  2.564  2.564    1    0    0    0       14236      14236      14236      14236  GET /recent/106 HTTP/1.1
    1    2.549  2.5490  0.0000  2.549  2.549  2.549  2.549  2.549  2.549    1    0    0    0       14458      14458      14458      14458  GET /recent/23 HTTP/1.1
    1    2.545  2.5450  0.0000  2.545  2.545  2.545  2.545  2.545  2.545    1    0    0    0       14363      14363      14363      14363  GET /recent/145 HTTP/1.1
    1    2.518  2.5180  0.0000  2.518  2.518  2.518  2.518  2.518  2.518    1    0    0    0       14296      14296      14296      14296  GET /recent/92 HTTP/1.1
    1    2.499  2.4990  0.0000  2.499  2.499  2.499  2.499  2.499  2.499    1    0    0    0       14302      14302      14302      14302  GET /recent/153 HTTP/1.1
    1    2.473  2.4730  0.0000  2.473  2.473  2.473  2.473  2.473  2.473    1    0    0    0       14116      14116      14116      14116  GET /recent/1 HTTP/1.1
    2    2.533  1.2665  1.1495  0.117  2.416  2.416  2.416  2.416  2.416    2    0    0    0       28843      14418      14421      14425  GET /recent/121 HTTP/1.1
    1    2.365  2.3650  0.0000  2.365  2.365  2.365  2.365  2.365  2.365    1    0    0    0       14164      14164      14164      14164  GET /recent/133 HTTP/1.1
    1    2.345  2.3450  0.0000  2.345  2.345  2.345  2.345  2.345  2.345    1    0    0    0       14200      14200      14200      14200  GET /recent/55 HTTP/1.1
    1    2.334  2.3340  0.0000  2.334  2.334  2.334  2.334  2.334  2.334    1    0    0    0       14711      14711      14711      14711  GET /recent/120 HTTP/1.1
    2    2.445  1.2225  1.0495  0.173  2.272  2.272  2.272  2.272  2.272    2    0    0    0       27272      13454      13636      13818  GET /recent/165 HTTP/1.1
    1    2.187  2.1870  0.0000  2.187  2.187  2.187  2.187  2.187  2.187    1    0    0    0       13954      13954      13954      13954  GET /recent/70 HTTP/1.1
    1    2.038  2.0380  0.0000  2.038  2.038  2.038  2.038  2.038  2.038    1    0    0    0       14508      14508      14508      14508  GET /recent/140 HTTP/1.1
    1    1.966  1.9660  0.0000  1.966  1.966  1.966  1.966  1.966  1.966    1    0    0    0       14168      14168      14168      14168  GET /recent/74 HTTP/1.1

TOP 37 Slow Requests
 1  2.969  GET /recent/135 HTTP/1.1
 2  2.782  GET /recent/204 HTTP/1.1
 3  2.762  GET /recent/107 HTTP/1.1
 4  2.739  GET / HTTP/1.1
 5  2.729  GET /recent/204 HTTP/1.1
 6  2.716  GET /recent/204 HTTP/1.1
 7  2.695  GET /recent/204 HTTP/1.1
 8  2.678  GET /recent/93 HTTP/1.1
 9  2.651  GET / HTTP/1.1
10  2.632  GET /recent/202 HTTP/1.1
11  2.631  GET / HTTP/1.1
12  2.629  GET /recent/204 HTTP/1.1
13  2.617  GET / HTTP/1.1
14  2.615  GET / HTTP/1.1
15  2.613  GET / HTTP/1.1
16  2.583  GET / HTTP/1.1
17  2.575  GET / HTTP/1.1
18  2.568  GET / HTTP/1.1
19  2.564  GET /recent/106 HTTP/1.1
20  2.557  GET / HTTP/1.1
21  2.549  GET /recent/23 HTTP/1.1
22  2.545  GET /recent/145 HTTP/1.1
23  2.528  GET /recent/204 HTTP/1.1
24  2.526  GET /recent/204 HTTP/1.1
25  2.524  GET / HTTP/1.1
26  2.518  GET /recent/92 HTTP/1.1
27  2.516  GET / HTTP/1.1
28  2.510  GET / HTTP/1.1
29  2.501  GET / HTTP/1.1
30  2.499  GET /recent/153 HTTP/1.1
31  2.498  GET / HTTP/1.1
32  2.497  GET / HTTP/1.1
33  2.497  GET / HTTP/1.1
34  2.490  GET / HTTP/1.1
35  2.486  GET / HTTP/1.1
36  2.479  GET / HTTP/1.1
37  2.478  GET / HTTP/1.1

sloqquerylog

Reading mysql slow query log from /var/lib/mysql/mysql-slow.log
Count: 184  Time=1.23s (226s)  Lock=0.00s (0s)  Rows=100.0 (18400), isucon[isucon]@localhost
  SELECT memos.id, user, content, is_private, memos.created_at, memos.updated_at, username FROM memos INNER JOIN users ON memos.user = users.id WHERE is_private=N ORDER BY created_at DESC, id DESC LIMIT N

Count: 106  Time=0.83s (87s)  Lock=0.00s (0s)  Rows=100.0 (10600), isucon[isucon]@localhost
  SELECT memos.id, user, content, is_private, memos.created_at, memos.updated_at, username FROM memos INNER JOIN users ON memos.user = users.id WHERE is_private=N ORDER BY created_at DESC, memos.id DESC LIMIT N OFFSET N

Count: 290  Time=0.12s (34s)  Lock=0.00s (0s)  Rows=1.0 (290), isucon[isucon]@localhost
  SELECT count(*) AS c FROM memos WHERE is_private=N

Count: 35  Time=0.09s (2s)  Lock=0.00s (0s)  Rows=103.3 (3614), isucon[isucon]@localhost
  SELECT id, content, is_private, created_at, updated_at FROM memos WHERE user=N ORDER BY created_at DESC

Count: 13  Time=0.07s (0s)  Lock=0.00s (0s)  Rows=61.8 (803), isucon[isucon]@localhost
  SELECT id, content, is_private, created_at, updated_at FROM memos WHERE user=N AND is_private=N ORDER BY created_at

Count: 180  Time=0.07s (11s)  Lock=0.00s (0s)  Rows=112.5 (20248), isucon[isucon]@localhost
  SELECT id, content, is_private, created_at, updated_at FROM memos WHERE user=N  ORDER BY created_at

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), 0users@0hosts
FuwariSprit commented 4 years ago

pprof topHandler

(pprof) list .topHandler
Total: 2.23s
ROUTINE ======================== main.topHandler in /opt/isucon3-mod/app/src/app.go
      10ms      310ms (flat, cum) 13.90% of Total
         .          .    245:       dbConnPool <- dbConn
         .          .    246:   }()
         .          .    247:   user := getUser(w, r, dbConn, session)
         .          .    248:
         .          .    249:   var totalCount int
         .       10ms    250:   rows, err := dbConn.Query("SELECT count(*) AS c FROM memos WHERE is_private=0")
         .          .    251:   if err != nil {
         .          .    252:       serverError(w, err)
         .          .    253:       return
         .          .    254:   }
         .          .    255:   if rows.Next() {
         .          .    256:       rows.Scan(&totalCount)
         .          .    257:   }
         .          .    258:   rows.Close()
         .          .    259:
         .          .    260:   rows, err = dbConn.Query("SELECT memos.id, user, content, is_private, memos.created_at, memos.updated_at, username FROM memos INNER JOIN users ON memos.user = users.id WHERE is_private=0 ORDER BY created_at DESC, id DESC LIMIT ?", memosPerPage)
         .          .    261:   if err != nil {
         .          .    262:       serverError(w, err)
         .          .    263:       return
         .          .    264:   }
         .          .    265:   memos := make(Memos, 0)
         .       10ms    266:   for rows.Next() {
         .          .    267:       memo := Memo{}
      10ms       20ms    268:       rows.Scan(&memo.Id, &memo.User, &memo.Content, &memo.IsPrivate, &memo.CreatedAt, &memo.UpdatedAt, &memo.Username)
         .          .    269:       memos = append(memos, &memo)
         .          .    270:   }
         .          .    271:   rows.Close()
         .          .    272:
         .          .    273:   v := &View{
         .          .    274:       Total:             totalCount,
         .          .    275:       Page:              0,
         .          .    276:       PageStart:         1,
         .          .    277:       PageEnd:           memosPerPage,
         .          .    278:       Memos:             &memos,
         .          .    279:       User:              user,
         .          .    280:       Session:           session,
         .          .    281:       Url_for:           _Url_for(),
         .          .    282:       My_token:          _My_token(session),
         .       10ms    283:       Memos_first_lines: _to_first_line(&memos),
         .          .    284:   }
         .      260ms    285:   if err = tmpl.ExecuteTemplate(w, "index", v); err != nil {
         .          .    286:       serverError(w, err)
         .          .    287:   }
         .          .    288:}
         .          .    289:
         .          .    290:func recentHandler(w http.ResponseWriter, r *http.Request) {
FuwariSprit commented 4 years ago

explainの結果

mysql> explain SELECT * FROM memos INNER JOIN users ON memos.user = users.id WHERE is_private=0 ORDER BY created_at DESC, memos.id DESC LIMIT 100 OFFSET 0;
+----+-------------+-------+------------+--------+---------------+------------------+---------+-------------------+------+----------+-------------+
| id | select_type | table | partitions | type   | possible_keys | key              | key_len | ref               | rows | filtered | Extra       |
+----+-------------+-------+------------+--------+---------------+------------------+---------+-------------------+------+----------+-------------+
|  1 | SIMPLE      | memos | NULL       | index  | index_user    | index_created_at | 5       | NULL              |  100 |    10.00 | Using where |
|  1 | SIMPLE      | users | NULL       | eq_ref | PRIMARY       | PRIMARY          | 4       | isucon.memos.user |    1 |   100.00 | NULL        |
+----+-------------+-------+------------+--------+---------------+------------------+---------+-------------------+------+----------+-------------+
2 rows in set, 1 warning (0.00 sec)
FuwariSprit commented 4 years ago

ローカルでのexplain

memos.userに対してindexを貼ったあとの結果

mysql> explain SELECT * FROM memos INNER JOIN users ON memos.user = users.id WHERE is_private=0 ORDER BY created_at DESC, memos.id DESC LIMIT 100 OFFSET 0;
+----+-------------+-------+------------+------+---------------+------------+---------+-----------------+------+----------+---------------------------------+
| id | select_type | table | partitions | type | possible_keys | key        | key_len | ref             | rows | filtered | Extra                           |
+----+-------------+-------+------------+------+---------------+------------+---------+-----------------+------+----------+---------------------------------+
|  1 | SIMPLE      | users | NULL       | ALL  | PRIMARY       | NULL       | NULL    | NULL            |    1 |   100.00 | Using temporary; Using filesort |
|  1 | SIMPLE      | memos | NULL       | ref  | index_user    | index_user | 4       | isucon.users.id |    1 |    10.00 | Using where                     |
+----+-------------+-------+------------+------+---------------+------------+---------+-----------------+------+----------+---------------------------------+
2 rows in set, 1 warning (0.01 sec)
okashoi commented 4 years ago
$ make bench                                                                                                                               
sudo /opt/isucon3-mod/bench/bench benchmark --workload 3 --init ./init.sh                                                                                                      
2020/07/18 10:53:23 <<<DEBUG build>>>                                                                                                                                          
2020/07/18 10:53:23 benchmark mode                                                                                                                                             
2020/07/18 10:53:23 initialize data...                                                                                                                                         
2020/07/18 10:53:29 run ./init.sh timeout 60 sec...                                                                                                                            
2020/07/18 10:53:40 done                                                                                                                                                       
2020/07/18 10:53:40 sleeping 5 sec...                                                                                                                                          
2020/07/18 10:53:45 run benchmark workload: 3                                                                                                                                  
2020/07/18 10:54:46 done benchmark                                                                                                                                             
Result:   SUCCESS                                                                                                                                                              
RawScore: 7222.2                                                                                                                                                               
Fails:    0                                                                                                                                                                    
Score:    7222.2
okashoi commented 4 years ago

さがった

$ make bench
sudo /opt/isucon3-mod/bench/bench benchmark --workload 3 --init ./init.sh
2020/07/18 13:04:23 <<<DEBUG build>>>
2020/07/18 13:04:23 benchmark mode
2020/07/18 13:04:23 initialize data...
2020/07/18 13:04:29 run ./init.sh timeout 60 sec...
2020/07/18 13:04:40 done
2020/07/18 13:04:40 sleeping 5 sec...
2020/07/18 13:04:45 run benchmark workload: 3
2020/07/18 13:05:47 done benchmark
Result:   SUCCESS 
RawScore: 6057.9
Fails:    0
Score:    6057.9

pprof

http://18.183.182.156/torch-20200718130446.svg

kataribe

Top 20 Sort By Count
Count    Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max   2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
 3265   10.871  0.0033  0.0056  0.000  0.001  0.009  0.014  0.028  0.072  3265    0    0    0   346138975     106015     106015     106015  GET /css/bootstrap.min.css HTTP/1.1
 3265   10.669  0.0033  0.0053  0.000  0.001  0.009  0.013  0.028  0.048  3265    0    0    0   303994355      93107      93107      93107  GET /js/jquery.min.js HTTP/1.1
 3265   10.244  0.0031  0.0054  0.000  0.001  0.009  0.014  0.027  0.049  3265    0    0    0    93480215      28631      28631      28631  GET /js/bootstrap.min.js HTTP/1.1
 3265   10.754  0.0033  0.0059  0.000  0.001  0.010  0.015  0.027  0.079  3265    0    0    0    55011985      16849      16849      16849  GET /css/bootstrap-responsive.min.css HTTP/1.1
 2703  195.617  0.0724  0.0612  0.000  0.057  0.157  0.192  0.250  0.406  2356    0  347    0     7208905         10       2667      58970  get memo
 1597  456.422  0.2858  0.0926  0.027  0.277  0.400  0.440  0.576  0.786  1597    0    0    0    23966617      13478      15007      15755  GET / HTTP/1.1
  648   47.104  0.0727  0.0593  0.002  0.059  0.160  0.186  0.246  0.411     0  648    0    0           0          0          0          0  POST /signin HTTP/1.1
  648   52.516  0.0810  0.0722  0.000  0.066  0.177  0.212  0.341  0.420   648    0    0    0      864432       1334       1334       1334  GET /signin HTTP/1.1
  648    2.580  0.0040  0.0061  0.000  0.001  0.011  0.015  0.029  0.055     0  648    0    0           0          0          0          0  POST /signout HTTP/1.1
  648   53.648  0.0828  0.0620  0.001  0.069  0.171  0.201  0.258  0.334   648    0    0    0     7345738       1763      11336      20494  GET /mypage HTTP/1.1
  648   45.903  0.0708  0.0610  0.001  0.053  0.163  0.191  0.246  0.351     0  648    0    0           0          0          0          0  POST /memo HTTP/1.1
   11    9.704  0.8822  0.1050  0.773  0.854  1.005  1.088  1.088  1.088    11    0    0    0      152144      13479      13831      14009  GET /recent/205 HTTP/1.1
   10    8.809  0.8809  0.1253  0.714  0.830  1.085  1.085  1.085  1.085    10    0    0    0      139041      13307      13904      14075  GET /recent/206 HTTP/1.1
    6    3.897  0.6495  0.3062  0.215  0.727  1.002  1.002  1.002  1.002     6    0    0    0       82469      13452      13744      13910  GET /recent/207 HTTP/1.1
    5    1.580  0.3160  0.1150  0.191  0.298  0.488  0.488  0.488  0.488     5    0    0    0       71620      13960      14324      15274  GET /recent/1 HTTP/1.1
    5    4.054  0.8108  0.1003  0.677  0.847  0.917  0.917  0.917  0.917     5    0    0    0       69964      13641      13992      14175  GET /recent/131 HTTP/1.1
    5    3.727  0.7454  0.1342  0.482  0.813  0.848  0.848  0.848  0.848     5    0    0    0       70895      14009      14179      14309  GET /recent/147 HTTP/1.1
    5    5.022  1.0044  0.1392  0.886  0.963  1.276  1.276  1.276  1.276     5    0    0    0       70052      13927      14010      14070  GET /recent/204 HTTP/1.1
    4    3.363  0.8407  0.0724  0.756  0.831  0.956  0.956  0.956  0.956     4    0    0    0       57878      14247      14469      14587  GET /recent/117 HTTP/1.1
    4    3.171  0.7928  0.0457  0.745  0.829  0.847  0.847  0.847  0.847     4    0    0    0       56305      13937      14076      14164  GET /recent/110 HTTP/1.1

Top 20 Sort By Total
Count    Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max   2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
 1597  456.422  0.2858  0.0926  0.027  0.277  0.400  0.440  0.576  0.786  1597    0    0    0    23966617      13478      15007      15755  GET / HTTP/1.1
 2703  195.617  0.0724  0.0612  0.000  0.057  0.157  0.192  0.250  0.406  2356    0  347    0     7208905         10       2667      58970  get memo
  648   53.648  0.0828  0.0620  0.001  0.069  0.171  0.201  0.258  0.334   648    0    0    0     7345738       1763      11336      20494  GET /mypage HTTP/1.1
  648   52.516  0.0810  0.0722  0.000  0.066  0.177  0.212  0.341  0.420   648    0    0    0      864432       1334       1334       1334  GET /signin HTTP/1.1
  648   47.104  0.0727  0.0593  0.002  0.059  0.160  0.186  0.246  0.411     0  648    0    0           0          0          0          0  POST /signin HTTP/1.1
  648   45.903  0.0708  0.0610  0.001  0.053  0.163  0.191  0.246  0.351     0  648    0    0           0          0          0          0  POST /memo HTTP/1.1
 3265   10.871  0.0033  0.0056  0.000  0.001  0.009  0.014  0.028  0.072  3265    0    0    0   346138975     106015     106015     106015  GET /css/bootstrap.min.css HTTP/1.1
 3265   10.754  0.0033  0.0059  0.000  0.001  0.010  0.015  0.027  0.079  3265    0    0    0    55011985      16849      16849      16849  GET /css/bootstrap-responsive.min.css HTTP/1.1
 3265   10.669  0.0033  0.0053  0.000  0.001  0.009  0.013  0.028  0.048  3265    0    0    0   303994355      93107      93107      93107  GET /js/jquery.min.js HTTP/1.1
 3265   10.244  0.0031  0.0054  0.000  0.001  0.009  0.014  0.027  0.049  3265    0    0    0    93480215      28631      28631      28631  GET /js/bootstrap.min.js HTTP/1.1
   11    9.704  0.8822  0.1050  0.773  0.854  1.005  1.088  1.088  1.088    11    0    0    0      152144      13479      13831      14009  GET /recent/205 HTTP/1.1
   10    8.809  0.8809  0.1253  0.714  0.830  1.085  1.085  1.085  1.085    10    0    0    0      139041      13307      13904      14075  GET /recent/206 HTTP/1.1
    5    5.022  1.0044  0.1392  0.886  0.963  1.276  1.276  1.276  1.276     5    0    0    0       70052      13927      14010      14070  GET /recent/204 HTTP/1.1
    5    4.054  0.8108  0.1003  0.677  0.847  0.917  0.917  0.917  0.917     5    0    0    0       69964      13641      13992      14175  GET /recent/131 HTTP/1.1
    6    3.897  0.6495  0.3062  0.215  0.727  1.002  1.002  1.002  1.002     6    0    0    0       82469      13452      13744      13910  GET /recent/207 HTTP/1.1
    5    3.727  0.7454  0.1342  0.482  0.813  0.848  0.848  0.848  0.848     5    0    0    0       70895      14009      14179      14309  GET /recent/147 HTTP/1.1
    4    3.363  0.8407  0.0724  0.756  0.831  0.956  0.956  0.956  0.956     4    0    0    0       57878      14247      14469      14587  GET /recent/117 HTTP/1.1
    4    3.171  0.7928  0.0457  0.745  0.829  0.847  0.847  0.847  0.847     4    0    0    0       56305      13937      14076      14164  GET /recent/110 HTTP/1.1
    3    3.008  1.0027  0.0536  0.947  0.986  1.075  1.075  1.075  1.075     3    0    0    0       41957      13707      13985      14153  GET /recent/150 HTTP/1.1
    3    2.984  0.9947  0.1985  0.789  0.932  1.263  1.263  1.263  1.263     3    0    0    0       41736      13817      13912      14028  GET /recent/173 HTTP/1.1

Top 20 Sort By Mean
Count  Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max  2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
    1  1.582  1.5820  0.0000  1.582  1.582  1.582  1.582  1.582  1.582    1    0    0    0       14305      14305      14305      14305  GET /recent/180 HTTP/1.1
    1  1.365  1.3650  0.0000  1.365  1.365  1.365  1.365  1.365  1.365    1    0    0    0       14162      14162      14162      14162  GET /recent/178 HTTP/1.1
    2  2.697  1.3485  0.0625  1.286  1.411  1.411  1.411  1.411  1.411    2    0    0    0       27711      13842      13855      13869  GET /recent/192 HTTP/1.1
    2  2.658  1.3290  0.1490  1.180  1.478  1.478  1.478  1.478  1.478    2    0    0    0       27194      13574      13597      13620  GET /recent/194 HTTP/1.1
    1  1.307  1.3070  0.0000  1.307  1.307  1.307  1.307  1.307  1.307    1    0    0    0       14306      14306      14306      14306  GET /recent/189 HTTP/1.1
    1  1.298  1.2980  0.0000  1.298  1.298  1.298  1.298  1.298  1.298    1    0    0    0       14333      14333      14333      14333  GET /recent/171 HTTP/1.1
    1  1.286  1.2860  0.0000  1.286  1.286  1.286  1.286  1.286  1.286    1    0    0    0       13966      13966      13966      13966  GET /recent/165 HTTP/1.1
    2  2.528  1.2640  0.0310  1.233  1.295  1.295  1.295  1.295  1.295    2    0    0    0       27723      13433      13861      14290  GET /recent/195 HTTP/1.1
    1  1.239  1.2390  0.0000  1.239  1.239  1.239  1.239  1.239  1.239    1    0    0    0       13662      13662      13662      13662  GET /recent/162 HTTP/1.1
    1  1.228  1.2280  0.0000  1.228  1.228  1.228  1.228  1.228  1.228    1    0    0    0       14221      14221      14221      14221  GET /recent/186 HTTP/1.1
    1  1.223  1.2230  0.0000  1.223  1.223  1.223  1.223  1.223  1.223    1    0    0    0       14480      14480      14480      14480  GET /recent/170 HTTP/1.1
    2  2.404  1.2020  0.0110  1.191  1.213  1.213  1.213  1.213  1.213    2    0    0    0       27191      13477      13595      13714  GET /recent/190 HTTP/1.1
    1  1.196  1.1960  0.0000  1.196  1.196  1.196  1.196  1.196  1.196    1    0    0    0       13383      13383      13383      13383  GET /recent/184 HTTP/1.1
    1  1.173  1.1730  0.0000  1.173  1.173  1.173  1.173  1.173  1.173    1    0    0    0       13717      13717      13717      13717  GET /recent/166 HTTP/1.1
    2  2.285  1.1425  0.0465  1.096  1.189  1.189  1.189  1.189  1.189    2    0    0    0       27982      13909      13991      14073  GET /recent/158 HTTP/1.1
    1  1.137  1.1370  0.0000  1.137  1.137  1.137  1.137  1.137  1.137    1    0    0    0       13736      13736      13736      13736  GET /recent/153 HTTP/1.1
    2  2.261  1.1305  0.0425  1.088  1.173  1.173  1.173  1.173  1.173    2    0    0    0       27652      13640      13826      14012  GET /recent/160 HTTP/1.1
    1  1.126  1.1260  0.0000  1.126  1.126  1.126  1.126  1.126  1.126    1    0    0    0       14315      14315      14315      14315  GET /recent/134 HTTP/1.1
    1  1.082  1.0820  0.0000  1.082  1.082  1.082  1.082  1.082  1.082    1    0    0    0       13640      13640      13640      13640  GET /recent/161 HTTP/1.1
    2  2.161  1.0805  0.2755  0.805  1.356  1.356  1.356  1.356  1.356    2    0    0    0       28808      14214      14404      14594  GET /recent/188 HTTP/1.1

Top 20 Sort By Standard Deviation
Count  Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max  2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
    2  1.301  0.6505  0.3275  0.323  0.978  0.978  0.978  0.978  0.978    2    0    0    0       27896      13752      13948      14144  GET /recent/177 HTTP/1.1
    6  3.897  0.6495  0.3062  0.215  0.727  1.002  1.002  1.002  1.002    6    0    0    0       82469      13452      13744      13910  GET /recent/207 HTTP/1.1
    2  1.622  0.8110  0.3040  0.507  1.115  1.115  1.115  1.115  1.115    2    0    0    0       27148      13569      13574      13579  GET /recent/137 HTTP/1.1
    3  2.303  0.7677  0.3021  0.399  0.765  1.139  1.139  1.139  1.139    3    0    0    0       43397      14147      14465      14657  GET /recent/95 HTTP/1.1
    2  1.274  0.6370  0.3010  0.336  0.938  0.938  0.938  0.938  0.938    2    0    0    0       27779      13839      13889      13940  GET /recent/115 HTTP/1.1
    2  1.423  0.7115  0.2965  0.415  1.008  1.008  1.008  1.008  1.008    2    0    0    0       27593      13455      13796      14138  GET /recent/193 HTTP/1.1
    2  1.172  0.5860  0.2930  0.293  0.879  0.879  0.879  0.879  0.879    2    0    0    0       27038      13359      13519      13679  GET /recent/181 HTTP/1.1
    2  1.484  0.7420  0.2850  0.457  1.027  1.027  1.027  1.027  1.027    2    0    0    0       27980      13876      13990      14104  GET /recent/163 HTTP/1.1
    2  2.161  1.0805  0.2755  0.805  1.356  1.356  1.356  1.356  1.356    2    0    0    0       28808      14214      14404      14594  GET /recent/188 HTTP/1.1
    2  1.393  0.6965  0.2635  0.433  0.960  0.960  0.960  0.960  0.960    2    0    0    0       29331      14558      14665      14773  GET /recent/128 HTTP/1.1
    2  0.829  0.4145  0.2415  0.173  0.656  0.656  0.656  0.656  0.656    2    0    0    0       28019      13974      14009      14045  GET /recent/59 HTTP/1.1
    2  2.129  1.0645  0.2375  0.827  1.302  1.302  1.302  1.302  1.302    2    0    0    0       27561      13755      13780      13806  GET /recent/164 HTTP/1.1
    3  2.677  0.8923  0.2258  0.649  0.835  1.193  1.193  1.193  1.193    3    0    0    0       41642      13733      13880      14120  GET /recent/167 HTTP/1.1
    2  0.920  0.4600  0.2130  0.247  0.673  0.673  0.673  0.673  0.673    2    0    0    0       28595      13990      14297      14605  GET /recent/114 HTTP/1.1
    3  1.518  0.5060  0.2109  0.222  0.569  0.727  0.727  0.727  0.727    3    0    0    0       42229      14037      14076      14098  GET /recent/111 HTTP/1.1
    3  1.538  0.5127  0.2046  0.225  0.630  0.683  0.683  0.683  0.683    3    0    0    0       42180      13959      14060      14246  GET /recent/88 HTTP/1.1
    3  2.984  0.9947  0.1985  0.789  0.932  1.263  1.263  1.263  1.263    3    0    0    0       41736      13817      13912      14028  GET /recent/173 HTTP/1.1
    4  2.814  0.7035  0.1937  0.409  0.864  0.890  0.890  0.890  0.890    4    0    0    0       58255      14434      14563      14680  GET /recent/124 HTTP/1.1
    3  1.123  0.3743  0.1784  0.135  0.425  0.563  0.563  0.563  0.563    3    0    0    0       43512      14032      14504      14828  GET /recent/61 HTTP/1.1
    2  1.868  0.9340  0.1780  0.756  1.112  1.112  1.112  1.112  1.112    2    0    0    0       28579      14209      14289      14370  GET /recent/141 HTTP/1.1

Top 20 Sort By Maximum(100 Percentile)
Count  Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max  2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
    1  1.582  1.5820  0.0000  1.582  1.582  1.582  1.582  1.582  1.582    1    0    0    0       14305      14305      14305      14305  GET /recent/180 HTTP/1.1
    2  2.658  1.3290  0.1490  1.180  1.478  1.478  1.478  1.478  1.478    2    0    0    0       27194      13574      13597      13620  GET /recent/194 HTTP/1.1
    2  2.697  1.3485  0.0625  1.286  1.411  1.411  1.411  1.411  1.411    2    0    0    0       27711      13842      13855      13869  GET /recent/192 HTTP/1.1
    1  1.365  1.3650  0.0000  1.365  1.365  1.365  1.365  1.365  1.365    1    0    0    0       14162      14162      14162      14162  GET /recent/178 HTTP/1.1
    2  2.161  1.0805  0.2755  0.805  1.356  1.356  1.356  1.356  1.356    2    0    0    0       28808      14214      14404      14594  GET /recent/188 HTTP/1.1
    1  1.307  1.3070  0.0000  1.307  1.307  1.307  1.307  1.307  1.307    1    0    0    0       14306      14306      14306      14306  GET /recent/189 HTTP/1.1
    2  2.129  1.0645  0.2375  0.827  1.302  1.302  1.302  1.302  1.302    2    0    0    0       27561      13755      13780      13806  GET /recent/164 HTTP/1.1
    1  1.298  1.2980  0.0000  1.298  1.298  1.298  1.298  1.298  1.298    1    0    0    0       14333      14333      14333      14333  GET /recent/171 HTTP/1.1
    2  2.528  1.2640  0.0310  1.233  1.295  1.295  1.295  1.295  1.295    2    0    0    0       27723      13433      13861      14290  GET /recent/195 HTTP/1.1
    1  1.286  1.2860  0.0000  1.286  1.286  1.286  1.286  1.286  1.286    1    0    0    0       13966      13966      13966      13966  GET /recent/165 HTTP/1.1
    5  5.022  1.0044  0.1392  0.886  0.963  1.276  1.276  1.276  1.276    5    0    0    0       70052      13927      14010      14070  GET /recent/204 HTTP/1.1
    3  2.984  0.9947  0.1985  0.789  0.932  1.263  1.263  1.263  1.263    3    0    0    0       41736      13817      13912      14028  GET /recent/173 HTTP/1.1
    1  1.239  1.2390  0.0000  1.239  1.239  1.239  1.239  1.239  1.239    1    0    0    0       13662      13662      13662      13662  GET /recent/162 HTTP/1.1
    1  1.228  1.2280  0.0000  1.228  1.228  1.228  1.228  1.228  1.228    1    0    0    0       14221      14221      14221      14221  GET /recent/186 HTTP/1.1
    1  1.223  1.2230  0.0000  1.223  1.223  1.223  1.223  1.223  1.223    1    0    0    0       14480      14480      14480      14480  GET /recent/170 HTTP/1.1
    2  2.404  1.2020  0.0110  1.191  1.213  1.213  1.213  1.213  1.213    2    0    0    0       27191      13477      13595      13714  GET /recent/190 HTTP/1.1
    1  1.196  1.1960  0.0000  1.196  1.196  1.196  1.196  1.196  1.196    1    0    0    0       13383      13383      13383      13383  GET /recent/184 HTTP/1.1
    3  2.677  0.8923  0.2258  0.649  0.835  1.193  1.193  1.193  1.193    3    0    0    0       41642      13733      13880      14120  GET /recent/167 HTTP/1.1
    2  2.285  1.1425  0.0465  1.096  1.189  1.189  1.189  1.189  1.189    2    0    0    0       27982      13909      13991      14073  GET /recent/158 HTTP/1.1
    2  2.261  1.1305  0.0425  1.088  1.173  1.173  1.173  1.173  1.173    2    0    0    0       27652      13640      13826      14012  GET /recent/160 HTTP/1.1

TOP 37 Slow Requests
 1  1.582  GET /recent/180 HTTP/1.1
 2  1.478  GET /recent/194 HTTP/1.1
 3  1.411  GET /recent/192 HTTP/1.1
 4  1.365  GET /recent/178 HTTP/1.1
 5  1.356  GET /recent/188 HTTP/1.1
 6  1.307  GET /recent/189 HTTP/1.1
 7  1.302  GET /recent/164 HTTP/1.1
 8  1.298  GET /recent/171 HTTP/1.1
 9  1.295  GET /recent/195 HTTP/1.1
10  1.286  GET /recent/192 HTTP/1.1
11  1.286  GET /recent/165 HTTP/1.1
12  1.276  GET /recent/204 HTTP/1.1
13  1.263  GET /recent/173 HTTP/1.1
14  1.239  GET /recent/162 HTTP/1.1
15  1.233  GET /recent/195 HTTP/1.1
16  1.228  GET /recent/186 HTTP/1.1
17  1.223  GET /recent/170 HTTP/1.1
18  1.213  GET /recent/190 HTTP/1.1
19  1.196  GET /recent/184 HTTP/1.1
20  1.193  GET /recent/167 HTTP/1.1
21  1.191  GET /recent/190 HTTP/1.1
22  1.189  GET /recent/158 HTTP/1.1
23  1.180  GET /recent/194 HTTP/1.1
24  1.173  GET /recent/160 HTTP/1.1
25  1.173  GET /recent/166 HTTP/1.1
26  1.139  GET /recent/95 HTTP/1.1
27  1.137  GET /recent/153 HTTP/1.1
28  1.126  GET /recent/134 HTTP/1.1
29  1.115  GET /recent/137 HTTP/1.1
30  1.112  GET /recent/141 HTTP/1.1
31  1.096  GET /recent/158 HTTP/1.1
32  1.093  GET /recent/156 HTTP/1.1
33  1.089  GET /recent/154 HTTP/1.1
34  1.088  GET /recent/160 HTTP/1.1
35  1.088  GET /recent/205 HTTP/1.1
36  1.085  GET /recent/206 HTTP/1.1
37  1.082  GET /recent/161 HTTP/1.1

slowquerylog

$ sudo mysqldumpslow /var/lib/mysql/mysql-slow.log

Reading mysql slow query log from /var/lib/mysql/mysql-slow.log
Count: 261  Time=0.51s (133s)  Lock=0.00s (0s)  Rows=100.0 (26100), isucon[isucon]@localhost
  SELECT id, user, content, is_private, created_at, updated_at, summary FROM memos WHERE is_private=N ORDER BY created_at DESC, memos.id DESC LIMIT N OFFSET N

Count: 1  Time=0.32s (0s)  Lock=0.00s (0s)  Rows=41175.0 (41175), isucon[isucon]@localhost
  SELECT id, content FROM memos

Count: 6  Time=0.14s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), isucon[isucon]@localhost
  #

Count: 1899  Time=0.12s (224s)  Lock=0.00s (0s)  Rows=1.0 (1899), isucon[isucon]@localhost
  SELECT count(*) AS c FROM memos WHERE is_private=N

Count: 6  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), 0users@0hosts
  administrator command: Prepare

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), 0users@0hosts
okashoi commented 4 years ago

あれ、 slowquery log は反映されてない?

SELECT id, user, content, is_private, created_at, updated_at, summary FROM memos WHERE is_private=N ORDER BY created_at DESC, memos.id DESC LIMIT N OFFSET N