Received: by 10.66.80.166 with SMTP id s6mr4251036pax.30.1346784981612;
Tue, 04 Sep 2012 11:56:21 -0700 (PDT)
X-BeenThere: mongodb-user@googlegroups.com
Received: by 10.68.237.161 with SMTP id vd1ls23370924pbc.3.gmail; Tue, 04 Sep
2012 11:56:10 -0700 (PDT)
Received: by 10.68.233.104 with SMTP id tv8mr286175pbc.5.1346784970015;
Tue, 04 Sep 2012 11:56:10 -0700 (PDT)
Date: Tue, 4 Sep 2012 11:56:09 -0700 (PDT)
From: Geoff L <ge...@channelmeter.com>
To: mongodb-user@googlegroups.com
Message-Id: <fb093a8d-106c-4867-81c3-37541fede88b@googlegroups.com>
In-Reply-To: <556131ad-4bef-4df5-8a04-f5f9c6997989@googlegroups.com>
References: <12350145-c175-4d82-8afc-6f180a3bac11@xd1g2000pbc.googlegroups.com>
<556131ad-4bef-4df5-8a04-f5f9c6997989@googlegroups.com>
Subject: Re: No data moving to new shard
MIME-Version: 1.0
Content-Type: multipart/mixed;
boundary="----=_Part_1739_25659531.1346784969297"
------=_Part_1739_25659531.1346784969297
Content-Type: multipart/alternative;
boundary="----=_Part_1740_18181855.1346784969297"
------=_Part_1740_18181855.1346784969297
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 7bit
Hi David,
I work with David Storrs, here's what he got from the flushRouterConfig. I
also poked in the mongos logs on the new shard machine and saw that the
balancer was having issues migrating. After all of dave's stuff is the
mongos log with the messages.
Thanks for the response. I tried it from mongos on the RS3 instance
and got the following:
mongos> db.adminCommand( 'flushRouterConfig' )
{ "flushed" : true, "ok" : 1 }
mongos> use cm_prod
switched to db cm_prod
mongos> db.printShardingStatus()
--- Sharding Status ---
sharding version: { "_id" : 1, "version" : 3 }
shards:
{ "_id" : "RS1", "host" : "RS1/xxx:27018" }
{ "_id" : "RS2", "host" : "RS2/xxx:27018" }
{ "_id" : "RS3", "host" : "RS3/xxx:27018" }
databases:
{ "_id" : "admin", "partitioned" : false, "primary" : "config" }
{ "_id" : "demo", "partitioned" : false, "primary" : "RS1" }
{ "_id" : "cm_prod", "partitioned" : true, "primary" : "RS1" }
cm_prod.profile_daily_stats chunks:
RS2 16
RS1 16
too many chunks to print, use verbose if you
want to force print
cm_prod.profile_raw_stats chunks:
RS2 160
RS1 158
too many chunks to print, use verbose if you
want to force print
cm_prod.video_latest_stats chunks:
RS1 152
RS2 153
too many chunks to print, use verbose if you
want to force print
cm_prod.video_raw_stats chunks:
RS1 3564
RS2 3533
too many chunks to print, use verbose if you
want to force print
{ "_id" : "test", "partitioned" : false, "primary" : "RS2" }
{ "_id" : "admin; db", "partitioned" : false, "primary" : "RS2" }
{ "_id" : "system", "partitioned" : false, "primary" : "RS2" }
{ "_id" : "geoff", "partitioned" : false, "primary" : "RS2" }
{ "_id" : "cm_demo_data", "partitioned" : false, "primary" :
"RS2" }
{ "_id" : "cm_develop_data", "partitioned" : false,
"primary" : "RS2" }
{ "_id" : "cm", "partitioned" : false, "primary" : "RS2" }
[RS1]# date
Tue Sep 4 17:28:37 UTC 2012
[RS1]# tail /var/log/mongo/mongod.log
Tue Sep 4 17:28:18 [conn287] about to log metadata event: { _id:
"RS1-2012-09-04T17:28:18-94774", server: "RS1", clientAddr:
"xxx.xxx.xxx.xxx:40811", time: new Date(1346779698624), what:
"moveChunk.start", ns: "cm_prod.video_raw_stats", details: { min: {
vt: MinKey, h: MinKey }, max: { vt: "---56wpitTM", h: 1340006584 },
from: "RS1", to: "RS3" } }
Tue Sep 4 17:28:18 [conn287] moveChunk request accepted at version
1542|1167
Tue Sep 4 17:28:18 [conn287] moveChunk number of documents: 18
Tue Sep 4 17:28:18 [conn287] distributed lock
'cm_prod.video_raw_stats/RS1:27018:1346463419:1483632176' unlocked.
Tue Sep 4 17:28:18 [conn287] about to log metadata event: { _id:
"RS1-2012-09-04T17:28:18-94775", server: "RS1", clientAddr:
"xxx.xxx.xxx.xxx:40811", time: new Date(1346779698932), what:
"moveChunk.from", ns: "cm_prod.video_raw_stats", details: { min: { vt:
MinKey, h: MinKey }, max: { vt: "---56wpitTM", h: 1340006584 }, step1:
0, step2: 360, note: "aborted" } }
Tue Sep 4 17:28:19 [conn287] command admin.$cmd command: { moveChunk:
"cm_prod.video_raw_stats", from: "RS1/RS1:27018", to:
"RS3/RS3:27018", min: { vt: MinKey, h: MinKey }, max: { vt:
"---56wpitTM", h: 1340006584 }, maxChunkSizeBytes: 67108864, shardId:
"cm_prod.video_raw_stats-vt_MinKeyh_MinKey", configdb:
"dbconf1:27019,dbconf2:27019,dbconf3:27019" } ntoreturn:1 reslen:199
751ms
Tue Sep 4 17:28:20 [conn287] request split points lookup for chunk
cm_prod.video_latest_stats { : "c49ZJ_AtsAE" } -->> { : "cI6nKmxZqwQ"
}
RS3#: date
Tue Sep 4 17:27:07 UTC 2012
RS3#: tail /var/log/mongo/mongod.log
Tue Sep 4 17:24:05 [initandlisten] connection accepted from
xxx.xxx.xxx.xxx:43430 #321 (99 connections now open)
Tue Sep 4 17:24:23 [conn198] command admin.$cmd command:
{writebacklisten: ObjectId('5041633c0774eaaaa46d50d3') } ntoreturn:1
keyUpdates:0 reslen:44 300000ms
Tue Sep 4 17:24:25 [conn200] command admin.$cmd command: {
writebacklisten: ObjectId('504163334bbb07ad9870119d') } ntoreturn:1
keyUpdates:0 reslen:44 300000ms
Tue Sep 4 17:24:25 [conn201] command admin.$cmd command: {
writebacklisten: ObjectId('50416343edfa40550746b1b8') } ntoreturn:1
keyUpdates:0 reslen:44 300000ms
RS3#: tail mongos.log
Tue Sep 4 17:49:11 [Balancer] moving chunk ns: cm_prod.video_latest_stats
moving ( ns:cm_prod.video_latest_stats at: RS2:RS2/RS2:27018 lastmod:
60|1||000000000000000000000000 min: { _id: "-OkLQldVbhI" } max: { _id:
"-amRGWbej2g" }) RS2:RS2/RS2:27018 -> RS3:RS3/RS3:27018
Tue Sep 4 17:49:15 [Balancer] moveChunk result: { cause: { errmsg:
"migrate already in progress", ok: 0.0 }, errmsg: "moveChunk failed to
engage TO-shard in the data transfer: migrate already in progress", ok: 0.0
}
Tue Sep 4 17:49:15 [Balancer] balancer move failed: { cause: { errmsg:
"migrate already in progress", ok: 0.0 }, errmsg: "moveChunk failed to
engage TO-shard in the data transfer: migrate already in progress", ok: 0.0
} from: RS2 to: RS3 chunk: min: { _id: "-OkLQldVbhI" } max: { _id:
"-OkLQldVbhI" }
Tue Sep 4 17:49:15 [Balancer] moving chunk ns: cm_prod.profile_raw_stats
moving ( ns:cm_prod.profile_raw_stats at: RS2:RS2/RS2:27018 lastmod:
52|1||000000000000000000000000 min: { u: MinKey, h: MinKey } max: { u:
"000christoph000", h: 1339286523 }) RS2:RS2/RS2:27018 -> RS3:RS3/RS3:27018
Tue Sep 4 17:49:16 [Balancer] moveChunk result: { cause: { errmsg:
"migrate already in progress", ok: 0.0 }, errmsg: "moveChunk failed to
engage TO-shard in the data transfer: migrate already in progress", ok: 0.0
}
Tue Sep 4 17:49:16 [Balancer] balancer move failed: { cause: { errmsg:
"migrate already in progress", ok: 0.0 }, errmsg: "moveChunk failed to
engage TO-shard in the data transfer: migrate already in progress", ok: 0.0
} from: RS2 to: RS3 chunk: min: { u: MinKey, h: MinKey } max: { u: MinKey,
h: MinKey }
Tue Sep 4 17:49:16 [Balancer] moving chunk ns: cm_prod.video_raw_stats
moving ( ns:cm_prod.video_raw_stats at: RS1:RS1/RS1:27018 lastmod:
1541|0||000000000000000000000000 min: { vt: MinKey, h: MinKey } max: { vt:
"---56wpitTM", h: 1340006584 }) RS1:RS1/RS1:27018 -> RS3:RS3/RS3:27018
Tue Sep 4 17:49:17 [Balancer] moveChunk result: { cause: { errmsg:
"migrate already in progress", ok: 0.0 }, errmsg: "moveChunk failed to
engage TO-shard in the data transfer: migrate already in progress", ok: 0.0
}
Tue Sep 4 17:49:17 [Balancer] balancer move failed: { cause: { errmsg:
"migrate already in progress", ok: 0.0 }, errmsg: "moveChunk failed to
engage TO-shard in the data transfer: migrate already in progress", ok: 0.0
} from: RS1 to: RS3 chunk: min: { vt: MinKey, h: MinKey } max: { vt:
MinKey, h: MinKey }
Tue Sep 4 17:49:17 [Balancer] distributed lock
'balancer/RS3:27017:1346462580:1804289383' unlocked.
On Monday, September 3, 2012 10:19:43 PM UTC-7, David Hows wrote:
>
> Hi David,
>
> After some discussion it seems like the new shard has registered
> but isn't being included properly in the balancing.
>
> Would you be willing to execute the flushRouterConfig command to try and
> clean out the cached router configurations and load them from the config
> servers, in order to get the router to acknowledged the new shard. The
> command is db.adminCommand( 'flushRouterConfig' ) on the mongos instance.
>
> Documentation on the flush router config command is available here
> http://docs.mongodb.org/manual/reference/commands/#flushRouterConfig
>
> On Tuesday, September 4, 2012 7:59:42 AM UTC+10, David K Storrs wrote:
>>
>> I added a third shard to my cluster last week and no data has moved to
>> it at all. I've been digging for answers and I'm finding related
>> things but nothing that quite addresses the issue -- my first thought
>> was that there is a stale lock somewhere, but I don't see it. Any
>> help would be much appreciated, because I've GOT to get this sorted
>> soon -- the RS1 shard is about 80% on disk.
>>
>> DB is v2.0; we have been using v2.0 for several months now and have
>> not made the jump to 2.2 yet.
>>
>> Below is everything I think might help someone figure this out. Sorry
>> for the wall o' text; I wasn't sure how much to include.
>>
>> ---------------------------------------------------------------------------
>>
>> [The following done from the RS1 primary unless otherwise indicated,
>> if that matters]
>>
>> mongos> ObjectId().getTimestamp()
>> ISODate("2012-09-03T21:03:09Z")
>>
>> mongos> use admin
>> switched to db admin
>> mongos> db.printShardingStatus()
>> --- Sharding Status ---
>> sharding version: { "_id" : 1, "version" : 3 }
>> shards:
>> { "_id" : "RS1", "host" : "RS1/xxx:27018" }
>> { "_id" : "RS2", "host" : "RS2/xxx:27018" }
>> { "_id" : "RS3", "host" : "RS3/xxx:27018" }
>> databases:
>> { "_id" : "admin", "partitioned" : false, "primary" :
>> "config" }
>> { "_id" : "demo", "partitioned" : false, "primary" :
>> "RS1" }
>> { "_id" : "cm_prod", "partitioned" : true, "primary" :
>> "RS1" }
>> cm_prod.profile_daily_stats chunks:
>> RS2 16
>> RS1 16
>> too many chunks to print, use verbose if you
>> want to force print
>> cm_prod.profile_raw_stats chunks:
>> RS2 160
>> RS1 157
>> too many chunks to print, use verbose if you
>> want to force print
>> cm_prod.video_latest_stats chunks:
>> RS1 152
>> RS2 153
>> too many chunks to print, use verbose if you
>> want to force print
>> cm_prod.video_raw_stats chunks:
>> RS1 3360
>> RS2 3364
>> too many chunks to print, use verbose if you
>> want to force print
>> { "_id" : "test", "partitioned" : false, "primary" :
>> "RS2" }
>> { "_id" : "admin; db", "partitioned" : false, "primary" :
>> "RS2" }
>> { "_id" : "system", "partitioned" : false, "primary" :
>> "RS2" }
>> { "_id" : "geoff", "partitioned" : false, "primary" :
>> "RS2" }
>> { "_id" : "cm_demo_data", "partitioned" : false,
>> "primary" : "RS2" }
>> { "_id" : "cm_develop_data", "partitioned" : false,
>> "primary" : "RS2" }
>> { "_id" : "cm", "partitioned" : false, "primary" : "RS2" }
>>
>> As you can see, there are only 4 sharded collections, all in the
>> cm_prod DB. Of those, video_raw_stats completely dominates the size:
>>
>> mongos> use cm_prod
>> switched to db cm_prod
>>
>> mongos> db.video_raw_stats.totalSize()
>> 558973318352 [ == 520G]
>>
>>
>> mongos> use config
>> switched to db config
>>
>>
>> There is only one balancer lock outstanding:
>>
>> mongos> db.locks.find({ _id : 'balancer'})
>> { "_id" : "balancer", "process" : "RS3:27017:1346462580:1804289383",
>> "state" : 2, "ts" : ObjectId("50451aea4bbb07ad98706071"), "when" :
>> ISODate("2012-09-03T21:02:34.033Z"), "who" :
>> "RS3:27017:1346462580:1804289383:Balancer:846930886", "why" : "doing
>> balance round" }
>>
>>
>>
>>
>> All existing locks (included for completeness):
>>
>> mongos> db.locks.find()
>> { "_id" : "balancer", "process" : "RS3:27017:1346462580:1804289383",
>> "state" : 2, "ts" : ObjectId("50451b814bbb07ad9870607f"), "when" :
>> ISODate("2012-09-03T21:05:05.089Z"), "who" :
>> "RS3:27017:1346462580:1804289383:Balancer:846930886", "why" : "doing
>> balance round" }
>>
>> { "_id" : "cm_prod.video_latest_stats", "process" :
>> "RS2:27018:1346463433:367275570", "state" : 0, "ts" :
>> ObjectId("50451b8828145fb74ca6281a"), "when" :
>> ISODate("2012-09-03T21:05:12.887Z"), "who" :
>> "RS2:27018:1346463433:367275570:conn19:96364934", "why" : "migrate-
>> { _id: \"-OkLQldVbhI\" }" }
>>
>> { "_id" : "cm_prod.video_descriptions", "process" :
>> RS1:27017:1343957738:1804289383", "state" : 0, "ts" :
>> ObjectId("5022feeaf7448e409c940963"), "when" :
>> ISODate("2012-08-09T00:06:02.618Z"), "who" :
>> "RS1:27017:1343957738:1804289383:conn9530:1058323149", "why" :
>> "drop" }
>>
>> { "_id" : "cm_prod.video_raw_stats", "process" :
>> "RS2:27018:1346463433:367275570", "state" : 0, "ts" :
>> ObjectId("50451b8a28145fb74ca6281c"), "when" :
>> ISODate("2012-09-03T21:05:14.050Z"), "who" :
>> "RS2:27018:1346463433:367275570:conn19:96364934", "why" : "migrate-
>> { vt: \"--RsEGRDz6g\", h: 1343228523 }" }
>>
>> { "_id" : "cm_prod.profile_raw_stats", "process" :
>> "RS2:27018:1346463433:367275570", "state" : 0, "ts" :
>> ObjectId("50451b8928145fb74ca6281b"), "when" :
>> ISODate("2012-09-03T21:05:13.469Z"), "who" :
>> "RS2:27018:1346463433:367275570:conn19:96364934", "why" : "migrate-
>> { u: MinKey, h: MinKey }" }
>>
>> { "_id" : "cm_prod.profile_daily_stats", "process" :
>> "RS1:27018:1346463419:1483632176", "state" : 0, "ts" :
>> ObjectId("50451b7d43ad3b2149370fe0"), "when" :
>> ISODate("2012-09-03T21:05:01.805Z"), "who" :
>> "RS1:27018:1346463419:1483632176:conn19:2127675310", "why" : "migrate-
>> { u: \"lionsgatelive\", h: 1345939325 }" }
>>
>> { "_id" : "cm_prod.channel_engagements", "process" :
>> "RS1:27017:1342673255:1804289383", "state" : 0, "ts" :
>> ObjectId("5007927048e98d9778948bb9"), "when" :
>> ISODate("2012-07-19T04:52:00.791Z"), "who" :
>> "RS1:27017:1342673255:1804289383:conn2:972605807", "why" : "drop" }
>>
>> { "_id" : "cm_prod.channel_video_grouped", "process" :
>> "RS1:27017:1343540831:1804289383", "state" : 0, "ts" :
>> ObjectId("501adff96dac5fc19aab36e4"), "when" :
>> ISODate("2012-08-02T20:15:53.401Z"), "who" :
>> "RS1:27017:1343540831:1804289383:conn1093:258764218", "why" : "drop" }
>>
>>
>>
>> On the RS2 machine:
>>
>> [RS2 ~]# tail -n 30 /var/log/mongo/mongod.log
>> Mon Sep 3 21:26:41 [conn19] command admin.$cmd command: { moveChunk:
>> "cm_prod.video_latest_stats", from: "RS2/xxx:27018", to: "RS3/xxx:
>> 27018", fromShard: "RS2", toShard: "RS3", min: { _id: "-OkLQldVbhI" },
>> max: { _id: "-amRGWbej2g" }, maxChunkSizeBytes: 67108864, shardId:
>> "cm_prod.video_latest_stats-_id_"-OkLQldVbhI"", configdb:
>> "dbconf1:27019,dbconf2:27019,dbconf3:27019", secondaryThrottle:
>> false } ntoreturn:1 reslen:199 680ms
>> Mon Sep 3 21:26:41 [conn19] received moveChunk request: { moveChunk:
>> "cm_prod.profile_raw_stats", from: "RS2/xxx:27018", to: "RS3/xxx:
>> 27018", fromShard: "RS2", toShard: "RS3", min: { u: MinKey, h:
>> MinKey }, max: { u: "000christoph000", h: 1339286523 },
>> maxChunkSizeBytes: 67108864, shardId: "cm_prod.profile_raw_stats-
>> u_MinKeyh_MinKey", configdb:
>> "dbconf1:27019,dbconf2:27019,dbconf3:27019", secondaryThrottle:
>> false }
>> Mon Sep 3 21:26:41 [conn19] created new distributed lock for
>> cm_prod.profile_raw_stats on dbconf1:27019,dbconf2:27019,dbconf3:27019
>> ( lock timeout : 900000, ping interval : 30000, process : 0 )
>> Mon Sep 3 21:26:41 [conn19] distributed lock
>> 'cm_prod.profile_raw_stats/RS2:27018:1346463433:367275570' acquired,
>> ts : 5045209128145fb74ca6290c
>> Mon Sep 3 21:26:41 [conn19] about to log metadata event: { _id:
>> "RS2-2012-09-03T21:26:41-228109", server: "RS2", clientAddr:
>> "xxx.xxx.xxx.xxx (RS3):58137", time: new Date(1346707601262), what:
>> "moveChunk.start", ns: "cm_prod.profile_raw_stats", details: { min:
>> { u: MinKey, h: MinKey }, max: { u: "000christoph000", h:
>> 1339286523 }, from: "RS2", to: "RS3" } }
>> Mon Sep 3 21:26:41 [conn19] moveChunk request accepted at version 52|
>> 7
>> Mon Sep 3 21:26:41 [conn19] moveChunk number of documents: 1241
>> Mon Sep 3 21:26:41 [conn19] distributed lock
>> 'cm_prod.profile_raw_stats/RS2:27018:1346463433:367275570' unlocked.
>> Mon Sep 3 21:26:41 [conn19] about to log metadata event: { _id:
>> "RS2-2012-09-03T21:26:41-228110", server: "RS2", clientAddr:
>> "xxx.xxx.xxx.xxx (RS3):58137", time: new Date(1346707601534), what:
>> "moveChunk.from", ns: "cm_prod.profile_raw_stats", details: { min:
>> { u: MinKey, h: MinKey }, max: { u: "000christoph000", h:
>> 1339286523 }, step1: 0, step2: 279, note: "aborted" } }
>> Mon Sep 3 21:26:41 [conn19] command admin.$cmd command: { moveChunk:
>> "cm_prod.profile_raw_stats", from: "RS2/xxx:27018", to: "RS3/xxx:
>> 27018", fromShard: "RS2", toShard: "RS3", min: { u: MinKey, h:
>> MinKey }, max: { u: "000christoph000", h: 1339286523 },
>> maxChunkSizeBytes: 67108864, shardId: "cm_prod.profile_raw_stats-
>> u_MinKeyh_MinKey", configdb:
>> "dbconf1:27019,dbconf2:27019,dbconf3:27019", secondaryThrottle:
>> false } ntoreturn:1 reslen:199 511ms
>> Mon Sep 3 21:26:41 [conn19] received moveChunk request: { moveChunk:
>> "cm_prod.video_raw_stats", from: "RS2/xxx:27018", to: "RS3/xxx:27018",
>> fromShard: "RS2", toShard: "RS3", min: { vt: "--RsEGRDz6g", h:
>> 1343228523 }, max: { vt: "--u6Xjj9524", h: "1340809383" },
>> maxChunkSizeBytes: 67108864, shardId: "cm_prod.video_raw_stats-vt_"--
>> RsEGRDz6g"h_1343228523", configdb:
>> "dbconf1:27019,dbconf2:27019,dbconf3:27019", secondaryThrottle:
>> false }
>> Mon Sep 3 21:26:41 [conn19] created new distributed lock for
>> cm_prod.video_raw_stats on dbconf1:27019,dbconf2:27019,dbconf3:27019
>> ( lock timeout : 900000, ping interval : 30000, process : 0 )
>> Mon Sep 3 21:26:41 [conn195] remove cm_prod.video_latest_stats query:
>> { _id: "Fh-DHjnZ1Q8" } 125ms
>> Mon Sep 3 21:26:41 [conn177] remove cm_prod.video_latest_stats query:
>> { _id: "NTo1BEPzXBs" } 118ms
>> Mon Sep 3 21:26:41 [conn191] remove cm_prod.video_latest_stats query:
>> { _id: "0lM78b-hM8k" } 162ms
>> Mon Sep 3 21:26:41 [conn19] distributed lock 'cm_prod.video_raw_stats/
>> RS2:27018:1346463433:367275570' acquired, ts :
>> 5045209128145fb74ca6290d
>> Mon Sep 3 21:26:41 [conn19] about to log metadata event: { _id:
>> "RS2-2012-09-03T21:26:41-228111", server: "RS2", clientAddr:
>> "xxx.xxx.xxx.xxx (RS3):58137", time: new Date(1346707601742), what:
>> "moveChunk.start", ns: "cm_prod.video_raw_stats", details: { min:
>> { vt: "--RsEGRDz6g", h: 1343228523 }, max: { vt: "--u6Xjj9524", h:
>> "1340809383" }, from: "RS2", to: "RS3" } }
>> Mon Sep 3 21:26:41 [conn19] moveChunk request accepted at version
>> 1542|437
>> Mon Sep 3 21:26:42 [conn177] remove cm_prod.video_latest_stats query:
>> { _id: "75B0x5bT87U" } 140ms
>> Mon Sep 3 21:26:42 [conn157] query cm_prod.video_raw_stats query:
>> { orderby: { h: -1 }, query: { vt: "4_V-NB2v6zI", hs: { $in:
>> [ 1346198400, 1345852800, 1345248000, 1343865600, 1338681600 ] } } }
>> ntoreturn:10 nscanned:10 scanAndOrder:1 nreturned:6 reslen:704 101ms
>> Mon Sep 3 21:26:43 [conn19] moveChunk number of documents: 68064
>> Mon Sep 3 21:26:43 [conn19] distributed lock 'cm_prod.video_raw_stats/
>> RS2:27018:1346463433:367275570' unlocked.
>> Mon Sep 3 21:26:43 [conn19] about to log metadata event: { _id:
>> "RS2-2012-09-03T21:26:43-228112", server: "RS2", clientAddr:
>> "xxx.xxx.xxx.xxx (RS3):58137", time: new Date(1346707603436), what:
>> "moveChunk.from", ns: "cm_prod.video_raw_stats", details: { min: { vt:
>> "--RsEGRDz6g", h: 1343228523 }, max: { vt: "--u6Xjj9524", h:
>> "1340809383" }, step1: 0, step2: 268, note: "aborted" } }
>> Mon Sep 3 21:26:43 [conn19] command admin.$cmd command: { moveChunk:
>> "cm_prod.video_raw_stats", from: "RS2/xxx:27018", to: "RS3/xxx:27018",
>> fromShard: "RS2", toShard: "RS3", min: { vt: "--RsEGRDz6g", h:
>> 1343228523 }, max: { vt: "--u6Xjj9524", h: "1340809383" },
>> maxChunkSizeBytes: 67108864, shardId: "cm_prod.video_raw_stats-vt_"--
>> RsEGRDz6g"h_1343228523", configdb:
>> "dbconf1:27019,dbconf2:27019,dbconf3:27019", secondaryThrottle:
>> false } ntoreturn:1 reslen:199 2036ms
>> Mon Sep 3 21:26:44 [conn193] remove cm_prod.video_latest_stats query:
>> { _id: "PXRPX2yZeBo" } 107ms
>> Mon Sep 3 21:26:44 [conn158] remove cm_prod.video_latest_stats query:
>> { _id: "RhvB4mPPYr0" } 152ms
>> Mon Sep 3 21:26:44 [conn187] remove cm_prod.video_latest_stats query:
>> { _id: "B2CtCrT3tXU" } 128ms
>> Mon Sep 3 21:26:44 [conn196] remove cm_prod.video_latest_stats query:
>> { _id: "AlKQTBRJ3nk" } 121ms
>> Mon Sep 3 21:26:44 [conn159] remove cm_prod.video_latest_stats query:
>> { _id: "HczAI7Hgf1Q" } 121ms
>> Mon Sep 3 21:26:44 [conn193] remove cm_prod.video_latest_stats query:
>> { _id: "N5WjWgatUm8" } 146ms
>>
>>
>>
>> On the RS3 machine:
>>
>> [RS3 ~]# tail -n 30 /var/log/mongo/mongod.log
>>
>> Mon Sep 3 20:37:06 [conn4] command admin.$cmd command:
>> { writebacklisten: ObjectId('50416343edfa40550746b1b8') } ntoreturn:1
>> keyUpdates:0 reslen:44 300000ms
>> Mon Sep 3 20:37:14 [conn10] command admin.$cmd command:
>> { writebacklisten: ObjectId('5041633c0774eaaaa46d50d3') } ntoreturn:1
>> keyUpdates:0 reslen:44 300000ms
>> Mon Sep 3 20:37:37 [conn14] command admin.$cmd command:
>> { writebacklisten: ObjectId('504163334bbb07ad9870119d') } ntoreturn:1
>> keyUpdates:0 reslen:44 300000ms
>> Mon Sep 3 20:39:37 [initandlisten] connection accepted from
>> 127.0.1.1:43404 #192 (74 connections now open)
>> Mon Sep 3 20:40:35 [initandlisten] connection accepted from <RS1
>> machine private IP>:46020 #193 (75 connections now open)
>> Mon Sep 3 20:42:06 [conn4] command admin.$cmd command:
>> { writebacklisten: ObjectId('50416343edfa40550746b1b8') } ntoreturn:1
>> keyUpdates:0 reslen:44 300000ms
>> Mon Sep 3 20:42:14 [conn10] command admin.$cmd command:
>> { writebacklisten: ObjectId('5041633c0774eaaaa46d50d3') } ntoreturn:1
>> keyUpdates:0 reslen:44 300000ms
>> Mon Sep 3 20:42:37 [conn14] command admin.$cmd command:
>> { writebacklisten: ObjectId('504163334bbb07ad9870119d') } ntoreturn:1
>> keyUpdates:0 reslen:44 300000ms
>> Mon Sep 3 20:47:06 [conn4] command admin.$cmd command:
>> { writebacklisten: ObjectId('50416343edfa40550746b1b8') } ntoreturn:1
>> keyUpdates:0 reslen:44 300000ms
>> Mon Sep 3 20:47:14 [conn10] command admin.$cmd command:
>> { writebacklisten: ObjectId('5041633c0774eaaaa46d50d3') } ntoreturn:1
>> keyUpdates:0 reslen:44 300000ms
>> Mon Sep 3 20:47:37 [conn14] command admin.$cmd command:
>> { writebacklisten: ObjectId('504163334bbb07ad9870119d') } ntoreturn:1
>> keyUpdates:0 reslen:44 300000ms
>> Mon Sep 3 20:52:06 [conn4] command admin.$cmd command:
>> { writebacklisten: ObjectId('50416343edfa40550746b1b8') } ntoreturn:1
>> keyUpdates:0 reslen:44 300000ms
>> Mon Sep 3 20:52:14 [conn10] command admin.$cmd command:
>> { writebacklisten: ObjectId('5041633c0774eaaaa46d50d3') } ntoreturn:1
>> keyUpdates:0 reslen:44 300000ms
>> Mon Sep 3 20:52:37 [conn14] command admin.$cmd command:
>> { writebacklisten: ObjectId('504163334bbb07ad9870119d') } ntoreturn:1
>> keyUpdates:0 reslen:44 300000ms
>> Mon Sep 3 20:57:06 [conn4] command admin.$cmd command:
>> { writebacklisten: ObjectId('50416343edfa40550746b1b8') } ntoreturn:1
>> keyUpdates:0 reslen:44 300000ms
>> Mon Sep 3 20:57:14 [conn10] command admin.$cmd command:
>> { writebacklisten: ObjectId('5041633c0774eaaaa46d50d3') } ntoreturn:1
>> keyUpdates:0 reslen:44 300000ms
>> Mon Sep 3 20:57:37 [conn14] command admin.$cmd command:
>> { writebacklisten: ObjectId('504163334bbb07ad9870119d') } ntoreturn:1
>> keyUpdates:0 reslen:44 300000ms
>> Mon Sep 3 21:02:06 [conn4] command admin.$cmd command:
>> { writebacklisten: ObjectId('50416343edfa40550746b1b8') } ntoreturn:1
>> keyUpdates:0 reslen:44 300000ms
>> Mon Sep 3 21:02:14 [conn10] command admin.$cmd command:
>> { writebacklisten: ObjectId('5041633c0774eaaaa46d50d3') } ntoreturn:1
>> keyUpdates:0 reslen:44 300000ms
>> Mon Sep 3 21:02:37 [conn14] command admin.$cmd command:
>> { writebacklisten: ObjectId('504163334bbb07ad9870119d') } ntoreturn:1
>> keyUpdates:0 reslen:44 300000ms
>> Mon Sep 3 21:03:40 [conn140] end connection "<RS2 machine private IP>:
>> 45967 (74 connections now open)
>> Mon Sep 3 21:07:06 [conn4] command admin.$cmd command:
>> { writebacklisten: ObjectId('50416343edfa40550746b1b8') } ntoreturn:1
>> keyUpdates:0 reslen:44 300000ms
>> Mon Sep 3 21:07:14 [conn10] command admin.$cmd command:
>> { writebacklisten: ObjectId('5041633c0774eaaaa46d50d3') } ntoreturn:1
>> keyUpdates:0 reslen:44 300000ms
>> Mon Sep 3 21:07:37 [conn14] command admin.$cmd command:
>> { writebacklisten: ObjectId('504163334bbb07ad9870119d') } ntoreturn:1
>> keyUpdates:0 reslen:44 300000ms
>> Mon Sep 3 21:12:06 [conn4] command admin.$cmd command:
>> { writebacklisten: ObjectId('50416343edfa40550746b1b8') } ntoreturn:1
>> keyUpdates:0 reslen:44 300000ms
>> Mon Sep 3 21:12:14 [conn10] command admin.$cmd command:
>> { writebacklisten: ObjectId('5041633c0774eaaaa46d50d3') } ntoreturn:1
>> keyUpdates:0 reslen:44 300000ms
>> Mon Sep 3 21:12:37 [conn14] command admin.$cmd command:
>> { writebacklisten: ObjectId('504163334bbb07ad9870119d') } ntoreturn:1
>> keyUpdates:0 reslen:44 300000ms
>> Mon Sep 3 21:17:06 [conn4] command admin.$cmd command:
>> { writebacklisten: ObjectId('50416343edfa40550746b1b8') } ntoreturn:1
>> keyUpdates:0 reslen:44 300000ms
>> Mon Sep 3 21:17:14 [conn10] command admin.$cmd command:
>> { writebacklisten: ObjectId('5041633c0774eaaaa46d50d3') } ntoreturn:1
>> keyUpdates:0 reslen:44 300000ms
>> Mon Sep 3 21:17:37 [conn14] command admin.$cmd command:
>> { writebacklisten: ObjectId('504163334bbb07ad9870119d') } ntoreturn:1
>> keyUpdates:0 reslen:44 300000ms
>>
>
------=_Part_1740_18181855.1346784969297
Content-Type: text/html; charset=utf-8
Content-Transfer-Encoding: quoted-printable
Hi David,<br>I work with David Storrs, here's what he got from the flushRou=
terConfig. I also poked in the mongos logs on the new shard machine and saw=
that the balancer was having issues migrating. After all of dave's stuff i=
s the mongos log with the messages.<br><br>Thanks for the response. I=
tried it from mongos on the RS3 instance<br>and got the following:<br><br>=
mongos> db.adminCommand( 'flushRouterConfig' )<br>{ "flushed" : true, "o=
k" : 1 }<br>mongos> use cm_prod<br>switched to db cm_prod<br>mongos> =
db.printShardingStatus()<br>--- Sharding Status ---<br> sharding vers=
ion: { "_id" : 1, "version" : 3 }<br> shards:<br> &n=
bsp; { "_id" : "RS1", "host" : "RS1/xxx:27018=
" }<br> { "_id" : "RS2",&nb=
sp; "host" : "RS2/xxx:27018" }<br>  =
; { "_id" : "RS3", "host" : "RS3/xxx:27018" }<br> databas=
es:<br> { "_id" : "admin",&=
nbsp; "partitioned" : false, "primary" : "config" }<br> &n=
bsp; { "_id" : "demo", "partitioned" : =
false, "primary" : "RS1" }<br> &nb=
sp; { "_id" : "cm_prod", "partitioned" : true, "primary" =
: "RS1" }<br> &n=
bsp; cm_prod.profile_daily_stats chunks:<br> &=
nbsp; &nbs=
p; &=
nbsp; RS2 16<br>  =
; &n=
bsp;  =
; RS1 16<br> &nb=
sp; =
too many chunks to print, =
use verbose if you<br>want to force print<br> =
cm_prod.profil=
e_raw_stats chunks:<br> &nbs=
p; &=
nbsp; RS2 =
160<br> &=
nbsp; &nbs=
p; RS1 &nb=
sp; 158<br> &nbs=
p; &=
nbsp; too many chunks to print, use verbose if you<br>want to force print<b=
r> &=
nbsp; cm_prod.video_latest_stats chunks:<br> &=
nbsp; &nbs=
p; &=
nbsp; RS1 152<br> &nbs=
p; &=
nbsp; &nbs=
p; RS2 153<br> &=
nbsp; &nbs=
p; too many chunks to print, use verbos=
e if you<br>want to force print<br> &nbs=
p; cm_prod.video_raw_stats =
chunks:<br> &nbs=
p; &=
nbsp; RS1 =
3564<br> =
&nb=
sp; RS2 3=
533<br> &n=
bsp; too =
many chunks to print, use verbose if you<br>want to force print<br> &n=
bsp; { "_id" : "test", "partition=
ed" : false, "primary" : "RS2" }<br> &nb=
sp; { "_id" : "admin; db", "partitioned" : false, "=
primary" : "RS2" }<br> { "_=
id" : "system", "partitioned" : false, "primary" : "RS2" }<br>&=
nbsp; { "_id" : "geoff", "p=
artitioned" : false, "primary" : "RS2" }<br> &=
nbsp; { "_id" : "cm_demo_data", "partitioned" : fal=
se, "primary" : "RS2" }<br> =
{ "_id" : "cm_develop_data", "partitioned" : false,<br>"primar=
y" : "RS2" }<br> { "_id" : =
"cm", "partitioned" : false, "primary" : "RS2" }<br><br><br>[RS=
1]# date<br>Tue Sep 4 17:28:37 UTC 2012<br><br>[RS1]# tail /var/log/m=
ongo/mongod.log<br>Tue Sep 4 17:28:18 [conn287] about to log metadata=
event: { _id:<br>"RS1-2012-09-04T17:28:18-94774", server: "RS1", clientAdd=
r:<br>"xxx.xxx.xxx.xxx:40811", time: new Date(1346779698624), what:<br>"mov=
eChunk.start", ns: "cm_prod.video_raw_stats", details: { min: {<br>vt: MinK=
ey, h: MinKey }, max: { vt: "---56wpitTM", h: 1340006584 },<br>from: "RS1",=
to: "RS3" } }<br>Tue Sep 4 17:28:18 [conn287] moveChunk request acce=
pted at version 1542|1167<br>Tue Sep 4 17:28:18 [conn287] moveChunk n=
umber of documents: 18<br>Tue Sep 4 17:28:18 [conn287] distributed lo=
ck<br>'cm_prod.video_raw_stats/RS1:27018:1346463419:1483632176' unlocked.<b=
r>Tue Sep 4 17:28:18 [conn287] about to log metadata event: { _id:<br=
>"RS1-2012-09-04T17:28:18-94775", server: "RS1", clientAddr:<br>"xxx.xxx.xx=
x.xxx:40811", time: new Date(1346779698932), what:<br>"moveChunk.from", ns:=
"cm_prod.video_raw_stats", details: { min: { vt:<br>MinKey, h: MinKey }, m=
ax: { vt: "---56wpitTM", h: 1340006584 }, step1:<br>0, step2: 360, note: "a=
borted" } }<br>Tue Sep 4 17:28:19 [conn287] command admin.$cmd comman=
d: { moveChunk:<br>"cm_prod.video_raw_stats", from: "RS1/RS1:27018", to:<br=
>"RS3/RS3:27018", min: { vt: MinKey, h: MinKey }, max: { vt:<br>"---56wpitT=
M", h: 1340006584 }, maxChunkSizeBytes: 67108864, shardId:<br>"cm_prod.vide=
o_raw_stats-vt_MinKeyh_MinKey", configdb:<br>"dbconf1:27019,dbconf2:27019,d=
bconf3:27019" } ntoreturn:1 reslen:199<br>751ms<br>Tue Sep 4 17:28:20=
[conn287] request split points lookup for chunk<br>cm_prod.video_latest_st=
ats { : "c49ZJ_AtsAE" } -->> { : "cI6nKmxZqwQ"<br>}<br><br><br>RS3#: =
date<br>Tue Sep 4 17:27:07 UTC 2012<br><br>RS3#: tail /var/log/mongo/=
mongod.log<br>Tue Sep 4 17:24:05 [initandlisten] connection accepted =
from<br>xxx.xxx.xxx.xxx:43430 #321 (99 connections now open)<br>Tue Sep&nbs=
p; 4 17:24:23 [conn198] command admin.$cmd command:<br>{writebacklisten: Ob=
jectId('5041633c0774eaaaa46d50d3') } ntoreturn:1<br>keyUpdates:0 resl=
en:44 300000ms<br>Tue Sep 4 17:24:25 [conn200] command admin.$cmd com=
mand: {<br>writebacklisten: ObjectId('504163334bbb07ad9870119d') } ntoretur=
n:1<br>keyUpdates:0 reslen:44 300000ms<br>Tue Sep 4 17:24:25 [c=
onn201] command admin.$cmd command: {<br>writebacklisten: ObjectId('5041634=
3edfa40550746b1b8') } ntoreturn:1<br>keyUpdates:0 reslen:44 300000ms<=
br><br>RS3#: tail mongos.log<br>Tue Sep 4 17:49:11 [Balancer] moving =
chunk ns: cm_prod.video_latest_stats moving ( ns:cm_prod.video_latest_stats=
at: RS2:RS2/RS2:27018 lastmod: 60|1||000000000000000000000000 min: { _id: =
"-OkLQldVbhI" } max: { _id: "-amRGWbej2g" }) RS2:RS2/RS2:27018 -> RS3:RS=
3/RS3:27018<br>Tue Sep 4 17:49:15 [Balancer] moveChunk result: { caus=
e: { errmsg: "migrate already in progress", ok: 0.0 }, errmsg: "moveChunk f=
ailed to engage TO-shard in the data transfer: migrate already in progress"=
, ok: 0.0 }<br>Tue Sep 4 17:49:15 [Balancer] balancer move failed: { =
cause: { errmsg: "migrate already in progress", ok: 0.0 }, errmsg: "moveChu=
nk failed to engage TO-shard in the data transfer: migrate already in progr=
ess", ok: 0.0 } from: RS2 to: RS3 chunk: min: { _id: "-OkLQldVbhI" } =
max: { _id: "-OkLQldVbhI" }<br>Tue Sep 4 17:49:15 [Balancer] moving c=
hunk ns: cm_prod.profile_raw_stats moving ( ns:cm_prod.profile_raw_stats at=
: RS2:RS2/RS2:27018 lastmod: 52|1||000000000000000000000000 min: { u: MinKe=
y, h: MinKey } max: { u: "000christoph000", h: 1339286523 }) RS2:RS2/RS2:27=
018 -> RS3:RS3/RS3:27018<br>Tue Sep 4 17:49:16 [Balancer] moveChun=
k result: { cause: { errmsg: "migrate already in progress", ok: 0.0 }, errm=
sg: "moveChunk failed to engage TO-shard in the data transfer: migrate alre=
ady in progress", ok: 0.0 }<br>Tue Sep 4 17:49:16 [Balancer] balancer=
move failed: { cause: { errmsg: "migrate already in progress", ok: 0.0 }, =
errmsg: "moveChunk failed to engage TO-shard in the data transfer: migrate =
already in progress", ok: 0.0 } from: RS2 to: RS3 chunk: min: { u: Mi=
nKey, h: MinKey } max: { u: MinKey, h: MinKey }<br>Tue Sep 4 17:49:16=
[Balancer] moving chunk ns: cm_prod.video_raw_stats moving ( ns:cm_prod.vi=
deo_raw_stats at: RS1:RS1/RS1:27018 lastmod: 1541|0||0000000000000000000000=
00 min: { vt: MinKey, h: MinKey } max: { vt: "---56wpitTM", h: 1340006584 }=
) RS1:RS1/RS1:27018 -> RS3:RS3/RS3:27018<br>Tue Sep 4 17:49:17 [Ba=
lancer] moveChunk result: { cause: { errmsg: "migrate already in progress",=
ok: 0.0 }, errmsg: "moveChunk failed to engage TO-shard in the data transf=
er: migrate already in progress", ok: 0.0 }<br>Tue Sep 4 17:49:17 [Ba=
lancer] balancer move failed: { cause: { errmsg: "migrate already in progre=
ss", ok: 0.0 }, errmsg: "moveChunk failed to engage TO-shard in the data tr=
ansfer: migrate already in progress", ok: 0.0 } from: RS1 to: RS3 chunk:&nb=
sp; min: { vt: MinKey, h: MinKey } max: { vt: MinKey, h: MinKey }<br>Tue Se=
p 4 17:49:17 [Balancer] distributed lock 'balancer/RS3:27017:13464625=
80:1804289383' unlocked.<br><br><br>On Monday, September 3, 2012 10:19:43 P=
M UTC-7, David Hows wrote:<blockquote class=3D"gmail_quote" style=3D"margin=
: 0;margin-left: 0.8ex;border-left: 1px #ccc solid;padding-left: 1ex;">Hi D=
avid,<div><br></div><div>After some discussion it seems like the new shard =
has registered but isn't being included properly in the balancing=
.</div><div><br></div><div>Would you be willing to execute the flushRouterC=
onfig command to try and clean out the cached router configurations and loa=
d them from the config servers, in order to get the router to acknowle=
dged the new shard. The command is db.adminCommand( 'flushRouterC=
onfig' ) on the mongos instance.</div><div><br></div><div>Documentation on =
the flush router config command is available here</div><div><a href=3D"http=
://docs.mongodb.org/manual/reference/commands/#flushRouterConfig" target=3D=
"_blank">http://docs.mongodb.org/<wbr>manual/reference/commands/#<wbr>flush=
RouterConfig</a><br><br>On Tuesday, September 4, 2012 7:59:42 AM UTC+10, Da=
vid K Storrs wrote:<blockquote class=3D"gmail_quote" style=3D"margin:0;marg=
in-left:0.8ex;border-left:1px #ccc solid;padding-left:1ex">I added a third =
shard to my cluster last week and no data has moved to
<br>it at all. I've been digging for answers and I'm finding related
<br>things but nothing that quite addresses the issue -- my first thought
<br>was that there is a stale lock somewhere, but I don't see it. Any
<br>help would be much appreciated, because I've GOT to get this sorted
<br>soon -- the RS1 shard is about 80% on disk.
<br>
<br>DB is v2.0; we have been using v2.0 for several months now and have
<br>not made the jump to 2.2 yet.
<br>
<br>Below is everything I think might help someone figure this out. S=
orry
<br>for the wall o' text; I wasn't sure how much to include.
<br>
<br>------------------------------<wbr>------------------------------<wbr>-=
--------------
<br>[The following done from the RS1 primary unless otherwise indicated,
<br>if that matters]
<br>
<br>mongos> ObjectId().getTimestamp()
<br>ISODate("2012-09-03T21:03:09Z"<wbr>)
<br>
<br>mongos> use admin
<br>switched to db admin
<br>mongos> db.printShardingStatus()
<br>--- Sharding Status ---
<br> sharding version: { "_id" : 1, "version" : 3 }
<br> shards:
<br> { "_id" : "RS1", "host" : "RS1/=
xxx:27018" }
<br> { "_id" : "RS2", "host" : "RS2/=
xxx:27018" }
<br> { "_id" : "RS3", "host" : "RS3/=
xxx:27018" }
<br> databases:
<br> { "_id" : "admin", "partitioned=
" : false, "primary" :
<br>"config" }
<br> { "_id" : "demo", "partitioned"=
: false, "primary" :
<br>"RS1" }
<br> { "_id" : "cm_prod", "partition=
ed" : true, "primary" :
<br>"RS1" }
<br> cm_prod.profile=
_daily_stats chunks:
<br> &=
nbsp; RS2 16
<br> &=
nbsp; RS1 16
<br> &=
nbsp; too many chunks to print, use verbose if you
<br>want to force print
<br> cm_prod.profile=
_raw_stats chunks:
<br> &=
nbsp; RS2 160
<br> &=
nbsp; RS1 157
<br> &=
nbsp; too many chunks to print, use verbose if you
<br>want to force print
<br> cm_prod.video_l=
atest_stats chunks:
<br> &=
nbsp; RS1 152
<br> &=
nbsp; RS2 153
<br> &=
nbsp; too many chunks to print, use verbose if you
<br>want to force print
<br> cm_prod.video_r=
aw_stats chunks:
<br> &=
nbsp; RS1 3360
<br> &=
nbsp; RS2 3364
<br> &=
nbsp; too many chunks to print, use verbose if you
<br>want to force print
<br> { "_id" : "test", "partitioned"=
: false, "primary" :
<br>"RS2" }
<br> { "_id" : "admin; db", "partiti=
oned" : false, "primary" :
<br>"RS2" }
<br> { "_id" : "system", "partitione=
d" : false, "primary" :
<br>"RS2" }
<br> { "_id" : "geoff", "partitioned=
" : false, "primary" :
<br>"RS2" }
<br> { "_id" : "cm_demo_data", "part=
itioned" : false,
<br>"primary" : "RS2" }
<br> { "_id" : "cm_develop_data", "p=
artitioned" : false,
<br>"primary" : "RS2" }
<br> { "_id" : "cm", "partitioned" :=
false, "primary" : "RS2" }
<br>
<br>As you can see, there are only 4 sharded collections, all in the
<br>cm_prod DB. Of those, video_raw_stats completely dominates the si=
ze:
<br>
<br>mongos> use cm_prod
<br>switched to db cm_prod
<br>
<br>mongos> db.video_raw_stats.totalSize()
<br>558973318352 [ =3D=3D 520G]
<br>
<br>
<br>mongos> use config
<br>switched to db config
<br>
<br>
<br>There is only one balancer lock outstanding:
<br>
<br>mongos> db.locks.find({ _id : 'balancer'})
<br>{ "_id" : "balancer", "process" : "RS3:27017:1346462580:<wbr>1804289383=
",
<br>"state" : 2, "ts" : ObjectId("<wbr>50451aea4bbb07ad98706071"), "when" :
<br>ISODate("2012-09-03T21:02:34.<wbr>033Z"), "who" :
<br>"RS3:27017:1346462580:<wbr>1804289383:Balancer:846930886"<wbr>, "why" :=
"doing
<br>balance round" }
<br>
<br>
<br>
<br>
<br>All existing locks (included for completeness):
<br>
<br>mongos> db.locks.find()
<br>{ "_id" : "balancer", "process" : "RS3:27017:1346462580:<wbr>1804289383=
",
<br>"state" : 2, "ts" : ObjectId("<wbr>50451b814bbb07ad9870607f"), "when" :
<br>ISODate("2012-09-03T21:05:05.<wbr>089Z"), "who" :
<br>"RS3:27017:1346462580:<wbr>1804289383:Balancer:846930886"<wbr>, "why" :=
"doing
<br>balance round" }
<br>
<br>{ "_id" : "cm_prod.video_latest_stats", "process" :
<br>"RS2:27018:1346463433:<wbr>367275570", "state" : 0, "ts" :
<br>ObjectId("<wbr>50451b8828145fb74ca6281a"), "when" :
<br>ISODate("2012-09-03T21:05:12.<wbr>887Z"), "who" :
<br>"RS2:27018:1346463433:<wbr>367275570:conn19:96364934", "why" : "migrate=
-
<br>{ _id: \"-OkLQldVbhI\" }" }
<br>
<br>{ "_id" : "cm_prod.video_descriptions", "process" :
<br>RS1:27017:1343957738:<wbr>1804289383", "state" : 0, "ts" :
<br>ObjectId("<wbr>5022feeaf7448e409c940963"), "when" :
<br>ISODate("2012-08-09T00:06:02.<wbr>618Z"), "who" :
<br>"RS1:27017:1343957738:<wbr>1804289383:conn9530:<wbr>1058323149", "why" =
:
<br>"drop" }
<br>
<br>{ "_id" : "cm_prod.video_raw_stats", "process" :
<br>"RS2:27018:1346463433:<wbr>367275570", "state" : 0, "ts" :
<br>ObjectId("<wbr>50451b8a28145fb74ca6281c"), "when" :
<br>ISODate("2012-09-03T21:05:14.<wbr>050Z"), "who" :
<br>"RS2:27018:1346463433:<wbr>367275570:conn19:96364934", "why" : "migrate=
-
<br>{ vt: \"--RsEGRDz6g\", h: 1343228523 }" }
<br>
<br>{ "_id" : "cm_prod.profile_raw_stats", "process" :
<br>"RS2:27018:1346463433:<wbr>367275570", "state" : 0, "ts" :
<br>ObjectId("<wbr>50451b8928145fb74ca6281b"), "when" :
<br>ISODate("2012-09-03T21:05:13.<wbr>469Z"), "who" :
<br>"RS2:27018:1346463433:<wbr>367275570:conn19:96364934", "why" : "migrate=
-
<br>{ u: MinKey, h: MinKey }" }
<br>
<br>{ "_id" : "cm_prod.profile_daily_stats", "process" :
<br>"RS1:27018:1346463419:<wbr>1483632176", "state" : 0, "ts" :
<br>ObjectId("<wbr>50451b7d43ad3b2149370fe0"), "when" :
<br>ISODate("2012-09-03T21:05:01.<wbr>805Z"), "who" :
<br>"RS1:27018:1346463419:<wbr>1483632176:conn19:2127675310", "why" : "migr=
ate-
<br>{ u: \"lionsgatelive\", h: 1345939325 }" }
<br>
<br>{ "_id" : "cm_prod.channel_engagements", "process" :
<br>"RS1:27017:1342673255:<wbr>1804289383", "state" : 0, "ts" :
<br>ObjectId("<wbr>5007927048e98d9778948bb9"), "when" :
<br>ISODate("2012-07-19T04:52:00.<wbr>791Z"), "who" :
<br>"RS1:27017:1342673255:<wbr>1804289383:conn2:972605807", "why" : "drop" =
}
<br>
<br>{ "_id" : "cm_prod.channel_video_<wbr>grouped", "process" :
<br>"RS1:27017:1343540831:<wbr>1804289383", "state" : 0, "ts" :
<br>ObjectId("<wbr>501adff96dac5fc19aab36e4"), "when" :
<br>ISODate("2012-08-02T20:15:53.<wbr>401Z"), "who" :
<br>"RS1:27017:1343540831:<wbr>1804289383:conn1093:258764218"<wbr>, "why" :=
"drop" }
<br>
<br>
<br>
<br>On the RS2 machine:
<br>
<br>[RS2 ~]# tail -n 30 /var/log/mongo/mongod.log
<br>Mon Sep 3 21:26:41 [conn19] command admin.$cmd command: { moveChu=
nk:
<br>"cm_prod.video_latest_stats", from: "RS2/xxx:27018", to: "RS3/xxx:
<br>27018", fromShard: "RS2", toShard: "RS3", min: { _id: "-OkLQldVbhI" },
<br>max: { _id: "-amRGWbej2g" }, maxChunkSizeBytes: 67108864, shardId:
<br>"cm_prod.video_latest_stats-_<wbr>id_"-OkLQldVbhI"", configdb:
<br>"dbconf1:27019,dbconf2:27019,<wbr>dbconf3:27019", secondaryThrottle:
<br>false } ntoreturn:1 reslen:199 680ms
<br>Mon Sep 3 21:26:41 [conn19] received moveChunk request: { moveChu=
nk:
<br>"cm_prod.profile_raw_stats", from: "RS2/xxx:27018", to: "RS3/xxx:
<br>27018", fromShard: "RS2", toShard: "RS3", min: { u: MinKey, h:
<br>MinKey }, max: { u: "000christoph000", h: 1339286523 },
<br>maxChunkSizeBytes: 67108864, shardId: "cm_prod.profile_raw_stats-
<br>u_MinKeyh_MinKey", configdb:
<br>"dbconf1:27019,dbconf2:27019,<wbr>dbconf3:27019", secondaryThrottle:
<br>false }
<br>Mon Sep 3 21:26:41 [conn19] created new distributed lock for
<br>cm_prod.profile_raw_stats on dbconf1:27019,dbconf2:27019,<wbr>dbconf3:2=
7019
<br>( lock timeout : 900000, ping interval : 30000, process : 0 )
<br>Mon Sep 3 21:26:41 [conn19] distributed lock
<br>'cm_prod.profile_raw_stats/<wbr>RS2:27018:1346463433:<wbr>367275570' ac=
quired,
<br>ts : 5045209128145fb74ca6290c
<br>Mon Sep 3 21:26:41 [conn19] about to log metadata event: { _id:
<br>"RS2-2012-09-03T21:26:41-<wbr>228109", server: "RS2", clientAddr:
<br>"xxx.xxx.xxx.xxx (RS3):58137", time: new Date(1346707601262), what:
<br>"moveChunk.start", ns: "cm_prod.profile_raw_stats", details: { min:
<br>{ u: MinKey, h: MinKey }, max: { u: "000christoph000", h:
<br>1339286523 }, from: "RS2", to: "RS3" } }
<br>Mon Sep 3 21:26:41 [conn19] moveChunk request accepted at version=
52|
<br>7
<br>Mon Sep 3 21:26:41 [conn19] moveChunk number of documents: 1241
<br>Mon Sep 3 21:26:41 [conn19] distributed lock
<br>'cm_prod.profile_raw_stats/<wbr>RS2:27018:1346463433:<wbr>367275570' un=
locked.
<br>Mon Sep 3 21:26:41 [conn19] about to log metadata event: { _id:
<br>"RS2-2012-09-03T21:26:41-<wbr>228110", server: "RS2", clientAddr:
<br>"xxx.xxx.xxx.xxx (RS3):58137", time: new Date(1346707601534), what:
<br>"moveChunk.from", ns: "cm_prod.profile_raw_stats", details: { min:
<br>{ u: MinKey, h: MinKey }, max: { u: "000christoph000", h:
<br>1339286523 }, step1: 0, step2: 279, note: "aborted" } }
<br>Mon Sep 3 21:26:41 [conn19] command admin.$cmd command: { moveChu=
nk:
<br>"cm_prod.profile_raw_stats", from: "RS2/xxx:27018", to: "RS3/xxx:
<br>27018", fromShard: "RS2", toShard: "RS3", min: { u: MinKey, h:
<br>MinKey }, max: { u: "000christoph000", h: 1339286523 },
<br>maxChunkSizeBytes: 67108864, shardId: "cm_prod.profile_raw_stats-
<br>u_MinKeyh_MinKey", configdb:
<br>"dbconf1:27019,dbconf2:27019,<wbr>dbconf3:27019", secondaryThrottle:
<br>false } ntoreturn:1 reslen:199 511ms
<br>Mon Sep 3 21:26:41 [conn19] received moveChunk request: { moveChu=
nk:
<br>"cm_prod.video_raw_stats", from: "RS2/xxx:27018", to: "RS3/xxx:27018",
<br>fromShard: "RS2", toShard: "RS3", min: { vt: "--RsEGRDz6g", h:
<br>1343228523 }, max: { vt: "--u6Xjj9524", h: "1340809383" },
<br>maxChunkSizeBytes: 67108864, shardId: "cm_prod.video_raw_stats-vt_"-<wb=
r>-
<br>RsEGRDz6g"h_1343228523", configdb:
<br>"dbconf1:27019,dbconf2:27019,<wbr>dbconf3:27019", secondaryThrottle:
<br>false }
<br>Mon Sep 3 21:26:41 [conn19] created new distributed lock for
<br>cm_prod.video_raw_stats on dbconf1:27019,dbconf2:27019,<wbr>dbconf3:270=
19
<br>( lock timeout : 900000, ping interval : 30000, process : 0 )
<br>Mon Sep 3 21:26:41 [conn195] remove cm_prod.video_latest_stats qu=
ery:
<br>{ _id: "Fh-DHjnZ1Q8" } 125ms
<br>Mon Sep 3 21:26:41 [conn177] remove cm_prod.video_latest_stats qu=
ery:
<br>{ _id: "NTo1BEPzXBs" } 118ms
<br>Mon Sep 3 21:26:41 [conn191] remove cm_prod.video_latest_stats qu=
ery:
<br>{ _id: "0lM78b-hM8k" } 162ms
<br>Mon Sep 3 21:26:41 [conn19] distributed lock 'cm_prod.video_raw_s=
tats/
<br>RS2:27018:1346463433:<wbr>367275570' acquired, ts :
<br>5045209128145fb74ca6290d
<br>Mon Sep 3 21:26:41 [conn19] about to log metadata event: { _id:
<br>"RS2-2012-09-03T21:26:41-<wbr>228111", server: "RS2", clientAddr:
<br>"xxx.xxx.xxx.xxx (RS3):58137", time: new Date(1346707601742), what:
<br>"moveChunk.start", ns: "cm_prod.video_raw_stats", details: { min:
<br>{ vt: "--RsEGRDz6g", h: 1343228523 }, max: { vt: "--u6Xjj9524", h:
<br>"1340809383" }, from: "RS2", to: "RS3" } }
<br>Mon Sep 3 21:26:41 [conn19] moveChunk request accepted at version
<br>1542|437
<br>Mon Sep 3 21:26:42 [conn177] remove cm_prod.video_latest_stats qu=
ery:
<br>{ _id: "75B0x5bT87U" } 140ms
<br>Mon Sep 3 21:26:42 [conn157] query cm_prod.video_raw_stats query:
<br>{ orderby: { h: -1 }, query: { vt: "4_V-NB2v6zI", hs: { $in:
<br>[ 1346198400, 1345852800, 1345248000, 1343865600, 1338681600 ] } } }
<br>ntoreturn:10 nscanned:10 scanAndOrder:1 nreturned:6 reslen:704 101ms
<br>Mon Sep 3 21:26:43 [conn19] moveChunk number of documents: 68064
<br>Mon Sep 3 21:26:43 [conn19] distributed lock 'cm_prod.video_raw_s=
tats/
<br>RS2:27018:1346463433:<wbr>367275570' unlocked.
<br>Mon Sep 3 21:26:43 [conn19] about to log metadata event: { _id:
<br>"RS2-2012-09-03T21:26:43-<wbr>228112", server: "RS2", clientAddr:
<br>"xxx.xxx.xxx.xxx (RS3):58137", time: new Date(1346707603436), what:
<br>"moveChunk.from", ns: "cm_prod.video_raw_stats", details: { min: { vt:
<br>"--RsEGRDz6g", h: 1343228523 }, max: { vt: "--u6Xjj9524", h:
<br>"1340809383" }, step1: 0, step2: 268, note: "aborted" } }
<br>Mon Sep 3 21:26:43 [conn19] command admin.$cmd command: { moveChu=
nk:
<br>"cm_prod.video_raw_stats", from: "RS2/xxx:27018", to: "RS3/xxx:27018",
<br>fromShard: "RS2", toShard: "RS3", min: { vt: "--RsEGRDz6g", h:
<br>1343228523 }, max: { vt: "--u6Xjj9524", h: "1340809383" },
<br>maxChunkSizeBytes: 67108864, shardId: "cm_prod.video_raw_stats-vt_"-<wb=
r>-
<br>RsEGRDz6g"h_1343228523", configdb:
<br>"dbconf1:27019,dbconf2:27019,<wbr>dbconf3:27019", secondaryThrottle:
<br>false } ntoreturn:1 reslen:199 2036ms
<br>Mon Sep 3 21:26:44 [conn193] remove cm_prod.video_latest_stats qu=
ery:
<br>{ _id: "PXRPX2yZeBo" } 107ms
<br>Mon Sep 3 21:26:44 [conn158] remove cm_prod.video_latest_stats qu=
ery:
<br>{ _id: "RhvB4mPPYr0" } 152ms
<br>Mon Sep 3 21:26:44 [conn187] remove cm_prod.video_latest_stats qu=
ery:
<br>{ _id: "B2CtCrT3tXU" } 128ms
<br>Mon Sep 3 21:26:44 [conn196] remove cm_prod.video_latest_stats qu=
ery:
<br>{ _id: "AlKQTBRJ3nk" } 121ms
<br>Mon Sep 3 21:26:44 [conn159] remove cm_prod.video_latest_stats qu=
ery:
<br>{ _id: "HczAI7Hgf1Q" } 121ms
<br>Mon Sep 3 21:26:44 [conn193] remove cm_prod.video_latest_stats qu=
ery:
<br>{ _id: "N5WjWgatUm8" } 146ms
<br>
<br>
<br>
<br>On the RS3 machine:
<br>
<br>[RS3 ~]# tail -n 30 /var/log/mongo/mongod.log
<br>
<br>Mon Sep 3 20:37:06 [conn4] command admin.$cmd command:
<br>{ writebacklisten: ObjectId('<wbr>50416343edfa40550746b1b8') } ntoretur=
n:1
<br>keyUpdates:0 reslen:44 300000ms
<br>Mon Sep 3 20:37:14 [conn10] command admin.$cmd command:
<br>{ writebacklisten: ObjectId('<wbr>5041633c0774eaaaa46d50d3') } ntoretur=
n:1
<br>keyUpdates:0 reslen:44 300000ms
<br>Mon Sep 3 20:37:37 [conn14] command admin.$cmd command:
<br>{ writebacklisten: ObjectId('<wbr>504163334bbb07ad9870119d') } ntoretur=
n:1
<br>keyUpdates:0 reslen:44 300000ms
<br>Mon Sep 3 20:39:37 [initandlisten] connection accepted from
<br><a href=3D"http://127.0.1.1:43404" target=3D"_blank">127.0.1.1:43404</a=
> #192 (74 connections now open)
<br>Mon Sep 3 20:40:35 [initandlisten] connection accepted from <R=
S1
<br>machine private IP>:46020 #193 (75 connections now open)
<br>Mon Sep 3 20:42:06 [conn4] command admin.$cmd command:
<br>{ writebacklisten: ObjectId('<wbr>50416343edfa40550746b1b8') } ntoretur=
n:1
<br>keyUpdates:0 reslen:44 300000ms
<br>Mon Sep 3 20:42:14 [conn10] command admin.$cmd command:
<br>{ writebacklisten: ObjectId('<wbr>5041633c0774eaaaa46d50d3') } ntoretur=
n:1
<br>keyUpdates:0 reslen:44 300000ms
<br>Mon Sep 3 20:42:37 [conn14] command admin.$cmd command:
<br>{ writebacklisten: ObjectId('<wbr>504163334bbb07ad9870119d') } ntoretur=
n:1
<br>keyUpdates:0 reslen:44 300000ms
<br>Mon Sep 3 20:47:06 [conn4] command admin.$cmd command:
<br>{ writebacklisten: ObjectId('<wbr>50416343edfa40550746b1b8') } ntoretur=
n:1
<br>keyUpdates:0 reslen:44 300000ms
<br>Mon Sep 3 20:47:14 [conn10] command admin.$cmd command:
<br>{ writebacklisten: ObjectId('<wbr>5041633c0774eaaaa46d50d3') } ntoretur=
n:1
<br>keyUpdates:0 reslen:44 300000ms
<br>Mon Sep 3 20:47:37 [conn14] command admin.$cmd command:
<br>{ writebacklisten: ObjectId('<wbr>504163334bbb07ad9870119d') } ntoretur=
n:1
<br>keyUpdates:0 reslen:44 300000ms
<br>Mon Sep 3 20:52:06 [conn4] command admin.$cmd command:
<br>{ writebacklisten: ObjectId('<wbr>50416343edfa40550746b1b8') } ntoretur=
n:1
<br>keyUpdates:0 reslen:44 300000ms
<br>Mon Sep 3 20:52:14 [conn10] command admin.$cmd command:
<br>{ writebacklisten: ObjectId('<wbr>5041633c0774eaaaa46d50d3') } ntoretur=
n:1
<br>keyUpdates:0 reslen:44 300000ms
<br>Mon Sep 3 20:52:37 [conn14] command admin.$cmd command:
<br>{ writebacklisten: ObjectId('<wbr>504163334bbb07ad9870119d') } ntoretur=
n:1
<br>keyUpdates:0 reslen:44 300000ms
<br>Mon Sep 3 20:57:06 [conn4] command admin.$cmd command:
<br>{ writebacklisten: ObjectId('<wbr>50416343edfa40550746b1b8') } ntoretur=
n:1
<br>keyUpdates:0 reslen:44 300000ms
<br>Mon Sep 3 20:57:14 [conn10] command admin.$cmd command:
<br>{ writebacklisten: ObjectId('<wbr>5041633c0774eaaaa46d50d3') } ntoretur=
n:1
<br>keyUpdates:0 reslen:44 300000ms
<br>Mon Sep 3 20:57:37 [conn14] command admin.$cmd command:
<br>{ writebacklisten: ObjectId('<wbr>504163334bbb07ad9870119d') } ntoretur=
n:1
<br>keyUpdates:0 reslen:44 300000ms
<br>Mon Sep 3 21:02:06 [conn4] command admin.$cmd command:
<br>{ writebacklisten: ObjectId('<wbr>50416343edfa40550746b1b8') } ntoretur=
n:1
<br>keyUpdates:0 reslen:44 300000ms
<br>Mon Sep 3 21:02:14 [conn10] command admin.$cmd command:
<br>{ writebacklisten: ObjectId('<wbr>5041633c0774eaaaa46d50d3') } ntoretur=
n:1
<br>keyUpdates:0 reslen:44 300000ms
<br>Mon Sep 3 21:02:37 [conn14] command admin.$cmd command:
<br>{ writebacklisten: ObjectId('<wbr>504163334bbb07ad9870119d') } ntoretur=
n:1
<br>keyUpdates:0 reslen:44 300000ms
<br>Mon Sep 3 21:03:40 [conn140] end connection "<RS2 machine priv=
ate IP>:
<br>45967 (74 connections now open)
<br>Mon Sep 3 21:07:06 [conn4] command admin.$cmd command:
<br>{ writebacklisten: ObjectId('<wbr>50416343edfa40550746b1b8') } ntoretur=
n:1
<br>keyUpdates:0 reslen:44 300000ms
<br>Mon Sep 3 21:07:14 [conn10] command admin.$cmd command:
<br>{ writebacklisten: ObjectId('<wbr>5041633c0774eaaaa46d50d3') } ntoretur=
n:1
<br>keyUpdates:0 reslen:44 300000ms
<br>Mon Sep 3 21:07:37 [conn14] command admin.$cmd command:
<br>{ writebacklisten: ObjectId('<wbr>504163334bbb07ad9870119d') } ntoretur=
n:1
<br>keyUpdates:0 reslen:44 300000ms
<br>Mon Sep 3 21:12:06 [conn4] command admin.$cmd command:
<br>{ writebacklisten: ObjectId('<wbr>50416343edfa40550746b1b8') } ntoretur=
n:1
<br>keyUpdates:0 reslen:44 300000ms
<br>Mon Sep 3 21:12:14 [conn10] command admin.$cmd command:
<br>{ writebacklisten: ObjectId('<wbr>5041633c0774eaaaa46d50d3') } ntoretur=
n:1
<br>keyUpdates:0 reslen:44 300000ms
<br>Mon Sep 3 21:12:37 [conn14] command admin.$cmd command:
<br>{ writebacklisten: ObjectId('<wbr>504163334bbb07ad9870119d') } ntoretur=
n:1
<br>keyUpdates:0 reslen:44 300000ms
<br>Mon Sep 3 21:17:06 [conn4] command admin.$cmd command:
<br>{ writebacklisten: ObjectId('<wbr>50416343edfa40550746b1b8') } ntoretur=
n:1
<br>keyUpdates:0 reslen:44 300000ms
<br>Mon Sep 3 21:17:14 [conn10] command admin.$cmd command:
<br>{ writebacklisten: ObjectId('<wbr>5041633c0774eaaaa46d50d3') } ntoretur=
n:1
<br>keyUpdates:0 reslen:44 300000ms
<br>Mon Sep 3 21:17:37 [conn14] command admin.$cmd command:
<br>{ writebacklisten: ObjectId('<wbr>504163334bbb07ad9870119d') } ntoretur=
n:1
<br>keyUpdates:0 reslen:44 300000ms
<br></blockquote></div></blockquote>
------=_Part_1740_18181855.1346784969297--
------=_Part_1739_25659531.1346784969297--
Message from discussion No data moving to new shard
| Create a group - Google Groups - Google Home - Terms of Service - Privacy Policy |
| ©2013 Google |