[SERVER-7260] Balancer lock is not relinquished Created: 04/Oct/12  Updated: 22/Dec/14  Resolved: 03/Jul/14

Status: Closed
Project: Core Server
Component/s: Sharding
Affects Version/s: 2.0.7, 2.2.0
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Ben Becker Assignee: Randolph Tan
Resolution: Done Votes: 4
Labels: balancer, migration
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Related
related to SERVER-14996 Locks not released if config server g... Closed
Operating System: ALL
Participants:

 Description   

Under certain conditions, the balancer lock may never be relinquished. One case appeasr to have occured when the balancer state was disabled during a chunk migration:

mongos> db.locks.findOne({_id:"balancer"});
{
        "_id" : "balancer",
        "process" : "r5.10gen.cc:27017:1349297686:1804289383",
        "state" : 2,
        "ts" : ObjectId("506cae1f13bf56db8d1b0856"),
        "when" : ISODate("2012-10-03T21:29:03.359Z"),
        "who" : "r5.10gen.cc:27017:1349297686:1804289383:Balancer:846930886",
        "why" : "doing balance round"
}

mongos> db.changelog.find().sort({$natural:-1}).limit(10).skip(10).pretty()
{
        "_id" : "r5.10gen.cc-2012-10-03T21:30:05-17",
        "server" : "r5.10gen.cc",
        "clientAddr" : "127.0.0.1:57957",
        "time" : ISODate("2012-10-03T21:30:05.136Z"),
        "what" : "moveChunk.from",
        "ns" : "sh.test",
        "details" : {
                "min" : {
                        "id" : "16540452295883480447516388304186410329865247257024"
                },
                "max" : {
                        "id" : "22754752024366413683521379069776306796548182491720"
                },
                "step1 of 6" : 0,
                "step2 of 6" : 305,
                "step3 of 6" : 378,
                "step4 of 6" : 32007,
                "step5 of 6" : 4542,
                "step6 of 6" : 24280
        }
}

Note the above output was taken 15 hours after the last moveChunk was logged to the config server. It's unclear if the mongos process holding the lock was killed before it had a chance to release the lock.

The net effect is that sh.isBalancerRunning() never returns false, even if the balancer is no longer running.



 Comments   
Comment by Andrey Miroshnichenko [ 22/Dec/14 ]

I have the same issue now on v. 2.2.3.

mongos> db.locks.find({'_id': 'balancer', 'state': {'$ne': 0}}).pretty()
{
        "_id" : "balancer",
        "process" : "atc005:37017:1415292838:1804289383",
        "state" : 1,
        "ts" : ObjectId("5485b6e0903bf7e88aaa2276"),
        "when" : ISODate("2014-12-08T14:34:08.769Z"),
        "who" : "atc005:37017:1415292838:1804289383:Balancer:1169620192",
        "why" : "doing balance round"
}
mongos> sh.isBalancerRunning()
true
mongos> sh.getBalancerState()
false

Comment by Thomas Rueckstiess [ 03/Jul/14 ]

Hi Guoming,

We haven't heard back from you and we can't continue the diagnosis without additional information. I'm going to resolve this ticket now. If this is still an issue, feel free to re-open the ticket and provide the verbose logs Randolph was asking for.

Thanks,
Thomas

Comment by Ramon Fernandez Marina [ 10/Jun/14 ]

xuguoming@nexlabs.com, we haven't heard back from you for a while. If this is still an issue for you, can you please send us the information that renctan requested?

Thanks, Ramón.

Comment by Randolph Tan [ 21/Apr/14 ]

Hi xuguoming@nexlabs.com,

It appears that there is a problem in one of the config servers. I need to gather more information before I can determine the best course of action. Can you set the verbosity to all config servers to 1 and upload the logs? You can do this by connecting to each of the config servers and send the command:

db.adminCommand({ setParameter: 1, logLevel: 1 })

You can also use the same command to set the log verbosity back to the original value.

Thanks!

Comment by Yang [ 21/Apr/14 ]

Randolph,

I see a number of errors as below. It appears something wrong with the config DBs. How do I fix that?

Thu Apr 17 20:00:06.384 [LockPinger] creating distributed lock ping thread for configserver1:port1,configserver2:port2,configserver3:port3 and process mongosserver:port4:1397702879:41 (sleeping for 30000ms)
Thu Apr 17 20:00:06.385 [Balancer] SyncClusterConnection connecting to [configserver2:port2]
Thu Apr 17 20:00:06.386 [Balancer] SyncClusterConnection connecting to [configserver3:port3]
Thu Apr 17 20:00:07.361 [Balancer] warning: distributed lock 'balancer/mongosserver:port4:1397702879:41 did not propagate properly. :: caused by :: 8017 update not consistent ns: config.locks query:

{ _id: "balancer", state: 0, ts: ObjectId('534d1329b5e92803768afc98') }

update: { $set:

{ state: 1, who: "mongosserver:port4:1397702879:41:Balancer:18467", process: "mongosserver:port4:1397702879:41", when: new Date(1397736006387), why: "doing balance round", ts: ObjectId('534fc2462db7a3a1f9f24e8e') }

} gle1:

{ err: "!loc.isNull()", n: 0, connectionId: 35, waited: 0, ok: 1.0 }

gle2:

{ updatedExisting: true, n: 1, lastOp: Timestamp 1397736006000|2, connectionId: 28, waited: 44, err: null, ok: 1.0 }

Thu Apr 17 20:00:07.361 [LockPinger] scoped connection to configserver1:port1,configserver2:port2,configserver3:port3 not being returned to the pool
Thu Apr 17 20:00:07.361 [LockPinger] warning: distributed lock pinger 'configserver1:port1,configserver2:port2,configserver3:port3/mongosserver:port4:1397702879:41' detected an exception while pinging. :: caused by :: update not consistent ns: config.lockpings query:

{ _id: "mongosserver:port4:1397702879:41" }

update: { $set:

{ ping: new Date(1397736006384) }

} gle1:

{ err: "!loc.isNull()", n: 0, connectionId: 5, waited: 387, ok: 1.0 }

gle2:

{ updatedExisting: false, n: 1, lastOp: Timestamp 1397736006000|1, connectionId: 5, waited: 44, err: null, ok: 1.0 }

Thu Apr 17 20:00:07.369 [Balancer] lock update won, completing lock propagation for 'balancer/mongosserver:port4:1397702879:41'
Thu Apr 17 20:00:07.942 [Balancer] scoped connection to configserver1:port1,configserver2:port2,configserver3:port3 not being returned to the pool
Thu Apr 17 20:00:07.942 [Balancer] caught exception while doing balance: exception finalizing winning lock :: caused by :: update not consistent ns: config.locks query:

{ _id: "balancer" }

update: { $set:

{ state: 2, who: "mongosserver:port4:1397702879:41:Balancer:18467", process: "mongosserver:port4:1397702879:41", when: new Date(1397736006387), why: "doing balance round", ts: ObjectId('534fc2462db7a3a1f9f24e8e') }

} gle1:

{ err: "!loc.isNull()", n: 0, connectionId: 35, waited: 140, ok: 1.0 }

gle2:

{ updatedExisting: true, n: 1, lastOp: Timestamp 1397736007000|1, connectionId: 28, waited: 11, err: null, ok: 1.0 }

Thu Apr 17 20:00:13.943 [Balancer] SyncClusterConnection connecting to [configserver1:port1]
Thu Apr 17 20:00:13.951 [Balancer] SyncClusterConnection connecting to [configserver2:port2]
Thu Apr 17 20:00:13.957 [Balancer] SyncClusterConnection connecting to [configserver3:port3]
Thu Apr 17 20:00:13.958 [Balancer] SyncClusterConnection connecting to [configserver1:port1]
Thu Apr 17 20:00:13.977 [Balancer] SyncClusterConnection connecting to [configserver2:port2]
Thu Apr 17 20:00:13.984 [Balancer] SyncClusterConnection connecting to [configserver3:port3]
Thu Apr 17 20:00:38.754 [LockPinger] scoped connection to configserver1:port1,configserver2:port2,configserver3:port3 not being returned to the pool
Thu Apr 17 20:00:38.754 [LockPinger] warning: distributed lock pinger 'configserver1:port1,configserver2:port2,configserver3:port3/mongosserver:port4:1397702879:41' detected an exception while pinging. :: caused by :: update not consistent ns: config.lockpings query:

{ _id: "mongosserver:port4:1397702879:41" }

update: { $set:

{ ping: new Date(1397736037361) }

} gle1:

{ err: "!loc.isNull()", n: 0, connectionId: 36, waited: 150, ok: 1.0 }

gle2:

{ updatedExisting: true, n: 1, lastOp: Timestamp 1397736037000|1, connectionId: 29, waited: 30, err: null, ok: 1.0 }

Thu Apr 17 20:00:39.369 [Balancer] SyncClusterConnection connecting to [configserver1:port1]
Thu Apr 17 20:00:39.371 [Balancer] SyncClusterConnection connecting to [configserver2:port2]
Thu Apr 17 20:00:39.403 [Balancer] SyncClusterConnection connecting to [configserver3:port3]

Comment by Randolph Tan [ 17/Apr/14 ]

Hi xuguoming@nexlabs.com,

Is the balancer lock still taken? If yes, can you provide the following:

1. mongodump of the config database.
2. Log for the mongos who has the balancer lock. To find out who currently has the lock, connect to any of the mongos through the shell and typing:

use config
db.locks.findOne({ _id: 'balancer' }).process

Thanks!

Comment by Yang [ 17/Apr/14 ]

Hi Randolph Tan,

No. It's doing nothing. Last entry from changelog is two days ago.

After trying sh.stopBalancer() a few times, I get to see "stopped:true" in settings for balancer entry.
However, the lock is still held by the balancer as status 2.
and sh.getBalancerState() = false, sh.isBalancerRunning() = true;

Comment by Randolph Tan [ 16/Apr/14 ]

Hi xuguoming@nexlabs.com,

Was there any balancer activity during that time? Is the same lock still being held? The balancer lock is held for the entire duration of the balancing round and this can sometimes take a long time, depending on many chunks it need to move.

Comment by Yang [ 16/Apr/14 ]

I get similar issue too in MongoDB 2.4.5 running in WIN Sever 2008R2/SP1.

In addition to similar changelog and locks records as posted by Stephen Hooper above, I also noticed it's impossible to stop the balancer by issuing command sh.stopBalancer() as I receive errors as below.
************************************************************************************************************************************************************
mongos> sh.stopBalancer(); Waiting for active hosts... Waiting for the balancer lock... assert.soon failed: function (){ var lock = db.getSisterDB( "config" ).locks.findOne(

{ _id : lockId }

)

if( state == false ) return ! lock || lock.state == 0
if( state == true ) return lock && lock.state == 2
if( state == undefined ) return (beginTS == undefined && lock) || (beginTS != undefined && ( !lock || lock.ts + "" != beginTS + "" ) )
else return lock && lock.state == state
}, msg:*Waited too long for lock balancer to unlock*
Error: Printing Stack Trace at printStackTrace (src/mongo/shell/utils.js:37:15) at doassert (src/mongo/shell/assert.js:6:5) at Function.assert.soon (src/mongo/shell/assert.js:110:60) at Function.sh.waitForDLock (src/mongo/shell/utils_sh.js:156:12) at Function.sh.waitForBalancerOff (src/mongo/shell/utils_sh.js:224:12) at Function.sh.waitForBalancer (src/mongo/shell/utils_sh.js:254:12) at Function.sh.stopBalancer (src/mongo/shell/utils_sh.js:126:8) at (shell):1:4*Balancer still may be active, you must manually verify this is not the case using the config.changelog collection.* Wed Apr 16 16:37:44.141 JavaScript execution failed: assert.soon failed: function (){ var lock = db.getSisterDB( "config" ).locks.findOne(

{ _id : lockId }

)

if( state == false ) return ! lock || lock.state == 0
if( state == true ) return lock && lock.state == 2
if( state == undefined ) return (beginTS == undefined && lock) ||
(beginTS != undefined && ( !lock || lock.ts + "" != beginTS + "" ) )
else return lock && lock.state == state
}, msg:Waited too long for lock balancer to unlock at src/mongo/shell/utils_sh.js:L228
mongos> sh.setBalancerState(false); update not consistent ns: config.settings query:

{ _id: "balancer" }

update: {$set:

{ stopped: true }

} gle1:

{ err: "!loc.isNull()", n: 0, connectionId: 4655 , waited: 130, ok: 1.0 }

gle2:

{ updatedExisting: true, n: 1, lastOp: Timestamp1397637878000|1, connectionId: 4639, waited: 14, err: null, ok: 1.0 }
Comment by Randolph Tan [ 05/Dec/13 ]

state of 1 is an intermediate state that means that the lock is currently being contended by multiple participants requesting for the lock. The time it takes to resolve (move to state of 2) depends on the number of participants.

Comment by Egan Neuhengen [ 04/Dec/13 ]

This looks old and left uncompleted, but I would like to report seeing this bug in version 2.4.8. The outputs to these commands distinctly imply this error:

mongos> sh.isBalancerRunning()
true
mongos> sh.getBalancerState()
false
mongos> db.locks.findOne({_id:"balancer"});
{
"_id" : "balancer",
"process" : "sel02.perf01.map2.nweacolo.pvt:27017:1382375736:1804289383",
"state" : 1,
"ts" : ObjectId("52668e92f7c817e5ce27e5d5"),
"when" : ISODate("2013-10-22T14:41:22.261Z"),
"who" : "sel02.perf01.map2.nweacolo.pvt:27017:1382375736:1804289383:Balancer:846930886",
"why" : "doing balance round"
}

Note that state is 1, even though we're on version 2.4 and the documentation states an active lock should have a state of 2 in versions 2.0+. I do not know what this signifies.

Comment by Randolph Tan [ 22/Feb/13 ]

Found out that distributed locks can be left locked when the mongos process exits while holding the lock.

Comment by Randolph Tan [ 03/Jan/13 ]

The balancer holds the balancer lock for a single balancing round and should release it afterwards. However, there can be more than one chunk that needs to be moved within a single round (which involves several collections), so the lock can be held over an extended periods of time.

Comment by Stephen Hooper [ 28/Dec/12 ]

I am also seeing something similar in 2.2.2

A single chunk is moved over but the locks remain open.

 
mongos> db.locks.find().pretty()
{
        "_id" : "pfmanager.physical_files",
        "process" : "devesx13:27017:1356718152:194783003",
        "state" : 2,
        "ts" : ObjectId("50de09f0acb90cad8e9d4c7e"),
        "when" : ISODate("2012-12-28T21:06:56.903Z"),
        "who" : "devesx13:27017:1356718152:194783003:conn766:246247121",
        "why" : "migrate-{ id_hash: \"028fba8dfd8a19b8795c98b43574b75b\" }"
}
{
        "_id" : "balancer",
        "process" : "devesx11:47017:1356718792:1804289383",
        "state" : 2,
        "ts" : ObjectId("50de09f082d7d8f91e5473cb"),
        "when" : ISODate("2012-12-28T21:06:56.378Z"),
        "who" : "devesx11:47017:1356718792:1804289383:Balancer:846930886",
        "why" : "doing balance round"
}

The change log shows the chunk commited.

 
mongos> db.changelog.find().sort({$natural:-1}).limit(2).pretty()
{
        "_id" : "devesx13-2012-12-28T21:13:10-167",
        "server" : "devesx13",
        "clientAddr" : "10.0.16.28:58116",
        "time" : ISODate("2012-12-28T21:13:10.925Z"),
        "what" : "moveChunk.commit",
        "ns" : "pfmanager.physical_files",
        "details" : {
                "min" : {
                        "id_hash" : "028fba8dfd8a19b8795c98b43574b75b"
                },
                "max" : {
                        "id_hash" : "029d3ff2ebc4975f26ba65ba9489e901"
                },
                "from" : "rs0",
                "to" : "rs1"
        }
}
{
        "_id" : "devesx12-2012-12-28T21:13:10-4",
        "server" : "devesx12",
        "clientAddr" : ":27017",
        "time" : ISODate("2012-12-28T21:13:10.895Z"),
        "what" : "moveChunk.to",
        "ns" : "pfmanager.physical_files",
        "details" : {
                "min" : {
                        "id_hash" : "028fba8dfd8a19b8795c98b43574b75b"
                },
                "max" : {
                        "id_hash" : "029d3ff2ebc4975f26ba65ba9489e901"
                },
                "step1 of 5" : 1,
                "step2 of 5" : 10563,
                "step3 of 5" : 362091,
                "step4 of 5" : 0,
                "step5 of 5" : 537
        }
}

However the locks remain open and a single thread is stuck in step 5 of 6 for a signfigant amount of time

 
{
		"opid" : "rs0:653242",
		"active" : true,
		"secs_running" : 637,
		"op" : "query",
		"ns" : "pfmanager.physical_files",
		"query" : {
				"$msg" : "query not recording (too large)"
		},
		"client_s" : "10.0.16.28:58116",
		"desc" : "conn766",
		"threadId" : "0x7e9e0ba62700",
		"connectionId" : 766,
		"locks" : {
				"^" : "w",
				"^pfmanager" : "W"
		},
		"waitingForLock" : false,
		"msg" : "step5 of 6",
		"numYields" : 2,
		"lockStats" : {
				"timeLockedMicros" : {
						"R" : NumberLong(0),
						"W" : NumberLong(18),
						"r" : NumberLong(1154755),
						"w" : NumberLong(258755739)
				},
				"timeAcquiringMicros" : {
						"R" : NumberLong(0),
						"W" : NumberLong(2),
						"r" : NumberLong(575336),
						"w" : NumberLong(1774204)
				}
		}
}

Comment by Ben Becker [ 08/Oct/12 ]

Yes, the skipped entries were strictly splits, to the best of my recollection. Perhaps this is also related to SERVER-7291?

Running short on time to determine exact repro steps; can dig further though.

Comment by Eliot Horowitz (Inactive) [ 06/Oct/12 ]

Are you sure there wasn't a different thing moving?
You skipped ahead in the changelog, so hard to tell.
Pretty hard to imagine a case where the lock isn't released.

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