[SERVER-2593] Background index creation inflates concurrent inserts/s operations in mongostat Created: 19/Feb/11  Updated: 30/Mar/12  Resolved: 19/Feb/11

Status: Closed
Project: Core Server
Component/s: Tools, Usability
Affects Version/s: 1.6.5, 1.7.6
Fix Version/s: None

Type: Bug Priority: Minor - P4
Reporter: Andrew Armstrong Assignee: Robert Stam
Resolution: Cannot Reproduce Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Windows 7 64bit, Intel i7 CPU 8 Core, 8GB RAM


Operating System: ALL
Participants:

 Description   

(Copied from http://groups.google.com/group/mongodb-user/browse_thread/thread/f65c2178ade3f9c8)

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.



 Comments   
Comment by Andrew Armstrong [ 20/Feb/11 ]

I start with an empty collection and then after waiting for the for loop ^ to run (or this: while(true) db.things.save(

{x:1}

) I wait a while until the index operation takes a few seconds (so I can see the results in mongostat).

That sounds quite plausible, I have plenty of free RAM.

Comment by Eliot Horowitz (Inactive) [ 20/Feb/11 ]

How big is the data set when you start to add index?
The only thing that makes sense is that the OS is keeping more of the index hot causing fewer page faults
From your mongostat, it does look like that could be the issue.

To be more specific.

Your'e inserting data and index.
As you add, the data and index gets paged out evenly.
With more inserts, some index pages have to get loaded back in.
If the background index is happening, the index is hotter, causing it to be more sticky in ram, forcing less data in ram.
This makes insertions faster since there are fewer faults accessing b-tree

Comment by Andrew Armstrong [ 20/Feb/11 ]

I gave this another go this morning and even created a new database (using --dbpath), same result.

I noticed that if I assign just a single CPU core to mongod, then the inserts/s decreases during background indexing as I would have expected to see.

If I let it use a lot more cores, the problem appears.

Comment by Robert Stam [ 19/Feb/11 ]

FYI, I am testing query performance in a different scenario, and I am loading a collection with just over 5 million documents. I was inserting at the rate of about 17000/second until I started a background index creation, at which point the insert rate dropped to about 15000/second. This makes more sense, that the rate should drop slightly. One difference is that in my new scenario I have a more complicated document.

Comment by Eliot Horowitz (Inactive) [ 19/Feb/11 ]

Ok.

@andrew, can you try this again and see if you get the same results?
if so, please let us know and give us as much detail about the system as you possibly can

Comment by Robert Stam [ 19/Feb/11 ]

First I started off the insert loop.

After it had inserted about 500,000 documents I issued the ensureIndex command from another window, so at that point the loop and the background index build were running concurrently.

Comment by Eliot Horowitz (Inactive) [ 19/Feb/11 ]

@robert, did you try it concurrently?

Comment by Robert Stam [ 19/Feb/11 ]

On a Windows 7 64-bit machine with 4GB RAM and a 1TB hard drive I get about 10-11K inserts per second.

I saw essentially NO change in the speed after the ensureIndex command was run.

Comment by Scott Hernandez (Inactive) [ 19/Feb/11 ]

As noted from the groups message, I was not able to reproduce this with 1.7.6.

My machine is considerable less powerful, if that matters.

Comment by Eliot Horowitz (Inactive) [ 19/Feb/11 ]

@robert, can you try this on windows

Comment by Andrew Armstrong [ 19/Feb/11 ]

Also this is just a single server running, there is no replica sets.

Generated at Thu Feb 08 03:00:29 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.