Background index creation inflates concurrent inserts/s operations

[Andrew Armstrong]

Hi,

I was just playing with MongoDB 1.6.5 (and development 1.7.6) and I
notice that if I am inserting a lot of items concurrently (using a for
loop at a mongo console) and perform a background index, the inserts/s
figure increases while background indexing. I am on Windows 7 64bit.

Is it really increasing or is there some bug here?

1) Start off with this running on a separate console:
> for(var i = 1; i < 10000000; i++) db.things.save({x:1, i: i});

2) Mongostat is running and showing about 8000 inserts/sec
---
insert query update delete getmore command flushes mapped vsize
res locked % idx miss % qr|qw ar|aw netIn netOut conn
time
7818 0 0 0 0 5 0 1.95g 2.01g
908m 13.1 0 0|0 0|0 594k 1k 3
19:46:55
8607 0 0 0 0 1 0 1.95g 2.01g
909m 14.7 0 0|0 0|0 654k 995b 3
19:46:56
7616 0 0 0 0 1 0 1.95g 2.01g
910m 12.5 0 0|0 0|0 578k 995b 3
19:46:57
7869 0 0 0 0 1 0 1.95g 2.01g
911m 13.1 0 0|0 0|0 598k 995b 3
19:46:59
8521 0 0 0 0 1 0 1.95g 2.01g
912m 15 0 0|0 0|0 647k 995b 3
19:47:00
7764 0 0 0 0 1 0 1.95g 2.01g
912m 13.5 0 0|0 0|0 590k 995b 3
19:47:01
7820 0 0 0 0 1 0 1.95g 2.01g
913m 13.5 0 0|0 0|0 594k 995b 3
19:47:02
---
I then run this command on another console talking to the same mongod:
> db.things.ensureIndex({c:1}, {background:1});

It does not matter what I am indexing (the 'c' field or 'a' or 'x'
etc).

Mongostat then shows a clear increase in inserts/sec:
---
9032 0 0 0 0 1 0 1.95g 2.01g
914m 26.3 0 0|1 0|2 686k 995b 3
19:47:03
12033 0 0 0 0 1 0 1.95g 2.01g
915m 67 0 0|1 0|2 914k 995b 3
19:47:04
11874 0 0 0 0 1 0 1.95g 2.01g
916m 71.8 0 0|1 0|2 902k 995b 3
19:47:05
insert query update delete getmore command flushes mapped vsize
res locked % idx miss % qr|qw ar|aw netIn netOut conn
time
10296 0 0 0 0 1 0 1.95g 2.01g
917m 82.9 0 0|1 0|2 782k 995b 3
19:47:06
10084 0 0 0 0 1 0 1.95g 2.01g
918m 82.9 0 0|0 0|1 766k 995b 3
19:47:07
9263 0 0 0 0 1 0 1.95g 2.01g
919m 78.1 0 0|1 0|2 704k 995b 3
19:47:08
10551 0 0 0 0 1 0 1.95g 2.01g
920m 81.1 0 0|1 0|2 801k 995b 3
19:47:09
8901 0 0 0 0 1 0 1.95g 2.01g
921m 80.2 0 0|1 0|2 676k 995b 3
19:47:10
11607 0 0 0 0 1 0 1.95g 2.01g
922m 72.4 0 0|1 0|2 882k 995b 3
19:47:11
13200 0 0 0 0 1 0 1.95g 2.01g
923m 72.9 0 0|1 0|2 1m 995b 3
19:47:12
12968 0 0 0 0 1 0 1.95g 2.01g
924m 72.8 0 0|1 0|2 985k 995b 3
19:47:13
13302 0 0 0 0 1 0 1.95g 2.01g
924m 73.1 0 0|1 0|2 1m 995b 3
19:47:14
13332 0 0 0 0 1 0 1.95g 2.01g
925m 71.7 0 0|1 0|2 1m 995b 3
19:47:15
insert query update delete getmore command flushes mapped vsize
res locked % idx miss % qr|qw ar|aw netIn netOut conn
time
13565 0 0 0 0 1 0 1.95g 2.01g
926m 72.3 0 0|0 0|1 1m 995b 3
19:47:16

... snip excess stats ...

13153 0 0 0 0 1 0 1.95g 2.01g
991m 83.9 0 0|1 0|2 999k 995b 3
19:47:59
12038 0 0 0 0 1 0 1.95g 2.01g
992m 86.6 0 0|1 0|2 914k 995b 3
19:48:00
10545 0 0 0 0 1 0 1.95g 2.01g
993m 84.5 0 0|1 0|2 801k 995b 3
19:48:01
7651 0 0 0 0 4 0 1.95g 2.01g
993m 19.5 0 0|0 0|0 581k 1k 3
19:48:02
7782 0 0 0 0 1 0 1.95g 2.01g
994m 15.6 0 0|0 0|0 591k 995b 3
19:48:03
7622 0 0 0 0 1 0 1.95g 2.01g
995m 17.4 0 0|0 0|0 579k 995b 3
19:48:04
7670 0 0 0 0 1 0 1.95g 2.01g
995m 16.3 0 0|0 0|0 582k 995b 3
19:48:05
8226 0 0 0 0 1 0 1.95g 2.01g
996m 19.8 0 0|0 0|0 625k 995b 3
19:48:06
insert query update delete getmore command flushes mapped vsize
res locked % idx miss % qr|qw ar|aw netIn netOut conn
time
8019 0 0 0 0 1 0 1.95g 2.01g
997m 18.7 0 0|0 0|0 609k 995b 3
19:48:07
7358 0 0 0 0 1 0 1.95g 2.01g
997m 16.2 0 0|0 0|0 559k 995b 3
19:48:08
7194 0 0 0 0 1 0 1.95g 2.01g
998m 18.3 0 0|0 0|0 546k 995b 3
19:48:09
7760 0 0 0 0 1 0 1.95g 2.01g
999m 12.6 0 0|0 0|0 589k 995b 3
19:48:10
7586 0 0 0 0 1 0 1.95g 2.01g
999m 17.1 0 0|0 0|0 576k 995b 3
19:48:11
---

3) Finally the inserts/sec drop back to what they were when the
background index operation finishes.

Not sure if this is a real bug or problem, just found it interesting.

- Andrew

[Scott Hernandez]

That is interesting; can you create an issue in jira? Please include
your hardware and software specs.

I was not able to re-create the issue.
https://gist.github.com/57d29865e3a7169bf05c

As you can see from my results the inserts/s drop by 15+ % when I
start to create the index.

> --
> 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.
> For more options, visit this group at http://groups.google.com/group/mongodb-user?hl=en.
>
>

[Andrew Armstrong]

Created http://jira.mongodb.org/browse/SERVER-2593 - thanks.

On Feb 19, 12:01 am, Scott Hernandez <scotthernan...@gmail.com> wrote:
> That is interesting; can you create an issue in jira? Please include
> your hardware and software specs.
>

> I was not able to re-create the issue.https://gist.github.com/57d29865e3a7169bf05c