[SERVER-18325] MongoDb 3.0.2 background index creation still blocking Created: 05/May/15  Updated: 05/May/15  Resolved: 05/May/15

Status: Closed
Project: Core Server
Component/s: Replication
Affects Version/s: 3.0.2
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Matjaž ?uk Assignee: Unassigned
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
duplicates SERVER-18190 Secondary reads may block replication Closed
Operating System: ALL
Participants:

 Description   

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.



 Comments   
Comment by Eric Milkie [ 05/May/15 ]

Thanks for filing this! We're already drawing up a fix for this issue.
Please see SERVER-18190 for updates; it's currently scheduled to be fixed in version 3.0.4.

Generated at Thu Feb 08 03:47:18 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.