Received: by 10.50.0.170 with SMTP id 10mr1332644igf.4.1352954822706;
Wed, 14 Nov 2012 20:47:02 -0800 (PST)
X-BeenThere: mongodb-user@googlegroups.com
Received: by 10.50.40.227 with SMTP id a3ls252095igl.20.canary; Wed, 14 Nov
2012 20:46:42 -0800 (PST)
Received: by 10.50.181.232 with SMTP id dz8mr247770igc.11.1352954802615;
Wed, 14 Nov 2012 20:46:42 -0800 (PST)
Date: Wed, 14 Nov 2012 20:46:42 -0800 (PST)
From: Tim Haines <tmhai...@gmail.com>
To: mongodb-user@googlegroups.com
Message-Id: <f0b9a414-c98b-449f-8551-558d41ea7e28@googlegroups.com>
Subject: inconsistent read speed - logs with flushing mmaps took 11205ms in
the log
MIME-Version: 1.0
Content-Type: multipart/mixed;
boundary="----=_Part_234_10684116.1352954802045"
------=_Part_234_10684116.1352954802045
Content-Type: multipart/alternative;
boundary="----=_Part_235_18183355.1352954802045"
------=_Part_235_18183355.1352954802045
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 7bit
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
------=_Part_235_18183355.1352954802045
Content-Type: text/html; charset=utf-8
Content-Transfer-Encoding: quoted-printable
Hi there,<div><br></div><div>I've plugged mongo into my production system t=
oday to see how it handles the write speed for a few days. So far I o=
nly 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.</div><div><br></div><div>Right now I'm doing about 200 ups=
ert findAndModify's per second, and 200 upsert updates. The stats tel=
ls me the averageObjSize is 129 bytes for the documents receiving findAndMo=
difys (4 indexes) and 91 bytes for the documents receiving updates (1 index=
). The dataset (data + indexes) is currently around 1GB in total.</di=
v><div><br></div><div>I have these entries in the mongo logs - I don't know=
what they mean yet, but they're concerning:</div><div><br></div><div><div>=
Wed Nov 14 21:49:23 [DataFileSync] flushing mmaps took 10482ms for 11=
files</div><div>Wed Nov 14 21:53:23 [DataFileSync] flushing mmaps took 105=
20ms for 11 files</div><div>Wed Nov 14 21:55:07 [websvr] serverStatus=
was very slow: { after basic: 0, middle of mem: 1640, after mem: 1640, aft=
er connections: 1640, after extra info: 1640, after counters: 1640, after r=
epl: 1640, after asserts: 1640, after dur: 1640, at end: 1640 }</div><div>W=
ed Nov 14 21:56:22 [DataFileSync] flushing mmaps took 10078ms for 11 =
files</div><div>Wed Nov 14 21:57:04 [journal] old journal file will be remo=
ved: /var/lib/mongodb/journal/j._46</div><div>Wed Nov 14 21:57:22 [DataFile=
Sync] flushing mmaps took 10008ms for 11 files</div><div>Wed Nov 14 2=
2:00:23 [DataFileSync] flushing mmaps took 10751ms for 11 files</div>=
<div>Wed Nov 14 22:01:23 [DataFileSync] flushing mmaps took 11075ms f=
or 11 files</div><div>Wed Nov 14 22:05:11 [journal] old journal file will b=
e removed: /var/lib/mongodb/journal/j._47</div><div>Wed Nov 14 22:06:23 [Da=
taFileSync] flushing mmaps took 10347ms for 11 files</div><div>Wed No=
v 14 22:07:24 [DataFileSync] flushing mmaps took 11479ms for 11 files=
</div><div>Wed Nov 14 22:10:23 [DataFileSync] flushing mmaps took 10410ms &=
nbsp;for 11 files</div><div>Wed Nov 14 22:11:23 [DataFileSync] flushing mma=
ps took 10340ms for 11 files</div><div>Wed Nov 14 22:13:24 [DataFileS=
ync] flushing mmaps took 11128ms for 11 files</div><div>Wed Nov 14 22=
:13:27 [journal] old journal file will be removed: /var/lib/mongodb/journal=
/j._48</div><div>Wed Nov 14 22:14:24 [DataFileSync] flushing mmaps took 118=
07ms for 11 files</div><div>Wed Nov 14 22:15:24 [DataFileSync] flushi=
ng mmaps took 11205ms for 11 files</div></div><div><br></div><div>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.</div><div><br></div><d=
iv>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 to=
ok 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..</di=
v><div><br></div><div><div>0.104574109 2012-11-14 22:13:54 -0600</div><div>=
<b>4.74783542</b> 2012-11-14 22:14:22 -0600</div><div>0.243556581 2012-11-1=
4 22:14:25 -0600</div><div>0.821347295 2012-11-14 22:14:30 -0600</div><div>=
0.036629986 2012-11-14 22:14:56 -0600</div><div><b>3.851662545</b> 2012-11-=
14 22:15:05 -0600</div><div>0.007991038 2012-11-14 22:15:10 -0600</div><div=
>0.004475775 2012-11-14 22:15:57 -0600</div><div>0.09404014 2012-11-14 22:1=
6:00 -0600</div><div>0.004445754 2012-11-14 22:16:07 -0600</div><div>0.0248=
27767 2012-11-14 22:16:16 -0600</div><div>0.004718648 2012-11-14 22:16:29 -=
0600</div><div>0.543830541 2012-11-14 22:16:48 -0600<br></div><div>0.081387=
443 2012-11-14 22:16:57 -0600</div><div>0.093996291 2012-11-14 22:17:55 -06=
00</div><div>0.013581206 2012-11-14 22:18:01 -0600</div><div>0.455109956 20=
12-11-14 22:18:17 -0600</div><div>0.543997559 2012-11-14 22:18:20 -0600</di=
v><div>0.006581586 2012-11-14 22:18:27 -0600</div><div>0.040279709 2012-11-=
14 22:18:52 -0600</div><div><b>3.9563892</b> 2012-11-14 22:19:22 -0600</div=
><div>0.08867152 2012-11-14 22:19:36 -0600</div><div>0.044744453 2012-11-14=
22:19:54 -0600</div><div>0.011553574 2012-11-14 22:20:14 -0600</div><div>0=
.151064978 2012-11-14 22:20:50 -0600</div><div><br></div></div><div>My muni=
n graph shows disk utilization is at 33%. iostat often reports util a=
t 0% - 2%, but has bursts at 100%.<br></div><div><br></div><div>Is it possi=
ble I have something misconfigured here or is there something I likely need=
to tune? Am I overloading the machine? It's my first day throw=
ing data at mongo, so if someone more experienced could offer any insight, =
it would be much appreciated. </div><div><br></div><div>Cheers,</div>=
<div><br></div><div>Tim</div>
------=_Part_235_18183355.1352954802045--
------=_Part_234_10684116.1352954802045--
Message from discussion inconsistent read speed - logs with flushing mmaps took 11205ms in the log
| Create a group - Google Groups - Google Home - Terms of Service - Privacy Policy |
| ©2013 Google |