久々に面白いモノを作った。
SlowQueryLogger
RailsではActiveRecordを利用してガンガン富豪プログラムを書きがちなため、適切にインデクスを張っていないとすぐに重たくなるので、Rails中で発行された遅いクエリをロギングするプログラムを作った。
ActiveRecordの参照系クエリを発行するメソッドをEXPLAINにより実行解析情報を取得しロギングしてから通常の参照クエリを発行するように拡張し、Rails付属のUnit::TestのfunctionalテストまたはRSpecのコントローラーのSpecファイルを実行する。最終的には、filesortか一時テーブルを使用しているクエリがログファイルに書き出される。
つまり、functional testを定義したファイルかRSpecのcontrollerのスペックファイルがあれば特に何も用意する必要はない。
現在MySQL限定だが、次のような情報もあわせてロギングするためSlow Query Logを見るよりもずっと解析が容易になる。
- 参照問い合わせが呼び出されたソースファイルと行番号
- 実行されたSQL
- EXPLAIN情報
インストールとデプロイ
#{RAILS_ROOT}/script/いかに配置後実行するだけ。
% svn co http://shindaita.stiq.net/svn/slow_query_logger/
% mv slow_query_logger/slow_query_logger.rb /railsapp/script/
% chmod +x /railsapp/script/sloq_query_logger.rb
実行
% ./script/slow_querry_logger.rb
仕様
- functional testとコントローラのRSpecファイルが両方存在する場合はfunctional testを実行する。
- 実行解析情報のExtraフィールドにfilesort or temporaryが存在する時にロギングする。
- 現在MySQLのみ。
- 実行の度にログファイルは初期化される。
log/mysql_slow_query.logの形式
カラーで出力するとかはやらない。
/var/www/rails_app/config/../app/models/user.rb:250:in `find_hoge'
SQL: EXPLAIN SELECT entries.`id` AS t0_r0, entries.`user_id` AS t0_r1, entries.`title` AS t0_r2, entries.`body` AS t0_r3, entries.`created_on` AS t0_r4, entries.`updated_on` AS t0_r5, entries.`group_id` AS t0_r6, entries.`unread_flag_for_self` AS t0_r7, entries.`comments_num` AS t0_r8, entries.`deleted_at` AS t0_r9, entries.`deleted_flag` AS t0_r10, entries.`last_updated_on` AS t0_r11, entries.`last_comment_id` AS t0_r12, entries.`photo_key` AS t0_r13, groups.`id` AS t1_r0, groups.`name` AS t1_r1, groups.`owner_id` AS t1_r2, groups.`public_level` AS t1_r3, groups.`category_id` AS t1_r4, groups.`photo_id` AS t1_r5, groups.`introduction` AS t1_r6, groups.`created_on` AS t1_r7, groups.`updated_on` AS t1_r8, groups.`users_num` AS t1_r9, groups.`official_flag` AS t1_r10, groups.`entry_num` AS t1_r11, groups.`deleted_flag` AS t1_r12 FROM entries LEFT OUTER JOIN groups ON groups.id = entries.group_id WHERE (( entries.deleted_flag = false ) AND ( group_id IN (NULL) )) ORDER BY entries.updated_on DESC LIMIT 5
select_type : SIMPLE
key_len : 5
type : ref
id : 1
Extra : Using where; Using filesort
possible_keys : entries_group_id_index,index_entries_on_group_id_and_created_on
table : entries
rows : 23
ref : const
key : entries_group_id_index
/var/www/rails_app/config/../app/models/user.rb:260:in `find_hoge_hoge'
SQL: EXPLAIN SELECT events.`id` AS t0_r0, events.`group_id` AS t0_r1, events.`title` AS t0_r2, events.`date` AS t0_r3, events.`supplement_date` AS t0_r4, events.`location_id` AS t0_r5, events.`supplement_location` AS t0_r6, events.`user_id` AS t0_r7, events.`description` AS t0_r8, events.`created_on` AS t0_r9, events.`updated_on` AS t0_r10, events.`deleted_at` AS t0_r11, events.`deleted_flag` AS t0_r12, events.`comments_num` AS t0_r13, groups.`id` AS t1_r0, groups.`name` AS t1_r1, groups.`owner_id` AS t1_r2, groups.`public_level` AS t1_r3, groups.`category_id` AS t1_r4, groups.`photo_id` AS t1_r5, groups.`introduction` AS t1_r6, groups.`created_on` AS t1_r7, groups.`updated_on` AS t1_r8, groups.`users_num` AS t1_r9, groups.`official_flag` AS t1_r10, groups.`entry_num` AS t1_r11, groups.`deleted_flag` AS t1_r12 FROM events LEFT OUTER JOIN groups ON groups.id = events.group_id WHERE (( events.deleted_flag = false ) AND ( group_id IN (NULL) )) ORDER BY events.updated_on DESC LIMIT 5
select_type : SIMPLE
key_len : 5
type : ref
id : 1
Extra : Using where; Using filesort
possible_keys : index_events_on_group_id,index_events_on_deleted_flag_and_updated_on
table : events
rows : 1
ref : const
key : index_events_on_group_id
ソース中の51行目の以下の部分を変更すればロギングするクエリを変更できます。(Extraカラムに対する正規表現パターン指定)
LOGGING_PATERN_FOR_EXTRA_FIELD = /(filesort|temporary)/
SlowQuerryLogger使って適切にインデクス張って、ログファイルが出力されなくなるようにしましょう。
参考
5.2.1. EXPLAIN 構文（SELECT に関する情報の取得）
7.2.1. Optimizing Queries with EXPLAIN
第5章 MySQL の最適化
Chapter 7. Optimization
