Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 5.1, 6.0
    • Component/s: None
    • Labels:
      None
    • Lucene Fields:
      New

      Description

      I hit this while testing various use cases for LUCENE-6119 (adding auto-throttle to ConcurrentMergeScheduler).

      When I tested "always call updateDocument" (each add buffers a delete term), with many indexing threads, opening an NRT reader once per second (forcing all deleted terms to be applied), I see that BufferedUpdatesStream.applyDeletes sometimes seems to take a loooong time, e.g.:

      BD 0 [2015-01-04 09:31:12.597; Lucene Merge Thread #69]: applyDeletes took 339 msec for 10 segments, 117 deleted docs, 607333 visited terms
      BD 0 [2015-01-04 09:31:18.148; Thread-4]: applyDeletes took 5533 msec for 62 segments, 10989 deleted docs, 8517225 visited terms
      BD 0 [2015-01-04 09:31:21.463; Lucene Merge Thread #71]: applyDeletes took 1065 msec for 10 segments, 470 deleted docs, 1825649 visited terms
      BD 0 [2015-01-04 09:31:26.301; Thread-5]: applyDeletes took 4835 msec for 61 segments, 14676 deleted docs, 9649860 visited terms
      BD 0 [2015-01-04 09:31:35.572; Thread-11]: applyDeletes took 6073 msec for 72 segments, 13835 deleted docs, 11865319 visited terms
      BD 0 [2015-01-04 09:31:37.604; Lucene Merge Thread #75]: applyDeletes took 251 msec for 10 segments, 58 deleted docs, 240721 visited terms
      BD 0 [2015-01-04 09:31:44.641; Thread-11]: applyDeletes took 5956 msec for 64 segments, 15109 deleted docs, 10599034 visited terms
      BD 0 [2015-01-04 09:31:47.814; Lucene Merge Thread #77]: applyDeletes took 396 msec for 10 segments, 137 deleted docs, 719914 visit
      

      What this means is even though I want an NRT reader every second, often I don't get one for up to ~7 or more seconds.

      This is on an SSD, machine has 48 GB RAM, heap size is only 2 GB. 12 indexing threads.

      As hideously complex as this code is, I think there are some inefficiencies, but fixing them could be hard / make code even hairier ...

      Also, this code is mega-locked: holds IW's lock, holds BD's lock. It blocks things like merges kicking off or finishing...

      E.g., we pull the MergedIterator many times on the same set of sub-iterators. Maybe we can create the sorted terms up front and reuse that?

      Maybe we should go "term stride" (one term visits all N segments) not "segment stride" (visit each segment, iterating all deleted terms for it). Just iterating the terms to be deleted takes a sizable part of the time, and we now do that once for every segment in the index.

      Also, the "isUnique" bit in LUCENE-6005 should help here, since if we know the field is unique, we can stop seekExact once we found a segment that has the deleted term, we can maybe pass false for removeDuplicates to MergedIterator...

      1. LUCENE-6161.patch
        66 kB
        Michael McCandless
      2. LUCENE-6161.patch
        72 kB
        Michael McCandless
      3. LUCENE-6161.patch
        28 kB
        Michael McCandless
      4. LUCENE-6161.patch
        27 kB
        Michael McCandless
      5. LUCENE-6161.patch
        18 kB
        Michael McCandless

        Issue Links

          Activity

          Hide
          ASF subversion and git services added a comment -

          Commit 1649599 from Michael McCandless in branch 'dev/trunk'
          [ https://svn.apache.org/r1649599 ]

          LUCENE-6161: reuse DocsEnum when resolving deleted terms/queries to doc id

          Show
          ASF subversion and git services added a comment - Commit 1649599 from Michael McCandless in branch 'dev/trunk' [ https://svn.apache.org/r1649599 ] LUCENE-6161 : reuse DocsEnum when resolving deleted terms/queries to doc id
          Hide
          Michael McCandless added a comment -

          I committed a fix for a silly performance bug: we were failing to reuse DocsEnum, so for every deleted term that had docs, we were making a new DocsEnum. This is awful!

          But ... it was not the particular source of slowness in my test since most terms did not result in deletions (I was randomly generating IDs over 100M space, on an index with not too many docs).

          Show
          Michael McCandless added a comment - I committed a fix for a silly performance bug: we were failing to reuse DocsEnum, so for every deleted term that had docs, we were making a new DocsEnum. This is awful! But ... it was not the particular source of slowness in my test since most terms did not result in deletions (I was randomly generating IDs over 100M space, on an index with not too many docs).
          Hide
          ASF subversion and git services added a comment -

          Commit 1649600 from Michael McCandless in branch 'dev/branches/branch_5x'
          [ https://svn.apache.org/r1649600 ]

          LUCENE-6161: reuse DocsEnum when resolving deleted terms/queries to doc id

          Show
          ASF subversion and git services added a comment - Commit 1649600 from Michael McCandless in branch 'dev/branches/branch_5x' [ https://svn.apache.org/r1649600 ] LUCENE-6161 : reuse DocsEnum when resolving deleted terms/queries to doc id
          Hide
          ASF subversion and git services added a comment -

          Commit 1649601 from Michael McCandless in branch 'dev/branches/lucene_solr_4_10'
          [ https://svn.apache.org/r1649601 ]

          LUCENE-6161: reuse DocsEnum when resolving deleted terms/queries to doc id

          Show
          ASF subversion and git services added a comment - Commit 1649601 from Michael McCandless in branch 'dev/branches/lucene_solr_4_10' [ https://svn.apache.org/r1649601 ] LUCENE-6161 : reuse DocsEnum when resolving deleted terms/queries to doc id
          Hide
          Michael McCandless added a comment -

          OK I think in fact this performance bug was what I was hitting, because I can't repro the dog-slowness (it's still slow-ish).

          I must have been using a smaller ID space for the updates than I thought (I can tell by the actual delete counts in the above SOPs).

          I've backported to 4.10.x ... the bug is quite severe in the case when many deletes to in fact resolve to a doc id.

          Show
          Michael McCandless added a comment - OK I think in fact this performance bug was what I was hitting, because I can't repro the dog-slowness (it's still slow-ish). I must have been using a smaller ID space for the updates than I thought (I can tell by the actual delete counts in the above SOPs). I've backported to 4.10.x ... the bug is quite severe in the case when many deletes to in fact resolve to a doc id.
          Hide
          Michael McCandless added a comment -

          Here's a hackish start at a prototype patch. Really, this is the same
          problem as intersecting doc id lists, but with sorted terms instead.

          The patch pre-builds FSTs for the deleted terms to be intersected, and then picks
          one of three methods (drive by segment's terms, drive by deleted
          terms, simple merge sort) to do the intersection.

          Really what would be best is if we could pass the FST to
          Terms.intersect (it only takes automaton today...). I could try
          building an automaton instead, but this may be a too RAM heavy....

          Tests pass, so I think it's correct, but the code is ugly/prototype.
          The logic of "when to pre-build FST" needs improving...

          I ran a test, indexing first 10M wikipedia docs using updateDocument
          over a random ID space of 100M. 8 indexing threads, CMS, 32 MB
          indexing buffer (frequent small segments written, stressing delete
          packets).

          Trunk applyDeletes took aggregate 159 sec (vs 117 sec with patch), and
          overall indexing time for trunk was 310 sec (vs 290 sec with patch).

          However, with 350 MB indexing ram buffer, applyDeletes took aggregate
          129 sec (vs 94 sec with patch), yet overall indexing time was 263 sec
          (vs 272 sec with patch: slower).

          I may need to index with single thread, SMS, to reduce noise... but
          this is slow.

          Show
          Michael McCandless added a comment - Here's a hackish start at a prototype patch. Really, this is the same problem as intersecting doc id lists, but with sorted terms instead. The patch pre-builds FSTs for the deleted terms to be intersected, and then picks one of three methods (drive by segment's terms, drive by deleted terms, simple merge sort) to do the intersection. Really what would be best is if we could pass the FST to Terms.intersect (it only takes automaton today...). I could try building an automaton instead, but this may be a too RAM heavy.... Tests pass, so I think it's correct, but the code is ugly/prototype. The logic of "when to pre-build FST" needs improving... I ran a test, indexing first 10M wikipedia docs using updateDocument over a random ID space of 100M. 8 indexing threads, CMS, 32 MB indexing buffer (frequent small segments written, stressing delete packets). Trunk applyDeletes took aggregate 159 sec (vs 117 sec with patch), and overall indexing time for trunk was 310 sec (vs 290 sec with patch). However, with 350 MB indexing ram buffer, applyDeletes took aggregate 129 sec (vs 94 sec with patch), yet overall indexing time was 263 sec (vs 272 sec with patch: slower). I may need to index with single thread, SMS, to reduce noise... but this is slow.
          Hide
          Michael McCandless added a comment -

          Another patch, this one using DaciukMihovAutomatonBuilder to create an automaton from the terms to delete, and then using Terms.intersect.

          This one spends even less time applying deletes (46 sec vs 129 sec on trunk) yet overall indexing time is still a bit slower (272 sec vs 263 on trunk).

          I also fixed Automaton to implement Accountable ...

          Show
          Michael McCandless added a comment - Another patch, this one using DaciukMihovAutomatonBuilder to create an automaton from the terms to delete, and then using Terms.intersect. This one spends even less time applying deletes (46 sec vs 129 sec on trunk) yet overall indexing time is still a bit slower (272 sec vs 263 on trunk). I also fixed Automaton to implement Accountable ...
          Hide
          Yonik Seeley added a comment -

          This one spends even less time applying deletes (46 sec vs 129 sec on trunk) yet overall indexing time is still a bit slower (272 sec vs 263 on trunk).

          That's pretty strange... were the same number of merges completed?

          Show
          Yonik Seeley added a comment - This one spends even less time applying deletes (46 sec vs 129 sec on trunk) yet overall indexing time is still a bit slower (272 sec vs 263 on trunk). That's pretty strange... were the same number of merges completed?
          Hide
          Michael McCandless added a comment -

          Here's a less risky change that shows sizable reduction in total time applying deletes (and opening NRT readers)... I think with some polishing the approach is committable.

          It just makes the merged iterator more efficient (don't check for a field change on every term; don't merge if there's only 1 sub), and side-steps O(N^2) seekExact cost for smaller segments.

          On an "index all wikipedia docs, 4 indexing threads, 350 MB IW buffer, opening NRT reader every 5 secs", total time to get 199 NRT readers went from 501 seconds in trunk to 313 seconds with the patch. Overall indexing rate is essentially the same (still strange!)...

          Show
          Michael McCandless added a comment - Here's a less risky change that shows sizable reduction in total time applying deletes (and opening NRT readers)... I think with some polishing the approach is committable. It just makes the merged iterator more efficient (don't check for a field change on every term; don't merge if there's only 1 sub), and side-steps O(N^2) seekExact cost for smaller segments. On an "index all wikipedia docs, 4 indexing threads, 350 MB IW buffer, opening NRT reader every 5 secs", total time to get 199 NRT readers went from 501 seconds in trunk to 313 seconds with the patch. Overall indexing rate is essentially the same (still strange!)...
          Hide
          Michael McCandless added a comment -

          were the same number of merges completed?

          In my last test it was very close: trunk did 83 merges and patch did 84.

          It is strange, because in my test I hijack one of the indexing threads to open an NRT reader periodically, and it's that thread that pays the cost of applying deletes. So I would expect a big reduction in applyDeletes to show some gains in overall indexing ...

          I could run everything with one thread, SMS, etc. Would just take sooo long.

          Show
          Michael McCandless added a comment - were the same number of merges completed? In my last test it was very close: trunk did 83 merges and patch did 84. It is strange, because in my test I hijack one of the indexing threads to open an NRT reader periodically, and it's that thread that pays the cost of applying deletes. So I would expect a big reduction in applyDeletes to show some gains in overall indexing ... I could run everything with one thread, SMS, etc. Would just take sooo long.
          Hide
          Otis Gospodnetic added a comment -

          I'd assume that while merges are now faster, they are using more of the computing resources (than before) needed for the rest of what Lucene is doing, hence no improvement in overall indexing time.

          Show
          Otis Gospodnetic added a comment - I'd assume that while merges are now faster, they are using more of the computing resources (than before) needed for the rest of what Lucene is doing, hence no improvement in overall indexing time.
          Hide
          Michael McCandless added a comment -

          New dirty-but-working patch, this one finally showing sizable gains
          in some cases. The gains vary depending on how frequently NRT reader
          is opened and how large IW's RAM buffer is.

          This patch does a merge sort of the segments TermsEnums, like
          MultiTermsEnum, intersecting with the merged deleted terms iterator,
          instead of visiting each segment separately.

          With NRT reader once per second, with 350 MB IW RAM buffer, trunk
          spends 93 seconds applying deletes and patch spends 66 seconds but no
          real difference in overall indexing speed.

          But with default 16 MB RAM buffer, never opening NRT reader, trunk
          spends 146 seconds applying deletes but patch spends 26 seconds, and
          overall indexing rate goes from 91 to 121 GB/hr.

          This patch adds an advance method on the PrefixCodedTerms iterator,
          however it never seems to help in my testing, so I'm posting here for
          posterity but I'll remove it next, as I try to clean up the patch...

          I think building an automaton and using Terms.intersect is too risky
          at this point: our automaton builder (DaciukMihovAutomatonBuilder) is
          RAM heavy (keeps a HashMap of size number of states in the final
          automaton). I briefly looked at pulling out a common interface
          between FST and Automaton so that we could pass an FST to
          Terms.intersect ... this looked promising at first, but then
          AutomatonTermsEnum stopped me since it requires the "int state" be
          compact for it's long[] visited path tracking / cycle detection "linear"
          optimization.

          Show
          Michael McCandless added a comment - New dirty-but-working patch, this one finally showing sizable gains in some cases. The gains vary depending on how frequently NRT reader is opened and how large IW's RAM buffer is. This patch does a merge sort of the segments TermsEnums, like MultiTermsEnum, intersecting with the merged deleted terms iterator, instead of visiting each segment separately. With NRT reader once per second, with 350 MB IW RAM buffer, trunk spends 93 seconds applying deletes and patch spends 66 seconds but no real difference in overall indexing speed. But with default 16 MB RAM buffer, never opening NRT reader, trunk spends 146 seconds applying deletes but patch spends 26 seconds, and overall indexing rate goes from 91 to 121 GB/hr. This patch adds an advance method on the PrefixCodedTerms iterator, however it never seems to help in my testing, so I'm posting here for posterity but I'll remove it next, as I try to clean up the patch... I think building an automaton and using Terms.intersect is too risky at this point: our automaton builder (DaciukMihovAutomatonBuilder) is RAM heavy (keeps a HashMap of size number of states in the final automaton). I briefly looked at pulling out a common interface between FST and Automaton so that we could pass an FST to Terms.intersect ... this looked promising at first, but then AutomatonTermsEnum stopped me since it requires the "int state" be compact for it's long[] visited path tracking / cycle detection "linear" optimization.
          Hide
          Michael McCandless added a comment -

          Final patch, I think it's ready.

          I removed the unfortunately-not-any-faster advance method on
          Prefix/MergedTermsIterator, cleaned up nocommits, fixed a tricky bug
          in DV updates, and cutover a couple deletes test to randomly sometimes
          use delete-by-query. I ran distributed test beasting for a while and
          no failures...

          The gist of the change is we now make a single pass through all terms
          to be deleted, and all segments's TermsEnums, doing a merge sort
          between them, instead of making a full pass through the merged deleted
          terms for every segment. In cases that heavily apply deletes this is
          a good speedup.

          Show
          Michael McCandless added a comment - Final patch, I think it's ready. I removed the unfortunately-not-any-faster advance method on Prefix/MergedTermsIterator, cleaned up nocommits, fixed a tricky bug in DV updates, and cutover a couple deletes test to randomly sometimes use delete-by-query. I ran distributed test beasting for a while and no failures... The gist of the change is we now make a single pass through all terms to be deleted, and all segments's TermsEnums, doing a merge sort between them, instead of making a full pass through the merged deleted terms for every segment. In cases that heavily apply deletes this is a good speedup.
          Hide
          Robert Muir added a comment -

          Just a few minor thoughts:

          Some of the iteration is more awkward now, it might be nice to open a followup to clean this up.
          delGen is awkward to see being held in PrefixCodedTerms, and we have an iterator api that ... is neither termsenum or iterable but another one instead.
          I wonder if we could have the same logic, but using a more natural one. if it would just make the code even more awkward, then screw it

          We should fix the issue though for now I think.

          Show
          Robert Muir added a comment - Just a few minor thoughts: Some of the iteration is more awkward now, it might be nice to open a followup to clean this up. delGen is awkward to see being held in PrefixCodedTerms, and we have an iterator api that ... is neither termsenum or iterable but another one instead. I wonder if we could have the same logic, but using a more natural one. if it would just make the code even more awkward, then screw it We should fix the issue though for now I think.
          Hide
          Michael McCandless added a comment -

          Thanks Rob, I'll commit the current patch to 5.1 / trunk so Jenkins chews on it, and then see if I can simplify the iterator...

          Show
          Michael McCandless added a comment - Thanks Rob, I'll commit the current patch to 5.1 / trunk so Jenkins chews on it, and then see if I can simplify the iterator...
          Hide
          ASF subversion and git services added a comment -

          Commit 1653891 from Michael McCandless in branch 'dev/trunk'
          [ https://svn.apache.org/r1653891 ]

          LUCENE-6161: speed up resolving deleted terms to doc ids

          Show
          ASF subversion and git services added a comment - Commit 1653891 from Michael McCandless in branch 'dev/trunk' [ https://svn.apache.org/r1653891 ] LUCENE-6161 : speed up resolving deleted terms to doc ids
          Hide
          ASF subversion and git services added a comment -

          Commit 1653914 from Michael McCandless in branch 'dev/branches/branch_5x'
          [ https://svn.apache.org/r1653914 ]

          LUCENE-6161: speed up resolving deleted terms to doc ids

          Show
          ASF subversion and git services added a comment - Commit 1653914 from Michael McCandless in branch 'dev/branches/branch_5x' [ https://svn.apache.org/r1653914 ] LUCENE-6161 : speed up resolving deleted terms to doc ids
          Hide
          Ralph Tice added a comment -

          Michael McCandless
          First of all, thank you SO much for back porting this to 4.10.4. I just applied this to one of our medium sized SolrClouds (13,676,545,570 documents) that was experiencing issues on merging. Empirically this has raised our ceiling on deletes per minute by almost triple, but more importantly indexing throughput stays steady.

          Blue lines in the graphs here are a sum of the red/green. Pink line on the top graph is the raw rate of the inbound data source we're indexing, so we're keeping up if blue is at that line or catching up if it's above.

          http://imgur.com/ZaXjiCI

          I've also included what I think are some relevant log lines, since we still see some 20-60 second pauses in indexing on occasion.
          https://gist.github.com/ralph-tice/268a7984cd701fe1252a

          Cheers!

          Show
          Ralph Tice added a comment - Michael McCandless First of all, thank you SO much for back porting this to 4.10.4. I just applied this to one of our medium sized SolrClouds (13,676,545,570 documents) that was experiencing issues on merging. Empirically this has raised our ceiling on deletes per minute by almost triple, but more importantly indexing throughput stays steady. Blue lines in the graphs here are a sum of the red/green. Pink line on the top graph is the raw rate of the inbound data source we're indexing, so we're keeping up if blue is at that line or catching up if it's above. http://imgur.com/ZaXjiCI I've also included what I think are some relevant log lines, since we still see some 20-60 second pauses in indexing on occasion. https://gist.github.com/ralph-tice/268a7984cd701fe1252a Cheers!
          Hide
          Michael McCandless added a comment -

          Thanks for reporting this impressive speedup!

          The attached log is hard to read, because the timestamp is "computer" readable (timestamp seconds) ...

          Show
          Michael McCandless added a comment - Thanks for reporting this impressive speedup! The attached log is hard to read, because the timestamp is "computer" readable (timestamp seconds) ...
          Hide
          Ralph Tice added a comment -

          Sorry, the timestamp is a long representing Java Date, but it's millis not seconds, what would you prefer? My logs are generated by https://github.com/abdulkadiryaman/logback-kafka/blob/master/src/main/java/org/clojars/canawar/logback/formatter/JsonFormatter.java#L22-L31
          and I usually parse them through https://github.com/stedolan/jq

          I've been thinking a lot about how to get better metrics out of Solr, maybe we should take this to the list for more discussion.

          Show
          Ralph Tice added a comment - Sorry, the timestamp is a long representing Java Date, but it's millis not seconds, what would you prefer? My logs are generated by https://github.com/abdulkadiryaman/logback-kafka/blob/master/src/main/java/org/clojars/canawar/logback/formatter/JsonFormatter.java#L22-L31 and I usually parse them through https://github.com/stedolan/jq I've been thinking a lot about how to get better metrics out of Solr, maybe we should take this to the list for more discussion.
          Hide
          Michael McCandless added a comment -

          what would you prefer?

          In this context, just something easily human readable E.g. a float showing seconds...

          Show
          Michael McCandless added a comment - what would you prefer? In this context, just something easily human readable E.g. a float showing seconds...
          Hide
          Timothy Potter added a comment -

          Bulk close after 5.1 release

          Show
          Timothy Potter added a comment - Bulk close after 5.1 release

            People

            • Assignee:
              Michael McCandless
              Reporter:
              Michael McCandless
            • Votes:
              0 Vote for this issue
              Watchers:
              7 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development