|
this happened while i was testing background indexing on mixed version replicasets, although i don't know if the server versions have any relevance to this issue.
repro script:
setVerboseShell(false)
|
var rs1 = new ReplSetTest({nodes:2, name:"test"})
|
rs1.startSet({binVersion:"2.4.1"})
|
rs1.initiate()
|
var pri = rs1.getPrimary()
|
for(var i=0;i<1000000;i++){
|
pri.getDB("poo").test.insert({"x":i})
|
}
|
|
|
var new_secondary = rs1.start(3,{binVersion:"2.5.3"})
|
var config = rs1.getPrimary().getDB("local").system.replset.findOne()
|
config.members.push({_id:config.members.length, host:new_secondary.host})
|
config.version++
|
rs1.getPrimary().getDB("admin").runCommand({replSetReconfig:config})
|
rs1.waitForState(new_secondary, rs1.SECONDARY, 60000);
|
|
printjson("MAKING BG INDEX")
|
rs1.getPrimary().getDB("poo").test.createIndex({x:1}, {background:true})
|
sleep(10)
|
print("Renaming collection.")
|
rs1.getPrimary().getDB("poo").adminCommand({ renameCollection: "poo.test", to: "poo2.test2", dropTarget: false })
|
printjson(rs1.getPrimary().getDB("poo").test.getIndexes())
|
printjson(rs1.getPrimary().getDB("poo2").test2.getIndexes())
|
while(true){
|
sleep(1000)
|
printjson("end of test, chillin")
|
printjson(rs1.getPrimary().getDB("poo").test.getIndexes())
|
printjson(rs1.getPrimary().getDB("poo2").test2.getIndexes())
|
}
|
By the end of the test run, the collection is correctly renamed and the indexes also seem to have been created properly, so I don't think there is any issue of correctness here.
However during the execution of the test, there are hundreds of logged lines like the following:
m31000| Wed Nov 20 16:05:32.394 [conn1] warning: ClientCursor::yield can't unlock b/c of recursive lock ns: poo.test top: { opid: 1377416, active: true, secs_running: 10, op: "query", ns: "poo2.test2", query: { renameCollection: "poo.test", to: "poo2.test2", dropTarget: false }, client: "127.0.0.1:57663", desc: "conn1", threadId: "0x10e6d5000", connectionId: 1, locks: { ^: "W" }, waitingForLock: false, msg: "index: (3/3) btree-middle", numYields: 0, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: { R: 0, W: 2 } } }
|
m31000| Wed Nov 20 16:05:32.394 [conn1] warning: ClientCursor::yield can't unlock b/c of recursive lock ns: poo.test top: { opid: 1377416, active: true, secs_running: 10, op: "query", ns: "poo2.test2", query: { renameCollection: "poo.test", to: "poo2.test2", dropTarget: false }, client: "127.0.0.1:57663", desc: "conn1", threadId: "0x10e6d5000", connectionId: 1, locks: { ^: "W" }, waitingForLock: false, msg: "index: (3/3) btree-middle", numYields: 0, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: { R: 0, W: 2 } } }
|
m31000| Wed Nov 20 16:05:32.394 [conn1] warning: ClientCursor::yield can't unlock b/c of recursive lock ns: poo.test top: { opid: 1377416, active: true, secs_running: 10, op: "query", ns: "poo2.test2", query: { renameCollection: "poo.test", to: "poo2.test2", dropTarget: false }, client: "127.0.0.1:57663", desc: "conn1", threadId: "0x10e6d5000", connectionId: 1, locks: { ^: "W" }, waitingForLock: false, msg: "index: (3/3) btree-middle", numYields: 0, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: { R: 0, W: 2 } } }
|
m31000| Wed Nov 20 16:05:32.394 [conn1] warning: ClientCursor::yield can't unlock b/c of recursive lock ns: poo.test top: { opid: 1377416, active: true, secs_running: 10, op: "query", ns: "poo2.test2", query: { renameCollection: "poo.test", to: "poo2.test2", dropTarget: false }, client: "127.0.0.1:57663", desc: "conn1", threadId: "0x10e6d5000", connectionId: 1, locks: { ^: "W" }, waitingForLock: false, msg: "index: (3/3) btree-middle", numYields: 0, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: { R: 0, W: 2 } } }
|
m31000| Wed Nov 20 16:05:32.394 [conn1] warning: ClientCursor::yield can't unlock b/c of recursive lock ns: poo.test top: { opid: 1377416, active: true, secs_running: 10, op: "query", ns: "poo2.test2", query: { renameCollection: "poo.test", to: "poo2.test2", dropTarget: false }, client: "127.0.0.1:57663", desc: "conn1", threadId: "0x10e6d5000", connectionId: 1, locks: { ^: "W" }, waitingForLock: false, msg: "index: (3/3) btree-middle", numYields: 0, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: { R: 0, W: 2 } } }
|
m31000| Wed Nov 20 16:05:32.394 [conn1] warning: ClientCursor::yield can't unlock b/c of recursive lock ns: poo.test top: { opid: 1377416, active: true, secs_running: 10, op: "query", ns: "poo2.test2", query: { renameCollection: "poo.test", to: "poo2.test2", dropTarget: false }, client: "127.0.0.1:57663", desc: "conn1", threadId: "0x10e6d5000", connectionId: 1, locks: { ^: "W" }, waitingForLock: false, msg: "index: (3/3) btree-middle", numYields: 0, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: { R: 0, W: 2 } } }
|
m31000| Wed Nov 20 16:05:32.394 [conn1] warning: ClientCursor::yield can't unlock b/c of recursive lock ns: poo.test top: { opid: 1377416, active: true, secs_running: 10, op: "query", ns: "poo2.test2", query: { renameCollection: "poo.test", to: "poo2.test2", dropTarget: false }, client: "127.0.0.1:57663", desc: "conn1", threadId: "0x10e6d5000", connectionId: 1, locks: { ^: "W" }, waitingForLock: false, msg: "index: (3/3) btree-middle", numYields: 0, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: { R: 0, W: 2 } } }
|
m31000| Wed Nov 20 16:05:32.394 [conn1] warning: ClientCursor::yield can't unlock b/c of recursive lock ns: poo.test top: { opid: 1377416, active: true, secs_running: 10, op: "query", ns: "poo2.test2", query: { renameCollection: "poo.test", to: "poo2.test2", dropTarget: false }, client: "127.0.0.1:57663", desc: "conn1", threadId: "0x10e6d5000", connectionId: 1, locks: { ^: "W" }, waitingForLock: false, msg: "index: (3/3) btree-middle", numYields: 0, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: { R: 0, W: 2 } } }
|
m31000| Wed Nov 20 16:05:32.395 [conn1] warning: ClientCursor::yield can't unlock b/c of recursive lock ns: poo.test top: { opid: 1377416, active: true, secs_running: 10, op: "query", ns: "poo2.test2", query: { renameCollection: "poo.test", to: "poo2.test2", dropTarget: false }, client: "127.0.0.1:57663", desc: "conn1", threadId: "0x10e6d5000", connectionId: 1, locks: { ^: "W" }, waitingForLock: false, msg: "index: (3/3) btree-middle", numYields: 0, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: { R: 0, W: 2 } } }
|
m31000| Wed Nov 20 16:05:32.395 [conn1] warning: ClientCursor::yield can't unlock b/c of recursive lock ns: poo.test top: { opid: 1377416, active: true, secs_running: 10, op: "query", ns: "poo2.test2", query: { renameCollection: "poo.test", to: "poo2.test2", dropTarget: false }, client: "127.0.0.1:57663", desc: "conn1", threadId: "0x10e6d5000", connectionId: 1, locks: { ^: "W" }, waitingForLock: false, msg: "index: (3/3) btree-middle", numYields: 0, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: { R: 0, W: 2 } } }
|
m31000| Wed Nov 20 16:05:32.415 [conn1] warning: ClientCursor::yield can't unlock b/c of recursive lock ns: poo.test top: { opid: 1377416, active: true, secs_running: 10, op: "query", ns: "poo2.test2", query: { renameCollection: "poo.test", to: "poo2.test2", dropTarget: false }, client: "127.0.0.1:57663", desc: "conn1", threadId: "0x10e6d5000", connectionId: 1, locks: { ^: "W" }, waitingForLock: false, msg: "index: (3/3) btree-middle", numYields: 0, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: { R: 0, W: 2 } } }
|
m31000| Wed Nov 20 16:05:32.415 [conn1] warning: ClientCursor::yield can't unlock b/c of recursive lock ns: poo.test top: { opid: 1377416, active: true, secs_running: 10, op: "query", ns: "poo2.test2", query: { renameCollection: "poo.test", to: "poo2.test2", dropTarget: false }, client: "127.0.0.1:57663", desc: "conn1", threadId: "0x10e6d5000", connectionId: 1, locks: { ^: "W" }, waitingForLock: false, msg: "index: (3/3) btree-middle", numYields: 0, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: { R: 0, W: 2 } } }
|
m31000| Wed Nov 20 16:05:32.415 [conn1] warning: ClientCursor::yield can't unlock b/c of recursive lock ns: poo.test top: { opid: 1377416, active: true, secs_running: 10, op: "query", ns: "poo2.test2", query: { renameCollection: "poo.test", to: "poo2.test2", dropTarget: false }, client: "127.0.0.1:57663", desc: "conn1", threadId: "0x10e6d5000", connectionId: 1, locks: { ^: "W" }, waitingForLock: false, msg: "index: (3/3) btr^CForLock: false, msg: "index: (3/3) btree-middle", numYields: 0, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: { R: 0, W: 2 } } }
|
m31000| Wed Nov 20 16:05:32.415 [conn1] warning: ClientCursor::yield can't unlock b/c of recursive lock ns: poo.test top: { opid: 1377416, active: true, secs_running: 10, op: "query", ns: "poo2.test2", query: { renameCollection: "poo.test", to: "poo2.test2", dropTarget: false }, client: "127.0.0.1:57663", desc: "conn1", threadId: "0x10e6d5000", connectionId: 1, locks: { ^: "W" }, waitingForLock: false, msg: "index: (3/3) btree-middle", numYields: 0, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: { R: 0, W: 2 } } }
|
m31000| Wed Nov 20 16:05:32.415 [conn1] warning: ClientCursor::yield can't unlock b/c of recursive lock ns: poo.test top: { opid: 1377416, active: true, secs_running: 10, op: "query", ns: "poo2.test2", query: { renameCollection: "poo.test", to: "poo2.test2", dropTarget: false }, client: "127.0.0.1:57663", desc: "conn1", threadId: "0x10e6d5000", connectionId: 1, locks: { ^: "W" }, waitingForLock: false, msg: "index: (3/3) btree-middle", numYields: 0, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: { R: 0, W: 2 } } }
|
|