Hi,
I am running solr 1.4.0+ds1-1ubuntu1. I have a master server that has a
number of solr instances running on it (150 or so), and nightly most of
them have documents written to them. The script that does these writes
(adds) does a commit and an optimize on the indexes when it's entirely
finished updating them, then initiates replication on the slave per
instance. In this configuration, the index versions between master and
slave remain in synch.
The optimize portion, which, again, happens nightly, is taking a lot of
time and I think it's unnecessary. I was hoping to stop doing this explicit
optimize, and to let my merge policy handle that. However, if I don't do an
optimize, and only do a commit before initiating slave replication, some
hours later the slave is, for reasons that are unclear to me, incrementing
its index version to 1 higher than the master.
I am not really sure I understand the logs, but it looks like the
incremented index version is the result of an optimize on the slave, but I
am never issuing any commands against the slave aside from initiating
replication, and I don't think there's anything in my solr configuration
that would be initiating this. I do have autoCommit on with maxDocs of
1000, but since I am initiating slave replication after doing a commit on
the master, I don't think there would ever be any uncommitted documents on
the slave. I do have a merge policy configured, but it's not clear to me
that it has anything to do with this. And if it did, I'd expect to see
similar behavior on the master (right?).
I have included a snipped from my slave logs that shows this issue. In this
snipped index version 1286065171264 is what the master has,
and 1286065171265 is what the slave increments itself to, which is then out
of synch with the master in terms of version numbers. Nothing that I know
of is issuing any commands to the slave at this time. If I understand these
logs (I might not), it looks like something issued an optimize that took
1023720ms? Any ideas?
Thanks in advance.
Andy
Jul 12, 2012 12:21:14 PM org.apache.solr.update.SolrIndexWriter close
FINE: Closing Writer DirectUpdateHandler2
Jul 12, 2012 12:21:14 PM org.apache.solr.core.SolrDeletionPolicy onCommit
INFO: SolrDeletionPolicy.onCommit: commits:num=2
commit{dir=/var/lib/ontolo/solr/o_3952/index,segFN=segments_h8,version=1286065171264,generation=620,filenames=[_h6.fnm,
_h5.nrm, segments_h8, _h4.nrm, _h5.tii, _h4
.tii, _h5.tis, _h4.tis, _h4.fdx, _h5.fnm, _h6.tii, _h4.fdt, _h5.fdt,
_h5.fdx, _h5.frq, _h4.fnm, _h6.frq, _h6.tis, _h4.prx, _h4.frq, _h6.nrm,
_h5.prx, _h6.prx, _h6.fdt, _h6
.fdx]
commit{dir=/var/lib/ontolo/solr/o_3952/index,segFN=segments_h9,version=1286065171265,generation=621,filenames=[_h7.tis,
_h7.fdx, _h7.fnm, _h7.fdt, _h7.prx, segment
s_h9, _h7.nrm, _h7.tii, _h7.frq]
Jul 12, 2012 12:21:14 PM org.apache.solr.core.SolrDeletionPolicy
updateCommits
INFO: newest commit = 1286065171265
Jul 12, 2012 12:21:14 PM org.apache.solr.search.SolrIndexSearcher <init>
INFO: Opening Searcher@4ac62082 main
Jul 12, 2012 12:21:14 PM org.apache.solr.update.DirectUpdateHandler2 commit
INFO: end_commit_flush
Jul 12, 2012 12:21:14 PM org.apache.solr.search.SolrIndexSearcher warm
INFO: autowarming Searcher@4ac62082 main from Searcher@48d901f7 main
fieldValueCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumulative_hitratio=0.00,cumulative
_inserts=0,cumulative_evictions=0}
Jul 12, 2012 12:21:14 PM org.apache.solr.search.SolrIndexSearcher warm
INFO: autowarming result for Searcher@4ac62082 main
fieldValueCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0}
Jul 12, 2012 12:21:14 PM org.apache.solr.search.SolrIndexSearcher warm
INFO: autowarming Searcher@4ac62082 main from Searcher@48d901f7 main
filterCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=18,cumulative_hits=14,cumulative_hitratio=0.77,cumulative_inserts=4,cumulative_evictions=0}
Jul 12, 2012 12:21:14 PM org.apache.solr.search.SolrIndexSearcher warm
INFO: autowarming result for Searcher@4ac62082 main
filterCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=18,cumulative_hits=14,cumulative_hitratio=0.77,cumulative_inserts=4,cumulative_evictions=0}
Jul 12, 2012 12:21:14 PM org.apache.solr.search.SolrIndexSearcher warm
INFO: autowarming Searcher@4ac62082 main from Searcher@48d901f7 main
queryResultCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=150,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=69,cumulative_evictions=0}
Jul 12, 2012 12:21:14 PM org.apache.solr.search.SolrIndexSearcher warm
INFO: autowarming result for Searcher@4ac62082 main
queryResultCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=150,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=69,cumulative_evictions=0}
Jul 12, 2012 12:21:14 PM org.apache.solr.search.SolrIndexSearcher warm
INFO: autowarming Searcher@4ac62082 main from Searcher@48d901f7 main
documentCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=191237,cumulative_hits=8295,cumulative_hitratio=0.04,cumulative_inserts=182942,cumulative_evictions=175772}
Jul 12, 2012 12:21:14 PM org.apache.solr.search.SolrIndexSearcher warm
INFO: autowarming result for Searcher@4ac62082 main
documentCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=191237,cumulative_hits=8295,cumulative_hitratio=0.04,cumulative_inserts=182942,cumulative_evictions=175772}
Jul 12, 2012 12:21:14 PM org.apache.solr.core.QuerySenderListener
newSearcher
INFO: QuerySenderListener sending requests to Searcher@4ac62082 main
Jul 12, 2012 12:21:14 PM org.apache.solr.core.QuerySenderListener
newSearcher
INFO: QuerySenderListener done.
Jul 12, 2012 12:21:14 PM org.apache.solr.core.SolrCore registerSearcher
INFO: [] Registered new searcher Searcher@4ac62082 main
Jul 12, 2012 12:21:14 PM org.apache.solr.search.SolrIndexSearcher close
INFO: Closing Searcher@48d901f7 main
fieldValueCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0}
filterCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=18,cumulative_hits=14,cumulative_hitratio=0.77,cumulative_inserts=4,cumulative_evictions=0}
queryResultCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=150,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=69,cumulative_evictions=0}
documentCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=191237,cumulative_hits=8295,cumulative_hitratio=0.04,cumulative_inserts=182942,cumulative_evictions=175772}
Jul 12, 2012 12:21:15 PM
org.apache.solr.update.processor.LogUpdateProcessor finish
INFO: {optimize=} 0 1023720
Jul 12, 2012 12:21:15 PM org.apache.solr.core.SolrCore execute
INFO: [] webapp=/o_3952 path=/update params={} status=0 QTime=1023720
