[SERVER-22611] ChunkManager refresh can occasionally cause a full reload Created: 15/Feb/16  Updated: 08/May/18  Resolved: 12/Mar/17

Status: Closed
Project: Core Server
Component/s: Sharding
Affects Version/s: 3.2.12, 3.4.2
Fix Version/s: 3.4.4, 3.5.5

Type: Bug Priority: Major - P3
Reporter: Yoni Douek Assignee: Kaloian Manassiev
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: HTML File cfg1     HTML File cfg2     HTML File cfg3     HTML File diff     HTML File donor     HTML File donor-metrics1     HTML File donor-metrics2     File double_reload.js     HTML File mongos     HTML File mongos2     File test.js     HTML File to     HTML File to-metrics1     HTML File to-metrics2    
Issue Links:
Backports
Depends
is depended on by SERVER-20854 Don't refresh database and collection... Closed
Duplicate
is duplicated by SERVER-23315 Encapsulate _configOpTime Closed
is duplicated by SERVER-26755 Collection chunk loading is aborted e... Closed
is duplicated by SERVER-22909 Unify ChunkManager, MetadataLoader, C... Closed
is duplicated by SERVER-23965 DBConfig::getChunkManager should not ... Closed
is duplicated by SERVER-28044 Improve / Refactor ConfigDiffTracker ... Closed
is duplicated by SERVER-28363 When shard empty collection I have no... Closed
Related
related to SERVER-32459 mongos incorrectly assumed collection... Closed
related to SERVER-7926 Map Reduce with sharded output can ap... Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Requested:
v3.4
Sprint: Sharding 11 (03/11/16), Sharding 12 (04/01/16), Sharding 13 (04/22/16), Sharding 14 (05/13/16), Sharding 15 (06/03/16), Sharding 2017-03-27
Participants:
Case:
Linked BF Score: 0

 Description   

And can block other operations since it will take the DBConfig mutex. This happens when the chunk differ got an unexpected result from the config server (see here). This can potentially occur when yield occurs while querying the config server.

Original Title: Chunk migration freezes all mongos servers for >60 seconds

Original description:

Time for bug #7.

We are moving chunks of a collection in which the avg document size is pretty big, 6K. After every other chunk, we see this behavior:

1. The source shard (from which the chunk is transferred) - shows this:

2016-02-15T06:53:06.556+0000 I SHARDING [conn102845] moveChunk data transfer progress: { active: true, ns: "mydomain.Sessions", from: "rsmydomain/10.35.151.119:27017,in.db1m1.mydomain.com:27017,in.db1m2.mydomain.com:27017", min: { a: ObjectId('5334b6f2645cff3b5097f4f9'), _id: ObjectId('55f705bca21c0f117ccc613c') }, max: { a: ObjectId('5334b6f2645cff3b5097f4f9'), _id: ObjectId('55fb9231584ad132f5207391') }, shardKeyPattern: { a: 1.0, _id: 1.0 }, state: "ready", counts: { cloned: 0, clonedBytes: 0, catchup: 0, steady: 0 }, ok: 1.0 } my mem used: 0
2016-02-15T06:53:06.559+0000 I SHARDING [conn102845] moveChunk data transfer progress: { active: true, ns: "mydomain.Sessions", from: "rsmydomain/10.35.151.119:27017,in.db1m1.mydomain.com:27017,in.db1m2.mydomain.com:27017", min: { a: ObjectId('5334b6f2645cff3b5097f4f9'), _id: ObjectId('55f705bca21c0f117ccc613c') }, max: { a: ObjectId('5334b6f2645cff3b5097f4f9'), _id: ObjectId('55fb9231584ad132f5207391') }, shardKeyPattern: { a: 1.0, _id: 1.0 }, state: "clone", counts: { cloned: 0, clonedBytes: 0, catchup: 0, steady: 0 }, ok: 1.0 } my mem used: 0
2016-02-15T06:53:06.563+0000 I SHARDING [conn102845] moveChunk data transfer progress: { active: true, ns: "mydomain.Sessions", from: "rsmydomain/10.35.151.119:27017,in.db1m1.mydomain.com:27017,in.db1m2.mydomain.com:27017", min: { a: ObjectId('5334b6f2645cff3b5097f4f9'), _id: ObjectId('55f705bca21c0f117ccc613c') }, max: { a: ObjectId('5334b6f2645cff3b5097f4f9'), _id: ObjectId('55fb9231584ad132f5207391') }, shardKeyPattern: { a: 1.0, _id: 1.0 }, state: "steady", counts: { cloned: 0, clonedBytes: 0, catchup: 0, steady: 0 }, ok: 1.0 } my mem used: 0
2016-02-15T06:53:06.563+0000 I SHARDING [conn102845] About to check if it is safe to enter critical section
2016-02-15T06:53:06.563+0000 I SHARDING [conn102845] About to enter migrate critical section
2016-02-15T06:53:06.565+0000 I SHARDING [conn626] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.565+0000 I SHARDING [conn24854] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.566+0000 I SHARDING [conn1399] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.567+0000 I SHARDING [conn297] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.567+0000 I SHARDING [conn23645] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.567+0000 I SHARDING [conn24637] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.650+0000 I SHARDING [conn102845] moveChunk setting version to: 6452|0||563ba74d869758a4542b9075
2016-02-15T06:53:06.650+0000 I SHARDING [conn1682] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.650+0000 I SHARDING [conn731] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.650+0000 I SHARDING [conn886] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.651+0000 I SHARDING [conn19421] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.651+0000 I SHARDING [conn1207] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.651+0000 I SHARDING [conn23153] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.651+0000 I SHARDING [conn24688] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.651+0000 I SHARDING [conn1258] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.651+0000 I SHARDING [conn24257] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.651+0000 I SHARDING [conn25297] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.651+0000 I SHARDING [conn413] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.651+0000 I SHARDING [conn549] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.651+0000 I SHARDING [conn23108] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.651+0000 I SHARDING [conn1416] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.651+0000 I SHARDING [conn24825] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.651+0000 I SHARDING [conn690] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.651+0000 I SHARDING [conn24280] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.651+0000 I SHARDING [conn778] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.651+0000 I SHARDING [conn24187] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.651+0000 I SHARDING [conn19456] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.652+0000 I SHARDING [conn22996] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.652+0000 I SHARDING [conn1052] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.652+0000 I SHARDING [conn24951] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.652+0000 I SHARDING [conn23221] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.652+0000 I SHARDING [conn39] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.652+0000 I SHARDING [conn24798] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.652+0000 I SHARDING [conn24267] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.652+0000 I SHARDING [conn500] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.652+0000 I SHARDING [conn25435] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.652+0000 I SHARDING [conn23410] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.652+0000 I SHARDING [conn1649] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.652+0000 I SHARDING [conn24004] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.652+0000 I SHARDING [conn22921] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.652+0000 I SHARDING [conn38050] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.652+0000 I SHARDING [conn23955] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.652+0000 I SHARDING [conn38048] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.652+0000 I SHARDING [conn1513] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.652+0000 I SHARDING [conn25348] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.652+0000 I SHARDING [conn1163] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.652+0000 I SHARDING [conn24304] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.653+0000 I SHARDING [conn25002] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.653+0000 I SHARDING [conn23489] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.653+0000 I SHARDING [conn141] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.653+0000 I SHARDING [conn720] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.653+0000 I SHARDING [conn196] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.654+0000 I SHARDING [conn23299] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.658+0000 I SHARDING [conn23908] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.659+0000 I SHARDING [conn23756] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.668+0000 I SHARDING [conn23617] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.668+0000 I SHARDING [conn24587] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.670+0000 I SHARDING [conn19435] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.672+0000 I SHARDING [conn23242] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.673+0000 I SHARDING [conn23442] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.677+0000 I SHARDING [conn23236] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.678+0000 I SHARDING [conn23358] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.680+0000 I SHARDING [conn868] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.684+0000 I SHARDING [conn25340] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.687+0000 I SHARDING [conn23963] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.689+0000 I SHARDING [conn1301] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.690+0000 I SHARDING [conn38131] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.694+0000 I SHARDING [conn19460] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.700+0000 I SHARDING [conn25085] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.701+0000 I SHARDING [conn144] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.701+0000 I SHARDING [conn23226] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.705+0000 I SHARDING [conn467] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.705+0000 I SHARDING [conn38121] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.707+0000 I SHARDING [conn24433] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.708+0000 I SHARDING [conn29531] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.708+0000 I SHARDING [conn787] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.709+0000 I NETWORK  [conn102384] end connection 10.40.7.177:48208 (5263 connections now open)
2016-02-15T06:53:06.709+0000 I NETWORK  [conn105280] end connection 10.40.7.177:48268 (5263 connections now open)
2016-02-15T06:53:06.709+0000 I SHARDING [conn102385] waiting till out of critical section
2016-02-15T06:53:06.709+0000 I SHARDING [conn102385] Waiting for 10 seconds for the migration critical section to end
2016-02-15T06:53:06.711+0000 I SHARDING [conn23961] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.711+0000 I SHARDING [conn24775] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.711+0000 I WRITE    [conn38653] write request to old shard version 6451|6266||563ba74d869758a4542b9075 waiting for migration commit
2016-02-15T06:53:06.711+0000 I SHARDING [conn38653] Waiting for 10 seconds for the migration critical section to end
2016-02-15T06:53:06.711+0000 I WRITE    [conn48728] write request to old shard version 6451|6269||563ba74d869758a4542b9075 waiting for migration commit
2016-02-15T06:53:06.711+0000 I WRITE    [conn72829] write request to old shard version 6451|6269||563ba74d869758a4542b9075 waiting for migration commit
2016-02-15T06:53:06.711+0000 I SHARDING [conn48728] Waiting for 10 seconds for the migration critical section to end
2016-02-15T06:53:06.711+0000 I SHARDING [conn72829] Waiting for 10 seconds for the migration critical section to end
2016-02-15T06:53:06.712+0000 I NETWORK  [conn105127] end connection 10.229.6.198:43840 (5261 connections now open)
2016-02-15T06:53:06.712+0000 I NETWORK  [conn105340] end connection 10.37.137.232:59474 (5260 connections now open)
2016-02-15T06:53:06.712+0000 I NETWORK  [conn105392] end connection 10.40.7.177:48282 (5259 connections now open)
2016-02-15T06:53:06.712+0000 I NETWORK  [conn105344] end connection 10.37.137.232:59484 (5259 connections now open)
2016-02-15T06:53:06.712+0000 I SHARDING [conn102875] waiting till out of critical section
2016-02-15T06:53:06.712+0000 I SHARDING [conn102875] Waiting for 10 seconds for the migration critical section to end
2016-02-15T06:53:06.712+0000 I NETWORK  [conn105341] end connection 10.37.137.232:59475 (5258 connections now open)
2016-02-15T06:53:06.713+0000 I SHARDING [conn399] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.713+0000 I SHARDING [conn24449] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.714+0000 I NETWORK  [conn105339] end connection 10.37.137.232:59472 (5256 connections now open)
2016-02-15T06:53:06.714+0000 I NETWORK  [conn105342] end connection 10.37.137.232:59476 (5255 connections now open)
2016-02-15T06:53:06.714+0000 I NETWORK  [conn105343] end connection 10.37.137.232:59482 (5255 connections now open)
2016-02-15T06:53:06.714+0000 I NETWORK  [conn84162] end connection 10.229.6.198:43482 (5254 connections now open)
2016-02-15T06:53:06.717+0000 I SHARDING [conn1005] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.723+0000 I SHARDING [conn23890] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.729+0000 I SHARDING [conn23314] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.737+0000 I SHARDING [conn23246] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.739+0000 I SHARDING [conn23684] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.744+0000 I SHARDING [conn102845] moveChunk migrate commit accepted by TO-shard: { active: false, ns: "mydomain.Sessions", from: "rsmydomain/10.35.151.119:27017,in.db1m1.mydomain.com:27017,in.db1m2.mydomain.com:27017", min: { a: ObjectId('5334b6f2645cff3b5097f4f9'), _id: ObjectId('55f705bca21c0f117ccc613c') }, max: { a: ObjectId('5334b6f2645cff3b5097f4f9'), _id: ObjectId('55fb9231584ad132f5207391') }, shardKeyPattern: { a: 1.0, _id: 1.0 }, state: "done", counts: { cloned: 0, clonedBytes: 0, catchup: 0, steady: 0 }, ok: 1.0 }
2016-02-15T06:53:06.744+0000 I SHARDING [conn102845] moveChunk updating self version to: 6452|1||563ba74d869758a4542b9075 through { a: ObjectId('5334b6f2645cff3b5097f4f9'), _id: ObjectId('55fb9231584ad132f5207391') } -> { a: ObjectId('5334b6f2645cff3b5097f4f9'), _id: ObjectId('56020ab2584ad15a7d97cb59') } for collection 'mydomain.Sessions'
2016-02-15T06:53:06.750+0000 I SHARDING [conn23929] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.756+0000 I SHARDING [conn23365] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.761+0000 I SHARDING [conn1420] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.765+0000 I SHARDING [conn1255] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.781+0000 I SHARDING [conn23810] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.796+0000 I SHARDING [conn22987] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.799+0000 I SHARDING [conn23350] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.803+0000 I SHARDING [conn1302] Waiting for 30 seconds for the migration critical section to end
2016-02-15T06:53:06.823+0000 I SHARDING [conn102845] about to log metadata event into changelog: { _id: "ip-10-41-58-141-2016-02-15T06:53:06.823+0000-56c175d207f175cfb9224557", server: "ip-10-41-58-141", clientAddr: "10.40.7.177:48224", time: new Date(1455519186823), what: "moveChunk.commit", ns: "mydomain.Sessions", details: { min: { a: ObjectId('5334b6f2645cff3b5097f4f9'), _id: ObjectId('55f705bca21c0f117ccc613c') }, max: { a: ObjectId('5334b6f2645cff3b5097f4f9'), _id: ObjectId('55fb9231584ad132f5207391') }, from: "shmydomain1", to: "shmydomain3", cloned: 0, clonedBytes: 0, catchup: 0, steady: 0 } }
2016-02-15T06:53:06.863+0000 I SHARDING [conn102845] MigrateFromStatus::done About to acquire global lock to exit critical section
2016-02-15T06:53:06.863+0000 I SHARDING [conn102845] forking for cleanup of chunk data
2016-02-15T06:53:06.865+0000 I SHARDING [conn102845] waiting for open cursors before removing range [{ a: ObjectId('5334b6f2645cff3b5097f4f9'), _id: ObjectId('55f705bca21c0f117ccc613c') }, { a: ObjectId('5334b6f2645cff3b5097f4f9'), _id: ObjectId('55fb9231584ad132f5207391') }) in mydomain.Sessions, cursor ids: [326986289469, 327861050987, 329266703753, 329633996806, 330038618700, 330161093014, 330597544814]
2016-02-15T06:53:06.865+0000 I SHARDING [conn102845] about to log metadata event into changelog: { _id: "ip-10-41-58-141-2016-02-15T06:53:06.865+0000-56c175d207f175cfb9224558", server: "ip-10-41-58-141", clientAddr: "10.40.7.177:48224", time: new Date(1455519186865), what: "moveChunk.from", ns: "mydomain.Sessions", details: { min: { a: ObjectId('5334b6f2645cff3b5097f4f9'), _id: ObjectId('55f705bca21c0f117ccc613c') }, max: { a: ObjectId('5334b6f2645cff3b5097f4f9'), _id: ObjectId('55fb9231584ad132f5207391') }, step 1 of 6: 0, step 2 of 6: 310, step 3 of 6: 15, step 4 of 6: 8, step 5 of 6: 299, step 6 of 6: 1, to: "shmydomain3", from: "shmydomain1", note: "success" } }
2016-02-15T06:53:06.993+0000 I SHARDING [conn102845] distributed lock 'mydomain.Sessions/ip-10-41-58-141:27017:1455127062:862901621' unlocked. 
2016-02-15T06:53:07.779+0000 I SHARDING [conn1302] remotely refreshing metadata for mydomain.Sessions with requested shard version 6452|1||563ba74d869758a4542b9075 based on current shard version 6452|0||563ba74d869758a4542b9075, current metadata version is 6452|0||563ba74d869758a4542b9075
2016-02-15T06:53:07.779+0000 I SHARDING [conn23450] remotely refreshing metadata for mydomain.Sessions with requested shard version 6452|1||563ba74d869758a4542b9075 based on current shard version 6452|0||563ba74d869758a4542b9075, current metadata version is 6452|0||563ba74d869758a4542b9075
2016-02-15T06:53:07.779+0000 I SHARDING [conn1311] remotely refreshing metadata for mydomain.Sessions with requested shard version 6452|1||563ba74d869758a4542b9075 based on current shard version 6452|0||563ba74d869758a4542b9075, current metadata version is 6452|0||563ba74d869758a4542b9075
2016-02-15T06:53:07.780+0000 I SHARDING [conn102845] received moveChunk request: { moveChunk: "mydomain.CrashIssueReports", from: "rsmydomain/10.35.151.119:27017,in.db1m1.mydomain.com:27017,in.db1m2.mydomain.com:27017", to: "rsmydomain2/in.db2m1.mydomain.com:27017,in.db2m2.mydomain.com:27017", fromShard: "shmydomain1", toShard: "shmydomain2", min: { p: 2, as: ObjectId('5660b4295e27753f5c614e0a'), d: new Date(1455408000000) }, max: { p: 3, as: ObjectId('569c9324294e2113fe1b23e1'), d: new Date(1455408000000) }, maxChunkSizeBytes: 67108864, configdb: "in.dbcfg1.mydomain.com:27019,in.dbcfg2.mydomain.com:27019,in.dbcfg3.mydomain.com:27019", secondaryThrottle: true, waitForDelete: false, maxTimeMS: 0, shardVersion: [ Timestamp 3000|1, ObjectId('56c0a812f6dbf7ace67b5e89') ], epoch: ObjectId('56c0a812f6dbf7ace67b5e89') }

2. Then, all mongos servers (we have 3) - show this - for every single collection:

2016-02-15T06:53:08.183+0000 I SHARDING [conn265475] ChunkManager: time to load chunks for mydomain.Col1: 1ms sequenceNumber: 15808 version: 26|7||54bd7ee267066c5f3e307c11 mydomain: (empty)
2016-02-15T06:53:08.187+0000 I SHARDING [conn265475] ChunkManager: time to load chunks for mydomain.Col2: 3ms sequenceNumber: 15809 version: 86|1||54c775a4509aea9affefdbe4 mydomain: (empty)
2016-02-15T06:53:08.188+0000 I SHARDING [conn265475] ChunkManager: time to load chunks for mydomain.Col3: 1ms sequenceNumber: 15810 version: 18|1||54be162bf5d6feabbc856429 mydomain: (empty)
2016-02-15T06:53:08.189+0000 I SHARDING [conn265475] ChunkManager: time to load chunks for mydomain.Col4: 0ms sequenceNumber: 15811 version: 43|1||54be7cb0f5d6feabbc856440 mydomain: (empty)

3. Then, all mongos don't respond for several seconds, sometimes more than 60 - rendering our database dead for that time.

Happens mostly on the large-document collection but not only.
mmapv1. 3 config servers. each shard: primary+secondary+arbiter.

To help you guys, we measured which components get locked, mongos vs mongods, and its only the mongos servers.

If it helps, we've also seen this "based on (empty)" behavior when a primary is demoted, and then comes back very fast after being demoted. When that happens - the only thing we found out that works is that we turn off all mongos and config servers, except one of each, and run flushRouterConfig - but that's probably another bug you have.



 Comments   
Comment by Ramon Fernandez Marina [ 24/Aug/17 ]

Author:

{'username': u'kaloianm', 'name': u'Kaloian Manassiev', 'email': u'kaloian.manassiev@mongodb.com'}

Message:SERVER-22611 Sharding catalog cache refactor
Branch:master
https://github.com/mongodb/mongo/commit/ae2518adace4ba7ed6a16eba6943bff6ea4ade10

Comment by Ramon Fernandez Marina [ 24/Aug/17 ]

Author:

{'username': u'kaloianm', 'name': u'Kaloian Manassiev', 'email': u'kaloian.manassiev@mongodb.com'}

Message:Revert "SERVER-22611 Sharding catalog cache refactor"

This reverts commit ae2518adace4ba7ed6a16eba6943bff6ea4ade10.
Branch:master
https://github.com/mongodb/mongo/commit/8125c55a251805899552d0af4776930216223703

Comment by Githook User [ 12/Apr/17 ]

Author:

{u'username': u'kaloianm', u'name': u'Kaloian Manassiev', u'email': u'kaloian.manassiev@mongodb.com'}

Message: SERVER-22611 Get rid of ChunkDiff and add more CatalogCache tests

This change gets rid of the "chunk differ" which was previously shared
between mongos and mongod. Instead its relatively simple logic has been
moved inside the CatalogCache.

(cherry picked from commit b1fd308ad04a5a6719fe72bcd23b10f1b8266097)
Branch: v3.4
https://github.com/mongodb/mongo/commit/9e3a63f9cf9ef3e64dd991824eb87dcf170d3d31

Comment by Githook User [ 12/Apr/17 ]

Author:

{u'username': u'kaloianm', u'name': u'Kaloian Manassiev', u'email': u'kaloian.manassiev@mongodb.com'}

Message: SERVER-22611 Make the catalog cache unit-tests go through the CatalogCache

Instead of calling its internal logic directly.

(cherry picked from commit 84d94351aa308caf2c684b0fe5fbb7f942c75bd0)
Branch: v3.4
https://github.com/mongodb/mongo/commit/892058e1cd3ae4744e8d13a589081330ea09f486

Comment by Githook User [ 12/Apr/17 ]

Author:

{u'username': u'kaloianm', u'name': u'Kaloian Manassiev', u'email': u'kaloian.manassiev@mongodb.com'}

Message: SERVER-22611 Make CatalogCache::onStaleConfigError clear the passed cache entry

(cherry picked from commit 758bc2adcf2c83363d0fdfdef0cbd1cf3c800e62)
Branch: v3.4
https://github.com/mongodb/mongo/commit/b868de40b3a60233aff3370323b2325deafc0e8d

Comment by Githook User [ 11/Apr/17 ]

Author:

{u'username': u'kaloianm', u'name': u'Kaloian Manassiev', u'email': u'kaloian.manassiev@mongodb.com'}

Message: SERVER-22611 Remove accidentally added temporary files and do cleanup
Branch: master
https://github.com/mongodb/mongo/commit/91196a0bed9277f6b170fdd0c1c79ed15b9295f5

Comment by Githook User [ 11/Apr/17 ]

Author:

{u'username': u'kaloianm', u'name': u'Kaloian Manassiev', u'email': u'kaloian.manassiev@mongodb.com'}

Message: SERVER-22611 Sharding catalog cache refactor

(cherry picked from commit 39e06c9ef8c797ad626956b564ac9ebe295cbaf3)
(cherry picked from commit d595a0fc8150411fd6541d06b08de9bee0039baa)
Branch: v3.4
https://github.com/mongodb/mongo/commit/0f715bb978334314a0304b3d9aa629d297f2b313

Comment by Clive Hill [ 06/Apr/17 ]

Understood - thanks Ramon

Comment by Ramon Fernandez Marina [ 06/Apr/17 ]

The current schedule for 3.4.4 is end of April, but there's no guarantee this bug will be fixed in 3.4.4. Please also note that this is not a commitment on our part and schedules are subject to change.

Regards,
Ramón.

Comment by Clive Hill [ 06/Apr/17 ]

Thanks Ramon, I misread the ticket. I see now it says affects 3.4.2; I thought it was fixed in that version.

Are you able to give estimate as to when 3.4.4 will be available?

(Previous releases seem to be around 4 to 6 weeks, hence as 3.4.3 was available on 27th March, do you think by mid-May is realistic?)

Comment by Ramon Fernandez Marina [ 06/Apr/17 ]

EvilChill, this issue is scheduled for inclusion in a future 3.4 release, but is unfortunately not available in 3.4.3.

If you're watching this ticket, you'll see the "3.4 Required" fixVersion change to 3.4.X (where X >= 4) when the fix lands in the v3.4 branch.

Regards,
Ramón.

Comment by Clive Hill [ 06/Apr/17 ]

I see this issue with MonoDb 3.4.3 with Java driver 3.4.2.

Should this be fixed now?

Comment by Githook User [ 04/Apr/17 ]

Author:

{u'username': u'kaloianm', u'name': u'Kaloian Manassiev', u'email': u'kaloian.manassiev@mongodb.com'}

Message: SERVER-22611 Get rid of ChunkDiff and add more CatalogCache tests

This change gets rid of the "chunk differ" which was previously shared
between mongos and mongod. Instead its relatively simple logic has been
moved inside the CatalogCache.
Branch: master
https://github.com/mongodb/mongo/commit/b1fd308ad04a5a6719fe72bcd23b10f1b8266097

Comment by Githook User [ 31/Mar/17 ]

Author:

{u'username': u'kaloianm', u'name': u'Kaloian Manassiev', u'email': u'kaloian.manassiev@mongodb.com'}

Message: SERVER-22611 Make CatalogCache::onStaleConfigError clear the passed cache entry
Branch: master
https://github.com/mongodb/mongo/commit/758bc2adcf2c83363d0fdfdef0cbd1cf3c800e62

Comment by Githook User [ 31/Mar/17 ]

Author:

{u'username': u'kaloianm', u'name': u'Kaloian Manassiev', u'email': u'kaloian.manassiev@mongodb.com'}

Message: SERVER-22611 Make the catalog cache unit-tests go through the CatalogCache

Instead of calling its internal logic directly.
Branch: master
https://github.com/mongodb/mongo/commit/84d94351aa308caf2c684b0fe5fbb7f942c75bd0

Comment by Githook User [ 20/Mar/17 ]

Author:

{u'username': u'kaloianm', u'name': u'Kaloian Manassiev', u'email': u'kaloian.manassiev@mongodb.com'}

Message: SERVER-22611 Skip invalidated collections in CatalogCache::onStaleConfigError
Branch: master
https://github.com/mongodb/mongo/commit/d595a0fc8150411fd6541d06b08de9bee0039baa

Comment by Githook User [ 12/Mar/17 ]

Author:

{u'username': u'kaloianm', u'name': u'Kaloian Manassiev', u'email': u'kaloian.manassiev@mongodb.com'}

Message: SERVER-22611 Sharding catalog cache refactor
Branch: master
https://github.com/mongodb/mongo/commit/39e06c9ef8c797ad626956b564ac9ebe295cbaf3

Comment by Andy Schwerin [ 21/Apr/16 ]

The design of the code that updates the ChunkManager (routing table) appears to heavily rely on the assumption that this scenario will be rare in order to keep the code simple and correct. It's going to take a substantial rewrite of that code to remove that assumption, which means higher risk of introducing undetected correctness errors.

I'm looking into design alternatives, but it may not be advisable to back port a change of this magnitude to the 3.2 release branch. I'll also check around to see if other users are experiencing similar problems.

In any event, I'll keep this ticket up to date.

Comment by Yoni Douek [ 19/Apr/16 ]

Any news?

Comment by Randolph Tan [ 04/Apr/16 ]

Update: I was able to successfully write a repro script that demonstrates the bug where a full reload more than once for a single request.

Explanation of how mongos reads the full config.chunks for a collection more than once:

1. New ChunkManager gets instantiated, with _version initialized from config.collections (ref)
2. ChunkManager::loadExistingRanges calls ChunkManager::_load
3. ChunkManager::_load calls ConfigDiffTracker::calculateConfigDiff
4. ConfigDiffTracker::calculateConfigDiff gets overlapping ranges because of yielding and returns -1 (ref)
5. ChunkManager::_version is set to (0, 0)|0 (ref)
6. Since ConfigDiffTracker::calculateConfigDiff applied some of the diff, ChunkManager::_load will return with allInonsistent == false. (ref)
7. This will go back to ChunkManager::loadExistingRanges and call _load again.
8. This time, _version now has an epoch of zero instead of the collection epoch. This will cause ConfigDiffTracker::calculateConfigDiff to return -1 without applying any diff because of epoch mismatch (ref)
9. And results in ChunkManager::_load returning true because no diffs where applied (ref)
10. This will result with a CollectionInfo with no ChunkManager (ref).

Now that the collection info has a zero shard version, mongos will send a zero version when it talks to the shard. The shard will reject it and returns the desired shard version. Since the epoch will never match, mongos will perform another full reload again (and risk hitting the same bug again).

Conditions to happen:

  • mongos is doing a reload.
  • the shard version gets bumped while mongos is querying config.chunks.
  • the config.chunks query yielded after putting the chunk that's about to get it's version bumped into the result set

Attached double_reload.js demonstrating this bug.

Comment by Randolph Tan [ 31/Mar/16 ]

I would like to share some updates. I was trying to write a more focused test script and was not able to successfully reproduced the problem. After digging more, I found out that my initial investigation was incorrect. The original test script attached to this ticket did not actually reproduce the problem, it only exhibited symptoms similar but was never actually doing a full reload because of ChunkManager refresh.

I also realize that the current code already handles the case when the chunk differ can get overlapping chunks because of yielding:

  • ChunkManager retries the reload up to 3 times and discards the new ChunkManager if it fails (ref).
  • MetadataLoader discards the new instance if it has overlapping chunks (ref).

We are going to re-examine this ticket again and find the real cause.

Comment by Andy Schwerin [ 26/Mar/16 ]

We know the sequence of events that cause the problem, as Randolph
described. While legal, it's somewhat surprising that this sequence of
events would happen with any regularity. We're going to spend some time
figuring out why it's happening more than we expect, as it might indicate a
performance bug elsewhere in the system. We'll also need to develop a patch
to mongos to react more robustly to this sequence of events. That's going
to take a little time. We'll keep this ticket up to date.

Comment by Yoni Douek [ 26/Mar/16 ]

Any news?

Comment by Randolph Tan [ 17/Mar/16 ]

Hi,

It looks like you have the right indexes.

Thanks!

Comment by Yoni Douek [ 17/Mar/16 ]

	"cursor" : {
		"id" : NumberLong(0),
		"ns" : "config.$cmd.listIndexes.chunks",
		"firstBatch" : [
			{
				"v" : 1,
				"key" : {
					"_id" : 1
				},
				"name" : "_id_",
				"ns" : "config.chunks"
			},
			{
				"v" : 1,
				"unique" : true,
				"key" : {
					"ns" : 1,
					"min" : 1
				},
				"name" : "ns_1_min_1",
				"ns" : "config.chunks"
			},
			{
				"v" : 1,
				"unique" : true,
				"key" : {
					"ns" : 1,
					"shard" : 1,
					"min" : 1
				},
				"name" : "ns_1_shard_1_min_1",
				"ns" : "config.chunks"
			},
			{
				"v" : 1,
				"unique" : true,
				"key" : {
					"ns" : 1,
					"lastmod" : 1
				},
				"name" : "ns_1_lastmod_1",
				"ns" : "config.chunks"
			}
		]
	},
	"ok" : 1

Comment by Randolph Tan [ 16/Mar/16 ]

Hi Yoni,

Is it possible to post the list of indexes in config.chunks collection? This can be performed by connecting to mongos using the shell and issuing this series of commands:

use config
db.runCommand({ listIndexes: 'chunks' });

Thanks!

Comment by Randolph Tan [ 16/Mar/16 ]

More detailed on the explanation of this bug:

1. Mongos gets a stale config exception and decides that it needs to update it's internal view of the routing table.
2. Mongos sends a query to the config server to look for chunks greater than shard version V 0 sorted by ascending version.
3. Current config server has up to version V 2.
4. Config server process query and see chunk C 0 with version V 0 and adds it to the query results.
5. Config query yields.
6. A recent migration is about to commit and bumps the version of chunk C 0 to version V 3.
7. Config query comes back from yield and continues on adding chunks with Version V 1, V 2 and V 3.
8. Mongos gets the query result with C 0 appearing twice, one with version V 0 and another with version version V 3.
9. Mongos detects that there is overlapping chunks after applying the diff it got from the config server. Decides that the routing table is corrupted and clears everything on this particular database, which in effect, will result to the mongos reloading all collections of the current database from scratch.

We are currently discussing options for fixing this issue and I'll update the ticket again once we decided what to do.

Comment by Yoni Douek [ 16/Mar/16 ]

Great.

mmapv1 for the entire cluster, including everything. I mentioned this in the bug description.

Comment by Randolph Tan [ 15/Mar/16 ]

Attached repro script test.js + diff file for failpoint.

Comment by Randolph Tan [ 15/Mar/16 ]

Hi,

I was able to reproduce the issue and I have also confirmed that this is also an issue in v3.0. I am trying to figure out why it happens more often on your v3.2 setup. Were you using the WiredTiger storage engine on the config server for both your v3.0 and v3.2 cluster?

Thanks!

Comment by Yoni Douek [ 15/Mar/16 ]

If monogodump is still necessary, let me know, but we'll need to find a private way to share it.

Comment by Yoni Douek [ 15/Mar/16 ]

Thanks. cfg x 3 attached. They are mirrored. There was a single additional mongos (2 total), attached as well.

We are 99% confident this bug started happening in 3.2.x and not in 3.0.x.

Comment by Randolph Tan [ 14/Mar/16 ]

Hi,

I noticed in the logs where both mongos and the shards try to load the full chunk metadata for mydomain.Sessions because some mongos sent find request with a zero shard version. And the load in the shard took about 6 seconds, and it roughly coincides with the hang period you mentioned. I am still trying to figure out how this can happen, but for the mean time, is it possible to upload the logs for the 3 config servers and the dump (using mongodump)? And if there are not a lot of mongos, is it possible to upload the logs for all mongos as well?

Thanks!

Comment by Yoni Douek [ 13/Mar/16 ]

Logs attached. To clarify: it doesn't happen only when the primary is demoted, it happens all the time when balancer is active. Demotion its a different bug, please read above.

You can see the "based on empty" in the mongos log attached.

All running 3.2.4.

mongos froze for 6-11 seconds, in the following times:
2016-03-13 09:17:44,184 - 11.784903 seconds
2016-03-13 09:17:51,231 - 6.045891 seconds
2016-03-13 09:17:58,772 - 6.540251 seconds
2016-03-13 09:18:16,750 - 11.949768 seconds
2016-03-13 09:18:29,447 - 5.699333 seconds
2016-03-13 09:18:36,503 - 6.054188 seconds
2016-03-13 09:18:49,195 - 11.690872 seconds

when it happens its usually such a "cluster" of freeze times.

Files:
mongos - mongos log
donor- donor primary mongod log
to - "to shard" primary mongod log
donor-metrics1+2 - donor primary mongod diagnostic.data
to-metrics1+2 - "to shard" primary mongod diagnostic.data

You should have everything you need.

Comment by Randolph Tan [ 10/Mar/16 ]

Hi,

Is it possible to upload one of the logs (not just snippets) for the mongos and the primary of the shard that got demoted when this happened?

Thanks!

Comment by Yoni Douek [ 10/Mar/16 ]

Looks like it still happens in 3.2.4, but maybe for shorter periods (so far we got it to freeze "only" for 6 seconds).

How can we help you help us ? : )

Reminder: our setup is 3 shards, each one P+S+A, 3 config servers, 2 mongos servers. mongos are the component that freeze, so plz be specific on the diagnostic data that you need.

Comment by Ramon Fernandez Marina [ 09/Mar/16 ]

Looks like this behavior is still present in 3.2.3, so we'll continue to investigate.

Comment by Kaloian Manassiev [ 19/Feb/16 ]

Hi yoni@appsee.com,

Thank you for the detailed report and apologies for problems this issue is causing you.

From the symptoms that you are experiencing (only mongos gets stuck) and also from the fact that you have seen this behaviour when the primary steps down I have strong suspicion that you might be seeing a manifestation of SERVER-22114, which causes the mongos instances to unnecessarily reload chunk metadata multiple times and then throw it away.

The fix for this bug is available in v3.2.3. If you haven't already, would it be possible that you upgrade to this version and see whether the problem goes away?

Best regards,
-Kal.

Comment by Yoni Douek [ 18/Feb/16 ]

The bug described in the last sentence happened also in 3.0.2.

Comment by Yoni Douek [ 18/Feb/16 ]

3.2, mirrored. Any workaround will be appreciated, we currently can't move any chunks.

Comment by Ramon Fernandez Marina [ 15/Feb/16 ]

yonido, can you please clarify which version(s) of MongoDB is this cluster running? If it's 3.2, are your config servers using a mirrored configuration or a replica set?

Generated at Thu Feb 08 04:00:54 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.