On 6/13/2014 9:36 AM, Sven Kiesewetter wrote:
> 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
This looks like requests to copy files from master to slave using the
replication handler.
> *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
If your Solr documents are not enormous (which could show a low QTime
but a large elapsed time), then I would suspect extreme garbage
collection activity, either from the heap being HUGE or the heap being a
little bit too small. It could also be that you don't have enough RAM
to allow the operating system to cache your index.
http://wiki.apache.org/solr/SolrPerformanceProblems
Thanks,
Shawn
