Hiroyuki Sato
hiroy****@gmail*****
2015年 8月 27日 (木) 12:17:38 JST
須藤様 佐藤です。 私のクエリが問題なのかもしれませんが、 やはり、highlight_htmlを使うと遅いです。 再現環境を用意しました。 https://github.com/hiroyuki-sato/groonga-highlight_test よろしくお願いします。 2015年8月27日 9:51 Hiroyuki Sato <hiroy****@gmail*****>: > 須藤様 > > 佐藤です。 > > ありがとうございます。 > ざっと見た感じ、hightlight_htmlが遅いようです。 > > highlight_htmlを使っている部分を外したら速くなりました。 > 再現できる何かを考えます。 > > func_highlight_htmlを見ましたが、これは一度テーブルを作って > データをインサートしたあとハイライトした文字列を生成する感じなんですね。(多分) > > > > limitの件失礼しました。完全に見落としていました。 > > > 2015年8月27日 0:21 Kouhei Sutou <kou****@clear*****>: >> 須藤です。 >> >> 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/ >> >> _______________________________________________ >> groonga-dev mailing list >> groon****@lists***** >> http://lists.osdn.me/mailman/listinfo/groonga-dev > > > > -- > Hiroyuki Sato -- Hiroyuki Sato
