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

MongoDb 3.0.2 background index creation still blocking

    • Type: Icon: Bug Bug
    • Resolution: Duplicate
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: 3.0.2
    • Component/s: Replication
    • None
    • ALL

      So today we run some index creation in the background and while primary still worked as it should, replica sets blocked all operations. Here is the currentOp :

      [
         {
            "desc":"conn1721",
            "threadId":"0x143e6bba0",
            "connectionId":1721,
            "opid":72551,
            "active":false,
            "op":"query",
            "ns":"database.collection",
            "query":{
               "$query":{
                  "sys.ts":{
                     "$gte":"20150502040415"
                  }
               },
               "$orderby":{
                  "sys.ts":-1
               },
               "$maxTimeMS":NumberLong(30000),
               "$readPreference":{
                  "mode":"secondaryPreferred"
               }
            },
            "client":"10.0.24.19:37890",
            "numYields":0,
            "locks":{
      
            },
            "waitingForLock":false,
            "lockStats":{
      
            }
         },
         {
            "desc":"conn1685",
            "threadId":"0xb99ea220",
            "connectionId":1685,
            "opid":74069,
            "active":true,
            "secs_running":1048,
            "microsecs_running":NumberLong(1048057524),
            "op":"query",
            "ns":"admin.$cmd",
            "query":{
               "listDatabases":1
            },
            "client":"127.0.0.1:48453",
            "numYields":0,
            "locks":{
      
            },
            "waitingForLock":false,
            "lockStats":{
      
            }
         },
         {
            "desc":"conn1359",
            "threadId":"0xbd6155a0",
            "connectionId":1359,
            "opid":66057,
            "active":true,
            "secs_running":3651,
            "microsecs_running":NumberLong("3651201149"),
            "op":"getmore",
            "ns":"local.oplog.rs",
            "query":{
      
            },
            "client":"10.200.24.100:44683",
            "numYields":0,
            "locks":{
      
            },
            "waitingForLock":false,
            "lockStats":{
               "Global":{
                  "acquireCount":{
                     "r":NumberLong(1)
                  }
               },
               "Database":{
                  "acquireCount":{
                     "r":NumberLong(1)
                  }
               },
               "oplog":{
                  "acquireCount":{
                     "r":NumberLong(1)
                  }
               }
            }
         },
         {
            "desc":"conn1328",
            "threadId":"0x143e6cd80",
            "connectionId":1328,
            "opid":66179,
            "active":true,
            "secs_running":3612,
            "microsecs_running":NumberLong("3612388324"),
            "op":"query",
            "ns":"database.$cmd",
            "query":{
               "count":"collection",
               "query":{
      
               },
               "$queryOptions":{
                  "$readPreference":{
                     "mode":"secondaryPreferred"
                  }
               },
               "maxTimeMS":NumberLong(30000)
            },
            "client":"10.0.24.19:37420",
            "numYields":0,
            "locks":{
      
            },
            "waitingForLock":false,
            "lockStats":{
      
            }
         },
         {
            "desc":"conn1318",
            "threadId":"0xb99eb400",
            "connectionId":1318,
            "opid":66959,
            "active":true,
            "secs_running":3360,
            "microsecs_running":NumberLong("3360024695"),
            "op":"query",
            "ns":"database.$cmd",
            "query":{
               "count":"collection",
               "query":{
      
               },
               "$queryOptions":{
                  "$readPreference":{
                     "mode":"secondaryPreferred"
                  }
               },
               "maxTimeMS":NumberLong(30000)
            },
            "client":"10.0.24.19:37408",
            "numYields":0,
            "locks":{
      
            },
            "waitingForLock":false,
            "lockStats":{
      
            }
         },
         {
            "desc":"repl index builder 7",
            "threadId":"0xbae77260",
            "opid":51964,
            "active":true,
            "secs_running":5264,
            "microsecs_running":NumberLong("5264632786"),
            "op":"insert",
            "ns":"database.system.indexes",
            "insert":{
               "key":{
                  "sys.ts":-1,
                  "sys.ext.maxL":1,
                  "sys.ext.bId":1
               },
               "name":"-ts_maxL_bId",
               "ns":"database.collection",
               "background":true
            },
            "msg":"Index Build (background) Index Build (background): 3524061/4701510 74%",
            "progress":{
               "done":3524061,
               "total":4701510
            },
            "numYields":157719,
            "locks":{
               "Global":"w",
               "Database":"w",
               "Collection":"w"
            },
            "waitingForLock":false,
            "lockStats":{
               "Global":{
                  "acquireCount":{
                     "w":NumberLong(157720)
                  },
                  "acquireWaitCount":{
                     "w":NumberLong(1)
                  },
                  "timeAcquiringMicros":{
                     "w":NumberLong(24771)
                  }
               },
               "Database":{
                  "acquireCount":{
                     "w":NumberLong(157720),
                     "W":NumberLong(1)
                  },
                  "acquireWaitCount":{
                     "w":NumberLong(10),
                     "W":NumberLong(1)
                  },
                  "timeAcquiringMicros":{
                     "w":NumberLong(83558),
                     "W":NumberLong(15942)
                  }
               },
               "Collection":{
                  "acquireCount":{
                     "w":NumberLong(157720)
                  }
               }
            }
         },
         {
            "desc":"conn1313",
            "threadId":"0xb99ea080",
            "connectionId":1313,
            "opid":68694,
            "active":false,
            "op":"query",
            "ns":"database.collection",
            "query":{
               "$query":{
                  "sys.ts":{
                     "$gte":"20150502034320"
                  }
               },
               "$orderby":{
                  "sys.ts":-1
               },
               "$maxTimeMS":NumberLong(30000),
               "$readPreference":{
                  "mode":"secondaryPreferred"
               }
            },
            "client":"10.0.24.19:37404",
            "numYields":0,
            "locks":{
      
            },
            "waitingForLock":false,
            "lockStats":{
      
            }
         },
         {
            "desc":"conn1321",
            "threadId":"0xb99eb5a0",
            "connectionId":1321,
            "opid":66493,
            "active":true,
            "secs_running":3510,
            "microsecs_running":NumberLong("3510922096"),
            "op":"query",
            "ns":"database.$cmd",
            "query":{
               "count":"collection",
               "query":{
      
               },
               "$queryOptions":{
                  "$readPreference":{
                     "mode":"secondaryPreferred"
                  }
               },
               "maxTimeMS":NumberLong(30000)
            },
            "client":"10.0.24.19:37414",
            "numYields":0,
            "locks":{
      
            },
            "waitingForLock":false,
            "lockStats":{
      
            }
         },
         {
            "desc":"conn1326",
            "threadId":"0xbd612000",
            "connectionId":1326,
            "opid":66645,
            "active":true,
            "secs_running":3460,
            "microsecs_running":NumberLong("3460744946"),
            "op":"query",
            "ns":"database.$cmd",
            "query":{
               "count":"collection",
               "query":{
      
               },
               "$queryOptions":{
                  "$readPreference":{
                     "mode":"secondaryPreferred"
                  }
               },
               "maxTimeMS":NumberLong(30000)
            },
            "client":"10.0.24.19:37418",
            "numYields":0,
            "locks":{
      
            },
            "waitingForLock":false,
            "lockStats":{
      
            }
         },
         {
            "desc":"conn171",
            "threadId":"0x341cf20",
            "connectionId":171,
            "opid":66802,
            "active":true,
            "secs_running":3410,
            "microsecs_running":NumberLong("3410288519"),
            "op":"query",
            "ns":"database.$cmd",
            "query":{
               "count":"collection",
               "query":{
      
               },
               "$queryOptions":{
                  "$readPreference":{
                     "mode":"secondaryPreferred"
                  }
               },
               "maxTimeMS":NumberLong(30000)
            },
            "client":"10.0.24.19:35923",
            "numYields":0,
            "locks":{
      
            },
            "waitingForLock":false,
            "lockStats":{
      
            }
         },
         {
            "desc":"conn1535",
            "threadId":"0xb99e9860",
            "connectionId":1535,
            "opid":69164,
            "active":false,
            "op":"query",
            "ns":"database.collection",
            "query":{
               "$query":{
      
               },
               "$orderby":{
                  "_id":-1
               },
               "$maxTimeMS":NumberLong(30000),
               "$readPreference":{
                  "mode":"secondaryPreferred"
               }
            },
            "client":"10.0.24.19:37667",
            "numYields":0,
            "locks":{
      
            },
            "waitingForLock":false,
            "lockStats":{
      
            }
         },
         {
            "desc":"conn185",
            "threadId":"0x341aea0",
            "connectionId":185,
            "opid":66337,
            "active":false,
            "op":"query",
            "ns":"database.collection",
            "query":{
               "$query":{
                  "$and":[
                     {
                        "sys.plL":{
                           "$lt":NumberLong("10000000000")
                        }
                     },
                     {
                        "sys.ts":{
                           "$gt":"20150504000000"
                        }
                     },
                     {
                        "sys.ts":{
                           "$lt":"20150504235959"
                        }
                     },
                     {
                        "state.re":{
                           "$in":[
                              "-"
                           ]
                        }
                     }
                  ]
               },
               "$orderby":{
                  "sys.stk":-1
               },
               "$maxTimeMS":NumberLong(30000),
               "$readPreference":{
                  "mode":"secondaryPreferred"
               }
            },
            "client":"10.0.24.19:35949",
            "numYields":0,
            "locks":{
      
            },
            "waitingForLock":false,
            "lockStats":{
      
            }
         },
         {
            "desc":"repl writer worker 12",
            "threadId":"0x4e06700",
            "opid":66058,
            "active":true,
            "secs_running":3651,
            "microsecs_running":NumberLong("3651038177"),
            "op":"none",
            "ns":"database.collection",
            "query":{
      
            },
            "numYields":0,
            "locks":{
      
            },
            "waitingForLock":false,
            "lockStats":{
               "Global":{
                  "acquireCount":{
                     "w":NumberLong(1),
                     "W":NumberLong(1)
                  },
                  "acquireWaitCount":{
                     "W":NumberLong(1)
                  },
                  "timeAcquiringMicros":{
                     "W":NumberLong(13911)
                  }
               },
               "Database":{
                  "acquireCount":{
                     "W":NumberLong(1)
                  },
                  "acquireWaitCount":{
                     "W":NumberLong(1)
                  },
                  "timeAcquiringMicros":{
                     "W":NumberLong(10)
                  }
               }
            }
         },
         {
            "desc":"conn907",
            "threadId":"0xba7455a0",
            "connectionId":907,
            "opid":66102,
            "active":true,
            "secs_running":3637,
            "microsecs_running":NumberLong("3637724006"),
            "op":"query",
            "ns":"database.$cmd",
            "query":{
               "count":"collection",
               "query":{
      
               },
               "$queryOptions":{
                  "$readPreference":{
                     "mode":"secondaryPreferred"
                  }
               },
               "maxTimeMS":NumberLong(30000)
            },
            "client":"10.0.24.19:36930",
            "numYields":0,
            "locks":{
      
            },
            "waitingForLock":false,
            "lockStats":{
      
            }
         },
         {
            "desc":"repl index builder 8",
            "threadId":"0x143e95860",
            "opid":53730,
            "active":true,
            "secs_running":4934,
            "microsecs_running":NumberLong("4934240334"),
            "op":"insert",
            "ns":"database.system.indexes",
            "insert":{
               "key":{
                  "sys.ts":-1,
                  "state.re":1,
                  "sys.plL":1,
                  "sys.stk":-1
               },
               "name":"-ts_result_plL_-stk",
               "ns":"database.collection",
               "background":true
            },
            "msg":"Index Build (background) Index Build (background): 3524064/4701510 74%",
            "progress":{
               "done":3524064,
               "total":4701510
            },
            "numYields":148388,
            "locks":{
               "Global":"w",
               "Database":"w",
               "Collection":"w"
            },
            "waitingForLock":false,
            "lockStats":{
               "Global":{
                  "acquireCount":{
                     "w":NumberLong(148389)
                  },
                  "acquireWaitCount":{
                     "w":NumberLong(1)
                  },
                  "timeAcquiringMicros":{
                     "w":NumberLong(15316)
                  }
               },
               "Database":{
                  "acquireCount":{
                     "w":NumberLong(148389),
                     "W":NumberLong(1)
                  },
                  "acquireWaitCount":{
                     "w":NumberLong(7),
                     "W":NumberLong(1)
                  },
                  "timeAcquiringMicros":{
                     "w":NumberLong(63986),
                     "W":NumberLong(19330)
                  }
               },
               "Collection":{
                  "acquireCount":{
                     "w":NumberLong(148389)
                  }
               }
            }
         },
         {
            "desc":"repl index builder 6",
            "threadId":"0xbae775a0",
            "opid":51960,
            "active":true,
            "secs_running":5264,
            "microsecs_running":NumberLong("5264765690"),
            "op":"insert",
            "ns":"database.system.indexes",
            "insert":{
               "key":{
                  "sys.ts":-1,
                  "sys.ext.bId":1,
                  "state.re":1
               },
               "name":"-ts_bId_result",
               "ns":"database.collection",
               "background":true
            },
            "msg":"Index Build (background) Index Build (background): 3524063/4701510 74%",
            "progress":{
               "done":3524063,
               "total":4701510
            },
            "numYields":157464,
            "locks":{
               "Global":"w",
               "Database":"w",
               "Collection":"w"
            },
            "waitingForLock":false,
            "lockStats":{
               "Global":{
                  "acquireCount":{
                     "w":NumberLong(157465)
                  },
                  "acquireWaitCount":{
                     "w":NumberLong(1)
                  },
                  "timeAcquiringMicros":{
                     "w":NumberLong(15025)
                  }
               },
               "Database":{
                  "acquireCount":{
                     "w":NumberLong(157465),
                     "W":NumberLong(1)
                  },
                  "acquireWaitCount":{
                     "w":NumberLong(14)
                  },
                  "timeAcquiringMicros":{
                     "w":NumberLong(111863)
                  }
               },
               "Collection":{
                  "acquireCount":{
                     "w":NumberLong(157465)
                  }
               }
            }
         },
         {
            "desc":"repl index builder 9",
            "threadId":"0x143e6a820",
            "opid":61905,
            "active":true,
            "secs_running":4501,
            "microsecs_running":NumberLong("4501444014"),
            "op":"insert",
            "ns":"database.system.indexes",
            "insert":{
               "key":{
                  "sys.ts":-1,
                  "sys.selections.expectedEventEnd":1,
                  "state.re":1
               },
               "name":"-ts_expectedMatchEnd_result",
               "ns":"database.collection",
               "background":true
            },
            "msg":"Index Build (background) Index Build (background): 3524063/4701510 74%",
            "progress":{
               "done":3524063,
               "total":4701510
            },
            "numYields":133864,
            "locks":{
               "Global":"w",
               "Database":"w",
               "Collection":"w"
            },
            "waitingForLock":false,
            "lockStats":{
               "Global":{
                  "acquireCount":{
                     "w":NumberLong(133865)
                  },
                  "acquireWaitCount":{
                     "w":NumberLong(1)
                  },
                  "timeAcquiringMicros":{
                     "w":NumberLong(24516)
                  }
               },
               "Database":{
                  "acquireCount":{
                     "w":NumberLong(133865),
                     "W":NumberLong(1)
                  },
                  "acquireWaitCount":{
                     "w":NumberLong(5),
                     "W":NumberLong(1)
                  },
                  "timeAcquiringMicros":{
                     "w":NumberLong(41651),
                     "W":NumberLong(19947)
                  }
               },
               "Collection":{
                  "acquireCount":{
                     "w":NumberLong(133865)
                  }
               }
            }
         },
         {
            "desc":"repl index builder 10",
            "threadId":"0xbd615c20",
            "opid":63670,
            "active":true,
            "secs_running":4230,
            "microsecs_running":NumberLong("4230483628"),
            "op":"insert",
            "ns":"database.system.indexes",
            "insert":{
               "key":{
                  "sys.ts":-1,
                  "manualSet":1
               },
               "name":"manualSet",
               "ns":"database.collection",
               "background":true
            },
            "msg":"Index Build (background) Index Build (background): 3524064/4701510 74%",
            "progress":{
               "done":3524064,
               "total":4701510
            },
            "numYields":126131,
            "locks":{
               "Global":"w",
               "Database":"w",
               "Collection":"w"
            },
            "waitingForLock":false,
            "lockStats":{
               "Global":{
                  "acquireCount":{
                     "w":NumberLong(126132)
                  },
                  "acquireWaitCount":{
                     "w":NumberLong(1)
                  },
                  "timeAcquiringMicros":{
                     "w":NumberLong(17408)
                  }
               },
               "Database":{
                  "acquireCount":{
                     "w":NumberLong(126132),
                     "W":NumberLong(1)
                  },
                  "acquireWaitCount":{
                     "w":NumberLong(1),
                     "W":NumberLong(1)
                  },
                  "timeAcquiringMicros":{
                     "w":NumberLong(15618),
                     "W":NumberLong(20386)
                  }
               },
               "Collection":{
                  "acquireCount":{
                     "w":NumberLong(126132)
                  }
               },
               "Metadata":{
                  "acquireCount":{
                     "W":NumberLong(1)
                  }
               }
            }
         },
         {
            "desc":"conn1299",
            "threadId":"0xbbed75a0",
            "connectionId":1299,
            "opid":67265,
            "active":true,
            "secs_running":3259,
            "microsecs_running":NumberLong("3259895639"),
            "op":"query",
            "ns":"database.$cmd",
            "query":{
               "count":"collection",
               "query":{
      
               },
               "$queryOptions":{
                  "$readPreference":{
                     "mode":"secondaryPreferred"
                  }
               },
               "maxTimeMS":NumberLong(30000)
            },
            "client":"10.0.24.19:37387",
            "numYields":0,
            "locks":{
      
            },
            "waitingForLock":false,
            "lockStats":{
      
            }
         },
         {
            "desc":"conn1306",
            "threadId":"0xbd612340",
            "connectionId":1306,
            "opid":67342,
            "active":true,
            "secs_running":3234,
            "microsecs_running":NumberLong("3234816477"),
            "op":"query",
            "ns":"database.$cmd",
            "query":{
               "count":"collection",
               "query":{
      
               },
               "$queryOptions":{
                  "$readPreference":{
                     "mode":"secondaryPreferred"
                  }
               },
               "maxTimeMS":NumberLong(30000)
            },
            "client":"10.0.24.19:37397",
            "numYields":0,
            "locks":{
      
            },
            "waitingForLock":false,
            "lockStats":{
      
            }
         }
      ]
      

      PS: The query params were anonymised.

      As soon as index was build everything started to work. As you can see background index creation had global&db&collection lock and our production was useless for couple of hours.

      On primary node it was running without blocking, above currentOp is from replica node. We use mongo 3.02 and WiredTiger.

      So this looks like a bug to me, as secondary should not block from 2.6 version forward.

            Assignee:
            Unassigned Unassigned
            Reporter:
            m.cuk Matjaž ?uk
            Votes:
            0 Vote for this issue
            Watchers:
            6 Start watching this issue

              Created:
              Updated:
              Resolved: