なるほどUNIXプロセス
http://tatsu-zine.com/books/naruhounix
帰省中の新幹線でナルホディウス!しながら読んだ。
中身としては思っていたよりはライトな内容で、わりと知っていることだった。
Resqueのworkerが毎回worker実行するときにforkするのはなんでだろーと思っていたので、そこの解説はよかった。
Resqueのところで、fork時にsrandしている説明があるが、これは解説通りごくごく一部のバージョンのバグなどで動かないというだけなので、以前調査したように、rubyではsrandする必要はない。
waitpid(2)が、子プロセスが死んでしまってから親プロセスが実行しても、Kernelがちゃんと動作を保証してくれる、というのは知らなかったので良い発見だった。
Kindleで読む気だったのだけど、Kindleがちょうど応答不能になってしまっていた関係で、泣く泣くPCで、iBookで読んだのだけど、Kindleよりは目が疲れるけど、サンプルすぐ試したりできるし、PCで本読むのはふつうにありだなと思いました。Cracking The Coding Interviewは重くて持ち運びにくいので、電子版も欲しくなってしまった
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++
