Re: Solr client 'Timeout was reached' ~ when new documents are inserted and commits are made.

2013-09-27 Thread Erick Erickson 
No, this isn't normal. You probably have your servlet container or your
clients have a too-short timeout. How long are we talking about here anyway?

Best,
Erick

On Fri, Sep 27, 2013 at 8:57 AM, Rafał Radecki
r.rade...@polskapresse.pl wrote:
 Hi All.

 I have a solr 3.5 multicore installation. It has ~250 of documents, 
 ~1,5GB of index data.
 When the solr is feed with new documents I see for a few seconds timeouts 
 'Timeout was reached' on clients.
 Is it normal behaviour of solr during inserting of new documents?

 Best regards,
 Rafał Radecki.

Re: Solr client 'Timeout was reached' ~ when new documents are inserted and commits are made.

2013-09-27 Thread Rafał Radecki 
On client side timeout is set to 5s but when I look in solr log I see QTime 
less than 5000 (in ms). We use jetty to start solr process, where should I look 
for directives connected with timeouts?

Re: Solr client 'Timeout was reached' ~ when new documents are inserted and commits are made.

2013-09-27 Thread Shawn Heisey 
On 9/27/2013 7:41 AM, Rafał Radecki wrote:
 On client side timeout is set to 5s but when I look in solr log I see QTime 
 less than 5000 (in ms). We use jetty to start solr process, where should I 
 look for directives connected with timeouts? 

Five seconds is WAY too short a timeout for the entire http
conversation.  Generally a timeout is not required, but if you feel you
need to set one, set it in terms of minutes, with one minute as an
absolute minimum.

Updates generally take longer than queries.  The amount of time taken
for the update itself is usually fairly small, but after a commit there
is usually cache warming, which depending on your configuration can take
quite a while.

I'm pretty sure that you won't see the QTime of update requests in the
log, at least not listed as QTime like it is on queries.  Here are two
entries from my log, one for the doc insert, the other for the commit.
I believe the last number is the QTime, but it doesn't *say* QTime.

INFO  - 2013-09-27 08:27:00.806;
org.apache.solr.update.processor.LogUpdateProcessor; [inclive]
webapp=/solr path=/update params={wt=javabinversion=2}
{add=[notimexpix438424 (144734108581888), notimexpix438425
(1447341085825171456), notimexpix438426 (1447341085826220032),
notimexpix438427 (1447341085826220033), notimexpix438428
(1447341085827268608), notimexpix438429(1447341085828317184),
notimexpix438430 (1447341085829365760), notimexpix438431
(1447341085830414336), notimexpix438432 (1447341085831462912),
notimexpix438433 (1447341085831462913), ... (66 adds)]} 0 181

INFO  - 2013-09-27 08:27:01.975;
org.apache.solr.update.processor.LogUpdateProcessor; [inclive]
webapp=/solr path=/update
params={waitSearcher=truecommit=truewt=javabinversion=2softCommit=false}
{commit=} 0 1065

Note that the QTime doesn't represent the total amount of time for the
request, because it only measures the part that's in under the control
of the specific class that's generating the log - in this case
LogUpdateProcessor.  It can't measure the time the servlet container
takes to handle the HTTP conversation, or any part of the request that
takes place in Solr classes called before or after LogUpdateProcessor.

Thanks,
Shawn

Re: Solr client 'Timeout was reached' ~ when new documents are inserted and commits are made.

2013-09-27 Thread Shawn Heisey 
On 9/27/2013 8:37 AM, Shawn Heisey wrote:
 INFO  - 2013-09-27 08:27:00.806;
 org.apache.solr.update.processor.LogUpdateProcessor; [inclive]
 webapp=/solr path=/update params={wt=javabinversion=2}
 {add=[notimexpix438424 (144734108581888), notimexpix438425
 (1447341085825171456), notimexpix438426 (1447341085826220032),
 notimexpix438427 (1447341085826220033), notimexpix438428
 (1447341085827268608), notimexpix438429(1447341085828317184),
 notimexpix438430 (1447341085829365760), notimexpix438431
 (1447341085830414336), notimexpix438432 (1447341085831462912),
 notimexpix438433 (1447341085831462913), ... (66 adds)]} 0 181
 
 INFO  - 2013-09-27 08:27:01.975;
 org.apache.solr.update.processor.LogUpdateProcessor; [inclive]
 webapp=/solr path=/update
 params={waitSearcher=truecommit=truewt=javabinversion=2softCommit=false}
 {commit=} 0 1065
 
 Note that the QTime doesn't represent the total amount of time for the
 request, because it only measures the part that's in under the control
 of the specific class that's generating the log - in this case
 LogUpdateProcessor.  It can't measure the time the servlet container
 takes to handle the HTTP conversation, or any part of the request that
 takes place in Solr classes called before or after LogUpdateProcessor.

I can illustrate the difference between QTime and the actual transaction
time by showing you the log entries from the application that correspond
exactly to the Solr log entries I shared:

INFO  - 2013-09-27 08:27:00.815; chain.c: Insert done, 66, time = 315
INFO  - 2013-09-27 08:27:01.976; chain.c: Commit done, time = 1161

The add request with 66 documents had a QTime of 181, but took 315
milliseconds.  The commit had a QTime of 1065, but actually took 1161
milliseconds.

Thanks,
Shawn