Masayuki Shibata
mshib****@shima*****
2010年 1月 6日 (水) 11:48:04 JST
柴田＠亀岡市です。
現象再現のため、昨日と同じバージョンで試しています。
条件もほぼ同じ (ロール設定のテストのためロール svnuser を設定
してみた... という状態が差異) ですが、クロールを開始してから
ちょっと忙しくて (仕事中に走らせてますので) 管理画面を開かず
にいたら２時間ほどで 4000件までドキュメント数が行ってました。
ところが管理画面を開いた (4000件也を確認) 後、ブラウザ上ログ
アウトしてそのままほかのサイトをしばらく見ていたところ、
Tomcat のターミナル出力にいままで順調に表示されていた
情報: {add=[http://...
...のログがしばらく出てこなくなっていました。
以下ターミナル出力の状況です。１行目までずっと順調で２行目か
ら管理画面を開けたときに出る文字列を表示してます。
10:34 ごろに 4000件也を確認しログアウトし、10:52 ごろにターミ
ナルに何も出てこないのを再度ログインして確認。
ログアウトしてブラウザを閉じたところ何やら出力されています。
＃Found a TextHeaderAtom not... の行です。
fess.out のログの方を見ると画面に出てなくても順調にクロールし
ているようなのですが... 何故かターミナルには出てこなくなってい
ました。そういうもののような気もしますが、少し長いような...
...でその後、しばらくして復活はしているのですが、以下の 10-17
行目に表示されている 3999 (4000 - 1) にまつわる出力行が少し気
になります。
不具合ではないかも知れませんが、一応お知らせしておきます。
＃現在 5000件まで行っているので、現象再現するかもう少ししたら
＃結果が出ます。後ほどまたご報告します。
01| 情報: {add=[http://{省略: URL の羅列}...;type=pc;role=svnuser, ...(3 more)]} 0 94
02| 2010/01/06 10:34:45 org.apache.solr.core.SolrCore execute
03| 情報: [] webapp=/solr path=/update params={wt=javabin&version=2.2} status=0 QTime=94
04| 2010/01/06 10:36:13 org.apache.solr.core.SolrCore execute
05| 情報: [] webapp=/solr path=/select params={facet=true&sort=segment+desc&q=*:
*&facet.field=segment&wt=javabin&version=2.2} hits=12158 status=0 QTime=94
06| 2010/01/06 10:52:02 org.apache.solr.core.SolrCore execute
07| 情報: [] webapp=/solr path=/select params={facet=true&sort=segment+desc&wt=javabin&version=
2.2&q=*:*&facet.field=segment} hits=12158 status=0 QTime=0
08| 2010/01/06 10:52:44 org.apache.solr.core.SolrCore execute
09| 情報: [] webapp=/solr path=/select params={facet=true&sort=segment+desc&wt=javabin&version=
2.2&q=*:*&facet.field=segment} hits=12158 status=0 QTime=0
10| Found a TextHeaderAtom not followed by a TextBytesAtom or TextCharsAtom: Followed by 3999
11| Found a TextHeaderAtom not followed by a TextBytesAtom or TextCharsAtom: Followed by 3999
12| Found a TextHeaderAtom not followed by a TextBytesAtom or TextCharsAtom: Followed by 3999
13| Found a TextHeaderAtom not followed by a TextBytesAtom or TextCharsAtom: Followed by 3999
14| Found a TextHeaderAtom not followed by a TextBytesAtom or TextCharsAtom: Followed by 3999
15| Found a TextHeaderAtom not followed by a TextBytesAtom or TextCharsAtom: Followed by 3999
16| Found a TextHeaderAtom not followed by a TextBytesAtom or TextCharsAtom: Followed by 3999
17| Found a TextHeaderAtom not followed by a TextBytesAtom or TextCharsAtom: Followed by 3999
>菅谷です。
>
>情報をありがとうございます。
>
>> ＃unprocessed documents は 400 台のようです。
>
>これくらいで3時間ですと、期待外の動きです…。
>
>ドキュメントサイズによると思いますが、「Sent 11
>documents.〜」で Solr への投入が秒レベルの時間が
>かかるのも気になります。私のテストデータですと
>(Apache 系プロジェクトのソースコード)、数十ミリ秒で
>投入している感じです。もしかしたら、
>maxDocumentCacheSize を増やすのではなく、5とか
>減らすと良いかもしれません。
>
>あとは、クロール全般の「ドキュメント数毎にコミット 」を
>500 とか減らしてしまってもよいかもしれません。
>
>3時間近く止まる件ですが、こちらの継続動作テストで
>全クロール停止のインデックス更新中に、管理画面で
>停止すると、止まらなくなる問題が発覚したので修正
>しました。(これでしたら、すいません…)
>
>http://sourceforge.jp/ticket/browse.php?group_id=4342&tid=20133
>
>あとは問題を絞り込んでいくためには対象部分の
>ログレベルを DEBUG にしていただけると、より
>分かってくるかと思います。webapps/fess/WEB-INF/
>classes/log4j.xml の
>
> <logger name="jp.sf.fess.solr" >
> <level value ="debug" />
> </logger>
>
>をコメントアウトから出していただけると、IndexUpdaterが
>よりいろいろと出力します。
>
>> 以前 6000 を少し越えるところまで溜まった段階で時間切れで手動停
>> 止したことはありますので、何か条件が異なるのだと思います。
>
>対象データによるというのもありますが、現在、手元の
>テストデータでは 2 日くらいで 60 万件くらいはいけてます。
>さすがにここら辺で遅くなってきていますが…。
>
>shinsuke
>
>
>2010年1月5日19:34 Masayuki Shibata <mshib****@shima*****>:
>> 柴田＠亀岡市です。
>>
>>>AuthChallengeProcessor のログを除いた、最後の数行ログは
>>>何になっているでしょうか?
>> ...
>>>しかし、その場合に３時間も返ってこないのは期待通り
>>>ではない感じです・・・。「You have XXX unprocessed
>>>documents.」のXXXがかなりの数になっていると別ですが。
>>>(数千など) あとは、「The execution time is XXXms.」の
>>>XXX (Solrにドキュメントを送って処理した時間) が大体
>>>どれくらいかも気になります。
>>
>> ファイル名 (URL) のみ伏せ字にしてますが、以下が生ログです。
>> ＃unprocessed documents は 400 台のようです。
>>
>> 2010-01-05 12:22:42,875 [Robot-20100105092954-1-5] INFO
>> org.seasar.robot.helper.impl.LogHelperImpl - Crawling URL: http://hostname/svn/project/XXXXXXXXXXXXXX/
>> 2010-01-05 12:22:42,890 [Robot-20100105092954-1-5] INFO
>> org.apache.commons.httpclient.auth.AuthChallengeProcessor - digest authentication scheme
selected
>> 2010-01-05 12:22:42,921 [IndexUpdater] INFO jp.sf.fess.solr.IndexUpdater - Sent 11 documents.
>> The execution time is 593ms.
>> 2010-01-05 12:29:36,640 [IndexUpdater] INFO jp.sf.fess.solr.IndexUpdater - Stopped all
crawler
>> threads. You have 497 unprocessed documents.
>> 2010-01-05 12:29:43,750 [IndexUpdater] INFO jp.sf.fess.solr.IndexUpdater - Sending 11
document
>> to a server.
>> 2010-01-05 12:29:43,906 [IndexUpdater] INFO
>> org.apache.commons.httpclient.auth.AuthChallengeProcessor - basic authentication scheme
selected
>> 2010-01-05 12:29:44,250 [IndexUpdater] INFO jp.sf.fess.solr.IndexUpdater - Sent 11 documents.
>> The execution time is 500ms.
>> 2010-01-05 12:36:48,125 [IndexUpdater] INFO jp.sf.fess.solr.IndexUpdater - Stopped all
crawler
>> threads. You have 487 unprocessed documents.
>> 2010-01-05 12:49:21,562 [http-8080-2] INFO
>> org.apache.commons.httpclient.auth.AuthChallengeProcessor - basic authentication scheme
selected
>> 2010-01-05 12:49:25,750 [http-8080-5] INFO
>> org.apache.commons.httpclient.auth.AuthChallengeProcessor - basic authentication scheme
selected
>> 2010-01-05 13:27:47,578 [IndexUpdater] INFO jp.sf.fess.solr.IndexUpdater - Sending 11
document
>> to a server.
>> 2010-01-05 13:27:47,953 [IndexUpdater] INFO
>> org.apache.commons.httpclient.auth.AuthChallengeProcessor - basic authentication scheme
selected
>> 2010-01-05 13:27:48,593 [IndexUpdater] INFO jp.sf.fess.solr.IndexUpdater - Sent 11 documents.
>> The execution time is 1015ms.
>> 2010-01-05 14:01:57,734 [IndexUpdater] INFO jp.sf.fess.solr.IndexUpdater - Stopped all
crawler
>> threads. You have 477 unprocessed documents.
>> 2010-01-05 14:08:13,906 [http-8080-5] INFO
>> org.apache.commons.httpclient.auth.AuthChallengeProcessor - basic authentication scheme
selected
>> 2010-01-05 14:08:17,281 [http-8080-5] INFO
>> org.apache.commons.httpclient.auth.AuthChallengeProcessor - basic authentication scheme
selected
>> 2010-01-05 14:11:18,875 [IndexUpdater] INFO jp.sf.fess.solr.IndexUpdater - Sending 11
document
>> to a server.
>> 2010-01-05 14:11:19,406 [IndexUpdater] INFO
>> org.apache.commons.httpclient.auth.AuthChallengeProcessor - basic authentication scheme
selected
>> 2010-01-05 14:11:20,187 [IndexUpdater] INFO jp.sf.fess.solr.IndexUpdater - Sent 11 documents.
>> The execution time is 1312ms.
>> 2010-01-05 14:32:07,828 [http-8080-5] INFO
>> org.apache.commons.httpclient.auth.AuthChallengeProcessor - basic authentication scheme
selected
>> 2010-01-05 14:32:12,218 [http-8080-5] INFO
>> org.apache.commons.httpclient.auth.AuthChallengeProcessor - basic authentication scheme
selected
>> 2010-01-05 14:35:34,312 [http-8080-5] INFO
>> org.apache.commons.httpclient.auth.AuthChallengeProcessor - basic authentication scheme
selected
>> ... (同じ内容のログが20行ほど続く)
>>
>>>あとは、Tomcat の logs/catalina.out に
>>>何か出ていないでしょうか?
>>
>> 黙り込む直前 14:11:20 頃まで 「情報: {add=[http://...」という
>> ログが出ているのですが、最後の３回分がかなり時間間隔が開いてい
>> ます。
>>
>> それ以前は１〜２秒間隔だったのが、最後の３つの間隔は１時間程度、
>> (その１つ前とは７分くらい) ですので、急激にのろくなった感じで
>> 止まっています。
>>
>> そのログの間に、クロール実行中の確認や、生きているかの確認のた
>> めの検索のログがはさまっているくらいで、特に不審なものは見あた
>> りません。
>>
>> 少しずつ設定をチューニングしているので同じ条件ではありませんが
>> 以前 6000 を少し越えるところまで溜まった段階で時間切れで手動停
>> 止したことはありますので、何か条件が異なるのだと思います。
>>
>> _______________________________________________
>> Fess-user mailing list
>> Fess-****@lists*****
>> http://lists.sourceforge.jp/mailman/listinfo/fess-user
>>
>
>_______________________________________________
>Fess-user mailing list
>Fess-****@lists*****
>http://lists.sourceforge.jp/mailman/listinfo/fess-user
>