Re: [mongodb-user] spikes in read performance during write operation

[Luciano Issoe]

I think you´re locking the database while doing these updates. You can read secondaries, all the drivers support it. In Ruby, you just have to set read : secondary at the connection level. 

But be aware that your reads will be eventually consistent...

On Thu, Aug 2, 2012 at 9:13 AM, Michael Illgner <michael...@googlemail.com> wrote:

Hi Folks
We are storing lots (~15.000.000) of simple documents (about 10 attributes with one additional index) in a single collection, the application justs reads single documents by an indexed field (eg. col.find({'id':12345}), usually this read takes about 1ms which seems to be OK.
Once a day, most documents have to be updated and some have to be "expired", this is done by a simple update (col.update({'id':123, {$set, {...}}}) in a 'loop'
During the update about 1% of the reads last for a very long time, upto 10 secs and more !!!, the other 99% seems not to be affected.

We use mongodb 2.06 with sharding and replica sets (two nodes) , but currently only one shard is used (and configured).
Any idea what is going on here and where we should start looking ?

Is it possible to use an of the nodes for the update and the other node for the read operations ?

Thanks in advance

--
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
See also the IRC channel -- freenode.net#mongodb

[William Z]

Hi Michael!

1) MongoDB has a "greedy writer" lock with yielding.  This means that writes will block reads, and pending writes will block out pending reads.  See here for more details:
  - http://www.mongodb.org/display/DOCS/How+does+concurrency+work#Howdoesconcurrencywork-mongod

It is likely that your reads are waiting based on having your collection locked for a long time by your batch update, but we don't have enough information in your problem description to tell for sure.

The best way for you to diagnose this issue is for you to run 'mongostat' while you're doing your updates and queries.  The columns to look at are the lock%, as well as the queued reads (qr) and queued writes (qw). 

If you could post the output of that command at the time that you're seeing the slowdown, it would help a lot in diagnosing your problem.

2) If you're willing to have your queries retrieve possibly-stale data, then you can direct your reads to the secondary member of the replica set using the SlaveOK directive.

Note that because the secondary members of a replica set will be some amount of time behind the primary member, you will not get guaranteed read-after-write semantics if you use SlaveOK reads.  You may or may not be OK with this.

Starting with MongoDB 2.2, you'll be able to use read preferences and tag sets to have more fine-grained control over where the queries go.

See here for more information:
 - http://docs.mongodb.org/manual/applications/replication/#read-preference
 - http://www.mongodb.org/display/DOCS/Querying

Let me know if you have further questions.

 -William

[William Z]

Hi Michael!

1) You can set the 'slaveOk()' property on the Mongo object within your code.  You can either apply it to the Mongo object, or to a DBCollection Object.

Ref:
 - http://api.mongodb.org/java/current/com/mongodb/Mongo.html#slaveOk%28%29
 - http://api.mongodb.org/java/current/com/mongodb/DBCollection.html#slaveOk%28%29

2) Can you post some sample output from 'mongostat' while the slowdown is happening?  It would also help if you can post the output of db.currentOp() from the shell during the slowdown, as that might give a hint as to what is the blocking operation.

3) Is the 'refDate' columned indexed?  If not, that could be the cause of your problem.
What is the output of db.find({$or':[{'refDate':null}, {'refDate':{$lt, ISO_Date(....)}}]}).explain() ?

4) 95% lock percentage is not OK.  At that level, you'll get reader starvation.  This is the most likely cause of the slowdown you're seeing. 

5) If you're doing multiple inserts/updates in a loop, then you can slow down the write operations in order to to get better read performance.  There are two ways to do this. 
  - You can insert some sleep() operations between the writes in order to allow the queued readers time to satisfy their requests.

  - You can insert some getLastError() commands into your stream of inserts and updates, using a WriteConcern of REPLICAS_SAFE. 

Using the WriteConcern is arguably the more elegant way to do this.  It will cause MongoDB to not allow the next write operation to go forward until the write has propagated to at least one secondary before the write call returns.  Doing this will cause the next write to block for a while, thus allowing the waiting readers to come in.

You would only want to do this once every thousand write operations or so, since specifying REPLICAS_SAFE will severely impact performance.

6) If the operation that's causing the slowdown is a single massive update() command, then the techniques described in (4) above won't work for you.   If that's the case, then you may need to restructure your update to do less work in one unit in order to allow the readers to proceed. 

You may have to break up your update into multiple smaller updates.  For example, if you're updating everything in the last 24 hours, you might have to restructure your update to update one hour's worth of data at a time.

Please let me know if you have further questions.

 -William


On Friday, August 3, 2012 2:39:56 AM UTC-7, Michael Illgner wrote:

Thanks for the answers

Our update/insert loop takes abount 20min, the interesting point ist that most of the 'timeouts' occur in the first 1-2 minutes of the process, after that everything is fine.
At last we have a kind of cleanup command to expire some 'old' date

update({'$or':[{'refDate':null}, {'refDate':{$lt, ISO_Date(....)}}]}, {'$set': {'status':0}})

this command runs about 5min and during its execution we have some more time, mongostatshows that the global lock ist about 95%, which seems to be OK, because this command affects most of the data,

for the slaveOK parameter

Both write and update application should use the same MongoURI pointing to the same router/mongos process, but the 'reader' should append slaveOK=true to the uri ?

BTW
We are using the java driver 2.8

[Michael Illgner]

Hi William

The query.explain() shows

{
        "cursor" : "BasicCursor",
        "nscanned" : 16388521,
        "nscannedObjects" : 16388521,
        "n" : 0,
        "millis" : 28472,
        "nYields" : 13,
        "nChunkSkips" : 0,
        "isMultiKey" : false,
        "indexOnly" : false,
        "indexBounds" : {

        }
}


Finally I got the slaveOK option working and we "slowed" don the data import by using a small delay as suggested. A typical output of mongostat during the import is

                 insert  query update delete getmore command flushes mapped  vsize    res faults locked % idx miss %     qr|qw   ar|aw  netIn netOut  conn     set repl       time
pf1:27018         0      0   5098      0     133      14       0  64.3g  66.1g  48.1g      0     93.1          0       0|0     0|1     2m     2m    97 shard-a    M   12:59:58
pf2:27018        *0     *0  *5006     *0       0     2|0       0  32.3g  32.7g  29.4g      0     80.9          0       0|0     0|0   188b     1k    10 shard-a  SEC   12:59:58

pf1:27018         0      0   5122      0     189       2       0  64.3g  66.1g  48.1g      0     92.9          0       0|0     0|1     2m     2m    97 shard-a    M   12:59:59
pf2:27018        *0     *0  *5106     *0       0     6|0       0  32.3g  32.7g  29.4g      1     83.1          0       0|0     0|0   436b     3k    10 shard-a  SEC   12:59:59

pf1:27018         0      0   5213      0      49       2       0  64.3g  66.1g  48.1g      0     93.4          0       0|0     0|1     2m     2m    97 shard-a    M   13:00:00
pf2:27018        *0     *0  *4937     *0       0     2|0       0  32.3g  32.7g  29.4g      0     78.4          0       0|0     0|0   188b     1k    10 shard-a  SEC   13:00:00

pf1:27018         0      0   5213      0      49       2       0  64.3g  66.1g  48.1g      0     93.4          0       0|0     0|1     2m     2m    97 shard-a    M   13:00:01
pf2:27018        *0     *0  *5401     *0       0     2|0       0  32.3g  32.7g  29.4g      1       86          0       0|0     0|0   188b     1k    10 shard-a  SEC   13:00:01

pf1:27018         0      0   5213      0      49       2       0  64.3g  66.1g  48.1g      0     93.4          0       0|0     0|1     2m     2m    97 shard-a    M   13:00:02
pf2:27018        *0     *0   *561     *0       0     2|0       0  32.3g  32.7g  29.4g      0      9.1          0       0|0     0|0   188b     1k    10 shard-a  SEC   13:00:02

During the "single" update operation
                 insert  query update delete getmore command flushes mapped  vsize    res faults locked % idx miss %     qr|qw   ar|aw  netIn netOut  conn     set repl       time
pf1:27018         0      0      1      0       1       2       0  64.3g  66.1g  48.1g      0      237          0       0|0     0|1   235b     4m    97 shard-a    M   13:19:44
pf2:27018        *0     *0     *0  *4450       0     2|0       0  32.3g  32.7g  29.4g      0       37          0       0|0     0|0   188b     1k    10 shard-a  SEC   13:19:44

pf1:27018         0      0      0      0       0       2       0  64.3g  66.1g  48.1g      0        0          0       0|0     0|1   188b     1k    97 shard-a    M   13:19:45
pf2:27018        *0     *0     *0 *11853       0     4|0       0  32.3g  32.7g  29.4g      0     98.6          0       0|0     0|0   397b     1k    10 shard-a  SEC   13:19:45

pf1:27018         0      0      0      0       0       2       0  64.3g  66.1g  48.1g      0        0          0       0|0     0|1   188b     1k    97 shard-a    M   13:19:46
pf2:27018        *0     *0     *0 *11470       0     2|0       0  32.3g  32.7g  29.4g      0     98.6          0       0|0     0|0   188b     1k    10 shard-a  SEC   13:19:46

pf1:27018         0      0      0      0       0       2       0  64.3g  66.1g  48.1g      0      158          0       0|0     0|1   188b     1k    97 shard-a    M   13:19:47
pf2:27018        *0     *0     *0 *11510       0     2|0       1  32.3g  32.7g  29.4g      0     98.2          0       0|0     0|0   188b     1k    10 shard-a  SEC   13:19:47

pf1:27018         0      0      0      0       1       2       0  64.3g  66.1g  48.1g      0      126          0       1|0     1|1   188b     1k    97 shard-a    M   13:19:48
pf2:27018        *0     *0     *0  *1815       0     2|0       0  32.3g  32.7g  29.4g      0     15.1          0       0|0     0|0   188b     1k    10 shard-a  SEC   13:19:48

And now the strange thing, after the "single" update, the slave machine is blocked by replication

                 insert  query update delete getmore command flushes mapped  vsize    res faults locked % idx miss %     qr|qw   ar|aw  netIn netOut  conn     set repl       time
pf1:27018         0      0      0      0       0       2       0  64.3g  66.1g  48.1g      0        0          0       0|0     0|0   188b     1k    97 shard-a    M   13:20:44
pf2:27018        *0     *0     *0  *9624       0     2|0       0  32.3g  32.7g  29.4g      0     98.8          0       0|0     0|0   188b     1k    10 shard-a  SEC   13:20:44

pf1:27018         0      0      0      0       0       2       0  64.3g  66.1g  48.1g      0        0          0       0|0     0|0   188b     1k    97 shard-a    M   13:20:45
pf2:27018        *0     *0     *0  *9393       0     4|0       0  32.3g  32.7g  29.4g      0     98.2          0       0|0     0|0   397b     1k    10 shard-a  SEC   13:20:45

pf1:27018         0      0      0      0       0       2       0  64.3g  66.1g  48.1g      0        0          0       0|0     0|0   188b     1k    97 shard-a    M   13:20:46
pf2:27018        *0     *0     *0  *9811       0     2|0       0  32.3g  32.7g  29.4g      0     98.8          0       0|0     0|0   188b     1k    10 shard-a  SEC   13:20:46

pf1:27018         0      0      0      0       1       3       0  64.3g  66.1g  48.1g      0        0          0       0|0     0|0   293b     4m    97 shard-a    M   13:20:47
pf2:27018        *0     *0     *0  *7704       0     2|0       0  32.3g  32.7g  29.4g      0     92.9          0       0|0     0|0   188b     1k    10 shard-a  SEC   13:20:47

pf1:27018         0      0      1      0       0       2       0  64.3g  66.1g  48.1g      0        0          0       0|0     0|0   188b     1k    97 shard-a    M   13:20:48
pf2:27018        *0     *0     *0  *7761       0     2|0       0  32.3g  32.7g  29.4g      0       99          0       0|0     0|0   188b     1k    10 shard-a  SEC   13:20:48


Is this behaviour normal for a cluster ?
Any further hints ?

[William Z]

Hi Michael!

1) You don't appear to have a index on the 'refDate' field.  This is the reason that your update is slow.  Per the explain() output, your update is looking at all 16-Million documents in your database. 

This is also the reason that your queries are slow: they are blocking waiting for the updates to complete.

2) Slowing down the frequency of the updates won't help you if you're querying on an unindexed field.  (Note that your update() operation is doing just that!)

I recommend that you look at your schema and see what indexes you need to add.  You can use the freely-available 'Dex' index checker to get some recommendations on which indexes to add. 
  - http://blog.mongolab.com/2012/06/introducing-dex-the-index-bot/

Note that you need to be careful about adding indexes to a live system.  Adding an index is a blocking operation, so all other I/O will stop while the index build is in progress.  Please follow these instructions if you choose to add indexes to your system:
 - http://www.mongodb.org/display/DOCS/Building+indexes+with+replica+sets

3) Replication works by having the secondary apply the exact same operations that were applied on the primary.  If you have an operation that blocks access on the primary, then that operation will block access on the secondary when it replicates to the secondary.

If you want to avoid this, I recommend that you use a WriteConcern of REPLICAS_SAFE to throttle your incoming writes.  Doing so will space out the write load on the secondaries as well as on the primaries.

Let me know if you have further questions.

 -William

[Michael Illgner]

Hi again
So we have inserted some "sleeps" between our updates and changes the "big" update operation to a loop with a cursor and now the read timeouts do not occure anymore. We also test the recommended WriteConcern of REPLICAS_SAFE but this slowed down the whole process way to much.
Now I would like to make a suggestion for a future mongodb version, introduce a kind of "slow" or "not priorized" replication mode, where read operations take precedence over replication, so clients may get data which might be not actual, but it gets the data in a definite time intervall and are not affected by write operations or replication of other database instances.

[William Z]

Hi Michael!

Did you use a REPLICAS_SAFE Write Concern after *every* write?  That's going to be exceptionally slow, and it's not what I recommended.  Instead, you should insert a REPLICAS_SAFE write after every 1,000 writes or so.  You can do that with a getLastError() command.

The upcoming release of MongoDB 2.2 includes some optimization so that replication no longer interferes with reads from the primary.  

 -William