[SERVER-16344] invariant failure: missing required lock in AutoGetCollectionForRead Created: 27/Nov/14  Updated: 11/Jan/15  Resolved: 15/Dec/14

Status: Closed
Project: Core Server
Component/s: Concurrency, Storage
Affects Version/s: 2.8.0-rc1
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Dmitriy Selivanov Assignee: Kaloian Manassiev
Resolution: Cannot Reproduce Votes: 0
Labels: wiredtiger
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

amazon m3.xlarge, ubuntu 14.04.
------------------------
mongod.conf
------------------------
systemLog:
destination: file
path: "/storage/logs/mongodb.log"
logAppend: true
storage:
dbPath: "/storage/data"
engine: "wiredTiger"
wiredTiger:
engineConfig: "cache_size=12G"
collectionConfig: "block_compressor=snappy"
journal:
enabled: true
indexBuildRetry: false
net:
port: 27017


Issue Links:
Related
related to SERVER-16055 Commands with empty string cause the ... Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Participants:

 Description   

I can't construct compound index (like {source:1, sourceId:1}) in foreground mode on a big collection (~213 millions of records, ~500gb of snappy compressed data). After 60-70% (depend on attempts I made) mongod crashes.

But I CAN build it in background mode without any problems.

Here is backtrace (sorry, I don't know how to collapse it in jira):

2014-11-27T22:48:24.011+0000 I -        [conn61]   Index Build: 151044900/213991103 70%
2014-11-27T22:48:27.023+0000 I -        [conn61]   Index Build: 151066000/213991103 70%
2014-11-27T22:48:30.015+0000 I -        [conn61]   Index Build: 151087600/213991103 70%
2014-11-27T22:48:30.514+0000 I -        [conn65] LockerId 983034 has been waiting to acquire lock for more than 30 seconds. MongoDB will print the lock manager state and the stack
 of the thread that has been waiting, for diagnostic purposes. This message does not necessary imply that the server is experiencing an outage, but might be an indication of an ov
erload.
2014-11-27T22:48:30.514+0000 I -        [conn65] Dumping LockManager @ 0x1b21958
2014-11-27T22:48:30.514+0000 I -        [conn65] Lock @ 0x3F9C940: {2305843009213693953: Global, 1}
GRANTED:
        LockRequest 982999 @ 0x6764700: Mode = IX; ConvertMode = NONE; EnqueueAtFront = 0; CompatibleFirst = 0; 
        LockRequest 983001 @ 0x3FDC300: Mode = IS; ConvertMode = NONE; EnqueueAtFront = 0; CompatibleFirst = 0; 
        LockRequest 983018 @ 0x518C300: Mode = IS; ConvertMode = NONE; EnqueueAtFront = 0; CompatibleFirst = 0; 
        LockRequest 983034 @ 0xDF89100: Mode = IS; ConvertMode = NONE; EnqueueAtFront = 0; CompatibleFirst = 0; 
 
PENDING:
2014-11-27T22:48:30.514+0000 I -        [conn65] Lock @ 0x3F9BFE0: {7353707421137559428: Database, 436178393496477572}
GRANTED:
        LockRequest 982999 @ 0x6764700: Mode = X; ConvertMode = NONE; EnqueueAtFront = 0; CompatibleFirst = 0; 
 
2014-11-27T22:48:33.011+0000 I -        [conn61]   Index Build: 151109400/213991103 70%
2014-11-27T22:48:35.042+0000 I -        [clientcursormon] Invariant failure txn->lockState()->isDbLockedForMode(db, MODE_IS) src/mongo/db/catalog/database_holder.cpp 75
2014-11-27T22:48:35.051+0000 I CONTROL  [clientcursormon] 
 0xf41389 0xee8d61 0xecdf82 0x902001 0x912023 0x9121ae 0x8f6703 0x915395 0xed0e49 0xf8e994 0x7f263e784182 0x7f263d884fbd
----- BEGIN BACKTRACE -----
{"backtrace":[{"b":"400000","o":"B41389"},{"b":"400000","o":"AE8D61"},{"b":"400000","o":"ACDF82"},{"b":"400000","o":"502001"},{"b":"400000","o":"512023"},{"b":"400000","o":"5121AE"},{"b":"400000","o":"4F6703"},{"b":"400000","o":"515395"},{"b":"400000","o":"AD0E49"},{"b":"400000","o":"B8E994"},{"b":"7F263E77C000","o":"8182"},{"b":"7F263D78A000","o":"FAFBD"}],"processInfo":{ "mongodbVersion" : "2.8.0-rc1", "gitVersion" : "c8171e7f969519af8b87a43425ae291ee69a0191", "uname" : { "sysname" : "Linux", "release" : "3.13.0-36-generic", "version" : "#63-Ubuntu SMP Wed Sep 3 21:30:07 UTC 2014", "machine" : "x86_64" }, "somap" : [ { "elfType" : 2, "b" : "400000" }, { "b" : "7FFFFE663000", "elfType" : 3 }, { "b" : "7F263E77C000", "path" : "/lib/x86_64-linux-gnu/libpthread.so.0", "elfType" : 3 }, { "b" : "7F263E574000", "path" : "/lib/x86_64-linux-gnu/librt.so.1", "elfType" : 3 }, { "b" : "7F263E370000", "path" : "/lib/x86_64-linux-gnu/libdl.so.2", "elfType" : 3 }, { "b" : "7F263E06C000", "path" : "/usr/lib/x86_64-linux-gnu/libstdc++.so.6", "elfType" : 3 }, { "b" : "7F263DD66000", "path" : "/lib/x86_64-linux-gnu/libm.so.6", "elfType" : 3 }, { "b" : "7F263DB50000", "path" : "/lib/x86_64-linux-gnu/libgcc_s.so.1", "elfType" : 3 }, { "b" : "7F263D78A000", "path" : "/lib/x86_64-linux-gnu/libc.so.6", "elfType" : 3 }, { "b" : "7F263E99A000", "path" : "/lib64/ld-linux-x86-64.so.2", "elfType" : 3 } ] }}
 mongod(_ZN5mongo15printStackTraceERSo+0x29) [0xf41389]
 mongod(_ZN5mongo10logContextEPKc+0xE1) [0xee8d61]
 mongod(_ZN5mongo15invariantFailedEPKcS1_j+0xB2) [0xecdf82]
 mongod(_ZNK5mongo14DatabaseHolder3getEPNS_16OperationContextERKNS_10StringDataE+0xD1) [0x902001]
 mongod(_ZN5mongo9AutoGetDbC1EPNS_16OperationContextERKNS_10StringDataENS_8LockModeE+0x43) [0x912023]
 mongod(_ZN5mongo24AutoGetCollectionForReadC2EPNS_16OperationContextERKSs+0x6E) [0x9121ae]
 mongod(_ZN5mongo19GlobalCursorIdCache14timeoutCursorsEPNS_16OperationContextEi+0x113) [0x8f6703]
 mongod(_ZN5mongo19ClientCursorMonitor3runEv+0xA5) [0x915395]
 mongod(_ZN5mongo13BackgroundJob7jobBodyEv+0x119) [0xed0e49]
 mongod(+0xB8E994) [0xf8e994]
 libpthread.so.0(+0x8182) [0x7f263e784182]
 libc.so.6(clone+0x6D) [0x7f263d884fbd]
-----  END BACKTRACE  -----
2014-11-27T22:48:35.051+0000 I -        [clientcursormon] 
 
***aborting after invariant() failure
PENDING:
        LockRequest 983001 @ 0x3FDC300: Mode = IS; ConvertMode = NONE; EnqueueAtFront = 0; CompatibleFirst = 0; 
        LockRequest 983018 @ 0x518C300: Mode = IS; ConvertMode = NONE; EnqueueAtFront = 0; CompatibleFirst = 0; 
        LockRequest 983034 @ 0xDF89100: Mode = IS; ConvertMode = NONE; EnqueueAtFront = 0; CompatibleFirst = 0; 
2014-11-27T22:48:30.514+0000 I -        [conn65] Lock @ 0x3F9C160: {10974972495614759045: Collection, 1751600458759983237}
GRANTED:
        LockRequest 982999 @ 0x6764700: Mode = IX; ConvertMode = NONE; EnqueueAtFront = 0; CompatibleFirst = 0; 
 
PENDING:
2014-11-27T22:48:30.514+0000 I -        [conn65] 
2014-11-27T22:48:30.519+0000 I -        [conn65] 
 0xf41389 0x9a673a 0x9ae68c 0x99fcae 0x952282 0x9b67e4 0x9b7682 0x9b81f0 0xbb973c 0xa9db93 0x7e0290 0xefd9c1 0x7f263e784182 0x7f263d884fbd
----- BEGIN BACKTRACE -----
{"backtrace":[{"b":"400000","o":"B41389"},{"b":"400000","o":"5A673A"},{"b":"400000","o":"5AE68C"},{"b":"400000","o":"59FCAE"},{"b":"400000","o":"552282"},{"b":"400000","o":"5B67E4
"},{"b":"400000","o":"5B7682"},{"b":"400000","o":"5B81F0"},{"b":"400000","o":"7B973C"},{"b":"400000","o":"69DB93"},{"b":"400000","o":"3E0290"},{"b":"400000","o":"AFD9C1"},{"b":"7F
263E77C000","o":"8182"},{"b":"7F263D78A000","o":"FAFBD"}],"processInfo":{ "mongodbVersion" : "2.8.0-rc1", "gitVersion" : "c8171e7f969519af8b87a43425ae291ee69a0191", "uname" : { "s
ysname" : "Linux", "release" : "3.13.0-36-generic", "version" : "#63-Ubuntu SMP Wed Sep 3 21:30:07 UTC 2014", "machine" : "x86_64" }, "somap" : [ { "elfType" : 2, "b" : "400000" }
, { "b" : "7FFFFE663000", "elfType" : 3 }, { "b" : "7F263E77C000", "path" : "/lib/x86_64-linux-gnu/libpthread.so.0", "elfType" : 3 }, { "b" : "7F263E574000", "path" : "/lib/x86_64
-linux-gnu/librt.so.1", "elfType" : 3 }, { "b" : "7F263E370000", "path" : "/lib/x86_64-linux-gnu/libdl.so.2", "elfType" : 3 }, { "b" : "7F263E06C000", "path" : "/usr/lib/x86_64-li
nux-gnu/libstdc++.so.6", "elfType" : 3 }, { "b" : "7F263DD66000", "path" : "/lib/x86_64-linux-gnu/libm.so.6", "elfType" : 3 }, { "b" : "7F263DB50000", "path" : "/lib/x86_64-linux-
gnu/libgcc_s.so.1", "elfType" : 3 }, { "b" : "7F263D78A000", "path" : "/lib/x86_64-linux-gnu/libc.so.6", "elfType" : 3 }, { "b" : "7F263E99A000", "path" : "/lib64/ld-linux-x86-64.
so.2", "elfType" : 3 } ] }}
 mongod(_ZN5mongo15printStackTraceERSo+0x29) [0xf41389]
 mongod(+0x5A673A) [0x9a673a]
 mongod(_ZN5mongo10LockerImplILb0EE12lockCompleteENS_10ResourceIdEjb+0x18C) [0x9ae68c]
 mongod(_ZN5mongo4Lock6DBLockC1EPNS_6LockerERKNS_10StringDataENS_8LockModeE+0xCE) [0x99fcae]
 mongod(_ZN5mongo16CmdListDatabases3runEPNS_16OperationContextERKSsRNS_7BSONObjEiRSsRNS_14BSONObjBuilderEb+0x262) [0x952282]
 mongod(_ZN5mongo12_execCommandEPNS_16OperationContextEPNS_7CommandERKSsRNS_7BSONObjEiRSsRNS_14BSONObjBuilderEb+0x34) [0x9b67e4]
 mongod(_ZN5mongo7Command11execCommandEPNS_16OperationContextEPS0_iPKcRNS_7BSONObjERNS_14BSONObjBuilderEb+0xC62) [0x9b7682]
 mongod(_ZN5mongo12_runCommandsEPNS_16OperationContextEPKcRNS_7BSONObjERNS_11_BufBuilderINS_16TrivialAllocatorEEERNS_14BSONObjBuilderEbi+0x2D0) [0x9b81f0]
 mongod(_ZN5mongo11newRunQueryEPNS_16OperationContextERNS_7MessageERNS_12QueryMessageERNS_5CurOpES3_b+0x101C) [0xbb973c]
 mongod(_ZN5mongo16assembleResponseEPNS_16OperationContextERNS_7MessageERNS_10DbResponseERKNS_11HostAndPortEb+0xBB3) [0xa9db93]
 mongod(_ZN5mongo16MyMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortEPNS_9LastErrorE+0xE0) [0x7e0290]
 mongod(_ZN5mongo17PortMessageServer17handleIncomingMsgEPv+0x421) [0xefd9c1]
 libpthread.so.0(+0x8182) [0x7f263e784182]
 libc.so.6(clone+0x6D) [0x7f263d884fbd]
-----  END BACKTRACE  -----
 
2014-11-27T22:48:35.060+0000 F -        [clientcursormon] Got signal: 6 (Aborted).
 
 0xf41389 0xf40cf2 0xf41076 0x7f263d7c0c30 0x7f263d7c0bb9 0x7f263d7c3fc8 0xecdfc7 0x902001 0x912023 0x9121ae 0x8f6703 0x915395 0xed0e49 0xf8e994 0x7f263e784182 0x7f263d884fbd
----- BEGIN BACKTRACE -----
{"backtrace":[{"b":"400000","o":"B41389"},{"b":"400000","o":"B40CF2"},{"b":"400000","o":"B41076"},{"b":"7F263D78A000","o":"36C30"},{"b":"7F263D78A000","o":"36BB9"},{"b":"7F263D78A000","o":"39FC8"},{"b":"400000","o":"ACDFC7"},{"b":"400000","o":"502001"},{"b":"400000","o":"512023"},{"b":"400000","o":"5121AE"},{"b":"400000","o":"4F6703"},{"b":"400000","o":"515395"},{"b":"400000","o":"AD0E49"},{"b":"400000","o":"B8E994"},{"b":"7F263E77C000","o":"8182"},{"b":"7F263D78A000","o":"FAFBD"}],"processInfo":{ "mongodbVersion" : "2.8.0-rc1", "gitVersion" : "c8171e7f969519af8b87a43425ae291ee69a0191", "uname" : { "sysname" : "Linux", "release" : "3.13.0-36-generic", "version" : "#63-Ubuntu SMP Wed Sep 3 21:30:07 UTC 2014", "machine" : "x86_64" }, "somap" : [ { "elfType" : 2, "b" : "400000" }, { "b" : "7FFFFE663000", "elfType" : 3 }, { "b" : "7F263E77C000", "path" : "/lib/x86_64-linux-gnu/libpthread.so.0", "elfType" : 3 }, { "b" : "7F263E574000", "path" : "/lib/x86_64-linux-gnu/librt.so.1", "elfType" : 3 }, { "b" : "7F263E370000", "path" : "/lib/x86_64-linux-gnu/libdl.so.2", "elfType" : 3 }, { "b" : "7F263E06C000", "path" : "/usr/lib/x86_64-linux-gnu/libstdc++.so.6", "elfType" : 3 }, { "b" : "7F263DD66000", "path" : "/lib/x86_64-linux-gnu/libm.so.6", "elfType" : 3 }, { "b" : "7F263DB50000", "path" : "/lib/x86_64-linux-gnu/libgcc_s.so.1", "elfType" : 3 }, { "b" : "7F263D78A000", "path" : "/lib/x86_64-linux-gnu/libc.so.6", "elfType" : 3 }, { "b" : "7F263E99A000", "path" : "/lib64/ld-linux-x86-64.so.2", "elfType" : 3 } ] }}
 mongod(_ZN5mongo15printStackTraceERSo+0x29) [0xf41389]
 mongod(+0xB40CF2) [0xf40cf2]
 mongod(+0xB41076) [0xf41076]
 libc.so.6(+0x36C30) [0x7f263d7c0c30]
 libc.so.6(gsignal+0x39) [0x7f263d7c0bb9]
 libc.so.6(abort+0x148) [0x7f263d7c3fc8]
 mongod(_ZN5mongo15invariantFailedEPKcS1_j+0xF7) [0xecdfc7]
 mongod(_ZNK5mongo14DatabaseHolder3getEPNS_16OperationContextERKNS_10StringDataE+0xD1) [0x902001]
 mongod(_ZN5mongo9AutoGetDbC1EPNS_16OperationContextERKNS_10StringDataENS_8LockModeE+0x43) [0x912023]
 mongod(_ZN5mongo24AutoGetCollectionForReadC2EPNS_16OperationContextERKSs+0x6E) [0x9121ae]
 mongod(_ZN5mongo19GlobalCursorIdCache14timeoutCursorsEPNS_16OperationContextEi+0x113) [0x8f6703]
 mongod(_ZN5mongo19ClientCursorMonitor3runEv+0xA5) [0x915395]
 mongod(_ZN5mongo13BackgroundJob7jobBodyEv+0x119) [0xed0e49]
 mongod(+0xB8E994) [0xf8e994]
 libpthread.so.0(+0x8182) [0x7f263e784182]
 libc.so.6(clone+0x6D) [0x7f263d884fbd]
-----  END BACKTRACE  -----



 Comments   
Comment by Kaloian Manassiev [ 15/Dec/14 ]

We are unable to reproduce this issue, but we have added additional assertions and checks for the DB name conversion, which should help catch it (see SERVER-16055).

Comment by Kaloian Manassiev [ 03/Dec/14 ]

Hi Dmitriy,

Thank you for reporting this issue. We believe this is caused by a bug in the way MongoDB parses database names during enumeration. We put extra checking in the latest nightly build, but have not been able to reproduce it since. In order to help us track this down, would you be able to include the following:

use <DB name on which you are building the index>
print("\"" + db.getName() + "\"");

Also, if at all possible, could you try the latest nightly build and let me know if it still reproduces: https://fastdl.mongodb.org/linux/mongodb-linux-x86_64-latest.tgz?_ga=1.220015257.146050459.1414436872 ?

Thank you in advance.

-Kal.

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