[SERVER-17944] WiredTigerRecordStore::truncate spends a lot of time sleeping Created: 08/Apr/15  Updated: 19/Jun/15  Resolved: 13/May/15

Status: Closed
Project: Core Server
Component/s: WiredTiger
Affects Version/s: None
Fix Version/s: 3.0.4, 3.1.3

Type: Bug Priority: Major - P3
Reporter: Mathias Stearn Assignee: David Hows
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Completed:
Participants:

 Description   

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.



 Comments   
Comment by Githook User [ 19/May/15 ]

Author:

{u'username': u'daveh86', u'name': u'daveh86', u'email': u'howsdav@gmail.com'}

Message: SERVER-17944 backport to 3.0
Branch: v3.0
https://github.com/mongodb/mongo/commit/ca3915291cbc7bddb1c81c4fb07196a209f06988

Comment by David Hows [ 09/Apr/15 ]

Needs to be run via smoke or with testCommands enabled. Otherwise the 'emptycapped' command doesn't exist.

Comment by Mathias Stearn [ 08/Apr/15 ]

This may be related to SERVER-17907, but I'm not sure.

Generated at Thu Feb 08 03:46:04 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.