long time to load chunks

Zac Witte

unread,

Jun 11, 2012, 3:02:56 AM6/11/12

to mongod...@googlegroups.com

I'm getting very poor performance trying to insert a lot of documents for my analytics system. Looking at the mongos logs I'm seeing a lot of lines with multi-second time to load chunks. I also see a lot of warning: splitChunk failed because the collection's metadata lock is taken. The auto-balancer is turned off. I suppose the indexes are too big to fit in memory and it's thrashing trying to load index segments from disk, but I would appreciate any advice on the quickest way to relieve this. I'm already at the highest memory instances amazon offers. Is my only option to add more shards? Re-balancing is going to take a very long time. There are no updates or queries happening. Only inserts.

Mon Jun 11 06:47:43 [conn246] ChunkManager: time to load chunks for pb3.hourly_stats: 3156ms sequenceNumber: 133 version: 38916|395

Mon Jun 11 06:47:43 [conn254] created new distributed lock for pb3.hourly_stats on mongo1.foobar.com:27019,mongo2.foobar.com:27019,mongo3.foobar.com:27019 ( lock timeout : 900000, ping interval : 30000, process : 0 )

Mon Jun 11 06:47:44 [conn230] end connection 127.0.0.1:35531

Mon Jun 11 06:47:45 [mongosMain] connection accepted from 127.0.0.1:35566 #259

Mon Jun 11 06:47:47 [conn254] ChunkManager: time to load chunks for pb3.hourly_stats: 3480ms sequenceNumber: 134 version: 38916|395

Mon Jun 11 06:47:47 [conn247] created new distributed lock for pb3.hourly_stats on mongo1.foobar.com:27019,mongo2.foobar.com:27019,mongo3.foobar.com:27019 ( lock timeout : 900000, ping interval : 30000, process : 0 )

Mon Jun 11 06:47:47 [conn259] end connection 127.0.0.1:35566

Mon Jun 11 06:47:49 [conn254] end connection 127.0.0.1:35560

Mon Jun 11 06:47:51 [conn247] ChunkManager: time to load chunks for pb3.hourly_stats: 4184ms sequenceNumber: 135 version: 38916|397

Mon Jun 11 06:47:52 [mongosMain] connection accepted from 127.0.0.1:35567 #260

Mon Jun 11 06:47:52 [conn256] created new distributed lock for pb3.hourly_stats on mongo1.foobar.com:27019,mongo2.foobar.com:27019,mongo3.foobar.com:27019 ( lock timeout : 900000, ping interval : 30000, process : 0 )

Mon Jun 11 06:47:52 [conn247] end connection 127.0.0.1:35551

Mon Jun 11 06:47:54 [mongosMain] connection accepted from 127.0.0.1:35569 #261

Mon Jun 11 06:47:54 [mongosMain] connection accepted from 127.0.0.1:35570 #262

Mon Jun 11 06:47:55 [conn256] ChunkManager: time to load chunks for pb3.hourly_stats: 3312ms sequenceNumber: 136 version: 38916|397

Mon Jun 11 06:47:55 [conn248] created new distributed lock for pb3.hourly_stats on mongo1.foobar.com:27019,mongo2.foobar.com:27019,mongo3.foobar.com:27019 ( lock timeout : 900000, ping interval : 30000, process : 0 )

Mon Jun 11 06:47:58 [conn248] ChunkManager: time to load chunks for pb3.hourly_stats: 3151ms sequenceNumber: 137 version: 38916|399

Mon Jun 11 06:47:59 [conn257] created new distributed lock for pb3.hourly_stats on mongo1.foobar.com:27019,mongo2.foobar.com:27019,mongo3.foobar.com:27019 ( lock timeout : 900000, ping interval : 30000, process : 0 )

Mon Jun 11 06:48:00 [mongosMain] connection accepted from 127.0.0.1:35571 #263

Mon Jun 11 06:48:00 [conn248] end connection 127.0.0.1:35552

Mon Jun 11 06:48:02 [conn257] ChunkManager: time to load chunks for pb3.hourly_stats: 3238ms sequenceNumber: 138 version: 38916|399

Mon Jun 11 06:48:02 [conn258] created new distributed lock for pb3.hourly_stats on mongo1.foobar.com:27019,mongo2.foobar.com:27019,mongo3.foobar.com:27019 ( lock timeout : 900000, ping interval : 30000, process : 0 )

Mon Jun 11 06:48:07 [conn258] ChunkManager: time to load chunks for pb3.hourly_stats: 4293ms sequenceNumber: 139 version: 38916|401

Mon Jun 11 06:48:07 [conn246] created new distributed lock for pb3.hourly_stats on mongo1.foobar.com:27019,mongo2.foobar.com:27019,mongo3.foobar.com:27019 ( lock timeout : 900000, ping interval : 30000, process : 0 )

Mon Jun 11 06:48:09 [mongosMain] connection accepted from 127.0.0.1:35573 #264

Mon Jun 11 06:48:13 [conn246] ChunkManager: time to load chunks for pb3.hourly_stats: 6308ms sequenceNumber: 140 version: 38916|403

Mon Jun 11 06:48:13 [conn260] created new distributed lock for pb3.hourly_stats on mongo1.foobar.com:27019,mongo2.foobar.com:27019,mongo3.foobar.com:27019 ( lock timeout : 900000, ping interval : 30000, process : 0 )

Mon Jun 11 06:48:17 [conn260] ChunkManager: time to load chunks for pb3.hourly_stats: 3625ms sequenceNumber: 141 version: 38916|403

Mon Jun 11 06:48:17 [conn261] created new distributed lock for pb3.hourly_stats on mongo1.foobar.com:27019,mongo2.foobar.com:27019,mongo3.foobar.com:27019 ( lock timeout : 900000, ping interval : 30000, process : 0 )

Mon Jun 11 06:48:21 [conn261] ChunkManager: time to load chunks for pb3.hourly_stats: 3283ms sequenceNumber: 142 version: 38916|405

Mon Jun 11 06:48:21 [conn262] created new distributed lock for pb3.hourly_stats on mongo1.foobar.com:27019,mongo2.foobar.com:27019,mongo3.foobar.com:27019 ( lock timeout : 900000, ping interval : 30000, process : 0 )

mongostat doesn't show anything locked because there's no activity, but I see 1 of the 3 shards (rotating) with a lot of faults. These are the 64GB amazon instances with a RAID 10.

insert query update delete getmore command flushes mapped vsize res faults locked % idx miss % qr|qw ar|aw netIn netOut conn time

0 0 0 0 0 1 0 4057g 8116g 1.4g 11 0 0 1|24 1|23 62b 1k 78 06:51:15

0 0 0 0 0 2 0 4057g 8116g 1.4g 10 0 0 1|24 1|23 329b 1k 78 06:51:16

0 0 0 0 0 2 0 4057g 8116g 1.4g 13 0 0 1|24 1|23 329b 1k 78 06:51:17

mongos> db.hourly_stats.stats()

{

"sharded" : true,

"flags" : 0,

"ns" : "pb3.hourly_stats",

"count" : 10869908568,

"numExtents" : 3787,

"size" : NumberLong("7012767684972"),

"storageSize" : NumberLong("8128240079712"),

"totalIndexSize" : NumberLong("3085999411712"),

"indexSizes" : {

"_id_" : NumberLong("1972366499264"),

"log_file_name_1" : NumberLong("1113632912448")

},

"avgObjSize" : 645.1542477198875,

"nindexes" : 2,

"nchunks" : 195991,

"shards" : {

"shard0000" : {

"ns" : "pb3.hourly_stats",

"count" : 3560547991,

"size" : NumberLong("2332729783592"),

"avgObjSize" : 655.160326300458,

"storageSize" : NumberLong("2474551719936"),

"numExtents" : 1153,

"nindexes" : 2,

"lastExtentSize" : 2146426864,

"paddingFactor" : 1,

"flags" : 0,

"totalIndexSize" : 926457716800,

"indexSizes" : {

"_id_" : 569445326576,

"log_file_name_1" : 357012390224

},

"ok" : 1

},

"shard0001" : {

"ns" : "pb3.hourly_stats",

"count" : 3658149778,

"size" : NumberLong("2338500244900"),

"avgObjSize" : 639.2576539549224,

"storageSize" : NumberLong("2401851660816"),

"numExtents" : 1119,

"nindexes" : 2,

"lastExtentSize" : 2146426864,

"paddingFactor" : 1,

"flags" : 0,

"totalIndexSize" : 1074908400384,

"indexSizes" : {

"_id_" : 695319768528,

"log_file_name_1" : 379588631856

},

"ok" : 1

},

"shard0002" : {

"ns" : "pb3.hourly_stats",

"count" : 3651210799,

"size" : NumberLong("2341537656480"),

"avgObjSize" : 641.3044289640314,

"storageSize" : NumberLong("3251836698960"),

"numExtents" : 1515,

"nindexes" : 2,

"lastExtentSize" : 2146426864,

"paddingFactor" : 1,

"flags" : 0,

"totalIndexSize" : 1084633294528,

"indexSizes" : {

"_id_" : 707601404160,

"log_file_name_1" : 377031890368

},

"ok" : 1

}

},

"ok" : 1

}

Eliot Horowitz

unread,

Jun 11, 2012, 8:12:38 AM6/11/12

to mongod...@googlegroups.com

That looks like your config servers might be overloaded.
What size instance are they on?

> --
> You received this message because you are subscribed to the Google
> Groups "mongodb-user" group.
> To post to this group, send email to mongod...@googlegroups.com
> To unsubscribe from this group, send email to
> mongodb-user...@googlegroups.com
> See also the IRC channel -- freenode.net#mongodb

Zac Witte

unread,

Jun 11, 2012, 6:46:54 PM6/11/12

to mongod...@googlegroups.com

Interesting - I didn't think of that. The config servers were sharing the same hardware as the actual mongod servers so I moved them to their own hardware. I'm still getting the same warnings, but now I can actually monitor what's going on. It looks like the config server is saturated on network traffic. Now mongoconfig1.foobar.com is sending about 25-40MB/s and the other two config servers are idle. I have 4 mongos servers running. Why would they keep trying to reload the chunks? Does that happen after every chunk split or what? I'm inserting into a few small key ranges so chunk splits happen multiple times per second. This won't be sustainable. Even adding more shards wouldn't help if this is the case. I suppose I could increase the chunk size, but that makes moving them harder. If I increase chunk size from 64MB to 256MB I only reduce the number of splits by 4x. There are currently around 200,000 chunks for this collection.

Zac

William Z

unread,

Jun 12, 2012, 6:51:15 PM6/12/12

to mongod...@googlegroups.com

Hi Zac!

To address your follow-up questions:

1) There is a communication protocol between each 'mongos' process and all of the 'mongod' processes it connects with. As part of that protocol, the 'mongod' processes will inform the 'mongos' when the chunk configuration on that 'mongod' has changed. I know that this will happen when a chunk is migrated from one shard to another: I haven't been able to find out definitively if it happens when a chunk is split or not.

When this happens, the 'mongos' process needs to reload the latest configuration information from the config servers. In all current production versions of MongoDB, this requires the 'mongos' process to reload the entire config database. When the config database gets large -- over 100,000 shards or so -- the reload becomes slow.

Unfortunately, when this occurs, all updates get blocked until the 'mongos' gets the new config. If this is taking three seconds, then there's going to be a problem.

The good news is, this issue is addressed in the upcoming release of MongoDB: see https://jira.mongodb.org/browse/SERVER-5475 for details.

2) Please post the output of the following commands to verify that your balancer is turned off:

    // connect to mongos
    use config
    db.settings.find().pretty()

3) Please be aware that if you change the chunk size, you won't affect the sizes of the chunks already in the system. Raising the chunk size will reduce the number of splits for new data inserted, but won't cause any of your existing chunks to be merged.

It's not clear to me if you can reload the collection from scratch or not. If you can, it might be worthwhile to try reloading it, along with a combination of increasing the chunk size and pre-splitting the chunks, to try to keep down the size of configuration information that needs to be transmitted to 'mongos'.

I'll note that since your bottleneck is the communication between the 'mongos' and 'mongod' processes, slowing down the speed of chunk movement in order to reduce the number of configuration reloads might well be a worthwhile tradeoff.

Please let me know what you decide to do.

-William

On Monday, June 11, 2012 3:46:54 PM UTC-7, Zac Witte wrote:

Interesting - I didn't think of that. The config servers were sharing the same hardware as the actual mongod servers so I moved them to their own hardware. I'm still getting the same warnings, but now I can actually monitor what's going on. It looks like the config server is saturated on network traffic. Now mongoconfig1.foobar.com is sending about 25-40MB/s and the other two config servers are idle. I have 4 mongos servers running. Why would they keep trying to reload the chunks? Does that happen after every chunk split or what? I'm inserting into a few small key ranges so chunk splits happen multiple times per second. This won't be sustainable. Even adding more shards wouldn't help if this is the case. I suppose I could increase the chunk size, but that makes moving them harder. If I increase chunk size from 64MB to 256MB I only reduce the number of splits by 4x. There are currently around 200,000 chunks for this collection.

Zac

On Monday, June 11, 2012 at 5:12 AM, Eliot Horowitz wrote:

That looks like your config servers might be overloaded.
What size instance are they on?

Glenn Maynard

unread,

Jun 12, 2012, 7:08:42 PM6/12/12

to mongod...@googlegroups.com

On Tue, Jun 12, 2012 at 5:51 PM, William Z <willia...@10gen.com> wrote:

When this happens, the 'mongos' process needs to reload the latest configuration information from the config servers. In all current production versions of MongoDB, this requires the 'mongos' process to reload the entire config database. When the config database gets large -- over 100,000 shards or so -- the reload becomes slow.

You mean 100,000 chunks, right?

--
Glenn Maynard

William Z

unread,

Jun 12, 2012, 7:39:49 PM6/12/12

to mongod...@googlegroups.com

On Tuesday, June 12, 2012 4:08:42 PM UTC-7, Glenn Maynard wrote:

On Tue, Jun 12, 2012 at 5:51 PM, William Z wrote:
When this happens, the 'mongos' process needs to reload the latest configuration information from the config servers. In all current production versions of MongoDB, this requires the 'mongos' process to reload the entire config database. When the config database gets large -- over 100,000 shards or so -- the reload becomes slow.

You mean 100,000 chunks, right?