Re: Solr connection timeout hardwired to 60s
On 4/4/19 6:47 PM, dovecot-request@dovecot.org wrote:
For a typical Solr index, 60 seconds is an eternity. Most people aim for query times of 100 milliseconds or less, and they often achieve that goal.
I'm pretty sure I get these while indexing, not querying.
Apr 04 16:44:50 host dovecot[114690]: indexer-worker(me@example.com): Error: fts_solr: Indexing failed: Request timed out (Request queued 66.015 secs ago, 1 attempts in 66.005 secs, 63.146 in http ioloop, 0.000 in other ioloops, connected 94.903 secs ago)
/Peter
On 4/4/19 6:57 PM, Peter Mogensen wrote:
On 4/4/19 6:47 PM, dovecot-request@dovecot.org wrote:
For a typical Solr index, 60 seconds is an eternity. Most people aim for query times of 100 milliseconds or less, and they often achieve that goal.
I'm pretty sure I get these while indexing, not querying.
Apr 04 16:44:50 host dovecot[114690]: indexer-worker(me@example.com): Error: fts_solr: Indexing failed: Request timed out (Request queued 66.015 secs ago, 1 attempts in 66.005 secs, 63.146 in http ioloop, 0.000 in other ioloops, connected 94.903 secs ago)
Doing a TCP dump on indexing operations which consistently fail, I see that there's a lot of softCommits which never get an HTTP answer:
============================================== POST /solr/dovebody/update HTTP/1.1 Host: localhost:8983 Date: Wed, 10 Apr 2019 14:22:29 GMT Expect: 100-continue Content-Length: 47 Connection: Keep-Alive Content-Type: text/xml
HTTP/1.1 100 Continue
<commit softCommit="true" waitSearcher="true"/>
... in contrast to the first softCommit on the connection:
================================================ POST /solr/dovebody/update HTTP/1.1 Host: localhost:8983 Date: Wed, 10 Apr 2019 14:20:53 GMT Expect: 100-continue Content-Length: 47 Connection: Keep-Alive Content-Type: text/xml
HTTP/1.1 100 Continue
<commit softCommit="true" waitSearcher="true"/>HTTP/1.1 200 OK Content-Type: application/xml; charset=UTF-8 Content-Length: 156
<?xml version="1.0" encoding="UTF-8"?>
<response>
<lst name="responseHeader"> <int name="status">0</int> <int name="QTime">37</int> </lst> </response> ==================================================
The missing softCommit responses seem to start right after the last added document:
</field></doc></add> 0
HTTP/1.1 200 OK Content-Type: application/xml; charset=UTF-8 Content-Length: 156
<?xml version="1.0" encoding="UTF-8"?>
<response>
<lst name="responseHeader"> <int name="status">0</int> <int name="QTime">12</int> </lst> </response> POST /solr/dovebody/update HTTP/1.1 Host: localhost:8983 Date: Wed, 10 Apr 2019 14:22:29 GMT Expect: 100-continue Content-Length: 47 Connection: Keep-Alive Content-Type: text/xml
HTTP/1.1 100 Continue
<commit softCommit="true" waitSearcher="true"/>
... and then the rest of the TCP dump doesn't get responses to softCommit POSTs
/Peter
Looking further at tcpdumps of the Dovecot->Solr traffic and Solr metrics it doesn't seem like there's anything suspicious apart from the TCP windows running full and Dovecot backing of ... until it times out and close the connection.
From my understanding of how Dovecot operates towards Solr it will flush ~1000 documents towards Solr in /update request until it has traversed the mailbox (let's say 20.000 mails), doing softCommits after each.
But is it really reasonable for Dovecot to expect that no request will take more than 60s to process by Solr? It doesn't seem like my Solr can handle that, although it does process documents and it does reasonably fast clear pending documents after Dovecot closes the connection.
On the surface it looks like Dovecot is too impatient.
/Peter
On 4/10/19 6:25 PM, Peter Mogensen wrote:
On 4/4/19 6:57 PM, Peter Mogensen wrote:
On 4/4/19 6:47 PM, dovecot-request@dovecot.org wrote:
For a typical Solr index, 60 seconds is an eternity. Most people aim for query times of 100 milliseconds or less, and they often achieve that goal.
I'm pretty sure I get these while indexing, not querying.
Apr 04 16:44:50 host dovecot[114690]: indexer-worker(me@example.com): Error: fts_solr: Indexing failed: Request timed out (Request queued 66.015 secs ago, 1 attempts in 66.005 secs, 63.146 in http ioloop, 0.000 in other ioloops, connected 94.903 secs ago)
Doing a TCP dump on indexing operations which consistently fail, I see that there's a lot of softCommits which never get an HTTP answer:
============================================== POST /solr/dovebody/update HTTP/1.1 Host: localhost:8983 Date: Wed, 10 Apr 2019 14:22:29 GMT Expect: 100-continue Content-Length: 47 Connection: Keep-Alive Content-Type: text/xml
HTTP/1.1 100 Continue
<commit softCommit="true" waitSearcher="true"/>
....
On 12/04/2019 12:09, Peter Mogensen via dovecot wrote:
Looking further at tcpdumps of the Dovecot->Solr traffic and Solr metrics it doesn't seem like there's anything suspicious apart from the TCP windows running full and Dovecot backing of ... until it times out and close the connection.
From my understanding of how Dovecot operates towards Solr it will flush ~1000 documents towards Solr in /update request until it has traversed the mailbox (let's say 20.000 mails), doing softCommits after each.
But is it really reasonable for Dovecot to expect that no request will take more than 60s to process by Solr? It doesn't seem like my Solr can handle that, although it does process documents and it does reasonably fast clear pending documents after Dovecot closes the connection.
On the surface it looks like Dovecot is too impatient.
/Peter
If this value was made configurable people could set it to what they want. However the underlying problem is likely on solr configuration.
Is this a problem only on initial indexing or an ongoing problem after initial indexing?
The parameters that the solr plugin are using are designed to make documents visible to searches quickly.
If there is an issue on initial indexing, where you are not really concerned about qucik visibility but just getting things into the index efficiently, a better approach would be for dovecot plugin not to send any commit or softCommit (or waitSearcher either) and that should speed things up. You'd need to configure solr with a long autoSoftCommit maxTime and a reasonable autoCommit maxTime, which you could then reconfigure when the load was done.
If you're using dovecot built from source code it should be possible to test that by some minor modification of the code in fts-backend-solr.c.
John
On 4/13/2019 4:29 AM, John Fawcett via dovecot wrote:
If this value was made configurable people could set it to what they want. However the underlying problem is likely on solr configuration.
The Jetty that is included in Solr has its idle timeout set to 50 seconds. But in practice, I have not seen this timeout trigger ... and if the OP is seeing a 60 second timeout, then the 50 second idle timeout in Jetty must not be occurring.
There may be a socket timeout configured on inter-server requests -- distributed queries or the load balancing that SolrCloud does. I can never remember whether this is the case by default. I think it is.
If there is an issue on initial indexing, where you are not really concerned about qucik visibility but just getting things into the index efficiently, a better approach would be for dovecot plugin not to send any commit or softCommit (or waitSearcher either) and that should speed things up. You'd need to configure solr with a long autoSoftCommit maxTime and a reasonable autoCommit maxTime, which you could then reconfigure when the load was done.
Solr ships with autoCommit set to 15 seconds and openSearcher set to false on the autoCommit. The autoSoftCommit setting is not enabled by default, but depending on how the index was created, Solr might try to set autoSoftCommit to 3 seconds ... which is WAY too short.
I will usually increase the autoCommit time to 60 seconds, just to reduce the amount of work that Solr is doing. The autoSoftCommit time, if it is used, should be set to a reasonably long value ... values between two and five minutes would be good. Attempting to use a very short autoSoftCommit time will usually lead to problems.
This thread says that dovecot is sending explicit commits. One thing that might be happening to exceed 60 seconds is an extremely long commit, which is usually caused by excessive cache autowarming, but might be related to insufficient memory. The max heap setting on an out-of-the-box Solr install (5.0 and later) is 512MB. That's VERY small, and it doesn't take much index data before a much larger heap is required.
Thanks, Shawn
On 13/04/2019 17:16, Shawn Heisey via dovecot wrote:
On 4/13/2019 4:29 AM, John Fawcett via dovecot wrote:
If this value was made configurable people could set it to what they want. However the underlying problem is likely on solr configuration.
The Jetty that is included in Solr has its idle timeout set to 50 seconds. But in practice, I have not seen this timeout trigger ... and if the OP is seeing a 60 second timeout, then the 50 second idle timeout in Jetty must not be occurring.
There may be a socket timeout configured on inter-server requests -- distributed queries or the load balancing that SolrCloud does. I can never remember whether this is the case by default. I think it is.
If there is an issue on initial indexing, where you are not really concerned about qucik visibility but just getting things into the index efficiently, a better approach would be for dovecot plugin not to send any commit or softCommit (or waitSearcher either) and that should speed things up. You'd need to configure solr with a long autoSoftCommit maxTime and a reasonable autoCommit maxTime, which you could then reconfigure when the load was done.
Solr ships with autoCommit set to 15 seconds and openSearcher set to false on the autoCommit. The autoSoftCommit setting is not enabled by default, but depending on how the index was created, Solr might try to set autoSoftCommit to 3 seconds ... which is WAY too short.
I will usually increase the autoCommit time to 60 seconds, just to reduce the amount of work that Solr is doing. The autoSoftCommit time, if it is used, should be set to a reasonably long value ... values between two and five minutes would be good. Attempting to use a very short autoSoftCommit time will usually lead to problems.
This thread says that dovecot is sending explicit commits. One thing that might be happening to exceed 60 seconds is an extremely long commit, which is usually caused by excessive cache autowarming, but might be related to insufficient memory. The max heap setting on an out-of-the-box Solr install (5.0 and later) is 512MB. That's VERY small, and it doesn't take much index data before a much larger heap is required.
Thanks, Shawn
I looked into the code (version 2.3.5.1): the fts-solr plugin is not sending softCommit every 1000 emails. Emails from a single folder are batched in up to a maximum of 1000 emails per request, but the softCommit gets sent once per mailbox folder at the end of all the requests for that folder.
I immagine that one of the reasons dovecot sends softCommits is because without autoindex active and even if mailboxes are periodically indexed from cron, the last emails received with be indexed at the moment of the search. So while sending softCommit has the advantage of including recent mails in searches, it means that softCommits are being done upon user request. Frequency depends on user activity.
Going back to the original problem: seems the first advice to Peter is to look into solr configuration as others have said.
From dovecot point of view I can see the following as potentially useful features:
a configurable batch size would enable to tune the number of emails per request and help stay under the 60 seconds hard coded http request timeout. A configurable http timeout would be less useful, since this will potentially run into other timeouts on solr side.
abilty to turn off softCommits so as to have a more predictable softCommit workload. In that case autoSoftCommit should be configured in solr. In order to minimize risk of recent emails not appearing in search results, periodic indexing could be set up by cron.
I've attached a patch, any comments are welcome (especially about getting settings from the backend context).
Example config
plugin { fts = solr fts_solr = url=https://user:password@solr.example.com:443/solr/dovecot/ batch_size=500 no_soft_commit }
John
On 14/04/2019 16:04, Aki Tuomi via dovecot wrote:
On 14 April 2019 16:59 John Fawcett via dovecot < dovecot@dovecot.org mailto:dovecot@dovecot.org> wrote:
On 13/04/2019 17:16, Shawn Heisey via dovecot wrote:
On 4/13/2019 4:29 AM, John Fawcett via dovecot wrote:
If this value was made configurable people could set it to what they want. However the underlying problem is likely on solr configuration. The Jetty that is included in Solr has its idle timeout set to 50 seconds. But in practice, I have not seen this timeout trigger ... and if the OP is seeing a 60 second timeout, then the 50 second idle timeout in Jetty must not be occurring. There may be a socket timeout configured on inter-server requests -- distributed queries or the load balancing that SolrCloud does. I can never remember whether this is the case by default. I think it is. If there is an issue on initial indexing, where you are not really concerned about qucik visibility but just getting things into the index efficiently, a better approach would be for dovecot plugin not to send any commit or softCommit (or waitSearcher either) and that should speed things up. You'd need to configure solr with a long autoSoftCommit maxTime and a reasonable autoCommit maxTime, which you could then reconfigure when the load was done.
Solr ships with autoCommit set to 15 seconds and openSearcher set to false on the autoCommit. The autoSoftCommit setting is not enabled by default, but depending on how the index was created, Solr might try to set autoSoftCommit to 3 seconds ... which is WAY too short. I will usually increase the autoCommit time to 60 seconds, just to reduce the amount of work that Solr is doing. The autoSoftCommit time, if it is used, should be set to a reasonably long value ... values between two and five minutes would be good. Attempting to use a very short autoSoftCommit time will usually lead to problems. This thread says that dovecot is sending explicit commits. One thing that might be happening to exceed 60 seconds is an extremely long commit, which is usually caused by excessive cache autowarming, but might be related to insufficient memory. The max heap setting on an out-of-the-box Solr install (5.0 and later) is 512MB. That's VERY small, and it doesn't take much index data before a much larger heap is required. Thanks, Shawn I looked into the code (version 2.3.5.1): the fts-solr plugin is not sending softCommit every 1000 emails. Emails from a single folder are batched in up to a maximum of 1000 emails per request, but the softCommit gets sent once per mailbox folder at the end of all the requests for that folder.
I immagine that one of the reasons dovecot sends softCommits is because without autoindex active and even if mailboxes are periodically indexed from cron, the last emails received with be indexed at the moment of the search. So while sending softCommit has the advantage of including recent mails in searches, it means that softCommits are being done upon user request. Frequency depends on user activity.
Going back to the original problem: seems the first advice to Peter is to look into solr configuration as others have said.
From dovecot point of view I can see the following as potentially useful features:
a configurable batch size would enable to tune the number of emails per request and help stay under the 60 seconds hard coded http request timeout. A configurable http timeout would be less useful, since this will potentially run into other timeouts on solr side.
abilty to turn off softCommits so as to have a more predictable softCommit workload. In that case autoSoftCommit should be configured in solr. In order to minimize risk of recent emails not appearing in search results, periodic indexing could be set up by cron.
I've attached a patch, any comments are welcome (especially about getting settings from the backend context).
Example config
plugin { fts = solr fts_solr = url= https://user:password@solr.example.com:443/solr/dovecot/ batch_size=500 no_soft_commit }
John
Can you please open a pull request to https://github.com/dovecot/core ?
Aki Tuomi
Done, thanks for considering it.
John
On 4/14/2019 7:59 AM, John Fawcett via dovecot wrote:
From dovecot point of view I can see the following as potentially useful features:
- a configurable batch size would enable to tune the number of emails per request and help stay under the 60 seconds hard coded http request timeout. A configurable http timeout would be less useful, since this will potentially run into other timeouts on solr side.
Even if several thousand emails are sent per batch, unless they're incredibly large, I can't imagine indexing them taking more than a few seconds. Does dovecot send attachments to Solr as well as the email itself? Hopefully it doesn't. If it does, then you would want a smaller batch size.
But if the heap size for Solr is not big enough, that can cause major delays no matter what requests are being sent, because Java will be spending most of its time doing garbage collection.
I'm also assuming that the Solr server is on the same LAN as dovecot and that transferring the update data does not take a long time.
Thanks, Shawn
participants (5)
-
Aki Tuomi
-
John Fawcett
-
Peter Mogensen
-
Shawn Heisey
-
Shawn Heisey