mongodb and very high lock percentage with low throughput

Question

We have some problem with our first use of mongodb :) Here are some facts:

• 95+% lock percentage
• server is a VM with 2 cores, 6 GB ram, with an NFS v3 share (noatime) on a fast NAS for mongodb.
• centos 5.7 x86_64, mongo 2.0.2, php-pecl-mongo 1.2.6 (not latest version but will update soon :)
• mongo is (currently/wrongly) configured as a single master without slave
• db has been created today from scratch. 20 web servers are writing to it (using update)
• not sure how many updates/s are sent to the server, but the amount processed is very small
• i'm not sure if it's an index issue: how to diagnose ?
• current disk data (including oplog, journal ...) is less than 600 MB
• dstat:

----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw
 46   1  53   0   0   0|   0  4096B|  42k   19k|   0     0 | 317  5328
 48   1  52   0   0   1|   0    92k|  46k 7590B|   0     0 | 321  5308
 50   2  48   0   0   0|   0     0 |  39k 7218B|   0     0 | 304  5359
 47   1  51   0   0   1|   0     0 |  47k   10k|   0     0 | 332  5679
 46   1  52   0   0   0|   0     0 |  44k   15k|   0     0 | 319  5099

• nfsiostat is empty (0 ops/s) (of course iostat is the same)
• mongostat:

insert  query update delete getmore command flushes mapped  vsize    res faults locked % idx miss %     qr|qw   ar|aw  netIn netOut  conn repl       time
     0      0      0      0       0       1       0  1.41g  8.39g   242m      0     96.2          0    0|3280  1|5322    62b     1k  5324    M   21:11:50
     0      0      0      0       0       1       0  1.41g  8.39g   242m      0     96.5          0    0|3204  1|5322    62b     1k  5324    M   21:11:51
     0      0      0      0       0       1       0  1.41g  8.39g   242m      0       96          0    1|3351  1|5322    62b     1k  5324    M   21:11:52
     0      0      1      0       0       1       0  1.41g  8.39g   242m      0     96.9          0    0|3251  1|5322   485b     1k  5324    M   21:11:53
     0      0      0      0       1       1       0  1.41g  8.39g   242m      0     95.6          0    0|3280  1|5322   112b     1k  5324    M   21:11:54

• db.serverStatus()

{
        "host" : "foo001",
        "version" : "2.0.2",
        "process" : "mongod",
        "uptime" : 21370,
        "uptimeEstimate" : 18626,
        "localTime" : ISODate("2012-02-23T20:20:59.589Z"),
        "globalLock" : {
                "totalTime" : 21369761258,
                "lockTime" : 19450568051,
                "ratio" : 0.9101911722911022,
                "currentQueue" : {
                        "total" : 3570,
                        "readers" : 0,
                        "writers" : 3570
                },
                "activeClients" : {
                        "total" : 5500,
                        "readers" : 1,
                        "writers" : 5499
                }
        },
        "mem" : {
                "bits" : 64,
                "resident" : 255,
                "virtual" : 8782,
                "supported" : true,
                "mapped" : 1440,
                "mappedWithJournal" : 2880
        },
        "connections" : {
                "current" : 5501,
                "available" : 4099
        },
        "extra_info" : {
                "note" : "fields vary by platform",
                "heap_usage_bytes" : 81930736,
                "page_faults" : 2916
        },
        "indexCounters" : {
                "btree" : {
                        "accesses" : 2377,
                        "hits" : 2377,
                        "misses" : 0,
                        "resets" : 0,
                        "missRatio" : 0
                }
        },
        "backgroundFlushing" : {
                "flushes" : 356,
                "total_ms" : 2372,
                "average_ms" : 6.662921348314606,
                "last_ms" : 0,
                "last_finished" : ISODate("2012-02-23T20:20:56.446Z")
        },
        "cursors" : {
                "totalOpen" : 5500,
                "clientCursors_size" : 5500,
                "timedOut" : 0,
                "totalNoTimeout" : 5499
        },
        "network" : {
                "bytesIn" : 51373772,
                "bytesOut" : 51176411,
                "numRequests" : 176017
        },
        "repl" : {
                "ismaster" : true
        },
        "opcounters" : {
                "insert" : 0,
                "query" : 25,
                "update" : 142157,
                "delete" : 0,
                "getmore" : 39053,
                "command" : 284
        },
        "asserts" : {
                "regular" : 0,
                "warning" : 0,
                "msg" : 0,
                "user" : 0,
                "rollovers" : 0
        },
        "writeBacksQueued" : false,
        "dur" : {
                "commits" : 19,
                "journaledMB" : 0,
                "writeToDataFilesMB" : 0,
                "compression" : 0,
                "commitsInWriteLock" : 0,
                "earlyCommits" : 0,
                "timeMs" : {
                        "dt" : 3083,
                        "prepLogBuffer" : 0,
                        "writeToJournal" : 0,
                        "writeToDataFiles" : 0,
                        "remapPrivateView" : 0
                }
        },
        "ok" : 1
}

• our db:

{
        "db" : "mydb",
        "collections" : 6,
        "objects" : 119174,
        "avgObjSize" : 323.99872455401345,
        "dataSize" : 38612224,
        "storageSize" : 57286656,
        "numExtents" : 26,
        "indexes" : 4,
        "indexSize" : 3899952,
        "fileSize" : 469762048,
        "nsSizeMB" : 16,
        "ok" : 1
}

Any hint ?

Regards,

D.

PS: I also cross-posted this to mongo-user

Answer 1

Please, please, please do not use NFS as a database back-end. There are so many issues, especially with locking and especially with NFS < v4. And since they are not just performance issues, NFS should probably not even be considered.

I would start with moving my DB to a local disk and see if that solves the performance issues - which I suspect it will...

EDIT:

The MongoDB people seem to agree, even if somewhat tersely, that NFS is not recommended.

Answer 2

According to mongostat result, you are queueing writes (check qr|qw, the second value is high and going up), meaning that your system is not fast enough to write before a new write comes.

According to your mongostat, there are not many writes, but each of them is slow. It looks like the problem are the updates. Are you using maybe findAndModify? That will lock the DB for a while if you are using a complex query. Or maybe the info you put on the mongostat was after a huge spike of writes. Anyway, they are probably very slow, or you won't see that high lock (and the queued writes will decrease quickly)

You should activate the DB profiler and analyze your updates. Check this page for more info

PD: The size of the indexes looks fine:

    "indexes" : 4,
    "indexSize" : 3899952,

That's less than 4 MB

EDITED: Another detail, it looks like there are quite a few write clients connected at the same time. If there are 20 web servers, maybe each one is connecting several times.

"activeClients" : {
                    "total" : 5500,
                    "readers" : 1,
                    "writers" : 5499
                  }