Hi all!
I've got a problem with SolrJ taking 20-60 seconds to return some queries.
It doesn't happen often, but often enough to pose a problem. So far, I
haven't been able to pin down the cause.
The server is running Solr 1.4.1 and I'm using SolrJ 1.4.0. Another Solr
server is used for replication, but so far not for queries or updates.
According to my monitoring,
org.apache.solr.client.solrj.impl.CommonsHttpSolrServer/query takes 25,100
milliseconds to return.
I've looked into the logfiles on my solr server, and there, the query
itself only took 260ms. (according to "qtime")
Things that caught my eye:
- the query's log timestamp is about 15s *after* the application called
solrJ.
- there are a lot of queries in the log at the exact same second which
should not be the case
- there is a gap of about 25 seconds in the log.
What would be my next steps to analyze the problem?
Log excerpt:
*Dozens of this one:*
Jun 13, 2014 10:56:00 AM org.apache.solr.core.SolrCore execute
INFO: [] webapp=/solr path=/replication
params={indexversion=1369890003601&file=_wa2hg.fdt&command=filecontent&checksum=true&wt=filestream}
status=0 Q
Time=0
*No more entries between 10:56:00 and 10:56:25*
Jun 13, 2014 10:56:25 AM org.apache.solr.core.SolrDeletionPolicy onInit
INFO: SolrDeletionPolicy.onInit: commits:num=2
commit{dir=/home/foo/apache-tomcat-6.0.37-solr/conf/Catalina/localhost/solr/data/index,segFN=segments_syvu8,version=1369890002983,generation=48656816,filenames=[*long
list of filenames*]
commit{dir=/home/foo/apache-tomcat-6.0.37-solr/conf/Catalina/localhost/solr/data/index,segFN=segments_sywbe,version=1369890003601,generation=48657434,filenames=[*long
list of filenames*]
Jun 13, 2014 10:56:25 AM org.apache.solr.core.SolrDeletionPolicy
updateCommits
INFO: newest commit = 1369890003601
Jun 13, 2014 10:56:25 AM
org.apache.solr.update.processor.LogUpdateProcessor finish
INFO: {add=[de.profile.ProfilePollAnswer-943451]} 0 7
Jun 13, 2014 10:56:25 AM org.apache.solr.core.SolrCore execute
INFO: [] webapp=/solr path=/update params={wt=javabin&version=1} status=0
QTime=7
Jun 13, 2014 10:56:25 AM org.apache.solr.handler.dataimport.DataImporter
doFullImport
INFO: Starting Full Import
Jun 13, 2014 10:56:25 AM org.apache.solr.core.SolrCore execute
INFO: [] webapp=/solr path=/dataimport
params={clean=false&command=full-import} status=0 QTime=29
Jun 13, 2014 10:56:25 AM org.apache.solr.handler.dataimport.SolrWriter
readIndexerProperties
INFO: Read dataimport.properties
Jun 13, 2014 10:56:25 AM
org.apache.solr.handler.dataimport.JdbcDataSource$1 call
INFO: Creating a connection for entity profile with URL: jdbc:mysql://<
*DB-address*>
Jun 13, 2014 10:56:25 AM
org.apache.solr.handler.dataimport.JdbcDataSource$1 call
INFO: Time taken for getConnection(): 22
Jun 13, 2014 10:56:25 AM org.apache.solr.core.SolrCore execute
INFO: [] webapp=/solr path=/select params={<*simple query params
1*>&rows=24&version=1}
hits=688 status=0 QTime=1
Jun 13, 2014 10:56:25 AM org.apache.solr.core.SolrCore execute
INFO: [] webapp=/solr path=/select params={<*simple query params
1*>&rows=24&version=1}
hits=688 status=0 QTime=37
Jun 13, 2014 10:56:25 AM org.apache.solr.update.DirectUpdateHandler2 commit
INFO: start
commit(optimize=false,waitFlush=true,waitSearcher=true,expungeDeletes=false)
*36x one of these two:*
Jun 13, 2014 10:56:25 AM org.apache.solr.core.SolrCore execute
INFO: [] webapp=/solr path=/select params={<*simple query params
1*>&rows=24&version=1}
hits=688 status=0 QTime=1
Jun 13, 2014 10:56:25 AM org.apache.solr.core.SolrCore execute
INFO: [] webapp=/solr path=/select params={<*simple query params
2*>&rows=24&version=1}
hits=688 status=0 QTime=12
Jun 13, 2014 10:56:25 AM org.apache.solr.core.SolrCore execute
INFO: [] webapp=/solr path=/select
params={hl.requireFieldMatch=true&sort=confirmationDate_dt+desc&start=0&q={<*complex
query params*>&rows=150&version=1} hits=203 status=0 QTime=260
Thanks for any help,
Sven
