Hi Chris,
Amazing Analysis !
I did actually not investigated the log, because I was first trying to get
more information from the user.
"We are running full import and delta import crons .
Fulll index once a day
delta index : every 10 mins
last night my index automatically deleted(numdocs=0).
attaching logs for review ."
Reading better the user initial mail , he does a full import as well ( and
at this point, cleaning the Index) .
Not sure is there any practical reason to do that, the user will clarify
that to us.
So after the clean happened, something prevented the full import to
proceed, and we had the weird behaviour monitored in the logs.
Really curious of understanding this better :)
2015-06-11 1:36 GMT+01:00 Chris Hostetter <hossman_luc...@fucit.org>:
>
> : The guys was using delta import anyway, so maybe the problem is
> : different and not related to the clean.
>
> that's not what the logs say.
>
> Here's what i see...
>
> Log begins with server startup @ "Jun 10, 2015 11:14:56 AM"
>
> The DeletionPolicy for the "shopclue_prod" core is initialized at "Jun
> 10, 2015 11:15:04 AM" and we see a few interesting things here we note
> for the future as we keep reading...
>
> 1) There is currently "commits:num=1" commits on disk
> 2) the current index dir in use is "index.20150311161021822"
> 3) the current segment & generation are "segFN=segments_1a,generation=46"
>
> Immediately after this, we see some searcher warming using a searcher with
> this same segments file, and then this searcher is registered ("Jun 10,
> 2015 11:15:05 AM") and the core is registered.
>
> Next we see some replication polling, and we see what look like some
> simple monitoring requests for "q=*" which return hits=85898 being
> repeated over and over.
>
> At "Jun 10, 2015 11:16:30 AM" we see some requests for /dataimport that
> look like they are coming from the UI. and then at "Jun 10, 2015 11:17:01
> AM" we see a request for a full import started.
>
> We have no idea what the data import configuration file looks like, so we
> have no idea if clean=false is being used or not. it's certianly not
> specified in the URL.
>
> We see some more monitoring URLs returning hits=85898 and some more
> /repliation status calls, and then @ "Jun 10, 2015 11:18:02 AM" we see the
> first commit executed since hte server started up.
>
> there's no indication that this commit came from an external request (eg
> "/update") so probably was made by some internal request. One
> possiblility is that it came from DIH finishing -- but i doubt it, i'm
> fairly sure that would have involved more logging then this. A more
> probably scenerio is that it came from an autoCommit setting -- the fact
> that it is almost exactly 60 seconds after DIH started -- and almost
> exactly 60 seconds after DIH may have done a deleteAll query due to
> clean=true -- makes it seem very likely that this was a 1 minute
> autoCommit)
>
> (but since we don't have either hte data import config, or the
> solrconfig.xml, we have no way of knowing -- it's all just guess work.)
>
> Very importantly, note that this commit is not opening a new searcher...
>
> Jun 10, 2015 11:18:02 AM org.apache.solr.update.DirectUpdateHandler2 commit
> INFO: start
> commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
>
> Here are some other interesting things to note from the logging
> that comes from the DeletionPolicy when this commit happens...
>
> 1) it now notes that there are commits:num=2 on disk
> 2) the current index dir hasn't changed (index.20150311161021822) so
> some weird replication command didn't swap the world out from under us
> 3) the newest segment/generation are "segFN=segments_1b,generation=47"
> 4) the newest commit has no other files in it besides the segments file.
>
> this means, with out a doubt, there are no documents in this commits view
> of the index. they have all been deleted by something.
>
>
> At this point the *old* searcher (for commit generation 46) is still in
> use however -- nothing has done an openSearcher=true.
>
> we see more /dataimport status requests, and other requests that appear to
> come from the Solr UI, and more monitoring queries that still return
> hits=85898 because the same searcher is in use.
>
> At "Jun 10, 2015 11:27:04 AM" we see another commit happen -- again, no
> indication that this came from an outside /update request, so it might be
> from DIH, or it might be from an autoCommit setting. the fact that it is
> nearly exactly 10 minutes after DIH started (and probably did a clean=true
> deleteAll query) makes it seem extremely likely this is an autoSoftCommit
> setting kicking in.
>
> Very importantly, note that this softCommit *does* open a new searcher...
>
> Jun 10, 2015 11:27:04 AM org.apache.solr.update.DirectUpdateHandler2 commit
> INFO: start
>
> commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=true,prepareCommit=false}
>
>
> In less then a second, this new searcher is warmed up and the next time we
> see a q=* monitoring query get logged, it returns hits=0.
>
> Note that at no point in the logs, after the DataImporter is started, do
> we see it log anything other then that it has initiated the request to
> MySQL -- we do see some logs starting ~ "Jun 10, 2015 11:41:19 AM"
> indicating that someone was using the Web UI to look at the dataimport
> handler's status report. it would be really nice to know what that person
> saw at that point -- because my guess is DIH was still running and was
> staled waiting for MySql, and hadn't even started adding docs to Solr (if
> it had, i'm certian there would have been some log of it).
>
> So instead, the combination of a (probable) DIH clean=true option and a
> (near certainty) autoCommit=60sec and autoSoftCommit=10min ment that a new
> commit was created after the clean, and that commit was opened as a new
> searcher before the DIH ever finished.
>
> Or at least ... that's my best guess based solely on the Solr logs, w/o
> any concrete info on what the configs look like, or what the User observed
> at the time when looking at the DIH status.
>
>
>
> -Hoss
> http://www.lucidworks.com/
>
--
--------------------------
Benedetti Alessandro
Visiting card : http://about.me/alessandro_benedetti
"Tyger, tyger burning bright
In the forests of the night,
What immortal hand or eye
Could frame thy fearful symmetry?"
William Blake - Songs of Experience -1794 England
