All geek questions in one place

Surprisingly slow insertion into the collection with the mangodb collection

I use the mongodb capped + tailable cursors collections as a pubsub engine using pymongo. (This approach is described here ). My environment includes several topics, several publishers, and dozens of subscribers.

This works great, except that every time I come across plugin operations that allow a surprisingly long time to complete .

I understand that mongodb can support insertion> 10K docs / sec, so I am surprised that one insertion operation can take 85 ms . (I also observed> 1sec several times in my working environment, but could not reproduce it using this SSCCE).

To minimize delays, logging is disabled, and I use the lowest recording issue that helped but didn't solve the problem.

What causes this and how can I fix it?

Here is the SSCCE . I run the following script twice in parallel:

import time, pymongo, pandas as pd DBNAME = 'test5' COLLNAME = 'abc' mongo = pymongo.MongoClient() #mongo[DBNAME].drop_collection(COLLNAME) if DBNAME not in mongo.database_names(): coll = mongo[DBNAME].create_collection(COLLNAME, capped = True, size = 50 * 1024 * 1024, max = 1024 * 1024, fsync = False, # no delays please (FYI, journaling is disabled) #autoIndexId = False, ) tarr = [] for _ in range(1000): msg = dict.fromkeys([ 'f%d' % j for j in range(30) ], 'foo') t1 = time.time() coll.insert(msg) # <-- INSERT() HERE tarr.append(time.time() - t1) time.sleep(1./100) # 100 docs/sec. surely not too much load... print pd.Series(tarr).describe()

Ouput:

 RUN1: count 1000.000000 mean 0.001555 std 0.002712 min 0.000654 25% 0.001021 50% 0.001084 75% 0.001151 max 0.065006 <-- 65ms!! dtype: float64 RUN2: count 1000.000000 mean 0.001733 std 0.004013 min 0.000717 25% 0.001043 50% 0.001069 75% 0.001120 max 0.084803 <-- 84ms!! dtype: float64

Index Information:

 mongo[DBNAME][COLNAME].index_information() > {u'_id_': {u'key': [(u'_id', 1)], u'ns': u'xxxxx', u'v': 1}}

Information about mongodb:

 db version v3.2.0-rc0 git version: bf28bd20fa507c4d8cc5919dfbbe87b7750ae8b0 OpenSSL version: OpenSSL 1.0.1f 6 Jan 2014 allocator: tcmalloc modules: none build environment: distmod: ubuntu1404 distarch: x86_64 target_arch: x86_64 "storageEngine" : { "name" : "mmapv1", "supportsCommittedReads" : false } journaling DISABLED pymongo version = 3.0.3

The output of iostat -xtm 5 during the experiment:

 *** BEFORE *** 11/08/2015 09:05:02 AM avg-cpu: %user %nice %system %iowait %steal %idle 6.11 0.95 0.49 0.10 0.00 92.35 Device: rrqm/s wrqm/sr/sw/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sda 0.00 10.20 0.00 6.80 0.00 0.08 24.71 0.14 20.12 0.00 20.12 2.82 1.92 dm-0 0.00 0.00 0.00 17.00 0.00 0.08 9.88 0.24 13.84 0.00 13.84 1.13 1.92 dm-1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 dm-2 0.00 0.00 0.00 7.80 0.00 0.03 8.41 0.04 4.92 0.00 4.92 2.05 1.60 dm-3 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 *** DURING *** 11/08/2015 09:05:07 AM avg-cpu: %user %nice %system %iowait %steal %idle 9.25 0.26 0.55 0.26 0.00 89.67 Device: rrqm/s wrqm/sr/sw/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sda 0.00 13.60 0.00 40.60 0.00 0.59 29.52 4.84 119.15 0.00 119.15 1.60 6.48 dm-0 0.00 0.00 0.00 54.20 0.00 0.59 22.11 5.00 92.18 0.00 92.18 1.20 6.48 dm-1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 dm-2 0.00 0.00 0.00 4.20 0.00 0.02 9.14 0.01 2.29 0.00 2.29 2.29 0.96 dm-3 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 11/08/2015 09:05:12 AM avg-cpu: %user %nice %system %iowait %steal %idle 8.02 0.26 0.41 0.44 0.00 90.88 Device: rrqm/s wrqm/sr/sw/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sda 0.00 19.00 0.00 109.80 0.00 0.63 11.82 22.95 209.01 0.00 209.01 1.84 20.24 dm-0 0.00 0.00 0.00 128.80 0.00 0.63 10.07 25.55 198.37 0.00 198.37 1.57 20.24 dm-1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 dm-2 0.00 0.00 0.00 4.40 0.00 0.02 8.00 0.02 4.73 0.00 4.73 2.18 0.96 dm-3 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 11/08/2015 09:05:17 AM avg-cpu: %user %nice %system %iowait %steal %idle 5.81 0.27 0.39 0.16 0.00 93.37 Device: rrqm/s wrqm/sr/sw/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sda 0.00 8.40 0.00 24.80 0.00 0.29 24.19 0.26 10.55 0.00 10.55 1.94 4.80 dm-0 0.00 0.00 0.00 33.20 0.00 0.29 18.07 0.31 9.35 0.00 9.35 1.45 4.80 dm-1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 dm-2 0.00 0.00 0.00 3.40 0.00 0.01 8.94 0.01 2.35 0.00 2.35 2.35 0.80 dm-3 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 *** AFTER *** 11/08/2015 09:05:22 AM avg-cpu: %user %nice %system %iowait %steal %idle 5.85 0.40 0.46 0.00 0.00 93.28 Device: rrqm/s wrqm/sr/sw/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sda 0.00 3.80 0.00 0.40 0.00 0.02 84.00 0.00 6.00 0.00 6.00 6.00 0.24 dm-0 0.00 0.00 0.00 4.20 0.00 0.02 8.00 0.03 7.81 0.00 7.81 0.57 0.24 dm-1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 dm-2 0.00 0.00 0.00 1.60 0.00 0.01 11.00 0.00 0.00 0.00 0.00 0.00 0.00 dm-3 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00

UPDATE : we switched mongodb to run in memory (as described here ). The machine has enough memory to support it. Surprisingly, this did not help! We still see the same “bursts” during input. Something strange is happening. I have no idea what it is.

UPDATE : we also upgraded to mongodb V3.2 in memory. The same results.

+5
source share
1 answer

It seems that the problem is that you are using completely non-blocking entries when creating the collection (call create_collection ), and not when pasting.

You can disable write confirmation at the MongoClient level as:

 mongo = pymongo.MongoClient(w=0)

Or just for insert :

 coll.insert(msg, w=0)

In any case, the maximum time drops to 0.001 when I try to execute it locally on a regular 3.2 MongoDB drive using WiredTiger.

+1
source

Source: https://habr.com/ru/post/1235190/

More articles:


All Articles