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

WiredTigerRecordStore::truncate spends a lot of time sleeping

    • Type: Icon: Bug Bug
    • Resolution: Done
    • Priority: Icon: Major - P3 Major - P3
    • 3.0.4, 3.1.3
    • Affects Version/s: None
    • Component/s: WiredTiger
    • Labels:
      None
    • Fully Compatible
    • ALL

      Example:

      var t = db.slow_truncate;
      
      function insert() {
          for (var i=0; i<100*1000; i++) t.insert({_id: i});
      }
      
      print("insert: " + Date.timeFunc(insert));
      print("remove: " + Date.timeFunc(function() {t.remove({})}));
      
      t.drop(); // start next phase clean
      
      print("insert: " + Date.timeFunc(insert));
      print("trunc: " + Date.timeFunc(function() {t.runCommand('emptycapped')})); // does a truncate
      
      Thread 5 (Thread 0x7f65d7847700 (LWP 13329)):
      #0  0x00007f65d5f351b3 in select () from /usr/lib/libc.so.6
      #1  0x0000000001476581 in __wt_sleep (seconds=<optimized out>, micro_seconds=<optimized out>) at src/third_party/wiredtiger/src/os_posix/os_sleep.c:23
      #2  0x0000000001420cf3 in __wt_page_in_func (session=0x2dad640, ref=0x56bf4e0, flags=0) at src/third_party/wiredtiger/src/btree/bt_page.c:188
      #3  0x0000000001437773 in __wt_page_swap_func (flags=0, session=<optimized out>, held=<optimized out>, want=<optimized out>) at src/third_party/wiredtiger/src/include/btree.i:1155
      #4  __wt_row_search (session=0x2dad640, srch_key=0x421d158, leaf=0x0, cbt=0x421d080, insert=0) at src/third_party/wiredtiger/src/btree/row_srch.c:297
      #5  0x0000000001418bb7 in __cursor_row_search (cbt=<optimized out>, insert=0, session=<optimized out>) at src/third_party/wiredtiger/src/btree/bt_cursor.c:239
      #6  __wt_btcur_search (cbt=0x421d080) at src/third_party/wiredtiger/src/btree/bt_cursor.c:310
      #7  0x000000000144ae09 in __curfile_search (cursor=0x421d080) at src/third_party/wiredtiger/src/cursor/cur_file.c:200
      #8  0x0000000000e7770b in mongo::WiredTigerRecordStore::deleteRecord (this=0x2c0f800, txn=0x7f65d7846718, loc=...) at src/mongo/db/storage/wiredtiger/wiredtiger_record_store.cpp:362
      #9  0x0000000000e798a4 in mongo::WiredTigerRecordStore::truncate (this=0x2c0f800, txn=0x7f65d7846718) at src/mongo/db/storage/wiredtiger/wiredtiger_record_store.cpp:723
      #10 0x0000000000984cf8 in mongo::Collection::truncate (this=0x2a14400, txn=0x7f65d7846718) at src/mongo/db/catalog/collection.cpp:531
      #11 0x0000000000a298e5 in mongo::EmptyCapped::run (this=<optimized out>, txn=0x7f65d7846718, dbname=..., cmdObj=..., errmsg=<error reading variable: Cannot access memory at address 0x0>, result=..., fromRepl=false) at src/mongo/db/commands/test_commands.cpp:230
      #12 0x0000000000a76b2e in mongo::_execCommand (txn=0x0, c=<optimized out>, dbname=<error reading variable: Cannot access memory at address 0x0>, cmdObj=<error reading variable: Cannot access memory at address 0x7>, queryOptions=-679194984, errmsg=<error reading variable: Cannot access memory at address 0x0>, result=..., fromRepl=<optimized out>) at src/mongo/db/dbcommands.cpp:1326
      #13 0x0000000000a77d41 in mongo::Command::execCommand (txn=0x7f65d7846718, c=0x2a1f8a0, queryOptions=0, cmdns=<optimized out>, cmdObj=unonwed BSONObj 36 bytes @ 0x3e99426, result=..., fromRepl=<optimized out>) at src/mongo/db/dbcommands.cpp:1547
      #14 0x0000000000a792b6 in mongo::_runCommands (txn=0x7f65d7846718, ns=0x3e99414 "test.$cmd", _cmdobj=..., b=..., anObjBuilder=..., fromRepl=false, queryOptions=<optimized out>) at src/mongo/db/dbcommands.cpp:1621
      #15 0x0000000000a79751 in mongo::runCommands (txn=0x0, ns=0x0, jsobj=<error reading variable: Cannot access memory at address 0x8>, curop=..., b=..., anObjBuilder=..., fromRepl=<optimized out>, queryOptions=0) at src/mongo/db/dbcommands.cpp:1651
      #16 0x0000000000b4b7c6 in mongo::receivedCommand (txn=0x7f65d7846718, nss=..., client=..., dbResponse=..., message=...) at src/mongo/db/instance.cpp:238
      #17 0x0000000000b48f1a in mongo::assembleResponse (txn=0x7f65d7846718, m=..., dbresponse=..., remote=...) at src/mongo/db/instance.cpp:467
      #18 0x0000000000862ec6 in mongo::MyMessageHandler::process (this=<optimized out>, m=..., port=0x2c5a490, le=0x2c59fe0) at src/mongo/db/db.cpp:212
      #19 0x000000000103af4c in mongo::PortMessageServer::handleIncomingMsg (arg=0x2c5a490) at src/mongo/util/net/message_server_port.cpp:230
      #20 0x00007f65d61fe374 in start_thread () from /usr/lib/libpthread.so.0
      #21 0x00007f65d5f3c27d in clone () from /usr/lib/libc.so.6
      

      Attaching gdb during the truncate always lands in that __wt_sleep call inside of wiredtiger. It does slowly make progress, although I gave up waiting for it to finish. As far as the WTRecordStore code is concerned, the remove and truncates do the same things, except that the truncate does all removes in a single WT transaction while the remove version uses a transaction for each document deleted.

            Assignee:
            david.hows David Hows
            Reporter:
            mathias@mongodb.com Mathias Stearn
            Votes:
            0 Vote for this issue
            Watchers:
            8 Start watching this issue

              Created:
              Updated:
              Resolved: