为何我的mongoDB写入数据这么慢？

Question

我用mongoDB管理股票行情数据，目前已保存行情数据约120GB，在一个Quote集合中包含ticks（448903576条记录）和bids（622612318条记录）两个数据表，两个数据表都建立有日期和代码索引。使用的是mongoDB 3.0.7版64位版本。

最近发现写入数据时会非常慢，经常有时写入一条记录要10多秒，正常时写入一条记录是100ms左右。朋友用的服务器远不如我的服务器配置，而且同样一个mongoDB表数据记录超过1亿条，依然能快速写入，不知为何。

摘取了部分log如下，能帮我分析一下原因吗？

2015-11-01T21:45:47.444+0800 I WRITE    [conn31] insert quote.bids query: { _id: ObjectId('563617890bda790fc8b98d17'), code: "000893", price: 3.552713678800501e-015, volume: 2, flag: "00C", dt: new Date(1446212410000) } ninserted:1 keyUpdates:0 writeConflicts:0 numYields:0 locks:{ Global: { acquireCount: { r: 6, w: 6 } }, MMAPV1Journal: { acquireCount: { w: 702 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 109947 } }, Database: { acquireCount: { w: 6 } }, Collection: { acquireCount: { W: 6 } } } 110ms
2015-11-01T21:45:47.456+0800 I COMMAND  [conn31] command quote.$cmd command: insert { insert: "bids", ordered: true, documents: 1000 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:40 locks:{ Global: { acquireCount: { r: 9, w: 9 } }, MMAPV1Journal: { acquireCount: { w: 1009 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 109947 } }, Database: { acquireCount: { w: 9 } }, Collection: { acquireCount: { W: 9 } } } 144ms
2015-11-01T21:46:08.731+0800 I COMMAND  [conn31] command quote.$cmd command: insert { insert: "bids", ordered: true, documents: 1000 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:40 locks:{ Global: { acquireCount: { r: 9, w: 9 } }, MMAPV1Journal: { acquireCount: { w: 1009 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 69102 } }, Database: { acquireCount: { w: 9 } }, Collection: { acquireCount: { W: 9 } } } 104ms
2015-11-01T21:46:20.071+0800 I WRITE    [conn31] insert quote.bids query: { _id: ObjectId('563617ab0bda790fc8bdf667'), code: "000916", price: 5.739999999999998, volume: 69, flag: "00B", dt: new Date(1446212949000) } ninserted:1 keyUpdates:0 writeConflicts:0 numYields:0 locks:{ Global: { acquireCount: { r: 4, w: 4 } }, MMAPV1Journal: { acquireCount: { w: 415 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 103010 } }, Database: { acquireCount: { w: 4 } }, Collection: { acquireCount: { W: 4 } } } 103ms
2015-11-01T21:46:20.093+0800 I COMMAND  [conn31] command quote.$cmd command: insert { insert: "bids", ordered: true, documents: 1000 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:40 locks:{ Global: { acquireCount: { r: 9, w: 9 } }, MMAPV1Journal: { acquireCount: { w: 1009 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 103010 } }, Database: { acquireCount: { w: 9 } }, Collection: { acquireCount: { W: 9 } } } 137ms
2015-11-01T21:46:26.793+0800 I COMMAND  [conn31] command quote.$cmd command: insert { insert: "bids", ordered: true, documents: 1000 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:40 locks:{ Global: { acquireCount: { r: 9, w: 9 } }, MMAPV1Journal: { acquireCount: { w: 1009 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 71011 } }, Database: { acquireCount: { w: 9 } }, Collection: { acquireCount: { W: 9 } } } 101ms
2015-11-01T21:46:36.054+0800 I COMMAND  [conn31] command quote.$cmd command: insert { insert: "bids", ordered: true, documents: 1000 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:40 locks:{ Global: { acquireCount: { r: 9, w: 9 } }, MMAPV1Journal: { acquireCount: { w: 1009 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 73748 } }, Database: { acquireCount: { w: 9 } }, Collection: { acquireCount: { W: 9 } } } 113ms
2015-11-01T21:46:51.225+0800 I STORAGE  [DataFileSync] flushing mmaps took 63267ms  for 12 files


*****以下是最近异常的log记录*****
2015-11-29T08:29:59.714+0800 I WRITE    [conn65] insert quote.ticks query: { _id: ObjectId('565a46d50bda79121c058f73'), code: "603066", price: 58.43, volume: 1.0, dt: new Date(1448631616000), side: "S" } ninserted:1 keyUpdates:0 writeConflicts:0 numYields:0 locks:{ Global: { acquireCount: { r: 115, w: 115 } }, MMAPV1Journal: { acquireCount: { w: 527 }, acquireWaitCount: { w: 12 }, timeAcquiringMicros: { w: 122008 } }, Database: { acquireCount: { w: 115 } }, Collection: { acquireCount: { W: 115 }, acquireWaitCount: { W: 115 }, timeAcquiringMicros: { W: 2526086 } } } 140ms
2015-11-29T08:29:59.714+0800 I WRITE    [conn63] insert quote.ticks query: { _id: ObjectId('565a46f70bda791154306e11'), code: "600395", price: 8.050000000000001, volume: 78.0, dt: new Date(1448617010000), side: "S" } ninserted:1 keyUpdates:0 writeConflicts:0 numYields:0 locks:{ Global: { acquireCount: { r: 409, w: 409 } }, MMAPV1Journal: { acquireCount: { w: 1761 }, acquireWaitCount: { w: 25 }, timeAcquiringMicros: { w: 115750 } }, Database: { acquireCount: { w: 409 } }, Collection: { acquireCount: { W: 409 }, acquireWaitCount: { W: 409 }, timeAcquiringMicros: { W: 13637358 } } } 141ms
2015-11-29T08:29:59.714+0800 I WRITE    [conn67] insert quote.ticks query: { _id: ObjectId('565a46e90bda79179838a80e'), code: "000790", price: 15.19, volume: 2.0, dt: new Date(1448619704000), side: "S" } ninserted:1 keyUpdates:0 writeConflicts:0 numYields:0 locks:{ Global: { acquireCount: { r: 224, w: 224 } }, MMAPV1Journal: { acquireCount: { w: 1255 }, acquireWaitCount: { w: 20 }, timeAcquiringMicros: { w: 50202 } }, Database: { acquireCount: { w: 224 } }, Collection: { acquireCount: { W: 224 }, acquireWaitCount: { W: 224 }, timeAcquiringMicros: { W: 5196956 } } } 141ms
2015-11-29T08:30:00.101+0800 I COMMAND  [conn63] command quote.$cmd command: insert { insert: "ticks", ordered: true, documents: 1000 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:40 locks:{ Global: { acquireCount: { r: 421, w: 421 } }, MMAPV1Journal: { acquireCount: { w: 1842 }, acquireWaitCount: { w: 27 }, timeAcquiringMicros: { w: 133006 } }, Database: { acquireCount: { w: 421 } }, Collection: { acquireCount: { W: 421 }, acquireWaitCount: { W: 421 }, timeAcquiringMicros: { W: 13865934 } } } 16363ms
2015-11-29T08:30:01.036+0800 I WRITE    [conn65] insert quote.ticks query: { _id: ObjectId('565a46d50bda79121c058fdf'), code: "603066", price: 58.7, volume: 5.0, dt: new Date(1448631877000), side: "S" } ninserted:1 keyUpdates:0 writeConflicts:0 numYields:0 locks:{ Global: { acquireCount: { r: 153, w: 153 } }, MMAPV1Journal: { acquireCount: { w: 711 }, acquireWaitCount: { w: 16 }, timeAcquiringMicros: { w: 123164 } }, Database: { acquireCount: { w: 153 } }, Collection: { acquireCount: { W: 153 }, acquireWaitCount: { W: 153 }, timeAcquiringMicros: { W: 3215329 } } } 108ms

Answer 1

你说的异常操作情况也没有计时也是100+ms啊，是不是其他部分出现问题了

Answer 2

timeAcquiringMicros: { W: 13865934 } 耗时好像主要发生在获得锁上，你是不是进行过服务器同步操作

Answer 3

请问楼主解决了吗？我用的是mongodb 3.0.5 版本，做了分片后也有这个问题，插入数据时非常慢

Answer 4

我在进行集群测试的时候,也发现了这样的问题,在插入2亿条数据之后继续插入海量数据时,会发现间隔2分钟左右出现一阵(15秒)插入阻塞.
监控系统性能后发现,在阻塞发生的时候,是对索引文件进行操作的时候,写盘速度能达到40MB/S.
基本可以确认,应该是索引散列度较大,且不是单纯递增的,所以出现了对索引文件的调整导致的.
目前分析,只能是扩展内存,升级磁盘阵列性能才能有所缓解了,否则就得调整索引结构,牺牲查询性能了.

Answer 5

请问楼主最后是怎么解决的问题 遇到类似问题 苦恼中