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に日本語を含むを作ろうとしてみたが、文字化けしてしまった。
Sphinx+Guardでファイルを変更したときにビルドしつつ、自動でブラウザをリロードする
色々な言語が混ぜまくりすぎなので、他の人も環境を用意するようなものであればあまりおすすめできない。
guardfile内でふつうにWEBRick起動させるコードを書くのがよいんかな。
source/buildするディレクトリを分ける設定であるのを前提としております。
guard-shellとguard-livereloadが必要。
# A sample Guardfile # More info at https://github.com/guard/guard#readme guard 'shell' do watch(%r{source/.+\.rst}) { puts "invoke sphinx build" Process.spawn(%|make html >/dev/null|) } end guard 'shell' do watch(%r{app.psgi}) # dummy Process.spawn(%|plackup -MPlack::App::Directory -e 'Plack::App::Directory->new({root=>"build/html/"})->to_app' -p 3000|) end guard 'livereload' do watch(%r{build/html/.+\.html}) end
追記
WEBrickを使うようにしてみました
# A sample Guardfile # More info at https://github.com/guard/guard#readme guard 'shell' do watch(%r{source/.+\.rst}) { puts "invoke sphinx build" Process.spawn(%|make html >/dev/null|) } end guard 'shell' do watch(%r{app.psgi}) # dummy Process.fork do require 'webrick' webrick = WEBrick::HTTPServer.new({ :DocumentRoot => 'build/html/', :BindAddress => '127.0.0.1', :Port => 3000 }) trap("INT") { webrick.shutdown } webrick.start end end guard 'livereload' do watch(%r{build/html/.+\.html}) end
