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

Regression after mass deletion

    • ALL
    • Storage - Ra 2022-01-24, Storage - Ra 2022-02-07, Storage - Ra 2022-02-21, Storage - Ra 2022-03-07, Storage - Ra 2022-03-21, Storage - Ra 2022-06-13
    • 0

      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()
      }
      

        1. Stats.png
          Stats.png
          259 kB
        2. Screenshot 2024-02-07 at 13.21.39.png
          Screenshot 2024-02-07 at 13.21.39.png
          326 kB
        3. Screen Shot 2023-02-01 at 3.31.12 pm.png
          Screen Shot 2023-02-01 at 3.31.12 pm.png
          64 kB
        4. Screen Shot 2023-02-01 at 3.31.00 pm.png
          Screen Shot 2023-02-01 at 3.31.00 pm.png
          95 kB
        5. Screenshot 2021-03-30 at 16.25.27.png
          Screenshot 2021-03-30 at 16.25.27.png
          570 kB
        6. Screenshot 2021-03-29 at 15.19.39.png
          Screenshot 2021-03-29 at 15.19.39.png
          515 kB
        7. Screenshot 2021-03-29 at 15.18.34.png
          Screenshot 2021-03-29 at 15.18.34.png
          493 kB
        8. removes.png
          removes.png
          224 kB
        9. remove.png
          remove.png
          22 kB
        10. removals-mixed.png
          removals-mixed.png
          54 kB
        11. regression.tgz
          188 kB
        12. regression.png
          regression.png
          148 kB
        13. query-mixed.png
          query-mixed.png
          99 kB
        14. old_oplog_fetcher.png
          old_oplog_fetcher.png
          173 kB
        15. new_oplog_fetcher_exhaust_cursor.png
          new_oplog_fetcher_exhaust_cursor.png
          185 kB
        16. metrics.2021-03-26T21-18-07Z-00000
          158 kB
        17. metrics.2021-03-26T10-09-27Z-00000
          97 kB
        18. focused.png
          focused.png
          138 kB
        19. compare.png
          compare.png
          138 kB
        20. comp-3.png
          comp-3.png
          114 kB

            Assignee:
            siddhartha.mahajan@mongodb.com Sid Mahajan
            Reporter:
            bruce.lucas@mongodb.com Bruce Lucas (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            44 Start watching this issue

              Created:
              Updated:
              Resolved: