ISUCONに出場しました。
残念ながら予選落ちでした。
今、もう一度やってみれば、予選は突破できる気がします。（どのチームも思っているとは思いますが）
なぜ予選落ちしたのか振り返りを行った結果とやってはいけないことがいくつかわかったので、
共有します。
皆さんは勝った方法やこうしておけばよかったって書いている人が多かったので、
逆に僕は確実に負けるためにやるべきことを共有します。
※タイトルは完全に煽りです。
事前準備をしない
チャットの作成をしない
- チームメンバーでのコミュニケーションできる環境は必須です。コミュニケーションを取りづらくするために チャットを作成しないようにしましょう。
GCPの使用準備をしない
- 今回のISUCONはGCPを使用しての出題だったのですが、GCEのインスタンスにログインできる状態を 作ってしまうと、時間のロスができないので、ログインできるまでの準備はやめときましょう。
gcp - Google Cloud Platformをローカルから利用するための準備 - Qiita
GoogleCloudPlatform - GCEのインスタンスをCloud SDK(gcloud)で追加する - Qiita
過去問を解かない
- 過去問をやるとISUCONでのハマりどころやチューニングポイントがかなりわかってしまいます。
オンライン予選の概要を読まない
- 今回はOSがUbuntuをいうことが記述されていたりしたので、前提条件を読むことで事前準備できたり、練習できたり してしまうので、勝つ可能性が上がってしまいます。読まないようにしましょう。
【締め切りました】ISUCON5 オンライン予選の参加登録を開始＆参加チームとメンバーリスト : ISUCON公式Blog
レギュレーションは読まない
- レギュレーションを読んでしまうとレギュレーションぎりぎりの実装を思いついたりしてしまって、 その結果、スコアが伸びる可能性があるので、読まないでおきましょう。
方針を決めない
- 方針を決めるとチームとしてどういうふうにチューニングを行っていくかが定まってしまい、 非常に効率的な動きをしてしまう可能性が高いです。
計測しない
- ボトルネックとなる部分を見つけ、改善してしまうとスコアが上がってしまうので、 ボトルネックとなる部分を見つけないように計測はしないようにしましょう。
mysqlのスローログの出力は行わない
- 以下のような設定を行うと遅いクエリが出力されてしまいます。 そういった部分はボトルネックとなっている可能性が非常に高いので、 出力するのはやめときましょう。
set global long_query_time = 0.5;
set global slow_query_log = 1;
set global slow_query_log_file = "/tmp/slow.log";
set @@global.log_queries_not_using_indexes = 1;
- pt-query-digestを使用するとスローログのSlowクエリの統計情報、プロファイル情報が見えてしまいます。
pt-query-digest /tmp/slow.log > /tmp/digest.txt
# 230ms user time, 40ms system time, 32.43M rss, 99.63M vsz
# Current date: Sat Sep 26 12:27:04 2015
# Hostname: isucon5
# Files: /tmp/slow.log
# Overall: 21 total, 1 unique, 0.31 QPS, 0.37x concurrency _______________
# Time range: 2015-09-26 12:25:36 to 12:26:44
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 25s 717ms 2s 1s 2s 356ms 1s
# Lock time 1ms 48us 137us 68us 103us 21us 57us
# Rows sent 210 10 10 10 10 0 10
# Rows examine 14.58k 710 712 710.76 685.39 0.00 685.39
# Query size 4.63k 225 226 225.86 223.14 0 223.14
# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ============== ===== ====== ===== ==============
# 1 0xCE3E456E0D0EFD1C 25.1693 100.0% 21 1.1985 0.11 SELECT comments entries
# Query 1: 0.31 QPS, 0.37x concurrency, ID 0xCE3E456E0D0EFD1C at byte 0 __
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.11
# Time range: 2015-09-26 12:25:36 to 12:26:44
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 100 21
# Exec time 100 25s 717ms 2s 1s 2s 356ms 1s
# Lock time 100 1ms 48us 137us 68us 103us 21us 57us
# Rows sent 100 210 10 10 10 10 0 10
# Rows examine 100 14.58k 710 712 710.76 685.39 0.00 685.39
# Query size 100 4.63k 225 226 225.86 223.14 0 223.14
# String:
# Databases isucon5q
# Hosts localhost
# Users root
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms #######################################
# 1s ################################################################
# 10s+
# Tables
# SHOW TABLE STATUS FROM `isucon5q` LIKE 'comments'\G
# SHOW CREATE TABLE `isucon5q`.`comments`\G
# SHOW TABLE STATUS FROM `isucon5q` LIKE 'entries'\G
# SHOW CREATE TABLE `isucon5q`.`entries`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT c.id AS id, c.entry_id AS entry_id, c.user_id AS user_id, c.comment AS comment, c.created_at AS created_at
FROM comments c
JOIN entries e ON c.entry_id = e.id
WHERE e.user_id = '1025'
ORDER BY c.created_at DESC
LIMIT 10\G
- 今回だと以下のようにINDEXを貼るとボトルネックが解消されてしまいます。
CREATE INDEX comments_001 ON comments(entry_id, user_id, created_at);
CREATE INDEX relations_001 ON relations(one, another, created_at);
設定後に設定を確認しない
- いつもの場所にあるからってその場所にあるとは限りません、設定が反映されているかの 確認は行うと設定ファイルの場所が違うことに気づいてしまうので、確認作業はやめましょう。
※ mysqlの設定が反映されているかは以下のように行う
SHOW VARIABLES
nginxのアクセスログの解析は行わない。
- アクセスログからkataribeを使用して解析を行ってしまうと
/がボトルネックだってことがわかってしまいますので、アクセスログはそっとしておきましょう。
Top 20 Sort By Count
Count Total Mean Stddev Min P50.0 P90.0 P95.0 P99.0 Max 2xx 3xx 4xx 5xx Request
58 137.967 2.378741 2.383782 0.000 1.364 5.102 8.451 11.961 11.961 46 12 0 0 GET / HTTP/1.1
26 24.642 0.947769 1.514433 0.001 0.019 2.657 3.476 6.370 6.370 0 26 0 0 POST /login HTTP/1.1
26 11.090 0.426538 0.818077 0.000 0.013 1.849 2.413 3.221 3.221 26 0 0 0 GET /login HTTP/1.1
15 24.968 1.664533 1.372024 0.200 1.167 2.980 5.204 5.204 5.204 15 0 0 0 GET /friends HTTP/1.1
12 1.312 0.109333 0.220687 0.000 0.007 0.555 0.644 0.644 0.644 0 12 0 0 GET /logout HTTP/1.1
9 10.742 1.193556 1.496899 0.188 0.739 5.357 5.357 5.357 5.357 9 0 0 0 GET /footprints HTTP/1.1
9 12.865 1.429444 1.655567 0.004 0.724 4.465 4.465 4.465 4.465 0 9 0 0 POST /diary/entry HTTP/1.1
5 6.428 1.285600 1.108686 0.012 0.701 2.976 2.976 2.976 2.976 5 0 0 0 GET /profile/verna3128 HTTP/1.1
4 1.919 0.479750 0.482137 0.015 0.757 1.130 1.130 1.130 1.130 3 1 0 0 GET /diary/entries/verna3128 HTTP/1.1
3 2.855 0.951667 0.176621 0.747 0.930 1.178 1.178 1.178 1.178 3 0 0 0 GET /diary/entries/nelson_oconner3115 HTTP/1.1
3 2.051 0.683667 0.334091 0.245 0.751 1.055 1.055 1.055 1.055 3 0 0 0 GET /diary/entries/aubree2573 HTTP/1.1
3 2.391 0.797000 1.099584 0.009 0.030 2.352 2.352 2.352 2.352 3 0 0 0 GET /diary/entry/491143 HTTP/1.1
3 0.013 0.004333 0.000943 0.003 0.005 0.005 0.005 0.005 0.005 2 0 1 0 GET /diary/entry/500002 HTTP/1.1
3 1.354 0.451333 0.501273 0.081 0.113 1.160 1.160 1.160 1.160 3 0 0 0 GET /diary/entries/kadin4205 HTTP/1.1
3 1.518 0.506000 0.613385 0.007 0.141 1.370 1.370 1.370 1.370 3 0 0 0 GET /diary/entries/margaretta963 HTTP/1.1
3 4.974 1.658000 1.166931 0.009 2.426 2.539 2.539 2.539 2.539 3 0 0 0 GET /profile/nelson_oconner3115 HTTP/1.1
3 3.059 1.019667 1.026465 0.002 0.632 2.425 2.425 2.425 2.425 3 0 0 0 GET /diary/entry/498580 HTTP/1.1
3 0.443 0.147667 0.198246 0.004 0.011 0.428 0.428 0.428 0.428 3 0 0 0 GET /diary/entry/495813 HTTP/1.1
3 0.182 0.060667 0.059129 0.013 0.025 0.144 0.144 0.144 0.144 3 0 0 0 GET /diary/entries/nat4887 HTTP/1.1
3 11.190 3.730000 3.734361 0.006 2.349 8.835 8.835 8.835 8.835 3 0 0 0 GET /profile/gudrun262 HTTP/1.1
アプリケーションのプロファイリングは行わない
- stackprofなどを使うと以下のようにコードのどの部分がボトルネックか判明してしまいます。
stackprof.log
$ ./prof.sh
==================================
Mode: cpu(1000)
Samples: 2052 (0.10% miss rate)
GC: 212 (10.33%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
786 (38.3%) 786 (38.3%) block in Mysql2::Client#query
1788 (87.1%) 349 (17.0%) block in <class:WebApp>
339 (16.5%) 339 (16.5%) Mysql2::Client.pseudo_bind
1272 (62.0%) 91 (4.4%) Isucon5::WebApp#is_friend?
56 (2.7%) 56 (2.7%) Rack::Request#session
830 (40.4%) 44 (2.1%) Mysql2::Client#query
1196 (58.3%) 40 (1.9%) Mysql2::Client#xquery
34 (1.7%) 16 (0.8%) Erubis::XmlHelper#escape_xml
14 (0.7%) 14 (0.7%) Isucon5::WebApp#db
86 (4.2%) 14 (0.7%) Isucon5::WebApp#get_user
最後に
- 皆さん、この記事の内容のことを行うだけで確実にISUCONに負けることができます。 今後、ISUCONで負けたい方がいたら、参考にしていただけると幸いです。