Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-48522

Regression after mass deletion

    XMLWordPrintable

    Details

    • Operating System:
      ALL
    • Sprint:
      Storage - Ra 2021-11-15
    • Story Points:
      5

      Description

      Test inserts 100 k documents, removes them all, then looks for (the now non-existent) documents via the _id index.

      Left is 4.2.6, right is 4.4.0-rc7

      • A-B, D-E: removing 100 k documents. There is a regression of about 30% in rate of deletion ("cursor remove calls")
      • starting B, E: doing a find via the _id index for a non-existent document
      • B-C: in 4.2.6 for a period of time the queries are slow, then at C the rate picks up, apparently having something to do with pages evicted due to too many deleted items
      • E-F: in 4.4.0-rc7 the rate is also intially slow (albeit slower than in 4.2.6 at the same point), then picks up some at F, but remains much slower than in 4.2.6. Behavior of pages evicted due to too many deleted items is different - looks like we're trying but not able to evict them?

      PMP shows most of our time here

      #0  0x00005652ac555e4c in __wt_value_return_buf ()
      #1  0x00005652ac5248b7 in __wt_txn_read ()
      #2  0x00005652ac525bdf in __wt_btcur_next ()
      #3  0x00005652ac53294a in __wt_btcur_search_near ()
      #4  0x00005652ac484528 in __curfile_search_near ()
      #5  0x00005652ac41695f in int mongo::wiredTigerPrepareConflictRetry<mongo::(anonymous namespace)::WiredTigerIndexCursorBase::seekWTCursor(mongo::KeyString::Value const&)::{lambda()#1}>(mongo::OperationContext*, mongo::(anonymous namespace)::WiredTigerIndexCursorBase::seekWTCursor(mongo::KeyString::Value const&)::{lambda()#1}&&) ()
      #6  0x00005652ac417070 in mongo::(anonymous namespace)::WiredTigerIndexCursorBase::seekWTCursor(mongo::KeyString::Value const&) ()
      #7  0x00005652ac41d212 in mongo::(anonymous namespace)::WiredTigerIndexCursorBase::seek(mongo::KeyString::Value const&, mongo::SortedDataInterface::Cursor::RequestedInfo) ()
      #8  0x00005652ace06b22 in mongo::IndexScan::initIndexScan() ()
      #9  0x00005652ace07817 in mongo::IndexScan::doWork(unsigned long*) ()
      

      This one also showed up once

      #0  0x00005652ac52331e in __wt_txn_upd_value_visible_all ()
      #1  0x00005652ac526917 in __wt_btcur_next ()
      #2  0x00005652ac53294a in __wt_btcur_search_near ()
      #3  0x00005652ac484528 in __curfile_search_near ()
      #4  0x00005652ac41695f in int mongo::wiredTigerPrepareConflictRetry<mongo::(anonymous namespace)::WiredTigerIndexCursorBase::seekWTCursor(mongo::KeyString::Value const&)::{lambda()#1}>(mongo::OperationContext*, mongo::(anonymous namespace)::WiredTigerIndexCursorBase::seekWTCursor(mongo::KeyString::Value const&)::{lambda()#1}&&) ()
      #5  0x00005652ac417070 in mongo::(anonymous namespace)::WiredTigerIndexCursorBase::seekWTCursor(mongo::KeyString::Value const&) ()
      #6  0x00005652ac41d212 in mongo::(anonymous namespace)::WiredTigerIndexCursorBase::seek(mongo::KeyString::Value const&, mongo::SortedDataInterface::Cursor::RequestedInfo) ()
      #7  0x00005652ace06b22 in mongo::IndexScan::initIndexScan() ()
      #8  0x00005652ace07817 in mongo::IndexScan::doWork(unsigned long*) ()
      

      Repro: 3-node replica set

      function repro() {
       
          // insert 100 k documents
          nthreads = 10
          threads = []
          for (var t=0; t<nthreads; t++) {
              thread = new ScopedThread(function(t) {
                  size = 10
                  count = 10*1000;
                  every = 1000
                  const x = 'x'.repeat(size)
                  for (var i=0; i<count; i+=every) {
                      many = []
                      for (var j=0; j<every; j++)
                          many.push({_id: t*count+i+j, x})
                      db.c.insertMany(many)
                      if (i%10000==0) print(t, i)
                  }
              }, t)
              threads.push(thread)
              thread.start()
          }
          for (var t = 0; t < nthreads; t++)
              threads[t].join()
       
       
          // remove them
          print("removing")
          db.c.remove({_id: {$lt: 100000}})
       
          // loop trying to find non-existent document via _id index
          print("finding")
          while (true)
              db.c.find({_id: {$lt: 100000}}).itcount()
      }
      

        Attachments

        1. comp-3.png
          comp-3.png
          114 kB
        2. compare.png
          compare.png
          138 kB
        3. focused.png
          focused.png
          138 kB
        4. metrics.2021-03-26T10-09-27Z-00000
          97 kB
        5. metrics.2021-03-26T21-18-07Z-00000
          158 kB
        6. new_oplog_fetcher_exhaust_cursor.png
          new_oplog_fetcher_exhaust_cursor.png
          185 kB
        7. old_oplog_fetcher.png
          old_oplog_fetcher.png
          173 kB
        8. query-mixed.png
          query-mixed.png
          99 kB
        9. regression.png
          regression.png
          148 kB
        10. regression.tgz
          188 kB
        11. removals-mixed.png
          removals-mixed.png
          54 kB
        12. remove.png
          remove.png
          22 kB
        13. removes.png
          removes.png
          224 kB
        14. Screenshot 2021-03-29 at 15.18.34.png
          Screenshot 2021-03-29 at 15.18.34.png
          493 kB
        15. Screenshot 2021-03-29 at 15.19.39.png
          Screenshot 2021-03-29 at 15.19.39.png
          515 kB
        16. Screenshot 2021-03-30 at 16.25.27.png
          Screenshot 2021-03-30 at 16.25.27.png
          570 kB

          Issue Links

            Activity

              People

              Assignee:
              backlog-server-storage-engines Backlog - Storage Engines Team
              Reporter:
              bruce.lucas Bruce Lucas
              Participants:
              Votes:
              0 Vote for this issue
              Watchers:
              22 Start watching this issue

                Dates

                Created:
                Updated: