We have a Solr 4.51 (Debian) installation that is being filled up by a node.js app. Both reside on the same machine. We are adding about 250 to 350 documents per second. Solr is configured with auto-commit (1000 ms soft / 15000 ms hard).
After round about 100 to 150 seconds Solr becomes unavailable for one up to five seconds. So http.request() returns EADDRNOTAVAIL. In the meantime we have a workaround, which retries to add the document every 500 ms. So after one up to 10 tries Solr becomes available again and everything works fine (up to the next break).
We are wondering if this is normal. Or could the described behaviour be due to any misconfiguration?
There is no error or warning entry in the Solr log file. Notably while being unavailable the cpu workload of the corresponding Solr java process falls from 30 % down to almost zero.
Of course our node.js app always waits on the answer of the http.request, so there should not be any parallel requests that could rise any overflow.
What could be the reason that Solr makes these "coffee breaks"?
Thanks for any hint!
EDIT:
When looking into the Solr log (haviing auto-commit enabled) while the error occurs. The log file sais:
80583779 [commitScheduler-9-thread-1] INFO org.apache.solr.update.UpdateHandler â start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=true,prepareCommit=false}
80583788 [commitScheduler-9-thread-1] INFO org.apache.solr.search.SolrIndexSearcher â Opening Searcher@1263c036 main
80583789 [commitScheduler-9-thread-1] INFO org.apache.solr.update.UpdateHandler â end_commit_flush
80583789 [searcherExecutor-5-thread-1] INFO org.apache.solr.core.SolrCore â QuerySenderListener sending requests to Searcher@1263c036 main{StandardDirectoryReader(segments_1lv:67657:nrt _opz(4.5.1):C1371694/84779:delGen=1 _p29(4.5.1):C52149/1067:delGen=1 _q0p(4.5.1):C48456 _q0z(4.5.1):C2434 _q19(4.5.1):C2583 _q1j(4.5.1):C3195 _q1t(4.5.1):C2633 _q23(4.5.1):C3319 _q1c(4.5.1):C351 _q2n(4.5.1):C3277 _q2x(4.5.1):C2618 _q2d(4.5.1):C2621 _q2w(4.5.1):C201)}
80583789 [searcherExecutor-5-thread-1] INFO org.apache.solr.core.SolrCore â QuerySenderListener done.
80583789 [searcherExecutor-5-thread-1] INFO org.apache.solr.core.SolrCore â [base] Registered new searcher Searcher@1263c036 main{StandardDirectoryReader(segments_1lv:67657:nrt _opz(4.5.1):C1371694/84779:delGen=1 _p29(4.5.1):C52149/1067:delGen=1 _q0p(4.5.1):C48456 _q0z(4.5.1):C2434 _q19(4.5.1):C2583 _q1j(4.5.1):C3195 _q1t(4.5.1):C2633 _q23(4.5.1):C3319 _q1c(4.5.1):C351 _q2n(4.5.1):C3277 _q2x(4.5.1):C2618 _q2d(4.5.1):C2621 _q2w(4.5.1):C201)}
80593917 [commitScheduler-6-thread-1] INFO org.apache.solr.update.UpdateHandler â start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
80593931 [commitScheduler-6-thread-1] INFO org.apache.solr.core.SolrCore â SolrDeletionPolicy.onCommit: commits: num=2
So at first glance it looks like Solr refuses the http connections while performing a soft commit. BUT,
- there have been many soft commits before without refusals
- there will be many soft commit afterwards without refusalss
- and (most important) when disabling auto-commit at all the http requests from node are refused anyway (more or less at the same stage as if aut-commit wre enabled).
The Solr log file with auto-commit disabled just stops here (while adding the documents):
153314 [qtp1112461277-10] INFO org.apache.solr.update.processor.LogUpdateProcessor â [base] webapp=/solr path=/update/json params={commit=false&wt=json} {add=[52c14621fc45c82d4d009155]} 0 0
153317 [qtp1112461277-16] INFO org.apache.solr.update.processor.LogUpdateProcessor â [base] webapp=/solr path=/update/json params={commit=false&wt=json} {add=[52c14621fc45c82d4d009156]} 0 0
153320 [qtp1112461277-17] INFO org.apache.solr.update.processor.LogUpdateProcessor â [base] webapp=/solr path=/update/json params={commit=false&wt=json} {add=[52c14621fc45c82d4d009157]} 0 1
153322 [qtp1112461277-18] INFO org.apache.solr.update.processor.LogUpdateProcessor â [base] webapp=/solr path=/update/json params={commit=false&wt=json} {add=[52c14621fc45c82d4d009158]} 0 0
153325 [qtp1112461277-13] INFO org.apache.solr.update.processor.LogUpdateProcessor â [base] webapp=/solr path=/update/json params={commit=false&wt=json} {add=[52c14621fc45c82d4d009159]} 0 0
153329 [qtp1112461277-19] INFO org.apache.solr.update.processor.LogUpdateProcessor â [base] webapp=/solr path=/update/json params={commit=false&wt=json} {add=[52c14621fc45c82d4d00915a]} 0 1
153331 [qtp1112461277-12] INFO org.apache.solr.update.processor.LogUpdateProcessor â [base] webapp=/solr path=/update/json params={commit=false&wt=json} {add=[52c14621fc45c82d4d00915b]} 0 0
153334 [qtp1112461277-15] INFO org.apache.solr.update.processor.LogUpdateProcessor â [base] webapp=/solr path=/update/json params={commit=false&wt=json} {add=[52c14621fc45c82d4d00915c]} 0 0
153336 [qtp1112461277-11] INFO org.apache.solr.update.processor.LogUpdateProcessor â [base] webapp=/solr path=/update/json params={commit=false&wt=json} {add=[52c14621fc45c82d4d00915d]} 0 0
So here is no hint anymore that commiting or indexing could be the reason that Solr refuses any (any!) http request for 1-3 seconds.
EDIT2:
It is also remarkable, that if we switch root-logging to ALL, Solr becomes slower (that is obvious due to the more verbose logging) but also the error vanishes. So there are no refusal periods any more. This looks like it is also a timing problem...
EDIT3:
In the meantime I found out, that the unavailability of Solr only affects my node application. While not beeing available for node.js I can make requests from the Solr Web Admin. I also tried to connect from node.js to a different webserver whle not beeing able to access Solr. That works! So this is weird, my node.js app cannot access Solr for some seconds, but any other app can. Any idea what could be the reason for that?
