Loading...

Type: Bug
Resolution: Done
Priority: Major - P3
Fix Version/s: 2.5.5
Affects Version/s: None
Component/s: Index Maintenance
Labels:
- 26qa

Operating System:
ALL
CAR Domain/s:
None

Aha! Reference:
None
Tracking Level:
None
Risk Status:
None
Exec Notes:
None
Goal Name(s):
None
Goal Link:
None

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 } } }

Details

Description

Attachments

Activity

People

Dates