Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-11796

renaming collection during background index build on replica set spews a lot of "can't unlock b/c of recursive lock"

    XMLWordPrintableJSON

Details

    • Icon: Bug Bug
    • Resolution: Done
    • Icon: Major - P3 Major - P3
    • 2.5.5
    • None
    • Index Maintenance
    • ALL

    Description

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

      Attachments

        Activity

          People

            milkie@mongodb.com Eric Milkie
            mikeo@mongodb.com Michael O'Brien
            Votes:
            0 Vote for this issue
            Watchers:
            6 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: