Kouhei Sutou
kou****@clear*****
2015年 8月 27日 (木) 00:21:50 JST
須藤です。 In <CA+Tq****@mail*****> "[groonga-dev,03423] groonga-clientのタイムアウト値と、遅いクエリについて" on Wed, 26 Aug 2015 22:02:39 +0900, Hiroyuki Sato <hiroy****@gmail*****> wrote: > --query=((( 条件1 OR 条件2 OR 条件3 OR ... ) OR (別の条件 + 別の条件))) - また違う条件 \ ... > 条件1..条件3のORがやたらと多いです。 具体的な条件がわからないとあれなんですが、もしかしたら、 sub_filterかin_valuesで効率よく実行できるようにできるかもし れません。 ただ、後述するように、ボトルネックは出力なので、ここはまだそ んなに頑張らなくてもよさそうな気はします。 > 1, タイムアウトを伸ばすのは,Open時にread_timeoutを設定すれば良いでしょうか？ > > grn_conf = { :host => 'localhost', > :port => 1234, > :protocol => 'http' > :read_timeout => 360 } > @aggregates = var['aggregates'] > @client = Groonga::Client.open(grn_conf) はい、あっています。 ちなみに、read_timeoutの単位は病です。 > 2, クエリのどの部分に時間がかかっているか確認する方法 > > ORをたくさん繋いでいるのでなんとなく遅くなるのはわかるのですが、 > 実際どの部分に時間がかかっているか確認したいと思っています。 > > ログのどの辺を見れば良いでしょうか？ クエリーログを見るのがよいです。なので、あっています。 > 例えば次のクエリだと、ソートに15秒かかっているという理解でよいのでしょうか？ > > 2015-08-26 21:54:03.413553|0x10a88fd70|>/d/select > 2015-08-26 21:54:03.448127|0x10a88fd70|:000000034591000 filter(10234) > 2015-08-26 21:54:03.453527|0x10a88fd70|:000000039991000 filter(10234) > 2015-08-26 21:54:03.482513|0x10a88fd70|:000000068968000 filter(10234) > 2015-08-26 21:54:03.484300|0x10a88fd70|:000000070751000 filter(10234) > 2015-08-26 21:54:03.493638|0x10a88fd70|:000000080089000 filter(10255) > 2015-08-26 21:54:03.532504|0x10a88fd70|:000000118972000 filter(9194) > 2015-08-26 21:54:03.535103|0x10a88fd70|:000000121555000 filter(9173) > 2015-08-26 21:54:03.537450|0x10a88fd70|:000000123903000 filter(9173) > 2015-08-26 21:54:03.537477|0x10a88fd70|:000000123929000 select(9173) > 2015-08-26 21:54:03.573637|0x10a88fd70|:000000160103000 sort(9173) > 2015-08-26 21:54:18.676723|0x10a88fd70|:000015263184000 output(9173) > 2015-08-26 21:54:18.681831|0x10a88fd70|<000015268299000 rc=0 いえ、出力に15秒かかっています。 sortは0.03秒です。 たぶん、データを読み出すディスクIOがネックになっているんだと 思います。GroongaのDBのデータが入っているファイルがOSのペー ジキャッシュにのれば速くなる気がします。 あるいは、highlight_html()がネックになっているか、です。 CPUがiowaitになっていれば前者で、iowaitじゃなくCPUを使ってい るなら後者です。 ちなみに、groonga-query-logというgemがあって、それをインストー ルするとgroonga-query-log-analyzeというツールが使えるように なります。 ↑のログに適用すると次のような出力が得られます。 --- % groonga-query-log-analyze /tmp/query.log Summary: Threshold: slow response : 0.2 slow operation : 0.1 # of responses : 1 # of slow responses : 1 responses/sec : 0.06549518056988535 start time : 2015-08-26 21:54:03.3 last time : 2015-08-26 21:54:18.3 period(sec) : 15.268299 slow response ratio : 100.000% total response time : 15.268299 Slow Operations: [15.103081](98.92%) [1](100.00%) output: Slow Queries: 1) [2015-08-26 21:54:03.3-2015-08-26 21:54:18.3 (15.26829900)](0): /d/select name: <select> parameters: 1) 0.03459100: filter( 10234) 2) 0.00540000: filter( 10234) 3) 0.02897700: filter( 10234) 4) 0.00178300: filter( 10234) 5) 0.00933800: filter( 10255) 6) 0.03888300: filter( 9194) 7) 0.00258300: filter( 9173) 8) 0.00234800: filter( 9173) 9) 0.00002600: select( 9173) 10) 0.03617400: sort( 9173) 11) 15.10308100: output( 9173) --- 最後のリストを見るとどの処理にどのくらい時間がかかっているか がわかります。outputの左に15.xxxとあるので、出力 （output_columnsのところ）に15秒書いていることがわかります。 去年の「Groongaを囲む夕べ」で砂原さんが紹介してくれて、それ をQiitaにまとめたものがあるので、こちらもあわせて参照してく ださい。 * 運用に便利なgroonga-query-logの使い方 http://qiita.com/Ch_1012/items/363f96ded47375dc0d35 最近、GroongaのクエリーログをFluentdに入れて、それを↑でパー スしてすぐにデータとして扱えるようにするFluentdのプラグイン を作りました。 https://github.com/groonga/fluent-plugin-groonga-query-log スロークエリーがあったら（わりと）すぐに検出するシステムを作 るのに使えるといいなぁと思って作り始めました。 > 3, syscall error 'sendmsg' (Protocol wrong type for socket)[41]について > > この遅いクエリを実行しているとサーバ側で上記のメッセージがでるのですが、 > これはサーバ側の問題なのかクライアント側がコネクションが切れたのか > わかりますでしょうか？ このエラーははじめてみました。 引き金はクライアントがタイムアウトで接続を切っているのに、サー バー側が気づいていなくてそのまま処理を継続した、だと思います。 OS Xじゃないと発生しないのかもしれません。 死んでいるfdにsendmsg()しているようなメッセージに見えるんで すよねぇ。クライアントが接続を切った状態でsendmsg()してエラー になるのはGroonga的にはそういうものなので大丈夫なんですが、 それ以外の何かでこういう状況になっているならなにか問題がある かもしれません。 > 4, クエリのselect時にunlimitedで全件取得というのは可能でしょうか？ > > select時に--limit 0とすれば検索件数が取得できるのは知っていますが。 > 一回のクエリで全件簡単に取得することはできますでしょうか？ > 今は9999と大きな数値を指定しています。 実は、--limit -1で全件返します。 http://groonga.org/ja/docs/reference/commands/select.html#limit > 参考までにその他のログを一部gistにのせました。 > https://gist.github.com/hiroyuki-sato/a185469981de42de86b4 1回のクエリーで100行以上ログが出るのはなかなかすごいです ね。。。 -- 須藤 功平 <kou****@clear*****> 株式会社クリアコード <http://www.clear-code.com/> Groongaベースの全文検索システムを総合サポート: http://groonga.org/ja/support/ パッチ採用 - プログラミングが楽しい人向けの採用プロセス: http://www.clear-code.com/recruitment/ コードリーダー育成支援 - 自然とリーダブルコードを書くチームへ: http://www.clear-code.com/services/code-reader/
