-
Type:
Bug
-
Resolution: Duplicate
-
Priority:
Major - P3
-
None
-
Affects Version/s: 3.0.2
-
Component/s: Replication
-
None
-
ALL
-
None
-
None
-
None
-
None
-
None
-
None
-
None
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.
- duplicates
-
-
- Closed
-