HackMD
CA Backend tuning contest
初期: 748
11:20
動作中のsystemdサービス
systemctl list-unit-files | grep enable
snap-core-9066.mount enabled
snap-core-9289.mount enabled
snap-core18-1754.mount enabled
snap-google\x2dcloud\x2dsdk-133.mount enabled
snap-google\x2dcloud\x2dsdk-134.mount enabled
acpid.path enabled
apport-autoreport.path enabled
accounts-daemon.service enabled
apparmor.service enabled
atd.service enabled
autovt@.service enabled
blk-availability.service enabled
btc-php.service enabled
chrony.service enabled
chronyd.service enabled
cloud-config.service enabled
cloud-final.service enabled
cloud-init-local.service enabled
cloud-init.service enabled
console-setup.service enabled
cron.service enabled
dbus-org.freedesktop.resolve1.service enabled
ebtables.service enabled
getty@.service enabled
google-accounts-daemon.service enabled
google-clock-skew-daemon.service enabled
google-instance-setup.service enabled
google-network-daemon.service enabled
google-shutdown-scripts.service enabled
google-startup-scripts.service enabled
iscsi.service enabled
keyboard-setup.service enabled
lvm2-monitor.service enabled
lxcfs.service enabled
lxd-containers.service enabled
mysql.service enabled
networkd-dispatcher.service enabled
nginx.service enabled
ondemand.service enabled
open-iscsi.service enabled
open-vm-tools.service enabled
pollinate.service enabled
redis-server.service enabled
redis.service enabled
rsync.service enabled
rsyslog.service enabled
setvtrgb.service enabled
snapd.autoimport.service enabled
snapd.core-fixup.service enabled
snapd.seeded.service enabled
snapd.service enabled
snapd.system-shutdown.service enabled
ssh.service enabled
sshd.service enabled
sshguard.service enabled
syslog.service enabled
systemd-networkd-wait-online.service enabled
systemd-networkd.service enabled
systemd-resolved.service enabled
systemd-timesyncd.service enabled
ufw.service enabled
unattended-upgrades.service enabled
ureadahead.service enabled
vgauth.service enabled
vmtoolsd.service enabled
acpid.socket enabled
apport-forward.socket enabled
dm-event.socket enabled
iscsid.socket enabled
lvm2-lvmetad.socket enabled
lvm2-lvmpolld.socket enabled
lxd.socket enabled
snapd.socket enabled
systemd-networkd.socket enabled
uuidd.socket enabled
cloud-init.target enabled-runtime
remote-fs.target enabled
apt-daily-upgrade.timer enabled
apt-daily.timer enabled
fstrim.timer enabled
motd-news.timer enabled
phpsessionclean.timer enabled
snapd.snap-repair.timer enabled
Goに実装を切り替える: 744
11:30
どこに実装が置いてあるかわかんなかったのでsystemdの設定ファイルを見に行く。
/etc/systemd/system$ cat btc-go.service
[Unit]
Description=Backend Turning Competition Go Application
After=network.target
[Service]
WorkingDirectory=/var/www/html/webapp/go
ExecStart=/usr/bin/make run
Environment="GOPATH=/var/www/html/webapp/go"
User=www-data
Group=www-data
[Install]
WantedBy=multi-user.target
便利コマンドがあったので実装をGoに切り替え
sudo changelang go
goが動くようになったので、サービスのstatusは以下で見れる.
sudo systemctl status btc-go.service
編集内容を反映させるにはapp.goをビルドし直さなきゃいけなくてマジめんどい、Makefileでうまいことやることにする.
最初のディレクトリ構成はこんな感じ
Image Not Showing
Possible Reasons
- The image file may be corrupted
- The server hosting the image is unavailable
- The image path is incorrect
- The image format is not supported
htmlテンプレートがたくさんあるのでN+1の予感がする、細かく見た方がよさそう
htopをしつつベンチを回してみると、mysqlがほとんどを占めていたのでDBの改善が先っぽい。
めんどくさいので全部sudoでやります().
各種設定
12:00
いろいろ見てたら遅くなっちゃった。
htopやslackcatを入れたりしていた。Git管理も。
https://github.com/hppRC/ca-backend-tuning
各種ツールの導入はこんな感じ.
sudo apt update
sudo apt install -y percona-toolkit dstat git unzip snapd htop graphviz
git config --global user.email "hpp.ricecake@gmail.com"
git config --global user.name "hppRC"
wget https://github.com/matsuu/kataribe/releases/download/v0.4.1/kataribe-v0.4.1_linux_amd64.zip -O kataribe.zip
unzip -o kataribe.zip
sudo mv kataribe /usr/local/bin/
sudo chmod +x /usr/local/bin/kataribe
rm kataribe.zip
kataribe -generate
wget https://github.com/tkuchiki/alp/releases/download/v0.3.1/alp_linux_amd64.zip
apt install unzip
unzip alp_linux_amd64.zip
mv alp /usr/local/bin/
wget https://github.com/KLab/myprofiler/releases/download/0.2/myprofiler.linux_amd64.tar.gz
tar xf myprofiler.linux_amd64.tar.gz
rm myprofiler.linux_amd64.tar.gz
sudo mv myprofiler /usr/local/bin/
sudo chmod +x /usr/local/bin/myprofiler
wget https://github.com/bcicen/slackcat/releases/download/v1.5/slackcat-1.5-linux-amd64 -O slackcat
sudo mv slackcat /usr/local/bin/
sudo chmod +x /usr/local/bin/slackcat
slackcat --configure
GitHubのSSH keyを追加したりもしたぜ。
nginxの各種confファイルをGit管理下においてシンボリックリンク貼っているのだけど、怖すぎるので変更する度にベンチ回しています。
nginxをいじるくん
12:30
下みたいにログの出力形式を指定してconf.d配下に置いた.
log_format ltsv "time:$time_local"
"\thost:$remote_addr"
"\tforwardedfor:$http_x_forwarded_for"
"\treq:$request"
"\tstatus:$status"
"\tmethod:$request_method"
"\turi:$request_uri"
"\tsize:$body_bytes_sent"
"\treferer:$http_referer"
"\tua:$http_user_agent"
"\treqtime:$request_time"
"\tcache:$upstream_http_x_cache"
"\truntime:$upstream_http_x_runtime"
"\tapptime:$upstream_response_time"
"\tvhost:$host";
access_log /var/log/nginx/access.log ltsv;
昼飯を食べた
12:45
とーふとふさんのMakefileを参考にタスクランナーをいい感じにする
あとSlackcatでログの確認。
MySQLがシンボリックリンクでも動くかどうかを確認.
pprofの使い方わからんが
とかなんとかいいながらいろいろなツールを整える。pprofの出力をいい感じにしてslackに投げるタスクを書いた。
ほぼ初期状態だけどpprofを入れたのがこんな感じ。htmlのrenderingがかなり重そう。
alpのログは以下(aggregateしたあと).
+-------+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+--------+------------------------------+
| COUNT | MIN | MAX | SUM | AVG | P1 | P50 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) | METHOD | URI |
+-------+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+--------+------------------------------+
| 3 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 613.000 | 613.000 | 1839.000 | 613.000 | GET | /regist |
| 3 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 1359.000 | 1359.000 | 4077.000 | 1359.000 | GET | /css/bootstrap-tagsinput.css |
| 9 | 0.000 | 0.004 | 0.004 | 0.000 | 0.000 | 0.000 | 0.000 | 0.001 | 29.000 | 1128.000 | 3558.000 | 395.333 | GET | /write |
| 3 | 0.001 | 0.002 | 0.005 | 0.002 | 0.001 | 0.001 | 0.002 | 0.000 | 122540.000 | 122540.000 | 367620.000 | 122540.000 | GET | /css/bootstrap.min.css |
| 12 | 0.004 | 0.004 | 0.008 | 0.001 | 0.000 | 0.000 | 0.004 | 0.001 | 29.000 | 29.000 | 348.000 | 29.000 | GET | /logout |
| 9 | 0.004 | 0.004 | 0.008 | 0.001 | 0.000 | 0.000 | 0.004 | 0.002 | 29.000 | 1407.000 | 4394.000 | 488.222 | GET | /update |
| 9 | 0.004 | 0.004 | 0.008 | 0.001 | 0.000 | 0.000 | 0.004 | 0.002 | 29.000 | 1883.000 | 5823.000 | 647.000 | GET | /profileupdate |
| 1701 | 0.000 | 0.004 | 0.010 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 34143.000 | 48418.000 | 66711024.000 | 39218.709 | GET | /photo |
| 3 | 0.004 | 0.004 | 0.012 | 0.004 | 0.004 | 0.004 | 0.004 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | POST | /regist |
| 3 | 0.004 | 0.008 | 0.020 | 0.007 | 0.004 | 0.004 | 0.008 | 0.002 | 0.000 | 0.000 | 0.000 | 0.000 | POST | /write |
| 3 | 0.008 | 0.008 | 0.024 | 0.008 | 0.008 | 0.008 | 0.008 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | POST | /update |
| 3 | 0.008 | 0.012 | 0.028 | 0.009 | 0.008 | 0.008 | 0.008 | 0.002 | 0.000 | 0.000 | 0.000 | 0.000 | POST | /profileupdate |
| 42 | 0.004 | 0.004 | 0.056 | 0.001 | 0.000 | 0.000 | 0.004 | 0.002 | 739.000 | 739.000 | 31038.000 | 739.000 | GET | /login |
| 45 | 0.004 | 0.012 | 0.116 | 0.003 | 0.000 | 0.004 | 0.012 | 0.003 | 0.000 | 0.000 | 0.000 | 0.000 | POST | /login |
| 9 | 0.036 | 0.056 | 0.420 | 0.047 | 0.036 | 0.044 | 0.052 | 0.007 | 0.000 | 0.000 | 0.000 | 0.000 | GET | /initialize |
| 39 | 0.012 | 0.088 | 1.296 | 0.033 | 0.012 | 0.032 | 0.060 | 0.014 | 1.000 | 1.000 | 39.000 | 1.000 | POST | /iine |
| 54 | 0.004 | 0.160 | 4.013 | 0.074 | 0.000 | 0.080 | 0.148 | 0.046 | 29.000 | 9182.000 | 178236.000 | 3300.667 | GET | /article |
| 132 | 0.008 | 0.456 | 12.169 | 0.092 | 0.000 | 0.084 | 0.428 | 0.089 | 29.000 | 10565.000 | 267035.000 | 2022.992 | GET | /member |
| 39 | 0.264 | 0.928 | 16.028 | 0.411 | 0.000 | 0.368 | 0.924 | 0.260 | 29.000 | 9131.000 | 86767.000 | 2224.795 | GET | /tag/\d+ |
| 66 | 0.672 | 2.448 | 110.428 | 1.673 | 0.000 | 2.092 | 2.392 | 0.777 | 29.000 | 1720.000 | 97957.000 | 1484.197 | GET | /tags |
| 196 | 0.884 | 1.764 | 148.960 | 0.760 | 0.000 | 0.956 | 1.672 | 0.472 | 29.000 | 28041.000 | 1800031.000 | 9183.832 | GET | / |
+-------+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+--------+------------------------------+
tagsが馬鹿なのでこれを直す。
あとphotoがDBから画像引っ張ってくるやつになってる。これも直せたらいつものISUCONだと劇的にスコア上がる気がするが、pprofのGetPhotoはそんなに重くなさそうで謎。もしかして全然呼ばれてなかったり重くない処理なのか。
14:15
プロファイリングしてビルドしなおして、っていうサイクルになれるまでにかなり時間がかかってしまった。がんばるぞい。
tag countをオンメモリに
14:40
した後のalpがこれ。
+-------+-------+-------+--------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+--------+------------------------------+
| COUNT | MIN | MAX | SUM | AVG | P1 | P50 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) | METHOD | URI |
+-------+-------+-------+--------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+--------+------------------------------+
| 1 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 613.000 | 613.000 | 613.000 | 613.000 | GET | /regist |
| 4 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 29.000 | 29.000 | 116.000 | 29.000 | GET | /logout |
| 2 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 29.000 | 1126.000 | 1155.000 | 577.500 | GET | /write |
| 1 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 1359.000 | 1359.000 | 1359.000 | 1359.000 | GET | /css/bootstrap-tagsinput.css |
| 567 | 0.000 | 0.001 | 0.001 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 34143.000 | 48418.000 | 22237008.000 | 39218.709 | GET | /photo |
| 1 | 0.001 | 0.001 | 0.001 | 0.001 | 0.001 | 0.001 | 0.001 | 0.000 | 122540.000 | 122540.000 | 122540.000 | 122540.000 | GET | /css/bootstrap.min.css |
| 1 | 0.004 | 0.004 | 0.004 | 0.004 | 0.004 | 0.004 | 0.004 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | POST | /regist |
| 2 | 0.004 | 0.004 | 0.004 | 0.002 | 0.000 | 0.000 | 0.000 | 0.002 | 29.000 | 1412.000 | 1441.000 | 720.500 | GET | /update |
| 2 | 0.004 | 0.004 | 0.004 | 0.002 | 0.000 | 0.000 | 0.000 | 0.002 | 29.000 | 1889.000 | 1918.000 | 959.000 | GET | /profileupdate |
| 1 | 0.004 | 0.004 | 0.004 | 0.004 | 0.004 | 0.004 | 0.004 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | POST | /write |
| 12 | 0.000 | 0.004 | 0.008 | 0.001 | 0.000 | 0.000 | 0.004 | 0.001 | 739.000 | 739.000 | 8868.000 | 739.000 | GET | /login |
| 1 | 0.008 | 0.008 | 0.008 | 0.008 | 0.008 | 0.008 | 0.008 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | POST | /update |
| 1 | 0.012 | 0.012 | 0.012 | 0.012 | 0.012 | 0.012 | 0.012 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | POST | /profileupdate |
| 13 | 0.004 | 0.016 | 0.052 | 0.004 | 0.000 | 0.004 | 0.008 | 0.004 | 0.000 | 0.000 | 0.000 | 0.000 | POST | /login |
| 2 | 0.044 | 0.068 | 0.112 | 0.056 | 0.044 | 0.044 | 0.044 | 0.012 | 0.000 | 0.000 | 0.000 | 0.000 | GET | /initialize |
| 13 | 0.012 | 0.048 | 0.412 | 0.032 | 0.012 | 0.032 | 0.044 | 0.010 | 1.000 | 1.000 | 13.000 | 1.000 | POST | /iine |
| 17 | 0.032 | 0.156 | 1.272 | 0.075 | 0.000 | 0.064 | 0.132 | 0.044 | 29.000 | 9182.000 | 58539.000 | 3443.471 | GET | /article |
| 42 | 0.004 | 0.724 | 4.465 | 0.106 | 0.000 | 0.093 | 0.548 | 0.131 | 29.000 | 10930.000 | 93162.000 | 2218.143 | GET | /member |
| 12 | 0.280 | 0.820 | 5.440 | 0.453 | 0.000 | 0.384 | 0.812 | 0.217 | 29.000 | 9121.000 | 28894.000 | 2407.833 | GET | /tag/\d+ |
| 21 | 0.672 | 2.460 | 36.289 | 1.728 | 0.000 | 2.072 | 2.332 | 0.700 | 29.000 | 1719.000 | 32603.000 | 1552.524 | GET | /tags |
| 62 | 0.808 | 1.724 | 50.192 | 0.810 | 0.000 | 0.964 | 1.452 | 0.437 | 29.000 | 27939.000 | 600168.000 | 9680.129 | GET | / |
+-------+-------+-------+--------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+--------+------------------------------+
そういえばslow query logを貼ってなかった.
# 3.6s user time, 50ms system time, 29.91M rss, 85.07M vsz
# Current date: Sat Jun 6 15:10:59 2020
# Hostname: btc202006-tsukagoshi-hayato
# Files: /tmp/slow-query.log
# Overall: 43.00k total, 50 unique, 101.17 QPS, 0.21x concurrency ________
# Time range: 2020-06-06T04:47:18 to 2020-06-06T04:54:23
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 91s 1us 183ms 2ms 9ms 11ms 80us
# Lock time 460ms 0 9ms 10us 28us 122us 0
# Rows sent 25.36k 0 61 0.60 0.99 3.08 0
# Rows examine 163.83M 0 207.12k 3.90k 6.63k 21.54k 0
# Query size 1.59M 6 99.41k 38.83 56.92 479.20 31.70
# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ============= ===== ====== ===== ===============
# 1 0x2D7EEF3460ECBFB5 38.1273 41.8% 410 0.0930 0.01 SELECT article_relate_tags
# 2 0xEA5D2FD18109D465 29.5050 32.3% 1210 0.0244 0.00 SELECT iines
# 3 0x481F52E8533643C5 7.0543 7.7% 286 0.0247 0.01 SELECT iines
# 4 0xBA36CB1FA5DC0A93 5.1040 5.6% 54 0.0945 0.01 SELECT iines
# 5 0x99AA0165670CE848 2.0260 2.2% 14206 0.0001 0.00 ADMIN PREPARE
# 6 0x831AD2FB940FC23C 1.9161 2.1% 1218 0.0016 0.01 SELECT users
# 7 0xFE31CC2369854C56 1.8987 2.1% 8741 0.0002 0.00 SELECT tags
# 8 0x6E26BAAAB968BC09 1.8551 2.0% 420 0.0044 0.00 SELECT articles
# MISC 0xMISC 3.7839 4.1% 16453 0.0002 0.0 <42 ITEMS>
# Query 1: 9.53 QPS, 0.89x concurrency, ID 0x2D7EEF3460ECBFB5 at byte 9036145
# Scores: V/M = 0.01
# Time range: 2020-06-06T04:51:38 to 2020-06-06T04:52:21
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 410
# Exec time 41 38s 34ms 179ms 93ms 141ms 34ms 95ms
# Lock time 3 15ms 14us 3ms 37us 49us 147us 23us
# Rows sent 1 410 1 1 1 1 0 1
# Rows examine 50 82.93M 207.12k 207.12k 207.12k 201.74k 0 201.74k
# Query size 1 26.41k 64 68 65.97 65.89 0.88 65.89
# String:
# Databases hidakkathon
# Hosts localhost
# Users ubuntu
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms ######################################################
# 100ms ################################################################
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `hidakkathon` LIKE 'article_relate_tags'\G
# SHOW CREATE TABLE `hidakkathon`.`article_relate_tags`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT COUNT(*) as cnt FROM article_relate_tags WHERE tag_id = 270\G
めっちゃ遅い
1 0x2D7EEF3460ECBFB5 38.1273 41.8% 410 0.0930 0.01 SELECT article_relate_tags
あといろんなところにインデックスを貼った。
ALTER TABLE tags ADD INDEX index_tags_on_tagname(tagname);
ALTER TABLE articles ADD INDEX index_articles_on_author_id(author_id);
ALTER TABLE iines ADD INDEX index_iines_on_user_article_id(article_id, user_id);
initializeの時にmapで各tagの記事の個数をとかを持つようにした: 1363
16:00
時間かけすぎでは
var cnt int
var tag_id int
rows, err := db.Query("SELECT COUNT(*) as cnt, tag_id FROM article_relate_tags GROUP BY tag_id");
if err != nil {
panic(err)
}
defer rows.Close()
for rows.Next() {
err := rows.Scan(&cnt, &tag_id)
if err != nil {
panic(err)
}
tagsCounts[tag_id] = cnt
}
ここでslow-query-logがオフになっているのに気付く。mysqlのserviceをrestartしたらそりゃ設定した値元に戻るよね…という気持ちに
この時点のpt-query-digest
# 12.3s user time, 30ms system time, 30.02M rss, 85.08M vsz
# Current date: Sat Jun 6 16:26:44 2020
# Hostname: btc202006-tsukagoshi-hayato
# Files: /tmp/slow-query.log
# Overall: 156.04k total, 51 unique, 796.13 QPS, 0.28x concurrency _______
# Time range: 2020-06-06T07:22:56 to 2020-06-06T07:26:12
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 56s 1us 329ms 355us 366us 6ms 63us
# Lock time 2s 0 10ms 11us 36us 82us 0
# Rows sent 96.29k 0 999 0.63 0.99 4.86 0
# Rows examine 17.55M 0 209.07k 117.91 0.99 3.25k 0
# Query size 5.44M 6 99.41k 36.55 56.92 251.73 31.70
# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ============= ===== ====== ===== ===============
# 1 0xBA36CB1FA5DC0A93 30.9580 55.8% 167 0.1854 0.01 SELECT iines
# 2 0xFE31CC2369854C56 6.0724 10.9% 35132 0.0002 0.00 SELECT tags
# 3 0x99AA0165670CE848 5.9193 10.7% 51607 0.0001 0.00 ADMIN PREPARE
# 4 0x54DF8FFA57472495 3.9759 7.2% 33 0.1205 0.03 SELECT article_relate_tags
# 5 0xD6D8F9E7EE1D3C81 2.0144 3.6% 167 0.0121 0.01 SELECT articles
# 6 0x0B76102AE62842B0 1.4191 2.6% 3938 0.0004 0.00 SELECT article_relate_tags
# 7 0xEA5D2FD18109D465 0.9895 1.8% 3971 0.0002 0.00 SELECT iines
# 8 0x831AD2FB940FC23C 0.9658 1.7% 4003 0.0002 0.00 SELECT users
# 9 0x481F52E8533643C5 0.5609 1.0% 873 0.0006 0.00 SELECT iines
# MISC 0xMISC 2.6394 4.8% 56150 0.0000 0.0 <42 ITEMS>
# Query 1: 4.07 QPS, 0.76x concurrency, ID 0xBA36CB1FA5DC0A93 at byte 10093620
# Scores: V/M = 0.01
# Time range: 2020-06-06T07:25:31 to 2020-06-06T07:26:12
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 167
# Exec time 55 31s 57ms 329ms 185ms 253ms 50ms 189ms
# Lock time 2 50ms 62us 8ms 298us 761us 837us 113us
# Rows sent 0 835 5 5 5 5 0 5
# Rows examine 48 8.59M 52.66k 52.70k 52.68k 51.46k 0 51.46k
# Query size 0 33.92k 208 208 208 208 0 208
# String:
# Databases hidakkathon
# Hosts localhost
# Users ubuntu
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms ###
# 100ms ################################################################
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `hidakkathon` LIKE 'iines'\G
# SHOW CREATE TABLE `hidakkathon`.`iines`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT
article_id,
count(user_id) as iineCnt
FROM
iines
WHERE
updated_at >= DATE_ADD(NOW(), INTERVAL -1 MONTH)
GROUP BY
article_id
ORDER BY
iineCnt DESC,
article_id DESC
LIMIT 5\G
ここにきてiinesが一番重たくなっている、mapで持つ改善は大成功だったようだ(やったぜ)。
ただ、DELETEした時の記事数の更新が出来てないと思うので要注意。
ALTER TABLE iines ADD INDEX index_iines_on_updated_at(updated_at);
上記のようにupdated_atにINDEXを追加したが、使えていなさそう。何が原因だろう。
EXPLAIN SELECT article_id, count(user_id) as iineCnt FROM iines WHERE updated_at >= DATE_ADD(NOW(), INTERVAL -1 MONTH) GROUP BY article_id ORDER BY iineCnt DESC, article_id DESC LIMIT 5;
+----+-------------+-------+------------+-------+----------------------------------------------------------+--------------------------------+---------+------+-------+----------+----------------------------------------------+
| id | select_type | table | partitions | type | possible_keys | key | key_len | ref | rows | filtered | Extra |
+----+-------------+-------+------------+-------+----------------------------------------------------------+--------------------------------+---------+------+-------+----------+----------------------------------------------+
| 1 | SIMPLE | iines | NULL | index | index_iines_on_user_article_id,index_iines_on_updated_at | index_iines_on_user_article_id | 8 | NULL | 50172 | 50.00 | Using where; Using temporary; Using filesort |
+----+-------------+-------+------------+-------+----------------------------------------------------------+--------------------------------+---------+------+-------+----------+----------------------------------------------+
各article_idごとのいいねの数が欲しい(sortしたいので)。
redis-cliで中に入ってredisがどんな感じになってるか見てみる.
redis-cli
これでいいね数に応じて昇順に5個取得
ZREVRANGE iine_by_article 0 4 WITHSCORES
Goのコードではこんな感じに取り出す。
keys, _ := redis.Strings(redisClient.Do("ZREVRANGE", "iine_by_article", 0, 4))
for _, key := range keys {
fmt.Println("%s", key)
}
redisClientの排他制御ができなくて死んでいます
19:30
くそが代
まだ死んでます
21:30
Mutex使えばいけそう
勝ち申した(勝ってない): 1855
22:30
redisのconnection poolを使うようにしたらスコア爆上がりした、天才
mutexはロック時間が長過ぎて死んでるので却下.
poolの作り方はこんな感じ.varでglobalに宣言しておく.
これ参照.
pool = &redis.Pool{
MaxIdle: 1000,
IdleTimeout: 240 * time.Second,
Dial: func () (redis.Conn, error) {
c, err := redis.Dial("tcp", rhost+":"+rport)
if err != nil {
log.Fatalf("Failed to connect to Redis: %s.", err.Error())
}
return c, err
},
TestOnBorrow: func(c redis.Conn, t time.Time) error {
_, err := c.Do("PING")
return err
},
}
使い方はこんなん.
conn := pool.Get()
defer conn.Close()
なんかTCPのコネクション数増やしたり
22:43
スコア上がってからのslow-query-logはこんな感じ。認証系がボトルネックになってきてる感がある。そういえばMySQLでSHA2をやっている、遅そう。Goのそれ用のパッケージ入れた方がいい気がする。
# 16.8s user time, 60ms system time, 29.93M rss, 85.03M vsz
# Current date: Sat Jun 6 22:42:41 2020
# Hostname: btc202006-tsukagoshi-hayato
# Files: /tmp/slow-query.log
# Overall: 215.93k total, 46 unique, 5.14k QPS, 0.72x concurrency ________
# Time range: 2020-06-06T13:38:24 to 2020-06-06T13:39:06
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 30s 1us 261ms 139us 332us 2ms 57us
# Lock time 3s 0 8ms 12us 27us 72us 0
# Rows sent 138.72k 0 3.80k 0.66 0.99 12.41 0
# Rows examine 11.40M 0 209.07k 55.35 0.99 2.57k 0
# Query size 7.45M 6 99.41k 36.19 56.92 214.01 31.70
# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ============= ===== ====== ===== ===============
# 1 0x99AA0165670CE848 8.1908 27.1% 71258 0.0001 0.00 ADMIN PREPARE
# 2 0xFE31CC2369854C56 7.0085 23.2% 48003 0.0001 0.00 SELECT tags
# 3 0x54DF8FFA57472495 4.9512 16.4% 40 0.1238 0.02 SELECT article_relate_tags
# 4 0xD6D8F9E7EE1D3C81 2.7144 9.0% 235 0.0116 0.01 SELECT articles
# 5 0x0B76102AE62842B0 1.3516 4.5% 5545 0.0002 0.00 SELECT article_relate_tags
# 6 0xEA5D2FD18109D465 1.3021 4.3% 5585 0.0002 0.00 SELECT iines
# 7 0x831AD2FB940FC23C 0.9161 3.0% 5644 0.0002 0.00 SELECT users
# 8 0x80D67BB0DB0CAF9B 0.6488 2.1% 235 0.0028 0.00 SELECT articles
# 9 0x111FD2D3F3B3B4EB 0.6285 2.1% 71258 0.0000 0.00 ADMIN CLOSE STMT
# 10 0x6E26BAAAB968BC09 0.4478 1.5% 2100 0.0002 0.00 SELECT articles
# 11 0xB6B92D185D7FD205 0.3553 1.2% 1787 0.0002 0.00 SELECT articles
# 12 0x481F52E8533643C5 0.3276 1.1% 1219 0.0003 0.00 SELECT iines
# MISC 0xMISC 1.3413 4.4% 3018 0.0004 0.0 <34 ITEMS>
# Query 1: 1.78k QPS, 0.20x concurrency, ID 0x99AA0165670CE848 at byte 35039548
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2020-06-06T13:38:25 to 2020-06-06T13:39:05
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 33 71258
# Exec time 27 8s 23us 10ms 114us 332us 230us 60us
# Lock time 0 0 0 0 0 0 0 0
# Rows sent 0 0 0 0 0 0 0 0
# Rows examine 0 0 0 0 0 0 0 0
# Query size 27 2.04M 30 30 30 30 0 30
# String:
# Databases hidakkathon
# Hosts localhost
# Users ubuntu
# Query_time distribution
# 1us
# 10us ################################################################
# 100us #################
# 1ms #
# 10ms #
# 100ms
# 1s
# 10s+
administrator command: Prepare\G
そういえばLIMIT 1を全然つけてないことを思い出したので、様子見ながらつけた。
ADMIN PREPAREはprepared statementを作るやつで発行されるクエリなので、prepareしすぎ。
あとMySQLのmysql.conf.dのmysql.cnfの権限が過剰だったので読めていないことに気づいた。読み取りだけにする。
chmod 444 /etc/mysql/mysql.conf.d/mysql.cnf
調べた感じグローバルでstmtを持っておいてprepareするのが良さそう(https://qiita.com/methane/items/a9803388ff4a5a985b4d)
N+1クエリの改善: 2250
23:20
やっと楽しいところという感じ.1850 -> 2250に上昇。
rows, err := db.Query(`SELECT tag_id, tagname FROM article_relate_tags INNER JOIN tags ON article_relate_tags.tag_id=tags.id WHERE article_id = ? ORDER BY tag_id ASC`, articleID)
if err != nil && err != sql.ErrNoRows {
return nil, err
}
var tagNames []TagName
for rows.Next() {
var tagID int
var tagName string
if err := rows.Scan(&tagID, &tagName); err != nil {
return nil, err
}
// row := db.QueryRow(`SELECT tagname FROM tags WHERE id = ?`, tagID)
// var tagName string
// if err := row.Scan(&tagName); err != nil {
// return nil, err
// }
tagNames = append(tagNames, TagName{ID: tagID, Name: tagName})
}
rows.Close()
pprofのWebUIが見たい！: 2290
0:30
見れません。
go tool pprof -http=":8888" http://localhost:6060/debug/pprof/profile
外からアクセスしても見れなかった、なんかわかってない気がする。
とりあえず今の時点のpprofの結果を貼っておく.
alpの結果も.
+-------+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+---------------+------------+--------+------------------------------+
| COUNT | MIN | MAX | SUM | AVG | P1 | P50 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) | METHOD | URI |
+-------+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+---------------+------------+--------+------------------------------+
| 6 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 1359.000 | 1359.000 | 8154.000 | 1359.000 | GET | /css/bootstrap-tagsinput.css |
| 6 | 0.000 | 0.004 | 0.004 | 0.001 | 0.000 | 0.000 | 0.000 | 0.001 | 613.000 | 613.000 | 3678.000 | 613.000 | GET | /regist |
| 6 | 0.002 | 0.002 | 0.005 | 0.001 | 0.000 | 0.001 | 0.001 | 0.001 | 122540.000 | 122540.000 | 735240.000 | 122540.000 | GET | /css/bootstrap.min.css |
| 13 | 0.004 | 0.004 | 0.008 | 0.001 | 0.000 | 0.000 | 0.004 | 0.001 | 29.000 | 1889.000 | 11512.000 | 885.538 | GET | /profileupdate |
| 13 | 0.000 | 0.004 | 0.012 | 0.001 | 0.000 | 0.000 | 0.004 | 0.002 | 29.000 | 1412.000 | 8651.000 | 665.462 | GET | /update |
| 13 | 0.000 | 0.004 | 0.016 | 0.001 | 0.000 | 0.000 | 0.004 | 0.002 | 29.000 | 1129.000 | 6968.000 | 536.000 | GET | /write |
| 7098 | 0.000 | 0.004 | 0.017 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 34143.000 | 48418.000 | 274863600.000 | 38724.091 | GET | /photo |
| 6 | 0.004 | 0.008 | 0.032 | 0.005 | 0.004 | 0.004 | 0.008 | 0.002 | 0.000 | 0.000 | 0.000 | 0.000 | POST | /regist |
| 6 | 0.004 | 0.008 | 0.036 | 0.006 | 0.004 | 0.004 | 0.008 | 0.002 | 0.000 | 0.000 | 0.000 | 0.000 | POST | /write |
| 6 | 0.004 | 0.008 | 0.040 | 0.007 | 0.004 | 0.008 | 0.008 | 0.002 | 0.000 | 0.000 | 0.000 | 0.000 | POST | /update |
| 6 | 0.008 | 0.012 | 0.060 | 0.010 | 0.008 | 0.008 | 0.012 | 0.002 | 0.000 | 0.000 | 0.000 | 0.000 | POST | /profileupdate |
| 156 | 0.000 | 0.012 | 0.188 | 0.001 | 0.000 | 0.000 | 0.012 | 0.002 | 29.000 | 29.000 | 4524.000 | 29.000 | GET | /logout |
| 296 | 0.000 | 0.012 | 0.364 | 0.001 | 0.000 | 0.000 | 0.008 | 0.002 | 739.000 | 739.000 | 218744.000 | 739.000 | GET | /login |
| 299 | 0.000 | 0.020 | 0.876 | 0.003 | 0.000 | 0.004 | 0.012 | 0.003 | 0.000 | 0.000 | 0.000 | 0.000 | POST | /login |
| 475 | 0.004 | 0.044 | 4.629 | 0.010 | 0.004 | 0.008 | 0.028 | 0.006 | 1.000 | 2.000 | 492.000 | 1.036 | POST | /iine |
| 500 | 0.004 | 0.048 | 5.264 | 0.011 | 0.000 | 0.008 | 0.036 | 0.006 | 29.000 | 10067.000 | 2113264.000 | 4226.528 | GET | /article |
| 856 | 0.004 | 0.044 | 6.424 | 0.008 | 0.000 | 0.008 | 0.024 | 0.005 | 29.000 | 1765.000 | 1378802.000 | 1610.750 | GET | /tags |
| 13 | 0.492 | 0.580 | 6.853 | 0.527 | 0.492 | 0.504 | 0.577 | 0.032 | 0.000 | 0.000 | 0.000 | 0.000 | GET | /initialize |
| 1715 | 0.004 | 0.160 | 41.227 | 0.024 | 0.000 | 0.024 | 0.072 | 0.016 | 29.000 | 11896.000 | 4056858.000 | 2365.515 | GET | /member |
| 473 | 0.052 | 0.532 | 89.030 | 0.188 | 0.000 | 0.188 | 0.337 | 0.066 | 29.000 | 38694.000 | 3592627.000 | 7595.406 | GET | /tag/\d+ |
| 2213 | 0.000 | 0.424 | 348.093 | 0.157 | 0.000 | 0.164 | 0.288 | 0.057 | 29.000 | 46025.000 | 25087922.000 | 11336.612 | GET | / |
+-------+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+---------------+------------+--------+------------------------------+
GetIndexがクソ重そうなのでここを改善する、適当に記事の総数をオンメモリで持つことにした。トランザクションがロールバックしたときが心配、バグったらここを疑った方がいい。
無事動いた。
DESC用のINDEXを貼る: 2393
01:11
上の改善でかなり軽くなったが、まだ重いのでインデックスが効いていなさそうな以下のクエリをいい感じにする。
rows, err := db.Query(`SELECT * FROM articles ORDER BY created_at DESC, id DESC LIMIT ? OFFSET ?`, pageSize, offset)
両方ASCやDESCの場合なら、複合インデックスを貼ればなんとかなるらしい(https://yk5656.hatenadiary.org/entry/20140206/1392097362).
こんな感じ。
ALTER TABLE articles ADD INDEX index_articles_on_created_at(created_at);
ALTER TABLE articles ADD INDEX index_articles_on_multi_desc(created_at, id);
インデックス無しの場合のEXPLAINが下記.
mysql> EXPLAIN SELECT * FROM articles ORDER BY created_at DESC, id DESC LIMIT 10 OFFSET 10;
+----+-------------+----------+------------+------+---------------+------+---------+------+------+----------+----------------+
| id | select_type | table | partitions | type | possible_keys | key | key_len | ref | rows | filtered | Extra |
+----+-------------+----------+------------+------+---------------+------+---------+------+------+----------+----------------+
| 1 | SIMPLE | articles | NULL | ALL | NULL | NULL | NULL | NULL | 5566 | 100.00 | Using filesort |
+----+-------------+----------+------------+------+---------------+------+---------+------+------+----------+----------------+
複合インデックスを貼ってみる。
ALTER TABLE articles ADD INDEX index_articles_on_multi_desc(created_at, id);
EXPLAINする。
EXPLAIN SELECT * FROM articles ORDER BY created_at DESC, id DESC LIMIT 10 OFFSET 10;
+----+-------------+----------+------------+-------+---------------+------------------------------+---------+------+------+----------+-------+
| id | select_type | table | partitions | type | possible_keys | key | key_len | ref | rows | filtered | Extra |
+----+-------------+----------+------------+-------+---------------+------------------------------+---------+------+------+----------+-------+
| 1 | SIMPLE | articles | NULL | index | NULL | index_articles_on_multi_desc | 9 | NULL | 20 | 100.00 | NULL |
+----+-------------+----------+------------+-------+---------------+------------------------------+---------+------+------+----------+-------+
検索件数が劇的に少なくなった、いい感じ。
目についた遅いやつを改善
rows, err := db.Query(`
SELECT
*
FROM
users
ORDER BY
id
LIMIT ? OFFSET ?
`, pageSize, offset)
// LIMIT OFFSETは遅いのでBETWEENか id >= ? みたいな感じで範囲検索にする
rows, err := db.Query(`
SELECT
*
FROM
users
WEHRE
id > ?
ORDER BY
id
LIMIT ?
`, offset, pageSize)
ってかORDER BY いらないじゃん…😇
あとこれ、めっちゃ参考になりそうなので後で読む(https://qiita.com/mpyw/items/07c03600c2e38e91415e)
上で出来ると思ったらダメだった、WHEREの順番が違う(先にWHEREかけちゃダメ)
https://blog.mmmcorp.co.jp/blog/2018/03/22/sql_order_by/
offsetは大きくなればなるほど重くなるので要改善。
mysql> EXPLAIN SELECT * FROM users ORDER BY id LIMIT 10 OFFSET 10;
+----+-------------+-------+------------+-------+---------------+---------+---------+------+------+----------+-------+
| id | select_type | table | partitions | type | possible_keys | key | key_len | ref | rows | filtered | Extra |
+----+-------------+-------+------------+-------+---------------+---------+---------+------+------+----------+-------+
| 1 | SIMPLE | users | NULL | index | NULL | PRIMARY | 4 | NULL | 20 | 100.00 | NULL |
+----+-------------+-------+------------+-------+---------------+---------+---------+------+------+----------+-------+
1 row in set, 1 warning (0.00 sec)
mysql> EXPLAIN SELECT * FROM users ORDER BY id LIMIT 10 OFFSET 10000;
+----+-------------+-------+------------+-------+---------------+---------+---------+------+------+----------+-------+
| id | select_type | table | partitions | type | possible_keys | key | key_len | ref | rows | filtered | Extra |
+----+-------------+-------+------------+-------+---------------+---------+---------+------+------+----------+-------+
| 1 | SIMPLE | users | NULL | index | NULL | PRIMARY | 4 | NULL | 4964 | 100.00 | NULL |
+----+-------------+-------+------------+-------+---------------+---------+---------+------+------+----------+-------+
ORDER BYのOFFSETをいい感じにやるの無理くさいからオンメモリでもてば良くね?という気持ちに。
RAMに超余裕あるし。全ユーザーの配列持ってスライスでいい感じにすればよさそう。
RAMの使いどき！🥺
GetIndexの改善: 3247
03:14
memberのあれとか改善したのでもう一回alp見てみる。
+-------+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+--------+------------------------------+
| COUNT | MIN | MAX | SUM | AVG | P1 | P50 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) | METHOD | URI |
+-------+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+--------+------------------------------+
| 4 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 29.000 | 1128.000 | 2312.000 | 578.000 | GET | /write |
| 2 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 1359.000 | 1359.000 | 2718.000 | 1359.000 | GET | /css/bootstrap-tagsinput.css |
| 2476 | 0.000 | 0.001 | 0.001 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 34143.000 | 48418.000 | 95830770.000 | 38703.865 | GET | /photo |
| 4 | 0.000 | 0.004 | 0.004 | 0.001 | 0.000 | 0.000 | 0.000 | 0.002 | 29.000 | 1888.000 | 3829.000 | 957.250 | GET | /profileupdate |
| 2 | 0.001 | 0.003 | 0.004 | 0.002 | 0.001 | 0.001 | 0.001 | 0.001 | 122540.000 | 122540.000 | 245080.000 | 122540.000 | GET | /css/bootstrap.min.css |
| 4 | 0.004 | 0.004 | 0.008 | 0.002 | 0.000 | 0.000 | 0.004 | 0.002 | 29.000 | 1414.000 | 2878.000 | 719.500 | GET | /update |
| 2 | 0.004 | 0.004 | 0.008 | 0.004 | 0.004 | 0.004 | 0.004 | 0.000 | 613.000 | 613.000 | 1226.000 | 613.000 | GET | /regist |
| 2 | 0.004 | 0.008 | 0.012 | 0.006 | 0.004 | 0.004 | 0.004 | 0.002 | 0.000 | 0.000 | 0.000 | 0.000 | POST | /regist |
| 2 | 0.004 | 0.008 | 0.012 | 0.006 | 0.004 | 0.004 | 0.004 | 0.002 | 0.000 | 0.000 | 0.000 | 0.000 | POST | /write |
| 2 | 0.008 | 0.008 | 0.016 | 0.008 | 0.008 | 0.008 | 0.008 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | POST | /update |
| 2 | 0.012 | 0.016 | 0.028 | 0.014 | 0.012 | 0.012 | 0.012 | 0.002 | 0.000 | 0.000 | 0.000 | 0.000 | POST | /profileupdate |
| 56 | 0.000 | 0.016 | 0.076 | 0.001 | 0.000 | 0.000 | 0.008 | 0.003 | 29.000 | 29.000 | 1624.000 | 29.000 | GET | /logout |
| 104 | 0.004 | 0.008 | 0.100 | 0.001 | 0.000 | 0.000 | 0.004 | 0.002 | 739.000 | 739.000 | 76856.000 | 739.000 | GET | /login |
| 106 | 0.004 | 0.020 | 0.320 | 0.003 | 0.000 | 0.004 | 0.012 | 0.003 | 0.000 | 0.000 | 0.000 | 0.000 | POST | /login |
| 167 | 0.004 | 0.024 | 1.561 | 0.009 | 0.004 | 0.008 | 0.024 | 0.005 | 1.000 | 2.000 | 173.000 | 1.036 | POST | /iine |
| 175 | 0.004 | 0.040 | 1.868 | 0.011 | 0.000 | 0.008 | 0.032 | 0.007 | 29.000 | 10071.000 | 734001.000 | 4194.291 | GET | /article |
| 303 | 0.004 | 0.032 | 2.228 | 0.007 | 0.000 | 0.008 | 0.028 | 0.005 | 29.000 | 1765.000 | 490292.000 | 1618.125 | GET | /tags |
| 4 | 0.572 | 0.668 | 2.496 | 0.624 | 0.572 | 0.608 | 0.648 | 0.037 | 0.000 | 0.000 | 0.000 | 0.000 | GET | /initialize |
| 610 | 0.004 | 0.076 | 12.580 | 0.021 | 0.000 | 0.020 | 0.060 | 0.013 | 29.000 | 10676.000 | 1382080.000 | 2265.705 | GET | /member |
| 166 | 0.060 | 0.312 | 30.710 | 0.185 | 0.000 | 0.192 | 0.308 | 0.058 | 29.000 | 38678.000 | 1298756.000 | 7823.831 | GET | /tag/\d+ |
| 782 | 0.092 | 0.348 | 113.478 | 0.145 | 0.000 | 0.148 | 0.272 | 0.054 | 29.000 | 45919.000 | 8818147.000 | 11276.403 | GET | / |
+-------+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+--------+------------------------------+
いまだに/が遅いのどうにかならんか.
pprofのindexの結果.
(pprof) list main.GetIndex
Total: 18.18s
ROUTINE ======================== main.GetIndex in /var/www/html/webapp/go/app.go
10ms 11.86s (flat, cum) 65.24% of Total
. . 881: // respondErr(w, http.StatusInternalServerError, err)
. . 882: // return
. . 883: // }
. . 884: maxPage := int(math.Ceil(float64(articleCounts) / float64(pageSize)))
. . 885:
. 30ms 886: rows, err := db.Query(`SELECT * FROM articles ORDER BY created_at DESC, id DESC LIMIT ? OFFSET ?`, pageSize, offset)
. . 887: if err != nil && err != sql.ErrNoRows {
. . 888: respondErr(w, http.StatusInternalServerError, err)
. . 889: return
. . 890: }
. . 891: articles := make([]Article, 0, pageSize)
. 50ms 892: for rows.Next() {
. . 893: var id, authorID int
. 10ms 894: var title, description string
. . 895: var createdAt, updatedAt time.Time
. 20ms 896: if err := rows.Scan(&id, &authorID, &title, &description, &updatedAt, &createdAt); err != nil {
. . 897: respondErr(w, http.StatusInternalServerError, err)
. . 898: return
. . 899: }
. . 900: articles = append(articles, Article{id, authorID, title, description, updatedAt, createdAt})
. . 901: }
. . 902: rows.Close()
. . 903:
10ms 10ms 904: headerInfo.Current = "new"
. . 905: headerInfo.Write = true
. . 906:
. 20ms 907: popularArticles, err := getPopularArticles()
. . 908: if err != nil {
. . 909: respondErr(w, http.StatusInternalServerError, err)
. . 910: return
. . 911: }
. . 912:
. 7.52s 913: render(w, http.StatusOK, "index.html", struct {
. . 914: User User
. . 915: Articles []Article
. . 916: PopularArticles []PopularArticle
. . 917: OnlineUsers []int
. . 918: Page int
. . 919: MaxPage int
. . 920: HeaderInfo HeaderInfo
. . 921: }{
. . 922: *user,
. . 923: articles,
. . 924: popularArticles,
. 4.20s 925: getLoginUsers(),
. . 926: page,
. . 927: maxPage,
. . 928: headerInfo,
. . 929: })
. . 930:}
どうやらgetLoginUsers()がかなりの比重を占めていそう。
getLoginUsersが以下.
Total: 19.68s
ROUTINE ======================== main.getLoginUsers in /usr/lib/go-1.10/src/time/time.go
10ms 10ms (flat, cum) 0.051% of Total
. . 153: return int32(t.wall & nsecMask)
. . 154:}
. . 155:
. . 156:// sec returns the time's seconds since Jan 1 year 1.
. . 157:func (t *Time) sec() int64 {
10ms 10ms 158: if t.wall&hasMonotonic != 0 {
. . 159: return wallToInternal + int64(t.wall<<1>>(nsecShift+1))
. . 160: }
. . 161: return int64(t.ext)
. . 162:}
. . 163:
ROUTINE ======================== main.getLoginUsers in /var/www/html/webapp/go/app.go
30ms 4.30s (flat, cum) 21.85% of Total
. . 651: conn := pool.Get()
. . 652: defer conn.Close()
. . 653: conn.Do("SET", "login_"+strconv.Itoa(userID), time.Now().UnixNano()/int64(time.Millisecond))
. . 654:}
. . 655:
. 20ms 656:func getLoginUsers() []int {
. . 657: var onLineUsers []int
. 60ms 658: conn := pool.Get()
. . 659: defer conn.Close()
30ms 4.16s 660: keys, _ := redis.Strings(conn.Do("KEYS", "login_*"))
. . 661: for _, key := range keys {
. 30ms 662: loginTime, _ := redis.Int(conn.Do("GET", key))
. . 663: if time.Now().UnixNano()/int64(time.Millisecond)-int64(loginTime) < 60*60*1000 {
. . 664: userID, err := strconv.Atoi(key[6:])
. . 665: if err != nil {
. 10ms 666: continue
. . 667: }
. . 668: onLineUsers = append(onLineUsers, userID)
. 20ms 669: }
. . 670: }
. . 671: sort.Ints(onLineUsers)
. . 672: return onLineUsers
. . 673:}
. . 674:
明らかにredisから頑張って持ってくるのは無駄なのでmapでいい感じに持つようにした.
func setLogin(userID int) {
loginUsers[userID] = time.Now().UnixNano()/int64(time.Millisecond)
}
func getLoginUsers() []int {
var onLineUsers []int
for userID, loginTime := range loginUsers {
if time.Now().UnixNano()/int64(time.Millisecond)-int64(loginTime) < 60*60*1000 {
onLineUsers = append(onLineUsers, userID)
}
}
sort.Ints(onLineUsers)
return onLineUsers
}
爆上がり、多分redisのコネクションもあんまり使わなくなったっていうのもあると思う。
いろいろ
上でかなり改善されたので、pprofをじっくり見てみる.
Showing top 10 nodes out of 252
flat flat% sum% cum cum%
2590ms 15.04% 15.04% 2740ms 15.91% syscall.Syscall
1120ms 6.50% 21.54% 1600ms 9.29% runtime.scanobject
1030ms 5.98% 27.53% 2340ms 13.59% runtime.mallocgc
510ms 2.96% 30.49% 510ms 2.96% runtime.heapBitsSetType
470ms 2.73% 33.22% 7890ms 45.82% reflect.Value.call
450ms 2.61% 35.83% 450ms 2.61% runtime.heapBitsForObject
410ms 2.38% 38.21% 410ms 2.38% runtime.futex
390ms 2.26% 40.48% 390ms 2.26% runtime.usleep
270ms 1.57% 42.04% 9410ms 54.65% text/template.(*state).evalCall
260ms 1.51% 43.55% 260ms 1.51% runtime.memclrNoHeapPointers
(pprof) top -cum
Showing nodes accounting for 0, 0% of 17.22s total
Dropped 451 nodes (cum <= 0.09s)
Showing top 10 nodes out of 252
flat flat% sum% cum cum%
0 0% 0% 13.99s 81.24% net/http.(*conn).serve
0 0% 0% 13.82s 80.26% github.com/gorilla/mux.(*Router).ServeHTTP
0 0% 0% 13.82s 80.26% net/http.serverHandler.ServeHTTP
0 0% 0% 13.80s 80.14% main.recoverMiddleware.func1
0 0% 0% 13.80s 80.14% net/http.HandlerFunc.ServeHTTP
0 0% 0% 13.77s 79.97% main.authMiddleware.func1
0 0% 0% 13.18s 76.54% main.render
0 0% 0% 12.79s 74.27% html/template.(*Template).Execute
0 0% 0% 12.53s 72.76% text/template.(*Template).Execute
0 0% 0% 12.53s 72.76% text/template.(*Template).execute
(pprof) peek main.
Showing nodes accounting for 17.21s, 99.94% of 17.22s total
----------------------------------------------------------+-------------
flat flat% sum% cum cum% calls calls% + context
----------------------------------------------------------+-------------
0.38s 100% | main.render.func4
0.01s 0.058% 0.058% 0.38s 2.21% | main.getArticle
0.26s 68.42% | database/sql.(*DB).QueryRow
0.11s 28.95% | database/sql.(*Row).Scan
----------------------------------------------------------+-------------
0.09s 81.82% | main.getCurrentUser
0.01s 9.09% | main.authenticate
0.01s 9.09% | main.deleteSession
0.01s 0.058% 0.12% 0.11s 0.64% | main.getSession
0.10s 90.91% | github.com/gorilla/sessions.(*CookieStore).Get
----------------------------------------------------------+-------------
0.01s 100% | runtime.call32
0.01s 0.058% 0.17% 0.01s 0.058% | main.render.func9
----------------------------------------------------------+-------------
0.19s 100% | net/http.HandlerFunc.ServeHTTP
0 0% 0.17% 0.19s 1.10% | main.GetArticle
0.17s 89.47% | main.render
0.02s 10.53% | database/sql.(*DB).QueryRow
----------------------------------------------------------+-------------
10.07s 100% | net/http.HandlerFunc.ServeHTTP
0 0% 0.17% 10.07s 58.48% | main.GetIndex
9.87s 98.01% | main.render
0.08s 0.79% | main.getLoginUsers
0.05s 0.5% | database/sql.(*DB).Query
0.04s 0.4% | main.getPopularArticles
0.02s 0.2% | database/sql.(*Rows).Next
0.01s 0.099% | database/sql.(*Rows).Scan
----------------------------------------------------------+-------------
0.01s 100% | net/http.HandlerFunc.ServeHTTP
0 0% 0.17% 0.01s 0.058% | main.GetLogin
0.01s 100% | main.render
----------------------------------------------------------+-------------
0.01s 100% | net/http.HandlerFunc.ServeHTTP
0 0% 0.17% 0.01s 0.058% | main.GetLogout
0.01s 100% | main.deleteSession
----------------------------------------------------------+-------------
0.74s 100% | net/http.HandlerFunc.ServeHTTP
0 0% 0.17% 0.74s 4.30% | main.GetMember
0.66s 89.19% | main.render
0.04s 5.41% | main.getUser
0.02s 2.70% | database/sql.(*DB).Query
0.02s 2.70% | database/sql.(*Row).Scan
----------------------------------------------------------+-------------
0.82s 100% | net/http.HandlerFunc.ServeHTTP
0 0% 0.17% 0.82s 4.76% | main.GetMembers
0.82s 100% | main.render
----------------------------------------------------------+-------------
1.46s 100% | net/http.HandlerFunc.ServeHTTP
0 0% 0.17% 1.46s 8.48% | main.GetTag
1.44s 98.63% | main.render
0.02s 1.37% | database/sql.(*DB).Query
----------------------------------------------------------+-------------
0.23s 100% | net/http.HandlerFunc.ServeHTTP
0 0% 0.17% 0.23s 1.34% | main.GetTags
0.21s 91.30% | main.render
0.01s 4.35% | database/sql.(*DB).Query
0.01s 4.35% | database/sql.(*Rows).Next
----------------------------------------------------------+-------------
0.02s 100% | net/http.HandlerFunc.ServeHTTP
0 0% 0.17% 0.02s 0.12% | main.PostIine
0.02s 100% | database/sql.(*DB).Exec
----------------------------------------------------------+-------------
0.01s 100% | net/http.HandlerFunc.ServeHTTP
0 0% 0.17% 0.01s 0.058% | main.PostLogin
0.01s 100% | main.authenticate
----------------------------------------------------------+-------------
13.77s 100% | net/http.HandlerFunc.ServeHTTP
0 0% 0.17% 13.77s 79.97% | main.authMiddleware.func1
13.53s 98.26% | net/http.HandlerFunc.ServeHTTP
0.23s 1.67% | main.getCurrentUser
0.01s 0.073% | main.setLogin
----------------------------------------------------------+-------------
0.01s 100% | main.PostLogin
0 0% 0.17% 0.01s 0.058% | main.authenticate
0.01s 100% | main.getSession
----------------------------------------------------------+-------------
0.01s 100% | main.GetLogout
0 0% 0.17% 0.01s 0.058% | main.deleteSession
0.01s 100% | main.getSession
----------------------------------------------------------+-------------
0.26s 100% | main.render.func7
0 0% 0.17% 0.26s 1.51% | main.getArticleCount
0.19s 73.08% | database/sql.(*DB).QueryRow
0.07s 26.92% | database/sql.(*Row).Scan
----------------------------------------------------------+-------------
0.12s 100% | main.render.func5
0 0% 0.17% 0.12s 0.7% | main.getArticleIineUsers
0.07s 58.33% | database/sql.(*DB).Query
0.05s 41.67% | database/sql.(*Rows).Next
----------------------------------------------------------+-------------
1s 100% | main.render.func6
0 0% 0.17% 1s 5.81% | main.getArticleTagNames
0.62s 62.00% | database/sql.(*DB).Query
0.24s 24.00% | database/sql.(*Rows).Next
0.09s 9.00% | database/sql.(*Rows).Scan
0.03s 3.00% | database/sql.(*Rows).Close
0.01s 1.00% | runtime.duffcopy
0.01s 1.00% | runtime.growslice
----------------------------------------------------------+-------------
0.23s 100% | main.authMiddleware.func1
0 0% 0.17% 0.23s 1.34% | main.getCurrentUser
0.13s 56.52% | database/sql.(*DB).QueryRow
0.09s 39.13% | main.getSession
0.01s 4.35% | github.com/gorilla/context.Get
----------------------------------------------------------+-------------
0.86s 100% | main.render.func2
0 0% 0.17% 0.86s 4.99% | main.getIineCount
0.62s 72.09% | database/sql.(*DB).QueryRow
0.24s 27.91% | database/sql.(*Row).Scan
----------------------------------------------------------+-------------
0.08s 100% | main.GetIndex
0 0% 0.17% 0.08s 0.46% | main.getLoginUsers
0.04s 50.00% | sort.Ints
0.03s 37.50% | runtime.mapiternext
0.01s 12.50% | runtime.growslice
----------------------------------------------------------+-------------
0.04s 100% | main.GetIndex
0 0% 0.17% 0.04s 0.23% | main.getPopularArticles
0.02s 50.00% | github.com/gomodule/redigo/redis.(*Pool).Get
0.02s 50.00% | github.com/gomodule/redigo/redis.(*activeConn).Do
----------------------------------------------------------+-------------
0.90s 95.74% | main.render.func1
0.04s 4.26% | main.GetMember
0 0% 0.17% 0.94s 5.46% | main.getUser
0.70s 74.47% | database/sql.(*DB).QueryRow
0.24s 25.53% | database/sql.(*Row).Scan
----------------------------------------------------------+-------------
0.04s 100% | runtime.main
0 0% 0.17% 0.04s 0.23% | main.main
0.04s 100% | net/http.ListenAndServe
----------------------------------------------------------+-------------
0.02s 100% | github.com/gomodule/redigo/redis.(*Pool).GetContext
0 0% 0.17% 0.02s 0.12% | main.main.func3
0.02s 100% | github.com/gomodule/redigo/redis.(*conn).Do
----------------------------------------------------------+-------------
13.80s 100% | net/http.HandlerFunc.ServeHTTP
0 0% 0.17% 13.80s 80.14% | main.recoverMiddleware.func1
13.80s 100% | net/http.HandlerFunc.ServeHTTP
----------------------------------------------------------+-------------
9.87s 74.89% | main.GetIndex
1.44s 10.93% | main.GetTag
0.82s 6.22% | main.GetMembers
0.66s 5.01% | main.GetMember
0.21s 1.59% | main.GetTags
0.17s 1.29% | main.GetArticle
0.01s 0.076% | main.GetLogin
0 0% 0.17% 13.18s 76.54% | main.render
12.79s 97.04% | html/template.(*Template).Execute
0.36s 2.73% | html/template.(*Template).ParseFiles
0.02s 0.15% | html/template.(*Template).Funcs
0.01s 0.076% | runtime.makemap
----------------------------------------------------------+-------------
0.90s 100% | runtime.call32
0 0% 0.17% 0.90s 5.23% | main.render.func1
0.90s 100% | main.getUser
----------------------------------------------------------+-------------
0.86s 100% | runtime.call32
0 0% 0.17% 0.86s 4.99% | main.render.func2
0.86s 100% | main.getIineCount
----------------------------------------------------------+-------------
0.38s 100% | runtime.call32
0 0% 0.17% 0.38s 2.21% | main.render.func4
0.38s 100% | main.getArticle
----------------------------------------------------------+-------------
0.12s 100% | runtime.call64
0 0% 0.17% 0.12s 0.7% | main.render.func5
0.12s 100% | main.getArticleIineUsers
----------------------------------------------------------+-------------
1s 100% | runtime.call64
0 0% 0.17% 1s 5.81% | main.render.func6
1s 100% | main.getArticleTagNames
----------------------------------------------------------+-------------
0.26s 100% | runtime.call32
0 0% 0.17% 0.26s 1.51% | main.render.func7
0.26s 100% | main.getArticleCount
----------------------------------------------------------+-------------
0.01s 100% | main.authMiddleware.func1
0 0% 0.17% 0.01s 0.058% | main.setLogin
0.01s 100% | runtime.mapassign_fast64
----------------------------------------------------------+-------------
(pprof)
まだ重いらしい.
9.87s 74.89% | main.GetIndex
1.44s 10.93% | main.GetTag
中心的に重いのはmain.renderなのでrenderをpprofする.
Total: 17.22s
ROUTINE ======================== main.render in /var/www/html/webapp/go/app.go
0 13.18s (flat, cum) 76.54% of Total
. . 731:func getTemplatePath(file string) string {
. . 732: return path.Join("templates", file)
. . 733:}
. . 734:
. . 735:func render(w http.ResponseWriter, status int, file string, data interface{}) {
. 10ms 736: fmap := template.FuncMap{
. . 737: "getUser": func(id int) (*User, error) {
. . 738: return getUser(id)
. . 739: },
. . 740: "getIineCount": func(id int) (int, error) {
. . 741: return getIineCount(id)
. . 742: },
. . 743: "getTagCount": func(id int) (int, error) {
. . 744: return getTagCount(id)
. . 745: },
. . 746: "getArticle": func(id int) (*Article, error) {
. . 747: return getArticle(id)
. . 748: },
. . 749: "getArticleIineUsers": func(id int) ([]int, error) {
. . 750: return getArticleIineUsers(id)
. . 751: },
. . 752: "getArticleTagNames": func(id int) ([]TagName, error) {
. . 753: return getArticleTagNames(id)
. . 754: },
. . 755: "getArticleCount": func(id int) (int, error) {
. . 756: return getArticleCount(id)
. . 757: },
. . 758: "deltaTime": func(updateTime time.Time) string {
. . 759: return deltaTime(updateTime)
. . 760: },
. . 761: "add": func(a int, b int) int {
. . 762: return a + b
. . 763: },
. . 764: "for": func(n int) []int {
. . 765: return make([]int, n)
. . 766: },
. . 767: }
. 380ms 768: tpl := template.Must(template.New(file).Funcs(fmap).ParseFiles(getTemplatePath(file), getTemplatePath("header.html")))
. . 769: w.WriteHeader(status)
. 12.79s 770: if err := tpl.Execute(w, data); err != nil {
. . 771: respondErr(w, http.StatusInternalServerError, err)
. . 772: return
. . 773: }
. . 774:}
. . 775:
ROUTINE ======================== main.render.func1 in /var/www/html/webapp/go/app.go
0 900ms (flat, cum) 5.23% of Total
. . 733:}
. . 734:
. . 735:func render(w http.ResponseWriter, status int, file string, data interface{}) {
. . 736: fmap := template.FuncMap{
. . 737: "getUser": func(id int) (*User, error) {
. 900ms 738: return getUser(id)
. . 739: },
. . 740: "getIineCount": func(id int) (int, error) {
. . 741: return getIineCount(id)
. . 742: },
. . 743: "getTagCount": func(id int) (int, error) {
ROUTINE ======================== main.render.func2 in /var/www/html/webapp/go/app.go
0 860ms (flat, cum) 4.99% of Total
. . 736: fmap := template.FuncMap{
. . 737: "getUser": func(id int) (*User, error) {
. . 738: return getUser(id)
. . 739: },
. . 740: "getIineCount": func(id int) (int, error) {
. 860ms 741: return getIineCount(id)
. . 742: },
. . 743: "getTagCount": func(id int) (int, error) {
. . 744: return getTagCount(id)
. . 745: },
. . 746: "getArticle": func(id int) (*Article, error) {
ROUTINE ======================== main.render.func4 in /var/www/html/webapp/go/app.go
0 380ms (flat, cum) 2.21% of Total
. . 742: },
. . 743: "getTagCount": func(id int) (int, error) {
. . 744: return getTagCount(id)
. . 745: },
. . 746: "getArticle": func(id int) (*Article, error) {
. 380ms 747: return getArticle(id)
. . 748: },
. . 749: "getArticleIineUsers": func(id int) ([]int, error) {
. . 750: return getArticleIineUsers(id)
. . 751: },
. . 752: "getArticleTagNames": func(id int) ([]TagName, error) {
ROUTINE ======================== main.render.func5 in /var/www/html/webapp/go/app.go
0 120ms (flat, cum) 0.7% of Total
. . 745: },
. . 746: "getArticle": func(id int) (*Article, error) {
. . 747: return getArticle(id)
. . 748: },
. . 749: "getArticleIineUsers": func(id int) ([]int, error) {
. 120ms 750: return getArticleIineUsers(id)
. . 751: },
. . 752: "getArticleTagNames": func(id int) ([]TagName, error) {
. . 753: return getArticleTagNames(id)
. . 754: },
. . 755: "getArticleCount": func(id int) (int, error) {
ROUTINE ======================== main.render.func6 in /var/www/html/webapp/go/app.go
0 1s (flat, cum) 5.81% of Total
. . 748: },
. . 749: "getArticleIineUsers": func(id int) ([]int, error) {
. . 750: return getArticleIineUsers(id)
. . 751: },
. . 752: "getArticleTagNames": func(id int) ([]TagName, error) {
. 1s 753: return getArticleTagNames(id)
. . 754: },
. . 755: "getArticleCount": func(id int) (int, error) {
. . 756: return getArticleCount(id)
. . 757: },
. . 758: "deltaTime": func(updateTime time.Time) string {
ROUTINE ======================== main.render.func7 in /var/www/html/webapp/go/app.go
0 260ms (flat, cum) 1.51% of Total
. . 751: },
. . 752: "getArticleTagNames": func(id int) ([]TagName, error) {
. . 753: return getArticleTagNames(id)
. . 754: },
. . 755: "getArticleCount": func(id int) (int, error) {
. 260ms 756: return getArticleCount(id)
. . 757: },
. . 758: "deltaTime": func(updateTime time.Time) string {
. . 759: return deltaTime(updateTime)
. . 760: },
. . 761: "add": func(a int, b int) int {
ROUTINE ======================== main.render.func9 in /var/www/html/webapp/go/app.go
10ms 10ms (flat, cum) 0.058% of Total
. . 756: return getArticleCount(id)
. . 757: },
. . 758: "deltaTime": func(updateTime time.Time) string {
. . 759: return deltaTime(updateTime)
. . 760: },
10ms 10ms 761: "add": func(a int, b int) int {
. . 762: return a + b
. . 763: },
. . 764: "for": func(n int) []int {
. . 765: return make([]int, n)
. . 766: },
renderを見た感じgetなんちゃらが遅い感じっぽい。
htopを見たらMySQL律速状態からは抜け出してるっぽい、あと6GBくらいRAMが空いているのでマジで全部mapにしてもいい気がする。
slow-query-logをみるとLIMIT OFFSETのところが遅そうなのでここもみる。以下のように置き換えられる。
mysql> SELECT * FROM article_relate_tags WHERE tag_id = 1 ORDER BY article_id DESC LIMIT 3 OFFSET 10;
+------------+--------+
| article_id | tag_id |
+------------+--------+
| 7091 | 1 |
| 7090 | 1 |
| 7089 | 1 |
+------------+--------+
3 rows in set (0.00 sec)
mysql> SELECT * FROM article_relate_tags WHERE tag_id = 1 AND 7101 - 10 >= article_id ORDER BY article_id DESC LIMIT 3;
+------------+--------+
| article_id | tag_id |
+------------+--------+
| 7091 | 1 |
| 7090 | 1 |
| 7089 | 1 |
+------------+--------+
3 rows in set (0.00 sec)
rowsのCloseの順番を変えたら死に始めた、なぜ
なんかデッドロック起こしてるっぽい？(-> data raceでした)
go run -race app.goでrace conditionをみながら動かしてみる。
==================
WARNING: DATA RACE
Read at 0x000000cf3e70 by goroutine 78:
main.GetIndex()
/var/www/html/webapp/go/app.go:967 +0xb52
net/http.HandlerFunc.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:1947 +0x51
main.authMiddleware.func1()
/var/www/html/webapp/go/app.go:657 +0x102
net/http.HandlerFunc.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:1947 +0x51
main.recoverMiddleware.func1()
/var/www/html/webapp/go/app.go:644 +0xac
net/http.HandlerFunc.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:1947 +0x51
github.com/gorilla/mux.(*Router).ServeHTTP()
/root/go/src/github.com/gorilla/mux/mux.go:210 +0x125
net/http.serverHandler.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:2697 +0xb9
net/http.(*conn).serve()
/usr/lib/go-1.10/src/net/http/server.go:1830 +0x7dc
Previous write at 0x000000cf3e70 by goroutine 21:
main.GetIndex()
/var/www/html/webapp/go/app.go:949 +0x94d
net/http.HandlerFunc.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:1947 +0x51
main.authMiddleware.func1()
/var/www/html/webapp/go/app.go:657 +0x102
net/http.HandlerFunc.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:1947 +0x51
main.recoverMiddleware.func1()
/var/www/html/webapp/go/app.go:644 +0xac
net/http.HandlerFunc.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:1947 +0x51
github.com/gorilla/mux.(*Router).ServeHTTP()
/root/go/src/github.com/gorilla/mux/mux.go:210 +0x125
net/http.serverHandler.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:2697 +0xb9
net/http.(*conn).serve()
/usr/lib/go-1.10/src/net/http/server.go:1830 +0x7dc
Goroutine 78 (running) created at:
net/http.(*Server).Serve()
/usr/lib/go-1.10/src/net/http/server.go:2798 +0x364
net/http.(*Server).ListenAndServe()
/usr/lib/go-1.10/src/net/http/server.go:2714 +0xc4
net/http.ListenAndServe()
/usr/lib/go-1.10/src/net/http/server.go:2972 +0xf6
main.main()
/var/www/html/webapp/go/app.go:1918 +0x1e99
Goroutine 21 (running) created at:
net/http.(*Server).Serve()
/usr/lib/go-1.10/src/net/http/server.go:2798 +0x364
net/http.(*Server).ListenAndServe()
/usr/lib/go-1.10/src/net/http/server.go:2714 +0xc4
net/http.ListenAndServe()
/usr/lib/go-1.10/src/net/http/server.go:2972 +0xf6
main.main()
/var/www/html/webapp/go/app.go:1918 +0x1e99
==================
==================
WARNING: DATA RACE
Read at 0x000000cf3e80 by goroutine 78:
main.GetIndex()
/var/www/html/webapp/go/app.go:967 +0xb52
net/http.HandlerFunc.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:1947 +0x51
main.authMiddleware.func1()
/var/www/html/webapp/go/app.go:657 +0x102
net/http.HandlerFunc.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:1947 +0x51
main.recoverMiddleware.func1()
/var/www/html/webapp/go/app.go:644 +0xac
net/http.HandlerFunc.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:1947 +0x51
github.com/gorilla/mux.(*Router).ServeHTTP()
/root/go/src/github.com/gorilla/mux/mux.go:210 +0x125
net/http.serverHandler.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:2697 +0xb9
net/http.(*conn).serve()
/usr/lib/go-1.10/src/net/http/server.go:1830 +0x7dc
Previous write at 0x000000cf3e80 by goroutine 21:
main.GetIndex()
/var/www/html/webapp/go/app.go:950 +0x984
net/http.HandlerFunc.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:1947 +0x51
main.authMiddleware.func1()
/var/www/html/webapp/go/app.go:657 +0x102
net/http.HandlerFunc.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:1947 +0x51
main.recoverMiddleware.func1()
/var/www/html/webapp/go/app.go:644 +0xac
net/http.HandlerFunc.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:1947 +0x51
github.com/gorilla/mux.(*Router).ServeHTTP()
/root/go/src/github.com/gorilla/mux/mux.go:210 +0x125
net/http.serverHandler.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:2697 +0xb9
net/http.(*conn).serve()
/usr/lib/go-1.10/src/net/http/server.go:1830 +0x7dc
Goroutine 78 (running) created at:
net/http.(*Server).Serve()
/usr/lib/go-1.10/src/net/http/server.go:2798 +0x364
net/http.(*Server).ListenAndServe()
/usr/lib/go-1.10/src/net/http/server.go:2714 +0xc4
net/http.ListenAndServe()
/usr/lib/go-1.10/src/net/http/server.go:2972 +0xf6
main.main()
/var/www/html/webapp/go/app.go:1918 +0x1e99
Goroutine 21 (running) created at:
net/http.(*Server).Serve()
/usr/lib/go-1.10/src/net/http/server.go:2798 +0x364
net/http.(*Server).ListenAndServe()
/usr/lib/go-1.10/src/net/http/server.go:2714 +0xc4
net/http.ListenAndServe()
/usr/lib/go-1.10/src/net/http/server.go:2972 +0xf6
main.main()
/var/www/html/webapp/go/app.go:1918 +0x1e99
==================
==================
WARNING: DATA RACE
Write at 0x00c42014cb70 by goroutine 51:
runtime.mapassign_fast64()
/usr/lib/go-1.10/src/runtime/hashmap_fast.go:522 +0x0
main.setLogin()
/var/www/html/webapp/go/app.go:680 +0xf1
main.authMiddleware.func1()
/var/www/html/webapp/go/app.go:656 +0xcd
net/http.HandlerFunc.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:1947 +0x51
main.recoverMiddleware.func1()
/var/www/html/webapp/go/app.go:644 +0xac
net/http.HandlerFunc.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:1947 +0x51
github.com/gorilla/mux.(*Router).ServeHTTP()
/root/go/src/github.com/gorilla/mux/mux.go:210 +0x125
net/http.serverHandler.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:2697 +0xb9
net/http.(*conn).serve()
/usr/lib/go-1.10/src/net/http/server.go:1830 +0x7dc
Previous read at 0x00c42014cb70 by goroutine 89:
[failed to restore the stack]
Goroutine 51 (running) created at:
net/http.(*Server).Serve()
/usr/lib/go-1.10/src/net/http/server.go:2798 +0x364
net/http.(*Server).ListenAndServe()
/usr/lib/go-1.10/src/net/http/server.go:2714 +0xc4
net/http.ListenAndServe()
/usr/lib/go-1.10/src/net/http/server.go:2972 +0xf6
main.main()
/var/www/html/webapp/go/app.go:1918 +0x1e99
Goroutine 89 (running) created at:
net/http.(*Server).Serve()
/usr/lib/go-1.10/src/net/http/server.go:2798 +0x364
net/http.(*Server).ListenAndServe()
/usr/lib/go-1.10/src/net/http/server.go:2714 +0xc4
net/http.ListenAndServe()
/usr/lib/go-1.10/src/net/http/server.go:2972 +0xf6
main.main()
/var/www/html/webapp/go/app.go:1918 +0x1e99
==================
==================
WARNING: DATA RACE
Write at 0x00c4201ea6b0 by goroutine 51:
main.setLogin()
/var/www/html/webapp/go/app.go:680 +0x104
main.authMiddleware.func1()
/var/www/html/webapp/go/app.go:656 +0xcd
net/http.HandlerFunc.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:1947 +0x51
main.recoverMiddleware.func1()
/var/www/html/webapp/go/app.go:644 +0xac
net/http.HandlerFunc.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:1947 +0x51
github.com/gorilla/mux.(*Router).ServeHTTP()
/root/go/src/github.com/gorilla/mux/mux.go:210 +0x125
net/http.serverHandler.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:2697 +0xb9
net/http.(*conn).serve()
/usr/lib/go-1.10/src/net/http/server.go:1830 +0x7dc
Previous read at 0x00c4201ea6b0 by goroutine 89:
[failed to restore the stack]
Goroutine 51 (running) created at:
net/http.(*Server).Serve()
/usr/lib/go-1.10/src/net/http/server.go:2798 +0x364
net/http.(*Server).ListenAndServe()
/usr/lib/go-1.10/src/net/http/server.go:2714 +0xc4
net/http.ListenAndServe()
/usr/lib/go-1.10/src/net/http/server.go:2972 +0xf6
main.main()
/var/www/html/webapp/go/app.go:1918 +0x1e99
Goroutine 89 (running) created at:
net/http.(*Server).Serve()
/usr/lib/go-1.10/src/net/http/server.go:2798 +0x364
net/http.(*Server).ListenAndServe()
/usr/lib/go-1.10/src/net/http/server.go:2714 +0xc4
net/http.ListenAndServe()
/usr/lib/go-1.10/src/net/http/server.go:2972 +0xf6
main.main()
/var/www/html/webapp/go/app.go:1918 +0x1e99
==================
==================
WARNING: DATA RACE
Write at 0x00c4201e9c88 by goroutine 65:
main.setLogin()
/var/www/html/webapp/go/app.go:680 +0x104
main.authMiddleware.func1()
/var/www/html/webapp/go/app.go:656 +0xcd
net/http.HandlerFunc.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:1947 +0x51
main.recoverMiddleware.func1()
/var/www/html/webapp/go/app.go:644 +0xac
net/http.HandlerFunc.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:1947 +0x51
github.com/gorilla/mux.(*Router).ServeHTTP()
/root/go/src/github.com/gorilla/mux/mux.go:210 +0x125
net/http.serverHandler.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:2697 +0xb9
net/http.(*conn).serve()
/usr/lib/go-1.10/src/net/http/server.go:1830 +0x7dc
Previous read at 0x00c4201e9c88 by goroutine 39:
main.getLoginUsers()
/var/www/html/webapp/go/app.go:704 +0x113
main.GetIndex()
/var/www/html/webapp/go/app.go:970 +0x9fb
net/http.HandlerFunc.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:1947 +0x51
main.authMiddleware.func1()
/var/www/html/webapp/go/app.go:657 +0x102
net/http.HandlerFunc.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:1947 +0x51
main.recoverMiddleware.func1()
/var/www/html/webapp/go/app.go:644 +0xac
net/http.HandlerFunc.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:1947 +0x51
github.com/gorilla/mux.(*Router).ServeHTTP()
/root/go/src/github.com/gorilla/mux/mux.go:210 +0x125
net/http.serverHandler.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:2697 +0xb9
net/http.(*conn).serve()
/usr/lib/go-1.10/src/net/http/server.go:1830 +0x7dc
Goroutine 65 (running) created at:
net/http.(*Server).Serve()
/usr/lib/go-1.10/src/net/http/server.go:2798 +0x364
net/http.(*Server).ListenAndServe()
/usr/lib/go-1.10/src/net/http/server.go:2714 +0xc4
net/http.ListenAndServe()
/usr/lib/go-1.10/src/net/http/server.go:2972 +0xf6
main.main()
/var/www/html/webapp/go/app.go:1918 +0x1e99
Goroutine 39 (running) created at:
net/http.(*Server).Serve()
/usr/lib/go-1.10/src/net/http/server.go:2798 +0x364
net/http.(*Server).ListenAndServe()
/usr/lib/go-1.10/src/net/http/server.go:2714 +0xc4
net/http.ListenAndServe()
/usr/lib/go-1.10/src/net/http/server.go:2972 +0xf6
main.main()
/var/www/html/webapp/go/app.go:1918 +0x1e99
==================
==================
WARNING: DATA RACE
Read at 0x00c4201ea078 by goroutine 85:
main.getLoginUsers()
/var/www/html/webapp/go/app.go:704 +0x113
main.GetIndex()
/var/www/html/webapp/go/app.go:970 +0x9fb
net/http.HandlerFunc.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:1947 +0x51
main.authMiddleware.func1()
/var/www/html/webapp/go/app.go:657 +0x102
net/http.HandlerFunc.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:1947 +0x51
main.recoverMiddleware.func1()
/var/www/html/webapp/go/app.go:644 +0xac
net/http.HandlerFunc.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:1947 +0x51
github.com/gorilla/mux.(*Router).ServeHTTP()
/root/go/src/github.com/gorilla/mux/mux.go:210 +0x125
net/http.serverHandler.ServeHTTP()
/usr/lib/go-1.10/src/net/http/server.go:2697 +0xb9
net/http.(*conn).serve()
/usr/lib/go-1.10/src/net/http/server.go:1830 +0x7dc
Previous write at 0x00c4201ea078 by goroutine 94:
[failed to restore the stack]
Goroutine 85 (running) created at:
net/http.(*Server).Serve()
/usr/lib/go-1.10/src/net/http/server.go:2798 +0x364
net/http.(*Server).ListenAndServe()
/usr/lib/go-1.10/src/net/http/server.go:2714 +0xc4
net/http.ListenAndServe()
/usr/lib/go-1.10/src/net/http/server.go:2972 +0xf6
main.main()
/var/www/html/webapp/go/app.go:1918 +0x1e99
Goroutine 94 (running) created at:
net/http.(*Server).Serve()
/usr/lib/go-1.10/src/net/http/server.go:2798 +0x364
net/http.(*Server).ListenAndServe()
/usr/lib/go-1.10/src/net/http/server.go:2714 +0xc4
net/http.ListenAndServe()
/usr/lib/go-1.10/src/net/http/server.go:2972 +0xf6
main.main()
/var/www/html/webapp/go/app.go:1918 +0x1e99
==================
排他制御全然できてない…直します。
データ競合の解消
13:55
RLockとかお勉強した. atomic.Intとかもあるらしい.
競合してたまに落ちる、みたいになってたのでちゃんと対応.
原因不明だけど死ぬ、みたいなことが無くなりベンチが安定した。
renderを軽くする(getIineCounts) : 3604
renderがボトルネックなのおもしろいよね(テンプレートの中でforを使ってgetIineCountとかをすると毎度SQLが発行されて遅くなる)
func getIineCount(articleID int) (int, error) {
iinesCountsMu.RLock()
defer iinesCountsMu.RUnlock()
return iinesCounts[articleID], nil
}
pprofからは見えにくいので、じっくり取り組んだ方が良さそう。
nginxに画像のキャッシュの設定を追加, getあたりの改善: 4161
14:30
何かしらの総数を持つ系はだいたいmapに入れときゃなんとかなる.
func getTagCount(tagID int) (int, error) {
tagsCountsMu.RLock()
cnt := tagsCounts[tagID]
tagsCountsMu.RUnlock()
return cnt, nil
}
もちろんINSERTが発行されてるところでこのmapの値も変更するようにしてあげる。
articlesをmapで持つように改善, MySQLの設定の上限値引き上げ: 4604
15:30
func getArticle(articleID int) (*Article, error) {
articlesMu.RLock()
origin := articlesMap[articleID]
articlesMu.RUnlock()
if origin.AuthorID == 0 {
return nil, fmt.Errorf("Error: %s", "no article")
}
article := &Article{articleID, origin.AuthorID, origin.Title, origin.Description, origin.UpdatedAt, origin.CreatedAt}
return article, nil
}
こんな感じ。
まとめ
最後の時点のslow-query-log
# 5.8s user time, 40ms system time, 29.65M rss, 84.64M vsz
# Current date: Sun Jun 7 15:56:23 2020
# Hostname: btc202006-tsukagoshi-hayato
# Files: /root/logs/1591511257/slow-query.log
# Overall: 68.51k total, 37 unique, 2.08k QPS, 0.86x concurrency _________
# Time range: 2020-06-07T06:26:23 to 2020-06-07T06:26:56
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 28s 1us 220ms 414us 366us 6ms 84us
# Lock time 796ms 0 7ms 11us 35us 57us 0
# Rows sent 263.55k 0 6.93k 3.94 19.46 46.17 0
# Rows examine 25.69M 0 209.07k 393.22 31.70 8.12k 0
# Query size 3.96M 6 254 60.58 143.84 47.58 31.70
# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ============= ===== ====== ===== ===============
# 1 0x54DF8FFA57472495 15.7720 55.5% 137 0.1151 0.02 SELECT article_relate_tags
# 2 0xC13D9DF58CA89398 3.8654 13.6% 15799 0.0002 0.00 SELECT article_relate_tags tags
# 3 0xD6D8F9E7EE1D3C81 2.9557 10.4% 642 0.0046 0.02 SELECT articles
# 4 0x99AA0165670CE848 2.6738 9.4% 22695 0.0001 0.00 ADMIN PREPARE
# 5 0x481F52E8533643C5 1.0246 3.6% 3353 0.0003 0.00 SELECT iines
# 6 0xEAAA74A437923DC7 0.5413 1.9% 135 0.0040 0.00 INSERT iines
# 7 0xBE9D41A010B4C60B 0.4596 1.6% 273 0.0017 0.00 SELECT tags
# MISC 0xMISC 1.1021 3.9% 25474 0.0000 0.0 <30 ITEMS>
# Query 1: 4.57 QPS, 0.53x concurrency, ID 0x54DF8FFA57472495 at byte 9635903
# Scores: V/M = 0.02
# Time range: 2020-06-07T06:26:26 to 2020-06-07T06:26:56
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 137
# Exec time 55 16s 307us 220ms 115ms 163ms 42ms 116ms
# Lock time 0 4ms 19us 261us 31us 49us 25us 25us
# Rows sent 0 1.93k 1 20 14.45 19.46 7.16 19.46
# Rows examine 91 23.61M 457 207.12k 176.45k 201.74k 55.11k 192.13k
# Query size 0 12.97k 95 97 96.91 92.72 0 92.72
# String:
# Databases hidakkathon
# Hosts localhost
# Users ubuntu
# Query_time distribution
# 1us
# 10us
# 100us ##
# 1ms ##
# 10ms ###########
# 100ms ################################################################
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `hidakkathon` LIKE 'article_relate_tags'\G
# SHOW CREATE TABLE `hidakkathon`.`article_relate_tags`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM article_relate_tags WHERE tag_id = '868' ORDER BY article_id DESC LIMIT 20 OFFSET 0\G
# Query 2: 526.63 QPS, 0.13x concurrency, ID 0xC13D9DF58CA89398 at byte 697230
# Scores: V/M = 0.00
# Time range: 2020-06-07T06:26:26 to 2020-06-07T06:26:56
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 23 15799
# Exec time 13 4s 78us 11ms 244us 541us 367us 144us
# Lock time 73 581ms 14us 7ms 36us 52us 98us 25us
# Rows sent 70 186.19k 0 124 12.07 80.10 24.53 0.99
# Rows examine 1 372.37k 0 248 24.13 158.58 48.97 1.96
# Query size 55 2.18M 143 145 144.98 143.84 0.08 143.84
# String:
# Databases hidakkathon
# Hosts localhost
# Users ubuntu
# Query_time distribution
# 1us
# 10us #
# 100us ################################################################
# 1ms #
# 10ms #
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `hidakkathon` LIKE 'article_relate_tags'\G
# SHOW CREATE TABLE `hidakkathon`.`article_relate_tags`\G
# SHOW TABLE STATUS FROM `hidakkathon` LIKE 'tags'\G
# SHOW CREATE TABLE `hidakkathon`.`tags`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT tag_id, tagname FROM article_relate_tags INNER JOIN tags ON article_relate_tags.tag_id=tags.id WHERE article_id = 7087 ORDER BY tag_id ASC\G
# Query 3: 21.40 QPS, 0.10x concurrency, ID 0xD6D8F9E7EE1D3C81 at byte 11942468
# Scores: V/M = 0.02
# Time range: 2020-06-07T06:26:26 to 2020-06-07T06:26:56
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 642
# Exec time 10 3s 155us 68ms 5ms 31ms 10ms 236us
# Lock time 2 17ms 14us 385us 26us 38us 24us 21us
# Rows sent 4 12.54k 20 20 20 20 0 20
# Rows examine 3 1.03M 20 13.75k 1.64k 10.80k 3.79k 19.46
# Query size 1 46.77k 74 77 74.60 76.28 1.40 72.65
# String:
# Databases hidakkathon
# Hosts localhost
# Users ubuntu
# Query_time distribution
# 1us
# 10us
# 100us ################################################################
# 1ms #########
# 10ms ############
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `hidakkathon` LIKE 'articles'\G
# SHOW CREATE TABLE `hidakkathon`.`articles`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM articles ORDER BY created_at DESC, id DESC LIMIT 20 OFFSET 5960\G
alp
+-------+-------+-------+--------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+--------+------------------------------+
| COUNT | MIN | MAX | SUM | AVG | P1 | P50 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) | METHOD | URI |
+-------+-------+-------+--------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+--------+------------------------------+
| 1 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 613.000 | 613.000 | 613.000 | 613.000 | GET | /regist |
| 1 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 19.000 | 19.000 | 19.000 | 19.000 | GET | /favicon.ico |
| 2 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 29.000 | 1889.000 | 1918.000 | 959.000 | GET | /profileupdate |
| 2 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 29.000 | 1412.000 | 1441.000 | 720.500 | GET | /update |
| 2 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 29.000 | 1126.000 | 1155.000 | 577.500 | GET | /write |
| 1 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 1359.000 | 1359.000 | 1359.000 | 1359.000 | GET | /css/bootstrap-tagsinput.css |
| 2283 | 0.000 | 0.001 | 0.001 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 34143.000 | 48418.000 | 87906300.000 | 38504.731 | GET | /photo |
| 1 | 0.002 | 0.002 | 0.002 | 0.002 | 0.002 | 0.002 | 0.002 | 0.000 | 122540.000 | 122540.000 | 122540.000 | 122540.000 | GET | /css/bootstrap.min.css |
| 1 | 0.008 | 0.008 | 0.008 | 0.008 | 0.008 | 0.008 | 0.008 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | POST | /write |
| 1 | 0.008 | 0.008 | 0.008 | 0.008 | 0.008 | 0.008 | 0.008 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | POST | /update |
| 1 | 0.008 | 0.008 | 0.008 | 0.008 | 0.008 | 0.008 | 0.008 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | POST | /regist |
| 1 | 0.012 | 0.012 | 0.012 | 0.012 | 0.012 | 0.012 | 0.012 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | POST | /profileupdate |
| 78 | 0.000 | 0.008 | 0.072 | 0.001 | 0.000 | 0.000 | 0.004 | 0.002 | 739.000 | 739.000 | 57642.000 | 739.000 | GET | /login |
| 53 | 0.000 | 0.008 | 0.080 | 0.002 | 0.000 | 0.000 | 0.008 | 0.003 | 29.000 | 29.000 | 1537.000 | 29.000 | GET | /logout |
| 78 | 0.004 | 0.008 | 0.132 | 0.002 | 0.000 | 0.000 | 0.008 | 0.002 | 0.000 | 0.000 | 0.000 | 0.000 | POST | /login |
| 161 | 0.004 | 0.024 | 1.108 | 0.007 | 0.000 | 0.004 | 0.020 | 0.004 | 29.000 | 16555.000 | 694251.000 | 4312.118 | GET | /article |
| 157 | 0.004 | 0.020 | 1.172 | 0.007 | 0.004 | 0.008 | 0.016 | 0.003 | 1.000 | 2.000 | 165.000 | 1.051 | POST | /iine |
| 2 | 0.668 | 0.768 | 1.436 | 0.718 | 0.668 | 0.668 | 0.668 | 0.050 | 0.000 | 0.000 | 0.000 | 0.000 | GET | /initialize |
| 322 | 0.004 | 0.040 | 1.980 | 0.006 | 0.000 | 0.004 | 0.016 | 0.004 | 29.000 | 1759.000 | 522137.000 | 1621.543 | GET | /tags |
| 322 | 0.004 | 0.028 | 2.080 | 0.006 | 0.000 | 0.004 | 0.020 | 0.004 | 29.000 | 2094.000 | 651035.000 | 2021.848 | GET | /members |
| 322 | 0.004 | 0.064 | 2.816 | 0.009 | 0.000 | 0.004 | 0.036 | 0.008 | 29.000 | 10675.000 | 714291.000 | 2218.295 | GET | /member/\d+ |
| 157 | 0.020 | 0.220 | 22.014 | 0.140 | 0.000 | 0.144 | 0.216 | 0.043 | 29.000 | 41074.000 | 1330778.000 | 8476.293 | GET | /tag/\d+ |
| 779 | 0.000 | 0.220 | 43.378 | 0.056 | 0.000 | 0.048 | 0.156 | 0.028 | 29.000 | 46910.000 | 8918036.000 | 11448.056 | GET | / |
+-------+-------+-------+--------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+--------+------------------------------+
pprofは取るの忘れたので終わった後に見せてもらえそうなら見に行く。
もうちょい改善できそうなポイントがいくつかあったので時間かけすぎちゃったのが残念という感じ。goroutine全然使えてない。
