Thanks Erick, I will look harder at our current configuration and how we're handling config replication, but I just realized that a backup script was doing a commit and an optimize on the slave prior to taking the backup. This happens daily, after updates and replication from the master. This is something I put in place many ages ago and didn't think to look at until now :/
Based on the times in the logs and the conditions under which my problem was occurring (when I wasn't optimizing on the master before initiating replication) it seems clear that this backup script is my problem. Sorry for taking your time with something that was clearly my own dang fault. I appreciate your suggestions and responses regardless! Andy On Mon, Jul 16, 2012 at 7:35 AM, Erick Erickson <erickerick...@gmail.com>wrote: > Andrew: > > I'm not entirely sure that's your problem, but it's the first thing I'd > try..... > > As for your config files, see the section "Replicating solrconfig.xml" > here: http://wiki.apache.org/solr/SolrReplication. That at least > allows you to centralize separate solrconfigs for master and > slave, making promoting a slave to a master a bit easier.... > > Best > Erick > > On Sun, Jul 15, 2012 at 2:00 PM, Andrew Davidoff <david...@qedmf.net> > wrote: > > Erick, > > > > Thank you. I think originally my thought was that if I had my slave > > configuration really close to my master config, it would be very easy to > > promote a slave to a master (and vice versa) if necessary. But I think > you > > are correct that ripping out from the slave config anything that would > > modify an index in any way makes sense. I will give this a try very soon. > > > > Thanks again. > > Andy > > > > > > On Sat, Jul 14, 2012 at 5:22 PM, Erick Erickson <erickerick...@gmail.com > >wrote: > > > >> Gotta admit it's a bit puzzling, and surely you want to move to the 3x > >> versions <G>.. > >> > >> But at a guess, things might be getting confused on the slaves given > >> you have a merge policy on them. There's no reason to have any > >> policies on the slaves; slaves should just be about copying the files > >> from the master, all the policies,commits,optimizes should be done on > >> the master. About all the slave does is copy the current state of the > index > >> from the master. > >> > >> So I'd try removing everything but the replication from the slaves, > >> including > >> any autocommit stuff and just let replication do it's thing. > >> > >> And I'd replicate after the optimize if you keep the optimize going. You > >> should > >> end up with one segment in the index after that, on both the master and > >> slave. > >> You can't get any more merged than that. > >> > >> Of course you'll also copy the _entire_ index every time after you've > >> optimized... > >> > >> Best > >> Erick > >> > >> On Fri, Jul 13, 2012 at 12:31 AM, Andrew Davidoff <david...@qedmf.net> > >> wrote: > >> > 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 > >> >
