[jira] [Updated] (SOLR-11455) change SoftAutoCommitTest to check when events *start* -- not when they finish

["Hoss Man (JIRA)" <ji...@apache.org>]

     [ https://issues.apache.org/jira/browse/SOLR-11455?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Hoss Man updated SOLR-11455:
----------------------------
    Attachment: SoftAutoCommitTest.jenkins.1398.txt

some of the comments in SOLR-11454 are an example of where tracking the (newSearcher) event finish results in a failure but tracking the even start would show it happened very quickly.

The attached jenkins log (SoftAutoCommitTest.jenkins.1398.txt) is another example...
https://builds.apache.org/job/Lucene-Solr-NightlyTests-master/1398/
{noformat}
Error Message:
softCommit: did not find a single commit

Stack Trace:
java.lang.AssertionError: softCommit: did not find a single commit
        at __randomizedtesting.SeedInfo.seed([CCAC87827208491B:90B929BB998A0863]:0)
        at org.junit.Assert.fail(Assert.java:93)
        at org.junit.Assert.assertTrue(Assert.java:43)
        at org.junit.Assert.assertNotNull(Assert.java:526)
        at org.apache.solr.update.SoftAutoCommitTest.assertRapidMultiCommitQueues(SoftAutoCommitTest.java:475)
        at org.apache.solr.update.SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds(SoftAutoCommitTest.java:440)
{noformat}

After some rapid fire adds, the test does a loop looking for an expected# of commits based on the relative pre/post timestamp of the adds (ie: at least 1 softCommit, maybemore more if the total time to add the docs exceeded the autoCommitTime) .. but in this vase it fails because it didn't dedect a softCommit _finish_ in the expected wait time.

But according to the logs, the autoSoftCommit _started_ exactly when expected (508ms after the first doc was added, or 8ms after the autoSoftCommitMillis=500 said it should) ...

{noformat}
   [junit4]   2> 2487332 INFO  (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds-seed#[CCAC87827208491B]) [    ] o.a.s.u.p.LogUpdateProcessorFactory [collection1]  webapp=null path=null params={}{add=[5000 (1580608950822240256)]} 0 28
...
   [junit4]   2> 2487840 INFO  (commitScheduler-2095-thread-1) [    ] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=true,prepareCommit=false}
{noformat}

...it just didn't _finish_ as quickly as the monitor polling expected it to. 

> change SoftAutoCommitTest to check when events *start* -- not when they finish
> ------------------------------------------------------------------------------
>
>                 Key: SOLR-11455
>                 URL: https://issues.apache.org/jira/browse/SOLR-11455
>             Project: Solr
>          Issue Type: Sub-task
>      Security Level: Public(Default Security Level. Issues are Public) 
>            Reporter: Hoss Man
>         Attachments: SoftAutoCommitTest.jenkins.1398.txt
>
>
> AFAICT, most "slow machine" related (jenkins) failures in SoftAutoCommitTest seem to be exacerbated by the fact that the SolrEventListener model fires an effent when the action (softCommit, hardCommit, newSearcher) *finishes* successfully -- w/o paying any attention to when it *starts*.
> We should consider taking a more white/grey box approach to checking both the start & finish of these events -- and moving our autoCommit timing expectations to the "start" of the commits, with much more relaxed (ie: many seconds) checks that the event finished successfully.



--
This message was sent by Atlassian JIRA
(v6.4.14#64029)

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
For additional commands, e-mail: dev-help@lucene.apache.org