Received: by 10.236.118.161 with SMTP id l21mr1394242yhh.34.1353007350246; Thu, 15 Nov 2012 11:22:30 -0800 (PST) X-BeenThere: mongodb-user@googlegroups.com Received: by 10.49.18.230 with SMTP id z6ls508557qed.6.gmail; Thu, 15 Nov 2012 11:22:09 -0800 (PST) Received: by 10.49.26.39 with SMTP id i7mr505871qeg.18.1353007329881; Thu, 15 Nov 2012 11:22:09 -0800 (PST) Date: Thu, 15 Nov 2012 11:22:09 -0800 (PST) From: Gevorg Hari To: mongodb-user@googlegroups.com Message-Id: <1749eff9-fa65-4951-89c3-720455a1d6d8@googlegroups.com> In-Reply-To: References: Subject: Re: [mongodb-user] Re: inconsistent read speed - logs with flushing mmaps took 11205ms in the log MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="----=_Part_529_2851085.1353007329298" ------=_Part_529_2851085.1353007329298 Content-Type: multipart/alternative; boundary="----=_Part_530_2465912.1353007329298" ------=_Part_530_2465912.1353007329298 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 7bit I'm having a very similar issue. Flushing mmaps takes in general about 10000ms for 150 files and 300GB total but it sometimes jump even to 150000ms. During the flushing the db is basically not responsive. I noticed this while inserting data and creating indexes (I had to abort the operation even if in background). I'm running MongoDB 2.2.1 for Windows 64-bit 2008R2+ on a WIndows Server 2008 R2 with NTFS File System. There about 200GB of disk space available and plenty of RAM that slowly ramps up to be 100% of utilization when this issue starts occurring. On Thursday, November 15, 2012 7:08:45 PM UTC, Jason Lewis wrote: > > What OS and filesystem? > > On Thu, Nov 15, 2012 at 11:34 AM, Tim Haines > > wrote: > > The mmap flushing is even slower now.. > > > > Thu Nov 15 10:25:50 [journal] old journal file will be removed: > > /var/lib/mongodb/journal/j._79 > > Thu Nov 15 10:25:51 [journal] DR101 latency warning on journal file open > > 562ms > > Thu Nov 15 10:26:40 [DataFileSync] flushing mmaps took 27696ms for 14 > files > > Thu Nov 15 10:27:50 [DataFileSync] flushing mmaps took 37244ms for 14 > files > > Thu Nov 15 10:28:48 [DataFileSync] flushing mmaps took 35968ms for 14 > files > > Thu Nov 15 10:29:01 [journal] old journal file will be removed: > > /var/lib/mongodb/journal/j._80 > > Thu Nov 15 10:29:38 [DataFileSync] flushing mmaps took 25631ms for 14 > files > > Thu Nov 15 10:30:35 [DataFileSync] flushing mmaps took 22286ms for 14 > files > > Thu Nov 15 10:31:50 [DataFileSync] flushing mmaps took 37886ms for 14 > files > > > > Tim. > > > > On Wednesday, November 14, 2012 8:46:42 PM UTC-8, Tim Haines wrote: > >> > >> Hi there, > >> > >> I've plugged mongo into my production system today to see how it > handles > >> the write speed for a few days. So far I only have one server with a > 15k > >> RPM spinning disk and 8GB of ram. If I take this to production > properly, I > >> intend to shard, but hopefully to only 2 or 3 servers. > >> > >> Right now I'm doing about 200 upsert findAndModify's per second, and > 200 > >> upsert updates. The stats tells me the averageObjSize is 129 bytes for > the > >> documents receiving findAndModifys (4 indexes) and 91 bytes for the > >> documents receiving updates (1 index). The dataset (data + indexes) is > >> currently around 1GB in total. > >> > >> I have these entries in the mongo logs - I don't know what they mean > yet, > >> but they're concerning: > >> > >> Wed Nov 14 21:49:23 [DataFileSync] flushing mmaps took 10482ms for 11 > >> files > >> Wed Nov 14 21:53:23 [DataFileSync] flushing mmaps took 10520ms for 11 > >> files > >> Wed Nov 14 21:55:07 [websvr] serverStatus was very slow: { after basic: > 0, > >> middle of mem: 1640, after mem: 1640, after connections: 1640, after > extra > >> info: 1640, after counters: 1640, after repl: 1640, after asserts: > 1640, > >> after dur: 1640, at end: 1640 } > >> Wed Nov 14 21:56:22 [DataFileSync] flushing mmaps took 10078ms for 11 > >> files > >> Wed Nov 14 21:57:04 [journal] old journal file will be removed: > >> /var/lib/mongodb/journal/j._46 > >> Wed Nov 14 21:57:22 [DataFileSync] flushing mmaps took 10008ms for 11 > >> files > >> Wed Nov 14 22:00:23 [DataFileSync] flushing mmaps took 10751ms for 11 > >> files > >> Wed Nov 14 22:01:23 [DataFileSync] flushing mmaps took 11075ms for 11 > >> files > >> Wed Nov 14 22:05:11 [journal] old journal file will be removed: > >> /var/lib/mongodb/journal/j._47 > >> Wed Nov 14 22:06:23 [DataFileSync] flushing mmaps took 10347ms for 11 > >> files > >> Wed Nov 14 22:07:24 [DataFileSync] flushing mmaps took 11479ms for 11 > >> files > >> Wed Nov 14 22:10:23 [DataFileSync] flushing mmaps took 10410ms for 11 > >> files > >> Wed Nov 14 22:11:23 [DataFileSync] flushing mmaps took 10340ms for 11 > >> files > >> Wed Nov 14 22:13:24 [DataFileSync] flushing mmaps took 11128ms for 11 > >> files > >> Wed Nov 14 22:13:27 [journal] old journal file will be removed: > >> /var/lib/mongodb/journal/j._48 > >> Wed Nov 14 22:14:24 [DataFileSync] flushing mmaps took 11807ms for 11 > >> files > >> Wed Nov 14 22:15:24 [DataFileSync] flushing mmaps took 11205ms for 11 > >> files > >> > >> I'm not doing any reads yet, but I decided to check to see how > consistent > >> they are - if the mmaps flushing is causing read stalls. > >> > >> I set up a simple query which fetches one record based on an index, and > >> had it repeat every second. I log the duration and timestamp if it > took > >> longer than 3ms (most were under 1ms). This is the output I saw - some > >> operations taking multiple seconds for a single record query based on > an > >> index. Where all the data and indexes should still be in ram.. > >> > >> 0.104574109 2012-11-14 22:13:54 -0600 > >> 4.74783542 2012-11-14 22:14:22 -0600 > >> 0.243556581 2012-11-14 22:14:25 -0600 > >> 0.821347295 2012-11-14 22:14:30 -0600 > >> 0.036629986 2012-11-14 22:14:56 -0600 > >> 3.851662545 2012-11-14 22:15:05 -0600 > >> 0.007991038 2012-11-14 22:15:10 -0600 > >> 0.004475775 2012-11-14 22:15:57 -0600 > >> 0.09404014 2012-11-14 22:16:00 -0600 > >> 0.004445754 2012-11-14 22:16:07 -0600 > >> 0.024827767 2012-11-14 22:16:16 -0600 > >> 0.004718648 2012-11-14 22:16:29 -0600 > >> 0.543830541 2012-11-14 22:16:48 -0600 > >> 0.081387443 2012-11-14 22:16:57 -0600 > >> 0.093996291 2012-11-14 22:17:55 -0600 > >> 0.013581206 2012-11-14 22:18:01 -0600 > >> 0.455109956 2012-11-14 22:18:17 -0600 > >> 0.543997559 2012-11-14 22:18:20 -0600 > >> 0.006581586 2012-11-14 22:18:27 -0600 > >> 0.040279709 2012-11-14 22:18:52 -0600 > >> 3.9563892 2012-11-14 22:19:22 -0600 > >> 0.08867152 2012-11-14 22:19:36 -0600 > >> 0.044744453 2012-11-14 22:19:54 -0600 > >> 0.011553574 2012-11-14 22:20:14 -0600 > >> 0.151064978 2012-11-14 22:20:50 -0600 > >> > >> My munin graph shows disk utilization is at 33%. iostat often reports > >> util at 0% - 2%, but has bursts at 100%. > >> > >> Is it possible I have something misconfigured here or is there > something I > >> likely need to tune? Am I overloading the machine? It's my first day > >> throwing data at mongo, so if someone more experienced could offer any > >> insight, it would be much appreciated. > >> > >> Cheers, > >> > >> Tim > > > > -- > > 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 > ------=_Part_530_2465912.1353007329298 Content-Type: text/html; charset=utf-8 Content-Transfer-Encoding: 7bit I'm having a very similar issue. Flushing mmaps takes in general about 10000ms for 150 files and 300GB total but it sometimes jump even to 150000ms. During the flushing the db is basically not responsive. I noticed this while inserting data and creating indexes (I had to abort the operation even if in background).

I'm running MongoDB 2.2.1 for Windows 64-bit 2008R2+ on a WIndows Server 2008 R2 with NTFS File System. There about 200GB of disk space available and plenty of RAM that slowly ramps up to be 100% of utilization when this issue starts occurring.

On Thursday, November 15, 2012 7:08:45 PM UTC, Jason Lewis wrote:
What OS and filesystem?

On Thu, Nov 15, 2012 at 11:34 AM, Tim Haines <tmha...@gmail.com> wrote:
> The mmap flushing is even slower now..
>
> Thu Nov 15 10:25:50 [journal] old journal file will be removed:
> /var/lib/mongodb/journal/j._79
> Thu Nov 15 10:25:51 [journal] DR101 latency warning on journal file open
> 562ms
> Thu Nov 15 10:26:40 [DataFileSync] flushing mmaps took 27696ms  for 14 files
> Thu Nov 15 10:27:50 [DataFileSync] flushing mmaps took 37244ms  for 14 files
> Thu Nov 15 10:28:48 [DataFileSync] flushing mmaps took 35968ms  for 14 files
> Thu Nov 15 10:29:01 [journal] old journal file will be removed:
> /var/lib/mongodb/journal/j._80
> Thu Nov 15 10:29:38 [DataFileSync] flushing mmaps took 25631ms  for 14 files
> Thu Nov 15 10:30:35 [DataFileSync] flushing mmaps took 22286ms  for 14 files
> Thu Nov 15 10:31:50 [DataFileSync] flushing mmaps took 37886ms  for 14 files
>
> Tim.
>
> On Wednesday, November 14, 2012 8:46:42 PM UTC-8, Tim Haines wrote:
>>
>> Hi there,
>>
>> I've plugged mongo into my production system today to see how it handles
>> the write speed for a few days.  So far I only have one server with a 15k
>> RPM spinning disk and 8GB of ram.  If I take this to production properly, I
>> intend to shard, but hopefully to only 2 or 3 servers.
>>
>> Right now I'm doing about 200 upsert findAndModify's per second, and 200
>> upsert updates.  The stats tells me the averageObjSize is 129 bytes for the
>> documents receiving findAndModifys (4 indexes) and 91 bytes for the
>> documents receiving updates (1 index).  The dataset (data + indexes) is
>> currently around 1GB in total.
>>
>> I have these entries in the mongo logs - I don't know what they mean yet,
>> but they're concerning:
>>
>> Wed Nov 14 21:49:23 [DataFileSync] flushing mmaps took 10482ms  for 11
>> files
>> Wed Nov 14 21:53:23 [DataFileSync] flushing mmaps took 10520ms  for 11
>> files
>> Wed Nov 14 21:55:07 [websvr] serverStatus was very slow: { after basic: 0,
>> middle of mem: 1640, after mem: 1640, after connections: 1640, after extra
>> info: 1640, after counters: 1640, after repl: 1640, after asserts: 1640,
>> after dur: 1640, at end: 1640 }
>> Wed Nov 14 21:56:22 [DataFileSync] flushing mmaps took 10078ms  for 11
>> files
>> Wed Nov 14 21:57:04 [journal] old journal file will be removed:
>> /var/lib/mongodb/journal/j._46
>> Wed Nov 14 21:57:22 [DataFileSync] flushing mmaps took 10008ms  for 11
>> files
>> Wed Nov 14 22:00:23 [DataFileSync] flushing mmaps took 10751ms  for 11
>> files
>> Wed Nov 14 22:01:23 [DataFileSync] flushing mmaps took 11075ms  for 11
>> files
>> Wed Nov 14 22:05:11 [journal] old journal file will be removed:
>> /var/lib/mongodb/journal/j._47
>> Wed Nov 14 22:06:23 [DataFileSync] flushing mmaps took 10347ms  for 11
>> files
>> Wed Nov 14 22:07:24 [DataFileSync] flushing mmaps took 11479ms  for 11
>> files
>> Wed Nov 14 22:10:23 [DataFileSync] flushing mmaps took 10410ms  for 11
>> files
>> Wed Nov 14 22:11:23 [DataFileSync] flushing mmaps took 10340ms  for 11
>> files
>> Wed Nov 14 22:13:24 [DataFileSync] flushing mmaps took 11128ms  for 11
>> files
>> Wed Nov 14 22:13:27 [journal] old journal file will be removed:
>> /var/lib/mongodb/journal/j._48
>> Wed Nov 14 22:14:24 [DataFileSync] flushing mmaps took 11807ms  for 11
>> files
>> Wed Nov 14 22:15:24 [DataFileSync] flushing mmaps took 11205ms  for 11
>> files
>>
>> I'm not doing any reads yet, but I decided to check to see how consistent
>> they are - if the mmaps flushing is causing read stalls.
>>
>> I set up a simple query which fetches one record based on an index, and
>> had it repeat every second.  I log the duration and timestamp if it took
>> longer than 3ms (most were under 1ms).  This is the output I saw - some
>> operations taking multiple seconds for a single record query based on an
>> index.  Where all the data and indexes should still be in ram..
>>
>> 0.104574109 2012-11-14 22:13:54 -0600
>> 4.74783542 2012-11-14 22:14:22 -0600
>> 0.243556581 2012-11-14 22:14:25 -0600
>> 0.821347295 2012-11-14 22:14:30 -0600
>> 0.036629986 2012-11-14 22:14:56 -0600
>> 3.851662545 2012-11-14 22:15:05 -0600
>> 0.007991038 2012-11-14 22:15:10 -0600
>> 0.004475775 2012-11-14 22:15:57 -0600
>> 0.09404014 2012-11-14 22:16:00 -0600
>> 0.004445754 2012-11-14 22:16:07 -0600
>> 0.024827767 2012-11-14 22:16:16 -0600
>> 0.004718648 2012-11-14 22:16:29 -0600
>> 0.543830541 2012-11-14 22:16:48 -0600
>> 0.081387443 2012-11-14 22:16:57 -0600
>> 0.093996291 2012-11-14 22:17:55 -0600
>> 0.013581206 2012-11-14 22:18:01 -0600
>> 0.455109956 2012-11-14 22:18:17 -0600
>> 0.543997559 2012-11-14 22:18:20 -0600
>> 0.006581586 2012-11-14 22:18:27 -0600
>> 0.040279709 2012-11-14 22:18:52 -0600
>> 3.9563892 2012-11-14 22:19:22 -0600
>> 0.08867152 2012-11-14 22:19:36 -0600
>> 0.044744453 2012-11-14 22:19:54 -0600
>> 0.011553574 2012-11-14 22:20:14 -0600
>> 0.151064978 2012-11-14 22:20:50 -0600
>>
>> My munin graph shows disk utilization is at 33%.  iostat often reports
>> util at 0% - 2%, but has bursts at 100%.
>>
>> Is it possible I have something misconfigured here or is there something I
>> likely need to tune?  Am I overloading the machine?  It's my first day
>> throwing data at mongo, so if someone more experienced could offer any
>> insight, it would be much appreciated.
>>
>> Cheers,
>>
>> Tim
>
> --
> 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
------=_Part_530_2465912.1353007329298-- ------=_Part_529_2851085.1353007329298--