dalliはfork safeか?
ふと、dalliがunicornなどのmulti processで動作するアプリケーションで動かしたときにコネクションを張りなおす処理をしないといけないか気になったので、調べてみた。
これを実行してみると、
true 1 I, [2014-01-07T00:27:41.396287 #9290] INFO -- : localhost:11211 failed (count: 0) I, [2014-01-07T00:27:41.396622 #9291] INFO -- : localhost:11211 failed (count: 0) I, [2014-01-07T00:27:41.396905 #9292] INFO -- : localhost:11211 failed (count: 0) I, [2014-01-07T00:27:41.397327 #9293] INFO -- : localhost:11211 failed (count: 0) I, [2014-01-07T00:27:41.397726 #9294] INFO -- : localhost:11211 failed (count: 0) I, [2014-01-07T00:27:41.398108 #9295] INFO -- : localhost:11211 failed (count: 0) I, [2014-01-07T00:27:41.398495 #9296] INFO -- : localhost:11211 failed (count: 0) I, [2014-01-07T00:27:41.399108 #9297] INFO -- : localhost:11211 failed (count: 0) I, [2014-01-07T00:27:41.399440 #9298] INFO -- : localhost:11211 failed (count: 0) I, [2014-01-07T00:27:41.399961 #9299] INFO -- : localhost:11211 failed (count: 0) [9290, 0, 1] [9292, 0, 1] [9291, 0, 1] [9290, 1, 1] [9293, 0, 1]
こんな感じになり、forkした直後のログで失敗した、というエラーメッセージが出るが、その後、再接続し、通信できているようだ。
dalliのソースコード(acb1ff3afd4d)をpidでgrepすると、
# lib/dalli/server.rb def verify_state failure!(RuntimeError.new('Already writing to socket')) if @inprogress failure!(RuntimeError.new('Cannot share client between multiple processes')) if @pid && @pid != Process.pid end
という処理が出てきて、newしたときと、pidが変わっているかをチェックしていることがわかる。
このverify_stateはクライアントがリクエストしようとしたときには必ず通過するようになっているので、これでpidの変更を検出しているようだ。
failureの中では、
def failure!(exception) message = "#{hostname}:#{port} failed (count: #{@fail_count}) #{exception.class}: #{exception.message}" Dalli.logger.info { message } @fail_count += 1 if @fail_count >= options[:socket_max_failures] down! else close sleep(options[:socket_failure_delay]) if options[:socket_failure_delay] raise Dalli::NetworkError, "Socket operation failed, retrying..." end end
のようになっていて、失敗回数を保持するカウンタを1あげつつ、例外を吐いている。
ここで発生させた例外は、
# lib/dalli/client.rb # Chokepoint method for instrumentation def perform(*all_args, &blk) return blk.call if blk op, key, *args = *all_args key = key.to_s key = validate_key(key) begin server = ring.server_for_key(key) ret = server.request(op, key, *args) ret rescue NetworkError => e Dalli.logger.debug { e.inspect } Dalli.logger.debug { "retrying request with new server" } retry end end
serverを呼びだしている元の、performメソッドで、rescueされて、retryするようだ。
pidファイルの管理をする
pgrep -F pidfileオプションを使うと、pidfileを開いて、その中にあるプロセスIDが存在するか調べ、存在している場合には、0で終了してくれるようだ。
なので、起動スクリプトとかで、pidfileの存在チェックとかをするときには、
if test -e $PIDFILE && pgrep -F $PIDFILE > /dev/null; then restart fi
とか書いてやれば、マシンがハングアップとかして、正常に終了しなくて、pidfileが残っているがファイル内にあるプロセスIDはもういない場合にrestartをしても悲しいことにならずにすむ。
なるほど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