Hello,
In our application we make heavy use of transactions. Recently we started getting Lock not granted messages with multiple concurrent users. Before getting that message tokumx becomes unresponsive and afterwards can leave the data in inconsistent state.We are using Python and MongoEngine.
Below are the relevant log excerpts. I see two potential causes:
-
The bounds for locks are not set per document if the $in operator is used, but on the whole collection subrange. Can this be confirmed? What is the preferred way to update many documents in TokuMX? Would it be better to issue one update command per document in this case?
-
Very often the next operation after lock not granted is insert collection.system.indexes, which apparently requires write lock. Does this message mean that a new document is being added to the index or this means adding a new index? We are not adding any new indexes, but maybe this is related to changing type to multi key indexes?
I would appreciate any help with this.
Thanks
Maricn
Wed Aug 10 18:05:23.586 [conn10421] insert collection.changes keyUpdates:0 exception: Lock not granted. Try restarting the transaction. code:16759 lockNotGranted: { index: “collection.changes.$_cls_1_contract_1_item_parent_1_item_1”, requestingTxnid:
3746827, blockingTxnid: 3744908, bounds: [ { _cls: “ContractChange”, contract: ObjectId(‘57ab65cc135ff11f57c6cc0e’), item_parent: ObjectId(‘57ab65cd135ff11f57c6cc26’), item: ObjectId(‘57ab65cd135ff11f57c6cc24’), $primaryKey: MinKey }, { _cls: “ContractC
hange”, contract: ObjectId(‘57ab65cc135ff11f57c6cc0e’), item_parent: ObjectId(‘57ab65cd135ff11f57c6cc26’), item: ObjectId(‘57ab65cd135ff11f57c6cc24’), $primaryKey: MaxKey } ], blockingOp: { opid: 2444313, active: false, op: “query”, ns: “”, query: { $msg
: “query not recording (too large)” }, client: “172.31.42.160:36492”, desc: “conn10527”, threadId: “0x7f86f37fb700”, connectionId: 10527, rootTxnid: 3744908, locks: { ^collection: “R” }, context: “query (/mnt/workspace/percona-tokumx-2.0-debian-binary/
label_exp/vps-ubuntu-trusty-x64-04/tokumx-enterprise-2.0.2/src/mongo/db/ops/query.cpp:1003)”, waitingForLock: true, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: {} } } } locks(micros) r:10000248 10000ms
Wed Aug 10 18:05:23.586 [conn10438] insert collection.system.indexes ninserted:1 keyUpdates:0 locks(micros) r:75 w:86 3794ms
Wed Aug 10 18:03:20.345 [conn10529] update collection.changes query: { _cls: “ContractChange”, contract: ObjectId(‘57ab6c141ff701555fb4cb8d’), cid: 15 } update: { $set: { occurrence_counter: 1 } } nscanned:0 nupdated:0 keyUpdates:0 lockNotGranted: { in
dex: “collection.changes.$_cls_1_contract_1_item_1”, requestingTxnid: 3732428, blockingTxnid: 3730785, bounds: [ { _cls: “ContractChange”, contract: ObjectId(‘57ab6c141ff701555fb4cb8d’), item: MinKey, $primaryKey: MinKey }, { _cls: “ContractChange”, co
ntract: ObjectId(‘57ab6c141ff701555fb4cb8d’), item: MaxKey, $primaryKey: MaxKey } ], blockingOp: { opid: 2425666, active: true, secs_running: 19, op: “insert”, ns: “collection.system.indexes”, insert: {}, client: “172.31.29.55:51530”, desc: “conn10424”
, threadId: “0x7f87435fd700”, connectionId: 10424, rootTxnid: 3730785, locks: { ^: “w”, ^collection: “W” }, context: “insert (/mnt/workspace/percona-tokumx-2.0-debian-binary/label_exp/vps-ubuntu-trusty-x64-04/tokumx-enterprise-2.0.2/src/mongo/db/instan
ce.cpp:997)”, waitingForLock: false, lockStats: { timeLockedMicros: { r: 107, w: 0 }, timeAcquiringMicros: { r: 2, w: 19217213 } } } } locks(micros) r:20000719 20000ms
Wed Aug 10 18:02:47.491 [conn10424] update collection.changes query: { _cls: “ContractChange”, contract: ObjectId(‘57ab6badaa44d67627da7b80’), cid: 15 } update: { $set: { occurrence_counter: 1 } } nscanned:0 nupdated:0 keyUpdates:0 lockNotGranted: { in
dex: “collection.changes.$_cls_1_contract_1_item_parent_1_item_1”, requestingTxnid: 3730785, blockingTxnid: 3731261, bounds: [ { _cls: “ContractChange”, contract: ObjectId(‘57ab6badaa44d67627da7b80’), item_parent: MinKey, item: MinKey, $primaryKey: Min
Key }, { _cls: “ContractChange”, contract: ObjectId(‘57ab6badaa44d67627da7b80’), item_parent: MaxKey, item: MaxKey, $primaryKey: MaxKey } ], blockingOp: { opid: 2420278, active: true, secs_running: 49, op: “insert”, ns: “collection.system.indexes”, ins
ert: {}, client: “172.31.25.197:51859”, desc: “conn10414”, threadId: “0x7f86ea2fe700”, connectionId: 10414, rootTxnid: 3731261, locks: { ^: “w”, ^collection: “W” }, context: “insert (/mnt/workspace/percona-tokumx-2.0-debian-binary/label_exp/vps-ubuntu-
trusty-x64-04/tokumx-enterprise-2.0.2/src/mongo/db/instance.cpp:997)”, waitingForLock: false, lockStats: { timeLockedMicros: { r: 68, w: 0 }, timeAcquiringMicros: { r: 1, w: 49172164 } } } } locks(micros) r:50001297 50001ms
Wed Aug 10 18:02:47.491 [conn10414] insert collection.system.indexes ninserted:1 keyUpdates:0 locks(micros) r:68 w:98 49172ms
Wed Aug 10 18:01:36.733 [conn10366] query collection.tags query: { section: { $in: [ ObjectId(‘57ab56d11ff701555fb4b168’), ObjectId(‘57ab56d11ff701555fb4b15f’), ObjectId(‘57ab56d11ff701555fb4b160’), ObjectId(‘57ab56d11ff701555fb4b161’), ObjectId(‘57ab5
6d11ff701555fb4b120’), ObjectId(‘57ab56d11ff701555fb4b121’), ObjectId(‘57ab56d11ff701555fb4b12f’), ObjectId(‘57ab56d21ff701555fb4b18c’), ObjectId(‘57ab56d21ff701555fb4b18b’), ObjectId(‘57ab56d11ff701555fb4b130’), ObjectId(‘57ab56cd1ff701555fb4b057’), Obj
ectId(‘57ab56d11ff701555fb4b131’), ObjectId(‘57ab56d11ff701555fb4b169’), ObjectId(‘57ab56d11ff701555fb4b12d’), ObjectId(‘57ab56ce1ff701555fb4b063’), ObjectId(‘57ab56d11ff701555fb4b162’), ObjectId(‘57ab56d11ff701555fb4b124’), ObjectId(‘57ab56d11ff701555fb
4b163’), ObjectId(‘57ab56d11ff701555fb4b132’), ObjectId(‘57ab56d11ff701555fb4b133’), ObjectId(‘57ab56d21ff701555fb4b16d’), ObjectId(‘57ab56d21ff701555fb4b172’), ObjectId(‘57ab56d21ff701555fb4b174’), ObjectId(‘57ab56d01ff701555fb4b0f9’), ObjectId(‘57ab56d
11ff701555fb4b139’), ObjectId(‘57ab56d11ff701555fb4b164’), ObjectId(‘57ab56d11ff701555fb4b13a’), ObjectId(‘57ab56d11ff701555fb4b13b’), ObjectId(‘57ab56d11ff701555fb4b13c’), ObjectId(‘57ab56d11ff701555fb4b165’), ObjectId(‘57ab56ce1ff701555fb4b085’), Objec
tId(‘57ab56ce1ff701555fb4b08d’), ObjectId(‘57ab56ce1ff701555fb4b08f’), ObjectId(‘57ab56ce1ff701555fb4b092’), ObjectId(‘57ab56d11ff701555fb4b127’), ObjectId(‘57ab56d11ff701555fb4b134’), ObjectId(‘57ab56d11ff701555fb4b135’), ObjectId(‘57ab56cf1ff701555fb4b0ed’), ObjectId(‘5
7ab56cf1ff701555fb4b0c5’), ObjectId(‘57ab56cf1ff701555fb4b0c6’), ObjectId(‘57ab56cf1ff701555fb4b0c7’), ObjectId(‘57ab56d01ff701555fb4b0fc’), ObjectId(‘57ab56d01ff701555fb4b0fd’), ObjectId(‘57ab56d01ff701555fb4b0fe’), ObjectId(‘57ab56d11ff701555fb4b151’), Objec
tId(‘57ab56d11ff701555fb4b14a’), ObjectId(‘57ab56d11ff701555fb4b14b’), ObjectId(‘57ab56d11ff701555fb4b14c’), ObjectId(‘57ab56cf1ff701555fb4b0eb’), ObjectId(‘57ab56d11ff701555fb4b14d’), ObjectId(‘57ab56d11ff701555fb4b14e’), ObjectId(‘57ab56cf1ff701555fb4b
0ec’), ObjectId(‘57ab56d11ff701555fb4b14f’), ObjectId(‘57ab56d11ff701555fb4b150’) ] }, _cls: { $in: [ “Tag”, “Tag.ValueTag” ] }, contract: ObjectId(‘57ab56c91ff701555fb4aecd’) } ntoreturn:0 keyUpdates:0 exception: Lock not granted. Try restarting the transaction. code:16759 lockNotGranted: { inde
x: “collection.ns”, requestingTxnid: 3732456, blockingTxnid: 3730785, bounds: [ { ns: “collection.tags” }, { ns: “collection.tags” } ], blockingOp: { opid: 2419580, active: false, op: “query”, ns: “”, query: { $msg: "query not recording (too large)
" }, client: “172.31.29.55:51530”, desc: “conn10424”, threadId: “0x7f87435fd700”, connectionId: 10424, rootTxnid: 3730785, locks: { ^collection: “R” }, context: “query (/mnt/workspace/percona-tokumx-2.0-debian-binary/label_exp/vps-ubuntu-trusty-x64-04/
tokumx-enterprise-2.0.2/src/mongo/db/ops/query.cpp:1003)”, waitingForLock: true, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: {} } } } locks(micros) r:10000290 reslen:95 10000ms
Wed Aug 10 18:01:36.733 [conn10412] assertion 16759 Lock not granted. Try restarting the transaction. ns:collection.tags query:{ _id: { $in: [ ObjectId(‘57aabb61aa44d6450d2221a6’) ] } }
Current ops view of the indexing op:
{
“opid” : 10674100,
“active” : true,
“secs_running” : 380,
“op” : “insert”,
“ns” : “contractroom.system.indexes”,
“insert” : {
},
“client” : “172.31.47.18:47304”,
“desc” : “conn86929”,
“threadId” : “0x7fae17af9700”,
“connectionId” : 86929,
“rootTxnid” : 14824514,
“locks” : {
“^contractroom” : “W”
},
“context” : “insert (/mnt/workspace/percona-tokumx-2.0-debian-binary/label_exp/vps-ubuntu-trusty-x64-04/tokumx-enterprise-2.0.2/src/mongo/db/instance.cpp:997)”,
“waitingForLock” : true,
“lockStats” : {
“timeLockedMicros” : {
“r” : NumberLong(74),
“w” : NumberLong(0)
},
“timeAcquiringMicros” : {
“r” : NumberLong(1),
“w” : NumberLong(0)
}
}
},