isucon #3 予選に参加してきた
1日目で参加してきた。
今回は他の二人にアプリケーション側はお任せして、自分はミドルウェアまわりをやる、ということにしていた。
最初は、PHPを動くように設定を変更して、ベンチマークを実行していたのだけど、どうもfailしてしまう。原因を見ると、ログイン回りなので、セッションがおかしそうだ、というところまではわかったのだけど、ちゃんとした原因まではわかっていなかった。
セッションをファイルストレージに書くように変更してもfailするので、途中rubyにしようか、phpを5.5でコンパイルしなおして頑張ってみる、とか12:30ぐらいまで右往左往してた。
その後もfailし続けたので、セッションをAPCuに入れるようにしようとしてみたりとかしたが、解決できなかった。
途中で、ベンチマークスクリプトのworkloadをあげると、なんとかスコアが最後までfailしないでおける、ということがわかったので、それからようやくアプリのチューニングをしはじめた。
今までの経験上、isuconの場合はこれ知ってる、こうしたら早くなるはず...とかって手を動かしてしまうと検討違いのところに時間を使ってしまうのをようやく学びつつあるので、今回はなるべく現在のボトルネックになっている処理以外のことは考えないようにした。
そこでapacheにログと実行時間を出すように変更して、それを集計して、pathごとに実行回数、平均実行時間、合計実行時間を出すようなツールを書いた。
合計時間ベースで見ると、/および、/recent/xxxが遅いねー、ということで、pt-query-digestをかけて、クエリも確認して、INDEXを貼ったり書き換えをしてもらった。
INDEXを貼ったのだけど、/home/isucon/schema.sqlを変更しても反映されないなー、とちょっとはまってしまったが、まぁinitに書けばいいやということでscriptを書いた。
alter table memos add index (is_private, created_at) alter table memos add index (user, created_at)
SELECT * FROM memos WHERE is_private=0 ORDER BY created_at DESC, id DESC LIMIT 100 OFFSET #{page * 100}このクエリは、
SELECT id FROM memos WHERE is_private=0 ORDER BY created_at DESC, id DESC LIMIT 100 OFFSET #{page * 100}
SELECT * FROM memos WHERE id IN (?,...)という感じにした。OFFSETは気になる感じではあったけど、とりあえずそのままになった。また、usersへのクエリが非常に実行回数が多かったので、INでとるように変更した。
ベンチマークをかけて、topで見ていると、mysqlがCPUを一番たくさん使っていたのでmysqlをチューニングしようと思ってmy.cnfを探したがどこにあるかわからなかった。あと管理者権限で入る方法がわからなくってどうしようと色々しらべていたのだけど、あとから聞いた話だと、ちゃんとREADMEに書いてあったようだ。(勘で試してなんとか入れた
my.cnfはとりあえず/etc/my.cnfに書けばまぁだいたいの環境で読もうとするはず、ということで/etc/my.cnfに書いた。
ただデータセットはメモリに十分の乗りきるので、あまりmysqlのチューニングをしても効果がないだろうなということで、INSERTまわりに効きそうな変更以外は特にしなかった。
具体的には、
thread_cache_size = 200 innodb_buffer_pool_size = 1G innodb_flush_log_at_trx_commit = 2 innodb_locks_unsafe_for_binlog = on innodb_doublewrite=off
innodb_locks_unsafe_for_binlogはあまり効かなかったっぽいのでいらなかったかなと思う。例によって、早さのみを考慮した設定なので、本番などに適用するのはおすすめしない。
query_cacheはたぶん無駄だろうなーと思いつつ、一度有効にしてみたが、むしろ遅くなったので、やめた。
あとは他の人がクエリをAPCuにcacheするように書きかえたりしていて、気がつくと、だいぶmysqlのCPU使用率が下がってきたので、workloadの並列数を変えたりして、いちばんスコアの良いところを探っていったりした。
すると、markdownのプロセスの実行がCPUをくっているのがちらほらtopで見えだしたので、次はこれを潰さないと次のボトルネックにたどりつけないだろうなー、ということで、bin/markdownを覗いたら、コードがカオスすぎて絶望した。
実行自体が遅いというのもあると思いつつ、おそらくfork & execしまくっているのが問題なのかなーと思ったので、これをdaemon化して、TCPでappと通信するサーバーを書けば、なんとかできるかなーと思い、調査していた間に、適当なPHPのMarkdown Parserで試してもらったら動いてしまったので、どうかなーと思いつつ、他のperl以外のチームがこのコードをいじらないといけないようだとperlの人が有利になりそうなので多少は互換性が落ちても問題ないのかなーと思って、そのままいくことにした。
markdownを解決したら、スコアが10000を越えだしたので、あとは細かいところをあれこれやったり、ミドルウェアの設定とかを見直したら20000ぐらいになった。
終了したあとで、どの程度AMIをいじったりしても良いものか不安だったので、30分前からは再起動の検証とか作成したAMIをもとに起動の検証とかをしていたら終了した。
今回は(も?)けっこう別のところでハマったりして、チューニング自体にはうまく時間を割けなかった気はするのだけど、3回目の参加ということで、今までより計測と洞察を元に確実なものを改善する、ということは着実にできたかなとは思う。とはいえ、本戦で勝つにはもうちょっと抜本的な変更にもtryできないとだめだろうな、ということで今までのAMIの復習をがんばろうと思います。(まだ出れるかわからないけど。
SELECT COUNT(*) FROM (SELECT 1 FROM xxxx)が、SELECT COUNT(*) FROM (SELECT item_id FROM xxxx)より速い理由
とあるサービスでslow logをみていたら、どこかの記事で読んだことのあるクエリがでてきたのだけど、もうちょっと速くできないものか、と考えてみた。
結論を言えば、
BEFORE: SELECT sql_no_cache COUNT(*) FROM (SELECT item_id FROM category2item WHERE category_id = '2' group by item_id ) AS t; 1 row in set (2.06 sec) AFTER: SELECT sql_no_cache COUNT(*) FROM (SELECT 1 FROM category2item WHERE category_id = '2' group by item_id ) AS t; 1 row in set (1.89 sec)
という感じで、SELECT item_idではなく、SELECT 1とすると、ちょっとだけ早くなるようだ。
このクエリの実行結果はだいたい300万件ぐらい。
なぜこうすると早くなるのか、profilingを取ってみた。
profilingのとりかたは、
> set profiling=1; > select * from xxx; > show profile source;
のようにした。
BEFORE:
+---------------------------+----------+-------------------------+---------------+----
---------+
| Status | Duration | Source_function | Source_file | Source_line |
+---------------------------+----------+-------------------------+---------------+----
---------+
| starting | 0.000130 | NULL | NULL |
NULL |
| checking permissions | 0.000010 | check_access | sql_parse.cc |
4751 |
| Opening tables | 0.000025 | open_tables | sql_base.cc | 4831 |
| System lock | 0.000076 | mysql_lock_tables | lock.cc | 299 |
| optimizing | 0.000013 | optimize | sql_select.cc | 865 |
| statistics | 0.000107 | optimize | sql_select.cc | 1056 |
| preparing | 0.000033 | optimize | sql_select.cc | 1078 |
| executing | 0.000011 | exec | sql_select.cc | 1836 |
| Sorting result | 0.000005 | exec | sql_select.cc | 2267 |
| Sending data | 0.740704 | exec | sql_select.cc | 2380 |
| converting HEAP to MyISAM | 0.144822 | create_myisam_from_heap | sql_select.cc | 11286 |
| Sending data | 1.166885 | create_myisam_from_heap | sql_select.cc | 11352 |
| init | 0.000024 | mysql_select | sql_select.cc | 2579 |
| optimizing | 0.000008 | optimize | sql_select.cc | 865 |
| executing | 0.000012 | exec | sql_select.cc | 1836 |
| end | 0.000011 | mysql_select | sql_select.cc | 2615 |
| query end | 0.000009 | mysql_execute_command | sql_parse.cc | 4440 |
| closing tables | 0.000003 | mysql_execute_command | sql_parse.cc | 4492 |
| removing tmp table | 0.005282 | free_tmp_table | sql_select.cc | 11219 |
| closing tables | 0.000014 | free_tmp_table | sql_select.cc | 11244 |
| freeing items | 0.000026 | mysql_parse | sql_parse.cc | 5640 |
| logging slow query | 0.000004 | log_slow_statement | sql_parse.cc | 1461 |
| cleaning up | 0.000005 | dispatch_command | sql_parse.cc | 1417 |
AFTER:
+---------------------------+----------+-------------------------+---------------+----
---------+
| Status | Duration | Source_function | Source_file | Sou
rce_line |
+---------------------------+----------+-------------------------+---------------+----
---------+
| starting | 0.000074 | NULL | NULL |
NULL |
| checking permissions | 0.000008 | check_access | sql_parse.cc |
4751 |
| Opening tables | 0.000018 | open_tables | sql_base.cc | 4831 |
| System lock | 0.000059 | mysql_lock_tables | lock.cc | 299 |
| optimizing | 0.000010 | optimize | sql_select.cc | 865 |
| statistics | 0.000088 | optimize | sql_select.cc | 1056 |
| preparing | 0.000024 | optimize | sql_select.cc | 1078 |
| executing | 0.000008 | exec | sql_select.cc | 1836 |
| Sorting result | 0.000004 | exec | sql_select.cc | 2267 |
| Sending data | 0.659646 | exec | sql_select.cc | 2380 |
| converting HEAP to MyISAM | 0.164216 | create_myisam_from_heap | sql_select.cc | 11286 |
| Sending data | 1.052896 | create_myisam_from_heap | sql_select.cc | 11352 |
| init | 0.000025 | mysql_select | sql_select.cc | 2579 |
| optimizing | 0.000008 | optimize | sql_select.cc | 865 |
| executing | 0.000013 | exec | sql_select.cc | 1836 |
| end | 0.000004 | mysql_select | sql_select.cc | 2615 |
| query end | 0.000010 | mysql_execute_command | sql_parse.cc | 4440 |
| closing tables | 0.000003 | mysql_execute_command | sql_parse.cc | 4492 |
| removing tmp table | 0.005384 | free_tmp_table | sql_select.cc | 11219 |
| closing tables | 0.000014 | free_tmp_table | sql_select.cc | 11244 |
| freeing items | 0.000023 | mysql_parse | sql_parse.cc | 5640 |
| logging slow query | 0.000003 | log_slow_statement | sql_parse.cc | 1461 |
| cleaning up | 0.000005 | dispatch_command | sql_parse.cc | 1417 |見比べてみると、Sending dataの部分の時間の差が基本的にはそのまま実行時間の差になっているようだ。
このクエリは、まずサブクエリが評価されて、tmp_tableへ書きこまれ、tmp_tableがMyISAMに変換されて、それを数えあげて結果を返す、という感じのようだ。
おそらく、SELECT 1の方のクエリは、tmp tableを作成するときに固定のデータをINSERTしつづけるのに対し、SELECT item_idの方はitem_idのフィールドをフェッチする処理が必要で、その時間の差が時間差につながるのかなと思われる。
一番時間かかっているのは2回目のSending dataのところで、1行しか結果がないのに1秒かかっているのは、データを数えあげる時間もここに含まれている、ということだろうか。ただ、MemoryストレージエンジンあるいはMyISAMのSELECT COUNT(*)は最適化で一瞬で数えあげができるはず*1なのだけど、何に時間がかかってるのだろうか?
このプロファイルを実行した環境はtmp_table_sizeの調整をさほどしていないが、tmp_table_sizeを大きくして、メモリストレージエンジンからMyISAMへの変換がなくなれば、もうちょっと早くなると思われる。
なお、MySQLのバージョンは5.5.30で確認しましたが、5.6とかだとまた違ったりするかもしれない。
追記：
ちょっと納得していなかったのだけど、Sending Dataが2回出現するのは、MyISAMへの変換が行なわれるときに、
- Memoryストレージエンジンへデータを入れる
- tmp_table_sizeが溢れそうなので、処理を中断する (1回目のSending Data)
- MyISAMへ今まで入れたデータをconvertする ( converting HEAP to MyISAM )
- MyISAMのテーブルへ引き続きINSERTする (2回目のSending Data)
ということのようだ。tmp_table_sizeを大きくしたら、変換がなくなり、Sending Dataは1回のみになった。
*1:Select tables optimized away
Minillaで複数のテストスイートを実行するようにする
今ちまちま書いてるRedisismというRedis向けのフレームワークでは、Redisとのコネクション周りとかクエリ投げたりするところのハンドリングを自前では持っていなくてほとんど同じインターフェースなので、RedisDBあるいはRedisに任せている。
そうなると、Redisあるいは、RedisDBの両方で同じテストスイートを実行するようにしたくなるので、Text::XslateのAnyMoose対応を参考にModule::Install::Targetを使ってやっていたのだけど、Minillaへ置きかえてみた。
Minillaだと、minil.tomlに
[build] build_class = "builder::MyBuilder"
を追加して、自前でModule::Buildを拡張したものを書く、という感じにできる。
Creating working directory: /Users/yoshimin/project/perl/Redisism/.build/rHpXPchM
Detecting project name from directory name.
Retrieving meta data from lib/Redisism.pm.
Name: Redisism
Abstract: framework for Redis based application.
Version: 0.01
Writing MANIFEST file
Writing release tests: xt/minimum_version.t
Writing release tests: xt/cpan_meta.t
Writing release tests: xt/pod.t
Writing release tests: xt/spelling.t
$ perl -I/Users/yoshimin/project/perl/Redisism/.build/rHpXPchM Build.PL
Created MYMETA.yml and MYMETA.json
Creating new 'Build' script for 'Redisism' version '0.01'
Merging cpanfile prereqs to MYMETA.yml
Merging cpanfile prereqs to MYMETA.json
$ perl -I/Users/yoshimin/project/perl/Redisism/.build/rHpXPchM Build build
Building Redisism
$ perl -I/Users/yoshimin/project/perl/Redisism/.build/rHpXPchM Build test
Testing: $ENV{REDIS_CLIENT} = "Redis"
t/000_load.t .......... ok
t/001_basic.t ......... ok
t/011_factory.t ....... ok
t/020_list.t .......... ok
t/030_set.t ........... ok
t/040_sorted_set.t .... ok
t/050_hash.t .......... ok
xt/cpan_meta.t ........ ok
xt/minimum_version.t .. ok
xt/pod.t .............. ok
xt/podcoverage.t ...... ok
xt/podsynopsis.t ...... ok
xt/spelling.t ......... Possible attempt to separate words with commas at xt/spelling.t line 12.
xt/spelling.t ......... skipped: no ~/.spellunker.en
All tests successful.
Files=13, Tests=57, 6 wallclock secs ( 0.10 usr 0.05 sys + 4.84 cusr 0.44 csys = 5.43 CPU)
Result: PASS
Testing: $ENV{REDIS_CLIENT} = "RedisDB"
t/000_load.t .......... ok
t/001_basic.t ......... ok
t/011_factory.t ....... ok
t/020_list.t .......... ok
t/030_set.t ........... ok
t/040_sorted_set.t .... ok
t/050_hash.t .......... ok
xt/cpan_meta.t ........ ok
xt/minimum_version.t .. ok
xt/pod.t .............. ok
xt/podcoverage.t ...... ok
xt/podsynopsis.t ...... ok
xt/spelling.t ......... Possible attempt to separate words with commas at xt/spelling.t line 12.
xt/spelling.t ......... skipped: no ~/.spellunker.en
All tests successful.
Files=13, Tests=57, 6 wallclock secs ( 0.07 usr 0.04 sys + 4.77 cusr 0.41 csys = 5.29 CPU)
Result: PASS今の時点だと、別々に実行する必要のないところが2回走ってしまう(xt/とか)のがちょっとアレではあるけど、とりあえず良いということにした。
Module::Buildは色々覚えること多そうで移行するのめんどくさいなぁと思っていてまだModule::Install使っていたのだけど、なかなかMinillaは使いやすいし個人的にはもう移行してもよいかなという気になってきた。Module::Buildの拡張もいざやってみると拡張しやすくて使いやすい。Minilla本体ではまだ色々変更が入っているので、こういうニッチな部分はまだまだ仕様が代わったりしそうではある。
ActiveRecordのSQLの実行箇所をSQLのコメントに入れる
arproxyを使うと、SQLにフックして色々書きかえることができて非常に便利ですね。
module Arproxy class QueryLocationCommentAppender < Arproxy::Base WHITE_LIST_WORD_RE = %r{^[a-zA-Z0-9\-_/:\?]+$} def execute(sql, name=nil) if ENV["ARPROXY_QUERY_LOCATION"] # SQL Injection対策 # コメントの閉じ文字がパラメータに含まれていなければ大丈夫なはず if ENV["ARPROXY_QUERY_LOCATION"].index("*/").nil? # 制御文字や、マルチバイトの文字を防ぐため、文字種を制限する if ENV["ARPROXY_QUERY_LOCATION"] =~ WHITE_LIST_WORD_RE substr = ENV["ARPROXY_QUERY_LOCATION"] substr = substr.size >= 100 ? substr.slice(0, 100) : substr sql += " /* called from \"#{substr}\" */ " end end end super(sql, name) end end end Arproxy.configure do |config| config.adapter = "mysql2" config.use Arproxy::QueryLocationCommentAppender end Arproxy.enable!
みたいなのをconfig/initializers/arproxy.rbに書いておいて、ApplicationControllerのbefore_filterあたりにでも、
def set_query_comment_url ENV["ARPROXY_QUERY_LOCATION"] = request.path_info end
こんなのをしこんでおけば、実行したページのURL情報がわかるので、mysqlのslow queryのログなどを見て、どのURLのクエリが重たいのか判別できる。
(なおSQL Injection対策はmysql限定(それ以外は調べてないので、注意))
情報の受けわたしに環境変数をつかってしまったが、グローバル変数でよい気もする。
また、開発時には、URLではなくて、どのmodelや、controller、viewから発行されているか知りたくなるので、
def execute(sql, name=nil) stack_trace = caller.select {|i| i.inspect =~ %r{app/(models|controllers|view)} }.join("\t") if stack_trace # SQL Injection対策 # コメントの閉じ文字がパラメータに含まれていなければ大丈夫なはず if stack_trace.index("*/").nil? substr = stack_trace sql += " /* called from \"#{substr}\" */ " end end super(sql, name) end
こんな感じにしてdevelopment.logを見つつ、発行元を確認するとよい。(だいぶ見づらいけど。
arproxy++
isucon #2へ参加してきました
前回非常に楽しかったので、今回も参加したいなーと思っていたのですが、「くらげとみかん」チームで、なんとか参加できました。
走り書きだけど、考えたこと、やったことをメモっておく(あとでまとめなおすかもしれない)
まずは最初に全サーバーへsshの鍵を通して、screenで全サーバーへログインした。
前回ベンチマークを走らせるのが遅かった、という反省があったので、まずベンチマークを実行した。
まずappをいじるための環境を整備した。git reposを作ったり。(11:30)
次は、アプリケーションの概要を把握するために、全tableのschemaをshow create tableしたり、全テーブルの件数を把握して、stockテーブル以外は対した容量にならない、ということを把握した。
long_query_timeを0にして、ベンチを走らせて、全クエリをslowログへ出力し、mysqldumpslowで解析した。(この時点でpt-query-digest使っておけばよかった...)
前回は、ボトルネック以外のところへ時間を消費してしまった、という反省があったので、stockテーブルへ注力してチューニングを始めた。
チケットの席を発行する処理がぱっとみ遅そうだ、ということで、mysqldのINSERTまわりの設定をチューニング。
具体的には、
- innodb_flush_log_at_trx_commitを0に。
- log-binを無効に
してみると少しスコアがあがった。(通常のwebサービスでは真似しないように)
alter table stock change column seat_id seat_id varchar(6) ascii binary not null;
してseat_idのデータを減らす。
deployスクリプトをかいてなかったので、appをいじるためにdeployスクリプトを書く ( 13:00ごろ)
"order by rand"しているクエリがあったので、とりあえずオフにしてベンチしてみたら通ったので、そのままにした。
alter table stock ROW_FORMAT=Compressed
してみたら少しあがった。
mysqldumpslowが見づらいので、やっぱりpt-query-digestを落としてきて実行する。
stockテーブルのupdated_atは、最後のチケットCSVをダウンロードしているページでしか参照していなくて、order_requestにあっても同じ、ということでupdated_atを移動してやる (stockテーブルよりorder_requestの方が行数がすくない)
alter table order_request add column `updated_at` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP; alter table stock drop column updated_at
updateやJOINしているクエリで読む行数を減らせないかな、というので、
CREATE TABLE `stock_part` (  `variation_id` int(10) unsigned NOT NULL,  `seat_id` varchar(6) CHARACTER SET ascii COLLATE ascii_bin NOT NULL,  `order_id` int(10) unsigned DEFAULT NULL,  PRIMARY KEY `variation_seat` (`variation_id`,`seat_id`) ) ENGINE=InnoDB AUTO_INCREMENT=40961 DEFAULT CHARSET=utf8 ROW_FORMAT=COMPRESSED PARTITION BY LINEAR HASH(variation_id) PARTITIONS 10; rename table stock to stock_bk, stock_part to stock;
してみた (14:43)
stockテーブルの"order_id IS NULL "や、"order_id IS NOT NULL"のクエリが重いので、
そこをなんとかしてなくせないかなーと考えていたら、updated_atと同じ容量で、order_requestへ移せばいいんじゃね?と思ったので、アプリケーションを安全に保ちつつ、徐々に移行していった。
具体的には、variation_id/seat_idをorder_requestへ追加して、二重にINSERTするようにした。
次はJOINしまくっているクエリで、stockテーブルを使っていたところをカラムを追加したことでorder_requestを代用できるようになったのでとても高速になった。 (16:12)
最後にCSVを出力する処理でもstockを使わずにorder_requestで返せるようになったので修正 (16:20 )
このごろになると、徐々にチューニングが効きはじめて、最初のボトルネックからはかわってきたので、slow queryを取得し、pt-query-digestを実行し、アプリを書きかえては、ベンチを実行して測る、というのを繰り返した
for文の中で、1クエリ実行している箇所があったため、INを使ったクエリへ書きかえた。 (17:00)
さらにfor文の中で、1クエリ実行している箇所があったのでINを使って書きかえた(17:16)
ここまででタイムアップしました。
最終的にはチケットの売上枚数が少なかった(1887 ticket)ですが、スコア(260461, BEST: 235274)はけっこうよかったようです。
おそらくカウンタテーブルを用意したことで、購入処理は重くなったが、その一方でチケット残数表示は早くなったんじゃないかと思います。
他の方のまとめはこちら
Play Framework 2.0雑感
scala触ってみたいなぁ、とは前々から思っていつつ、なかなか触れていなかったので、えいやと最近よく聞く気がするPlay Framework 2.0のチュートリアルを触ってみたり、軽いアプリケーションを書いてみての感想。
- APIはよくできていて、非常に綺麗なAPIをしているなと感じた。
- エラー画面などはカッコいい
- devモードは、書きかえるたびにコンパイルが走るので、遅い。
- evolutionsは001.sql/002.sqlなどではダメで、1.sql/2.sqlとしなければいけないのがちょっと管理しにくそう
- anormは、ORMではなく、SQLを直接書く感じのAPIで、JavaでDBさわるときにめんどうな型定義しまくりをしなくてよい、というのは非常に楽で便利だなと思った。
- 一方で、今のところanormのSQLParserのAPIの文法がどういうsyntaxになっているのかが今のところさっぱりわからない。
- テンプレートエンジンは、標準だと、Scalaの文法をそのまま埋めこめるエンジンになっていて、コンパイル時に関数としてコンパイルされ、変数の引き渡しがチェックできるのは新鮮に感じた。一方で、簡単にコンパイルエラーになるので、エンジニア以外が触るのは厳しそうだなーという印象を受けた
- テンプレートエンジンのタグが、@から始まると、scalaのコードというようになっていて、わりとふつうの文章を書いていてもタグとして判別されるのがイケてないなと感じた。
- Formは、optional/nonEmptyTextなどの指定が、どのモジュールで定義されているのか、自前で拡張したいときにどうすればいいのか、がイマイチわからなかった。
- 例えば既に登録されているタイトルを入力できないようにするチェック、などのバリデーションをどう実装すればよいのかわからなかった。
- wikiのページなどのようにURLに日本語を含むを作ろうとしてみたが、文字化けしてしまった。
