FAQ
Hi All,

I have a database with 11 collections. Some cron scripts update the
database 24/7. CPU load is ~250% (quad-core), RAM is almost full
(12Gb). Here is a database status:
db.serverStatus()
{
"host" : ***",
"version" : "2.0.1",
"process" : "mongod",
"uptime" : 1521308,
"uptimeEstimate" : 1502924,
"localTime" : ISODate("2011-11-15T10:15:52.656Z"),
"globalLock" : {
"totalTime" : 1521307796713,
"lockTime" : 372583408477,
"ratio" : 0.24490994477384456,
"currentQueue" : {
"total" : 5,
"readers" : 4,
"writers" : 1
},
"activeClients" : {
"total" : 5,
"readers" : 5,
"writers" : 0
}
},
"mem" : {
"bits" : 64,
"resident" : 6999,
"virtual" : 37510,
"supported" : true,
"mapped" : 18456,
"mappedWithJournal" : 36912
},
"connections" : {
"current" : 13,
"available" : 806
},
"extra_info" : {
"note" : "fields vary by platform",
"heap_usage_bytes" : 6012848,
"page_faults" : 15887107
},
"indexCounters" : {
"btree" : {
"accesses" : 3081628,
"hits" : 3062232,
"misses" : 19391,
"resets" : 0,
"missRatio" : 0.006292453209796899
}
},
"backgroundFlushing" : {
"flushes" : 25324,
"total_ms" : 266242445,
"average_ms" : 10513.443571315747,
"last_ms" : 7644,
"last_finished" : ISODate("2011-11-15T10:15:32.661Z")
},
"cursors" : {
"totalOpen" : 0,
"clientCursors_size" : 0,
"timedOut" : 319
},
"network" : {
"bytesIn" : 46822763087,
"bytesOut" : NumberLong("5467048505643"),
"numRequests" : 127495426
},
"opcounters" : {
"insert" : 543330,
"query" : 62945009,
"update" : 15179557,
"delete" : 95,
"getmore" : 34769877,
"command" : 14020388
},
"asserts" : {
"regular" : 0,
"warning" : 0,
"msg" : 0,
"user" : 82,
"rollovers" : 0
},
"writeBacksQueued" : false,
"dur" : {
"commits" : 19,
"journaledMB" : 0.262144,
"writeToDataFilesMB" : 0.76099,
"compression" : 0.9999961853172863,
"commitsInWriteLock" : 0,
"earlyCommits" : 0,
"timeMs" : {
"dt" : 3089,
"prepLogBuffer" : 1,
"writeToJournal" : 924,
"writeToDataFiles" : 11,
"remapPrivateView" : 11
}
},
"ok" : 1
}

I can't decrease write operations, it's necessary for my system. CPU
usage looks normally, the same situation with indexes. Could you
please suggest how to reduce lock ratio? Or using MongoDB for such
class of tasks is not good idea generally?

Thanks.

--
You received this message because you are subscribed to the Google Groups "mongodb-user" group.
To post to this group, send email to mongodb-user@googlegroups.com.
To unsubscribe from this group, send email to mongodb-user+unsubscribe@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/mongodb-user?hl=en.

Search Discussions

  • Eliot Horowitz at Nov 15, 2011 at 2:47 pm
    Can you send mongostat output?
    What problems are you having because of the current lock %?
    It seems about 25%, which can be fine for many apps.


    On Tue, Nov 15, 2011 at 7:42 AM, silex
    wrote:
    Hi All,

    I have a database with 11 collections. Some cron scripts update the
    database 24/7. CPU load is ~250% (quad-core), RAM is almost full
    (12Gb). Here is a database status:
    db.serverStatus()
    {
    "host" : ***",
    "version" : "2.0.1",
    "process" : "mongod",
    "uptime" : 1521308,
    "uptimeEstimate" : 1502924,
    "localTime" : ISODate("2011-11-15T10:15:52.656Z"),
    "globalLock" : {
    "totalTime" : 1521307796713,
    "lockTime" : 372583408477,
    "ratio" : 0.24490994477384456,
    "currentQueue" : {
    "total" : 5,
    "readers" : 4,
    "writers" : 1
    },
    "activeClients" : {
    "total" : 5,
    "readers" : 5,
    "writers" : 0
    }
    },
    "mem" : {
    "bits" : 64,
    "resident" : 6999,
    "virtual" : 37510,
    "supported" : true,
    "mapped" : 18456,
    "mappedWithJournal" : 36912
    },
    "connections" : {
    "current" : 13,
    "available" : 806
    },
    "extra_info" : {
    "note" : "fields vary by platform",
    "heap_usage_bytes" : 6012848,
    "page_faults" : 15887107
    },
    "indexCounters" : {
    "btree" : {
    "accesses" : 3081628,
    "hits" : 3062232,
    "misses" : 19391,
    "resets" : 0,
    "missRatio" : 0.006292453209796899
    }
    },
    "backgroundFlushing" : {
    "flushes" : 25324,
    "total_ms" : 266242445,
    "average_ms" : 10513.443571315747,
    "last_ms" : 7644,
    "last_finished" : ISODate("2011-11-15T10:15:32.661Z")
    },
    "cursors" : {
    "totalOpen" : 0,
    "clientCursors_size" : 0,
    "timedOut" : 319
    },
    "network" : {
    "bytesIn" : 46822763087,
    "bytesOut" : NumberLong("5467048505643"),
    "numRequests" : 127495426
    },
    "opcounters" : {
    "insert" : 543330,
    "query" : 62945009,
    "update" : 15179557,
    "delete" : 95,
    "getmore" : 34769877,
    "command" : 14020388
    },
    "asserts" : {
    "regular" : 0,
    "warning" : 0,
    "msg" : 0,
    "user" : 82,
    "rollovers" : 0
    },
    "writeBacksQueued" : false,
    "dur" : {
    "commits" : 19,
    "journaledMB" : 0.262144,
    "writeToDataFilesMB" : 0.76099,
    "compression" : 0.9999961853172863,
    "commitsInWriteLock" : 0,
    "earlyCommits" : 0,
    "timeMs" : {
    "dt" : 3089,
    "prepLogBuffer" : 1,
    "writeToJournal" : 924,
    "writeToDataFiles" : 11,
    "remapPrivateView" : 11
    }
    },
    "ok" : 1
    }

    I can't decrease write operations, it's necessary for my system. CPU
    usage looks normally, the same situation with indexes. Could you
    please suggest how to reduce lock ratio? Or using MongoDB for such
    class of tasks is not good idea generally?

    Thanks.

    --
    You received this message because you are subscribed to the Google Groups "mongodb-user" group.
    To post to this group, send email to mongodb-user@googlegroups.com.
    To unsubscribe from this group, send email to mongodb-user+unsubscribe@googlegroups.com.
    For more options, visit this group at http://groups.google.com/group/mongodb-user?hl=en.
    --
    You received this message because you are subscribed to the Google Groups "mongodb-user" group.
    To post to this group, send email to mongodb-user@googlegroups.com.
    To unsubscribe from this group, send email to mongodb-user+unsubscribe@googlegroups.com.
    For more options, visit this group at http://groups.google.com/group/mongodb-user?hl=en.
  • Silex at Nov 15, 2011 at 3:20 pm
    What problems are you having because of the current lock %?
    I use mongoDB with PHP and this (?) issue causes errors like "Message:
    cursor timed out (timeout: 30000, time left: 0:0, status: 0)".
    Can you send mongostat output?
    insert query update delete getmore command flushes mapped vsize
    res faults locked % idx miss % qr|qw ar|aw netIn netOut
    conn time
    0 53 12 0 31 12 0 18g 36.6g
    7.04g 0 28.2 0 2|2 3|1 34k 4m
    13 14:57:25
    1 14 0 0 11 3 0 18g 36.6g
    7.04g 3 81.4 0 0|0 0|0 9k 1m
    13 14:57:27
    0 17 4 0 9 5 0 18g 36.6g
    6.9g 1 7 0 0|0 0|0 14k 1m
    13 14:57:28
    0 27 8 0 14 9 0 18g 36.6g
    6.91g 1 0.8 0 0|0 0|0 35k 2m
    13 14:57:29
    0 42 11 0 17 13 0 18g 36.6g
    6.91g 1 0.8 0 0|0 0|0 38k 2m
    13 14:57:30
    0 28 7 0 11 10 0 18g 36.6g
    6.91g 2 0.5 0 1|1 2|0 20k 1m
    13 14:57:31
    0 7 2 0 2 2 1 18g 36.6g
    6.91g 2 0.1 0 1|2 2|1 5k 568k
    13 14:57:32
    0 15 4 0 8 5 0 18g 36.6g
    6.91g 79 31.1 0 0|0 0|1 13k 2m
    13 14:57:33
    0 51 11 0 32 9 0 18g 36.6g
    6.91g 66 37.7 0 0|0 0|0 31k 4m
    13 14:57:34
    0 68 13 0 42 15 0 18g 36.6g
    6.91g 7 2.2 0 0|0 0|0 44k 9m
    13 14:57:35
    insert query update delete getmore command flushes mapped vsize
    res faults locked % idx miss % qr|qw ar|aw netIn netOut
    conn time
    0 69 16 0 40 13 0 18g 36.6g
    6.91g 12 6.5 0 0|0 0|0 39k 5m
    13 14:57:36
    0 38 10 0 23 11 0 18g 36.6g
    6.91g 44 20.9 0 1|0 1|1 25k 3m
    13 14:57:37
    0 59 12 0 36 10 0 18g 36.6g
    6.92g 61 36.1 0 0|0 0|0 29k 5m
    13 14:57:38
    0 76 15 0 48 16 0 18g 36.6g
    6.91g 2 12.9 0 0|0 0|0 43k 7m
    12 14:57:39
    0 71 18 0 41 16 0 18g 36.6g
    6.9g 6 5.2 0 0|0 0|0 42k 6m
    13 14:57:40
    0 53 10 0 34 11 0 18g 36.6g
    6.9g 22 10.2 0 0|0 0|0 26k 5m
    13 14:57:41
    0 41 12 0 25 9 0 18g 36.6g
    6.91g 33 15 0 0|0 0|1 21k 3m
    13 14:57:42
    0 46 10 0 30 8 0 18g 36.6g
    6.91g 24 22.1 0 0|0 0|0 30k 4m
    13 14:57:43
    1 46 6 0 29 8 0 18g 36.6g
    6.9g 12 10.6 0 0|0 0|0 28k 4m
    13 14:57:44
    0 71 14 0 43 13 0 18g 36.6g
    6.9g 6 6.7 0 1|1 1|2 43k 6m
    13 14:57:45
    insert query update delete getmore command flushes mapped vsize
    res faults locked % idx miss % qr|qw ar|aw netIn netOut
    conn time
    0 57 8 0 32 11 0 18g 36.6g
    6.9g 2 43.8 0 0|0 0|0 35k 4m
    13 14:57:46
    0 67 14 0 44 15 0 18g 36.6g
    6.9g 18 7.2 0 0|0 0|1 44k 6m
    13 14:57:47
    0 77 17 0 46 15 0 18g 36.6g
    6.91g 21 8.5 0 1|1 2|0 40k 6m
    13 14:57:48
    0 51 9 0 32 10 0 18g 36.6g
    6.9g 6 4.5 0 0|0 0|1 24k 4m
    13 14:57:49
    0 49 11 0 30 9 0 18g 36.6g
    6.9g 57 31.2 0 3|0 3|1 26k 4m
    13 14:57:50
    1 45 8 0 28 10 0 18g 36.6g
    6.9g 13 55.4 0 0|0 0|0 29k 4m
    13 14:57:51
    0 65 17 0 41 15 0 18g 36.6g
    6.89g 18 9.9 0 0|0 0|0 36k 6m
    13 14:57:52
    0 77 19 0 45 17 0 18g 36.6g
    6.89g 1 2.4 0 0|0 0|0 43k 6m
    13 14:57:53
    0 75 19 0 45 15 0 18g 36.6g
    6.89g 34 18.9 0 0|0 0|0 37k 6m
    13 14:57:54
    0 80 22 0 47 19 0 18g 36.6g
    6.89g 4 4.2 0 0|0 0|0 44k 6m
    12 14:57:55
    insert query update delete getmore command flushes mapped vsize
    res faults locked % idx miss % qr|qw ar|aw netIn netOut
    conn time
    0 65 22 0 37 17 0 18g 36.6g
    6.89g 11 12.9 0 0|0 0|0 35k 5m
    12 14:57:56
    0 39 8 0 31 8 0 18g 36.6g
    6.89g 2 2.6 0 0|0 0|0 13k 4m
    13 14:57:57
    0 32 10 0 23 6 0 18g 36.6g
    6.89g 1 1 0 0|0 0|0 11k 3m
    13 14:57:58
    0 35 6 0 27 4 0 18g 36.6g
    6.91g 1 4.5 0 0|0 0|0 8k 3m
    13 14:57:59
    0 62 10 0 41 11 0 18g 36.6g
    6.89g 2 1.5 0 0|0 0|0 26k 6m
    13 14:58:00
    0 38 3 0 33 5 0 18g 36.6g
    6.89g 0 0.6 0 0|0 0|0 11k 4m
    13 14:58:01
    0 37 8 0 27 7 0 18g 36.6g
    6.88g 2 1.4 0 0|0 0|0 13k 3m
    13 14:58:02

    --
    You received this message because you are subscribed to the Google Groups "mongodb-user" group.
    To post to this group, send email to mongodb-user@googlegroups.com.
    To unsubscribe from this group, send email to mongodb-user+unsubscribe@googlegroups.com.
    For more options, visit this group at http://groups.google.com/group/mongodb-user?hl=en.
  • Eliot Horowitz at Nov 15, 2011 at 3:28 pm
    Things don't seem particularly busy.
    Can you send the mongo log?
    Problem is probably elsewhere.

    On Tue, Nov 15, 2011 at 10:19 AM, silex
    wrote:
    What problems are you having because of the current lock %?
    I use mongoDB with PHP and this (?) issue causes errors like "Message:
    cursor timed out (timeout: 30000, time left: 0:0, status: 0)".
    Can you send mongostat output?
    insert  query update delete getmore command flushes mapped  vsize
    res faults locked % idx miss %     qr|qw   ar|aw  netIn netOut
    conn       time
    0     53     12      0      31      12       0    18g  36.6g
    7.04g      0     28.2          0       2|2     3|1    34k     4m
    13   14:57:25
    1     14      0      0      11       3       0    18g  36.6g
    7.04g      3     81.4          0       0|0     0|0     9k     1m
    13   14:57:27
    0     17      4      0       9       5       0    18g  36.6g
    6.9g      1        7          0       0|0     0|0    14k     1m
    13   14:57:28
    0     27      8      0      14       9       0    18g  36.6g
    6.91g      1      0.8          0       0|0     0|0    35k     2m
    13   14:57:29
    0     42     11      0      17      13       0    18g  36.6g
    6.91g      1      0.8          0       0|0     0|0    38k     2m
    13   14:57:30
    0     28      7      0      11      10       0    18g  36.6g
    6.91g      2      0.5          0       1|1     2|0    20k     1m
    13   14:57:31
    0      7      2      0       2       2       1    18g  36.6g
    6.91g      2      0.1          0       1|2     2|1     5k   568k
    13   14:57:32
    0     15      4      0       8       5       0    18g  36.6g
    6.91g     79     31.1          0       0|0     0|1    13k     2m
    13   14:57:33
    0     51     11      0      32       9       0    18g  36.6g
    6.91g     66     37.7          0       0|0     0|0    31k     4m
    13   14:57:34
    0     68     13      0      42      15       0    18g  36.6g
    6.91g      7      2.2          0       0|0     0|0    44k     9m
    13   14:57:35
    insert  query update delete getmore command flushes mapped  vsize
    res faults locked % idx miss %     qr|qw   ar|aw  netIn netOut
    conn       time
    0     69     16      0      40      13       0    18g  36.6g
    6.91g     12      6.5          0       0|0     0|0    39k     5m
    13   14:57:36
    0     38     10      0      23      11       0    18g  36.6g
    6.91g     44     20.9          0       1|0     1|1    25k     3m
    13   14:57:37
    0     59     12      0      36      10       0    18g  36.6g
    6.92g     61     36.1          0       0|0     0|0    29k     5m
    13   14:57:38
    0     76     15      0      48      16       0    18g  36.6g
    6.91g      2     12.9          0       0|0     0|0    43k     7m
    12   14:57:39
    0     71     18      0      41      16       0    18g  36.6g
    6.9g      6      5.2          0       0|0     0|0    42k     6m
    13   14:57:40
    0     53     10      0      34      11       0    18g  36.6g
    6.9g     22     10.2          0       0|0     0|0    26k     5m
    13   14:57:41
    0     41     12      0      25       9       0    18g  36.6g
    6.91g     33       15          0       0|0     0|1    21k     3m
    13   14:57:42
    0     46     10      0      30       8       0    18g  36.6g
    6.91g     24     22.1          0       0|0     0|0    30k     4m
    13   14:57:43
    1     46      6      0      29       8       0    18g  36.6g
    6.9g     12     10.6          0       0|0     0|0    28k     4m
    13   14:57:44
    0     71     14      0      43      13       0    18g  36.6g
    6.9g      6      6.7          0       1|1     1|2    43k     6m
    13   14:57:45
    insert  query update delete getmore command flushes mapped  vsize
    res faults locked % idx miss %     qr|qw   ar|aw  netIn netOut
    conn       time
    0     57      8      0      32      11       0    18g  36.6g
    6.9g      2     43.8          0       0|0     0|0    35k     4m
    13   14:57:46
    0     67     14      0      44      15       0    18g  36.6g
    6.9g     18      7.2          0       0|0     0|1    44k     6m
    13   14:57:47
    0     77     17      0      46      15       0    18g  36.6g
    6.91g     21      8.5          0       1|1     2|0    40k     6m
    13   14:57:48
    0     51      9      0      32      10       0    18g  36.6g
    6.9g      6      4.5          0       0|0     0|1    24k     4m
    13   14:57:49
    0     49     11      0      30       9       0    18g  36.6g
    6.9g     57     31.2          0       3|0     3|1    26k     4m
    13   14:57:50
    1     45      8      0      28      10       0    18g  36.6g
    6.9g     13     55.4          0       0|0     0|0    29k     4m
    13   14:57:51
    0     65     17      0      41      15       0    18g  36.6g
    6.89g     18      9.9          0       0|0     0|0    36k     6m
    13   14:57:52
    0     77     19      0      45      17       0    18g  36.6g
    6.89g      1      2.4          0       0|0     0|0    43k     6m
    13   14:57:53
    0     75     19      0      45      15       0    18g  36.6g
    6.89g     34     18.9          0       0|0     0|0    37k     6m
    13   14:57:54
    0     80     22      0      47      19       0    18g  36.6g
    6.89g      4      4.2          0       0|0     0|0    44k     6m
    12   14:57:55
    insert  query update delete getmore command flushes mapped  vsize
    res faults locked % idx miss %     qr|qw   ar|aw  netIn netOut
    conn       time
    0     65     22      0      37      17       0    18g  36.6g
    6.89g     11     12.9          0       0|0     0|0    35k     5m
    12   14:57:56
    0     39      8      0      31       8       0    18g  36.6g
    6.89g      2      2.6          0       0|0     0|0    13k     4m
    13   14:57:57
    0     32     10      0      23       6       0    18g  36.6g
    6.89g      1        1          0       0|0     0|0    11k     3m
    13   14:57:58
    0     35      6      0      27       4       0    18g  36.6g
    6.91g      1      4.5          0       0|0     0|0     8k     3m
    13   14:57:59
    0     62     10      0      41      11       0    18g  36.6g
    6.89g      2      1.5          0       0|0     0|0    26k     6m
    13   14:58:00
    0     38      3      0      33       5       0    18g  36.6g
    6.89g      0      0.6          0       0|0     0|0    11k     4m
    13   14:58:01
    0     37      8      0      27       7       0    18g  36.6g
    6.88g      2      1.4          0       0|0     0|0    13k     3m
    13   14:58:02

    --
    You received this message because you are subscribed to the Google Groups "mongodb-user" group.
    To post to this group, send email to mongodb-user@googlegroups.com.
    To unsubscribe from this group, send email to mongodb-user+unsubscribe@googlegroups.com.
    For more options, visit this group at http://groups.google.com/group/mongodb-user?hl=en.
    --
    You received this message because you are subscribed to the Google Groups "mongodb-user" group.
    To post to this group, send email to mongodb-user@googlegroups.com.
    To unsubscribe from this group, send email to mongodb-user+unsubscribe@googlegroups.com.
    For more options, visit this group at http://groups.google.com/group/mongodb-user?hl=en.
  • Silex at Nov 15, 2011 at 4:07 pm
    Unfortunately daily log size is more than 500Mb. Could you please tell
    me what part do you like to see? Some random entries:

    Mon Nov 14 02:05:01 [conn902454] query test.articles ntoreturn:1
    idhack:1 reslen:1667 0ms
    Mon Nov 14 02:05:01 [conn902434] query test.articles ntoreturn:1
    idhack:1 reslen:2809 0ms
    Mon Nov 14 02:05:02 [conn902454] query test.phrases nscanned:102
    nreturned:101 reslen:17931 0ms
    Mon Nov 14 02:05:02 [conn902434] query test.phrases nscanned:102
    nreturned:101 reslen:17931 0ms
    Mon Nov 14 02:05:02 [conn902447] getmore test.phrases cursorid:
    3387769437243441904 nreturned:742 reslen:129152 1979ms
    Mon Nov 14 02:05:02 [conn902447] query test.phrases nscanned:102
    nreturned:101 reslen:17931 0ms
    Mon Nov 14 02:05:02 [conn902434] getmore test.phrases cursorid:
    7755136408541596315 nreturned:742 reslen:129152 3ms
    Mon Nov 14 02:05:02 [conn902454] getmore test.phrases cursorid:
    915014090417638043 nreturned:742 reslen:129152 3ms
    Mon Nov 14 02:05:02 [conn902447] getmore test.phrases cursorid:
    815593251146959969 nreturned:742 reslen:129152 1ms
    Mon Nov 14 02:05:02 [conn902454] query test.phrases nscanned:102
    nreturned:101 reslen:17931 0ms
    ======================
    Mon Nov 14 02:05:04 [conn902434] update test.articles query: { _id:
    ObjectId('4e72933629ab2dd82a000033') } update: { ...
    }@{
    " } ], ... image: { id: ObjectId('4e72933629ab2dd82a000032'),
    file_extension: "jpg" }, title_description: ... keywords: [ ... ],
    added_on: new Date(1316131638000), _id:
    ObjectId('4e72933629ab2dd82a000033') } idhack:1 0ms
    Mon Nov 14 02:05:04 [conn902434] run command test.$cmd { getlasterror:
    1 }
    Mon Nov 14 02:05:04 [conn902434] command test.$cmd command:
    { getlasterror: 1 } ntoreturn:1 reslen:85 0ms
    Mon Nov 14 02:05:04 [conn902434] query test.articles ntoreturn:1
    nscanned:1 nreturned:1 reslen:3166 0ms
    ======================
    Mon Nov 14 02:05:06 [DataFileSync] flushing mmap took 6395ms for 18
    files
    Mon Nov 14 02:05:07 [journal] lsn set 1388367607
    ======================
    Mon Nov 14 02:05:07 [initandlisten] connection accepted from
    127.0.0.1:45042 #902463
    Mon Nov 14 02:05:07 [conn902462] run command test.$cmd { profile: 2 }
    ======================
    Tue Nov 15 15:59:50 [conn967756] getmore test.phrases cursorid:
    5077928734388170591 nreturned:743 reslen:129344 4ms
    Tue Nov 15 15:59:50 [conn967773] query test.source ntoreturn:1
    nscanned:1127 nreturned:1 reslen:675 11ms
    Tue Nov 15 15:59:50 [conn967775] query test.source ntoreturn:1 idhack:
    1 reslen:610 0ms
    Tue Nov 15 15:59:50 [conn967772] query test.articles ntoreturn:1
    ntoskip:999 nscanned:985 reslen:20 502ms

    Most queries have execution time 0..3mb, but sometimes its value can
    be much higher (for example 502 and 1979 as listed above)
    On Nov 15, 5:28 pm, Eliot Horowitz wrote:
    Things don't seem particularly busy.
    Can you send the mongo log?
    Problem is probably elsewhere.

    On Tue, Nov 15, 2011 at 10:19 AM, silex







    wrote:
    What problems are you having because of the current lock %?
    I use mongoDB with PHP and this (?) issue causes errors like "Message:
    cursor timed out (timeout: 30000, time left: 0:0, status: 0)".
    Can you send mongostat output?
    insert  query update delete getmore command flushes mapped  vsize
    res faults locked % idx miss %     qr|qw   ar|aw  netIn netOut
    conn       time
    0     53     12      0      31      12       0    18g  36.6g
    7.04g      0     28.2          0       2|2     3|1    34k     4m
    13   14:57:25
    1     14      0      0      11       3       0    18g  36.6g
    7.04g      3     81.4          0       0|0     0|0     9k     1m
    13   14:57:27
    0     17      4      0       9       5       0    18g  36.6g
    6.9g      1        7          0       0|0     0|0    14k     1m
    13   14:57:28
    0     27      8      0      14       9       0    18g  36.6g
    6.91g      1      0.8          0       0|0     0|0    35k     2m
    13   14:57:29
    0     42     11      0      17      13       0    18g  36.6g
    6.91g      1      0.8          0       0|0     0|0    38k     2m
    13   14:57:30
    0     28      7      0      11      10       0    18g  36.6g
    6.91g      2      0.5          0       1|1     2|0    20k     1m
    13   14:57:31
    0      7      2      0       2       2       1    18g  36.6g
    6.91g      2      0.1          0       1|2     2|1     5k   568k
    13   14:57:32
    0     15      4      0       8       5       0    18g  36.6g
    6.91g     79     31.1          0       0|0     0|1    13k     2m
    13   14:57:33
    0     51     11      0      32       9       0    18g  36.6g
    6.91g     66     37.7          0       0|0     0|0    31k     4m
    13   14:57:34
    0     68     13      0      42      15       0    18g  36.6g
    6.91g      7      2.2          0       0|0     0|0    44k     9m
    13   14:57:35
    insert  query update delete getmore command flushes mapped  vsize
    res faults locked % idx miss %     qr|qw   ar|aw  netIn netOut
    conn       time
    0     69     16      0      40      13       0    18g  36.6g
    6.91g     12      6.5          0       0|0     0|0    39k     5m
    13   14:57:36
    0     38     10      0      23      11       0    18g  36.6g
    6.91g     44     20.9          0       1|0     1|1    25k     3m
    13   14:57:37
    0     59     12      0      36      10       0    18g  36.6g
    6.92g     61     36.1          0       0|0     0|0    29k     5m
    13   14:57:38
    0     76     15      0      48      16       0    18g  36.6g
    6.91g      2     12.9          0       0|0     0|0    43k     7m
    12   14:57:39
    0     71     18      0      41      16       0    18g  36.6g
    6.9g      6      5.2          0       0|0     0|0    42k     6m
    13   14:57:40
    0     53     10      0      34      11       0    18g  36.6g
    6.9g     22     10.2          0       0|0     0|0    26k     5m
    13   14:57:41
    0     41     12      0      25       9       0    18g  36.6g
    6.91g     33       15          0       0|0     0|1    21k     3m
    13   14:57:42
    0     46     10      0      30       8       0    18g  36.6g
    6.91g     24     22.1          0       0|0     0|0    30k     4m
    13   14:57:43
    1     46      6      0      29       8       0    18g  36.6g
    6.9g     12     10.6          0       0|0     0|0    28k     4m
    13   14:57:44
    0     71     14      0      43      13       0    18g  36.6g
    6.9g      6      6.7          0       1|1     1|2    43k     6m
    13   14:57:45
    insert  query update delete getmore command flushes mapped  vsize
    res faults locked % idx miss %     qr|qw   ar|aw  netIn netOut
    conn       time
    0     57      8      0      32      11       0    18g  36.6g
    6.9g      2     43.8          0       0|0     0|0    35k     4m
    13   14:57:46
    0     67     14      0      44      15       0    18g  36.6g
    6.9g     18      7.2          0       0|0     0|1    44k     6m
    13   14:57:47
    0     77     17      0      46      15       0    18g  36.6g
    6.91g     21      8.5          0       1|1     2|0    40k     6m
    13   14:57:48
    0     51      9      0      32      10       0    18g  36.6g
    6.9g      6      4.5          0       0|0     0|1    24k     4m
    13   14:57:49
    0     49     11      0      30       9       0    18g  36.6g
    6.9g     57     31.2          0       3|0     3|1    26k     4m
    13   14:57:50
    1     45      8      0      28      10       0    18g  36.6g
    6.9g     13     55.4          0       0|0     0|0    29k     4m
    13   14:57:51
    0     65     17      0      41      15       0    18g  36.6g
    6.89g     18      9.9          0       0|0     0|0    36k     6m
    13   14:57:52
    0     77     19      0      45      17       0    18g  36.6g
    6.89g      1      2.4          0       0|0     0|0    43k     6m
    13   14:57:53
    0     75     19      0      45      15       0    18g  36.6g
    6.89g     34     18.9          0       0|0     0|0    37k     6m
    13   14:57:54
    0     80     22      0      47      19       0    18g  36.6g
    6.89g      4      4.2          0       0|0     0|0    44k     6m
    12   14:57:55
    insert  query update delete getmore command flushes mapped  vsize
    res faults locked % idx miss %     qr|qw   ar|aw  netIn netOut
    conn       time
    0     65     22      0      37      17       0    18g  36.6g
    6.89g     11     12.9          0       0|0     0|0    35k     5m
    12   14:57:56
    0     39      8      0      31       8       0    18g  36.6g
    6.89g      2      2.6          0       0|0     0|0    13k     4m
    13   14:57:57
    0     32     10      0      23       6       0    18g  36.6g
    6.89g      1        1          0       0|0     0|0    11k     3m
    13   14:57:58
    0     35      6      0      27       4       0    18g  36.6g
    6.91g      1      4.5          0       0|0     0|0     8k     3m
    13   14:57:59
    0     62     10      0      41      11       0    18g  36.6g
    6.89g      2      1.5          0       0|0     0|0    26k     6m
    13   14:58:00
    0     38      3      0      33       5       0    18g  36.6g
    6.89g      0      0.6          0       0|0     0|0    11k     4m
    13   14:58:01
    0     37      8      0      27       7       0    18g  36.6g
    6.88g      2      1.4          0       0|0     0|0    13k     3m
    13   14:58:02
    --
    You received this message because you are subscribed to the Google Groups "mongodb-user" group.
    To post to this group, send email to mongodb-user@googlegroups.com.
    To unsubscribe from this group, send email to mongodb-user+unsubscribe@googlegroups.com.
    For more options, visit this group athttp://groups.google.com/group/mongodb-user?hl=en.
    --
    You received this message because you are subscribed to the Google Groups "mongodb-user" group.
    To post to this group, send email to mongodb-user@googlegroups.com.
    To unsubscribe from this group, send email to mongodb-user+unsubscribe@googlegroups.com.
    For more options, visit this group at http://groups.google.com/group/mongodb-user?hl=en.
  • Eliot Horowitz at Nov 15, 2011 at 5:01 pm
    Do they queries that timeout have a very high skip number?
    I see a skip 999 in that snippet.

    If so - that may be the issue.

    On Tue, Nov 15, 2011 at 11:07 AM, silex
    wrote:
    Unfortunately daily log size is more than 500Mb. Could you please tell
    me what part do you like to see? Some random entries:

    Mon Nov 14 02:05:01 [conn902454] query test.articles ntoreturn:1
    idhack:1 reslen:1667 0ms
    Mon Nov 14 02:05:01 [conn902434] query test.articles ntoreturn:1
    idhack:1 reslen:2809 0ms
    Mon Nov 14 02:05:02 [conn902454] query test.phrases nscanned:102
    nreturned:101 reslen:17931 0ms
    Mon Nov 14 02:05:02 [conn902434] query test.phrases nscanned:102
    nreturned:101 reslen:17931 0ms
    Mon Nov 14 02:05:02 [conn902447] getmore test.phrases cursorid:
    3387769437243441904 nreturned:742 reslen:129152 1979ms
    Mon Nov 14 02:05:02 [conn902447] query test.phrases nscanned:102
    nreturned:101 reslen:17931 0ms
    Mon Nov 14 02:05:02 [conn902434] getmore test.phrases cursorid:
    7755136408541596315 nreturned:742 reslen:129152 3ms
    Mon Nov 14 02:05:02 [conn902454] getmore test.phrases cursorid:
    915014090417638043 nreturned:742 reslen:129152 3ms
    Mon Nov 14 02:05:02 [conn902447] getmore test.phrases cursorid:
    815593251146959969 nreturned:742 reslen:129152 1ms
    Mon Nov 14 02:05:02 [conn902454] query test.phrases nscanned:102
    nreturned:101 reslen:17931 0ms
    ======================
    Mon Nov 14 02:05:04 [conn902434] update test.articles query: { _id:
    ObjectId('4e72933629ab2dd82a000033') } update: { ...
    }@{
    " } ], ... image: { id: ObjectId('4e72933629ab2dd82a000032'),
    file_extension: "jpg" }, title_description: ... keywords: [ ... ],
    added_on: new Date(1316131638000), _id:
    ObjectId('4e72933629ab2dd82a000033') } idhack:1 0ms
    Mon Nov 14 02:05:04 [conn902434] run command test.$cmd { getlasterror:
    1 }
    Mon Nov 14 02:05:04 [conn902434] command test.$cmd command:
    { getlasterror: 1 } ntoreturn:1 reslen:85 0ms
    Mon Nov 14 02:05:04 [conn902434] query test.articles ntoreturn:1
    nscanned:1 nreturned:1 reslen:3166 0ms
    ======================
    Mon Nov 14 02:05:06 [DataFileSync] flushing mmap took 6395ms  for 18
    files
    Mon Nov 14 02:05:07 [journal] lsn set 1388367607
    ======================
    Mon Nov 14 02:05:07 [initandlisten] connection accepted from
    127.0.0.1:45042 #902463
    Mon Nov 14 02:05:07 [conn902462] run command test.$cmd { profile: 2 }
    ======================
    Tue Nov 15 15:59:50 [conn967756] getmore test.phrases cursorid:
    5077928734388170591 nreturned:743 reslen:129344 4ms
    Tue Nov 15 15:59:50 [conn967773] query test.source ntoreturn:1
    nscanned:1127 nreturned:1 reslen:675 11ms
    Tue Nov 15 15:59:50 [conn967775] query test.source ntoreturn:1 idhack:
    1 reslen:610 0ms
    Tue Nov 15 15:59:50 [conn967772] query test.articles ntoreturn:1
    ntoskip:999 nscanned:985 reslen:20 502ms

    Most queries have execution time 0..3mb, but sometimes its value can
    be much higher (for example 502 and 1979 as listed above)
    On Nov 15, 5:28 pm, Eliot Horowitz wrote:
    Things don't seem particularly busy.
    Can you send the mongo log?
    Problem is probably elsewhere.

    On Tue, Nov 15, 2011 at 10:19 AM, silex







    wrote:
    What problems are you having because of the current lock %?
    I use mongoDB with PHP and this (?) issue causes errors like "Message:
    cursor timed out (timeout: 30000, time left: 0:0, status: 0)".
    Can you send mongostat output?
    insert  query update delete getmore command flushes mapped  vsize
    res faults locked % idx miss %     qr|qw   ar|aw  netIn netOut
    conn       time
    0     53     12      0      31      12       0    18g  36.6g
    7.04g      0     28.2          0       2|2     3|1    34k     4m
    13   14:57:25
    1     14      0      0      11       3       0    18g  36.6g
    7.04g      3     81.4          0       0|0     0|0     9k     1m
    13   14:57:27
    0     17      4      0       9       5       0    18g  36.6g
    6.9g      1        7          0       0|0     0|0    14k     1m
    13   14:57:28
    0     27      8      0      14       9       0    18g  36.6g
    6.91g      1      0.8          0       0|0     0|0    35k     2m
    13   14:57:29
    0     42     11      0      17      13       0    18g  36.6g
    6.91g      1      0.8          0       0|0     0|0    38k     2m
    13   14:57:30
    0     28      7      0      11      10       0    18g  36.6g
    6.91g      2      0.5          0       1|1     2|0    20k     1m
    13   14:57:31
    0      7      2      0       2       2       1    18g  36.6g
    6.91g      2      0.1          0       1|2     2|1     5k   568k
    13   14:57:32
    0     15      4      0       8       5       0    18g  36.6g
    6.91g     79     31.1          0       0|0     0|1    13k     2m
    13   14:57:33
    0     51     11      0      32       9       0    18g  36.6g
    6.91g     66     37.7          0       0|0     0|0    31k     4m
    13   14:57:34
    0     68     13      0      42      15       0    18g  36.6g
    6.91g      7      2.2          0       0|0     0|0    44k     9m
    13   14:57:35
    insert  query update delete getmore command flushes mapped  vsize
    res faults locked % idx miss %     qr|qw   ar|aw  netIn netOut
    conn       time
    0     69     16      0      40      13       0    18g  36.6g
    6.91g     12      6.5          0       0|0     0|0    39k     5m
    13   14:57:36
    0     38     10      0      23      11       0    18g  36.6g
    6.91g     44     20.9          0       1|0     1|1    25k     3m
    13   14:57:37
    0     59     12      0      36      10       0    18g  36.6g
    6.92g     61     36.1          0       0|0     0|0    29k     5m
    13   14:57:38
    0     76     15      0      48      16       0    18g  36.6g
    6.91g      2     12.9          0       0|0     0|0    43k     7m
    12   14:57:39
    0     71     18      0      41      16       0    18g  36.6g
    6.9g      6      5.2          0       0|0     0|0    42k     6m
    13   14:57:40
    0     53     10      0      34      11       0    18g  36.6g
    6.9g     22     10.2          0       0|0     0|0    26k     5m
    13   14:57:41
    0     41     12      0      25       9       0    18g  36.6g
    6.91g     33       15          0       0|0     0|1    21k     3m
    13   14:57:42
    0     46     10      0      30       8       0    18g  36.6g
    6.91g     24     22.1          0       0|0     0|0    30k     4m
    13   14:57:43
    1     46      6      0      29       8       0    18g  36.6g
    6.9g     12     10.6          0       0|0     0|0    28k     4m
    13   14:57:44
    0     71     14      0      43      13       0    18g  36.6g
    6.9g      6      6.7          0       1|1     1|2    43k     6m
    13   14:57:45
    insert  query update delete getmore command flushes mapped  vsize
    res faults locked % idx miss %     qr|qw   ar|aw  netIn netOut
    conn       time
    0     57      8      0      32      11       0    18g  36.6g
    6.9g      2     43.8          0       0|0     0|0    35k     4m
    13   14:57:46
    0     67     14      0      44      15       0    18g  36.6g
    6.9g     18      7.2          0       0|0     0|1    44k     6m
    13   14:57:47
    0     77     17      0      46      15       0    18g  36.6g
    6.91g     21      8.5          0       1|1     2|0    40k     6m
    13   14:57:48
    0     51      9      0      32      10       0    18g  36.6g
    6.9g      6      4.5          0       0|0     0|1    24k     4m
    13   14:57:49
    0     49     11      0      30       9       0    18g  36.6g
    6.9g     57     31.2          0       3|0     3|1    26k     4m
    13   14:57:50
    1     45      8      0      28      10       0    18g  36.6g
    6.9g     13     55.4          0       0|0     0|0    29k     4m
    13   14:57:51
    0     65     17      0      41      15       0    18g  36.6g
    6.89g     18      9.9          0       0|0     0|0    36k     6m
    13   14:57:52
    0     77     19      0      45      17       0    18g  36.6g
    6.89g      1      2.4          0       0|0     0|0    43k     6m
    13   14:57:53
    0     75     19      0      45      15       0    18g  36.6g
    6.89g     34     18.9          0       0|0     0|0    37k     6m
    13   14:57:54
    0     80     22      0      47      19       0    18g  36.6g
    6.89g      4      4.2          0       0|0     0|0    44k     6m
    12   14:57:55
    insert  query update delete getmore command flushes mapped  vsize
    res faults locked % idx miss %     qr|qw   ar|aw  netIn netOut
    conn       time
    0     65     22      0      37      17       0    18g  36.6g
    6.89g     11     12.9          0       0|0     0|0    35k     5m
    12   14:57:56
    0     39      8      0      31       8       0    18g  36.6g
    6.89g      2      2.6          0       0|0     0|0    13k     4m
    13   14:57:57
    0     32     10      0      23       6       0    18g  36.6g
    6.89g      1        1          0       0|0     0|0    11k     3m
    13   14:57:58
    0     35      6      0      27       4       0    18g  36.6g
    6.91g      1      4.5          0       0|0     0|0     8k     3m
    13   14:57:59
    0     62     10      0      41      11       0    18g  36.6g
    6.89g      2      1.5          0       0|0     0|0    26k     6m
    13   14:58:00
    0     38      3      0      33       5       0    18g  36.6g
    6.89g      0      0.6          0       0|0     0|0    11k     4m
    13   14:58:01
    0     37      8      0      27       7       0    18g  36.6g
    6.88g      2      1.4          0       0|0     0|0    13k     3m
    13   14:58:02
    --
    You received this message because you are subscribed to the Google Groups "mongodb-user" group.
    To post to this group, send email to mongodb-user@googlegroups.com.
    To unsubscribe from this group, send email to mongodb-user+unsubscribe@googlegroups.com.
    For more options, visit this group athttp://groups.google.com/group/mongodb-user?hl=en.
    --
    You received this message because you are subscribed to the Google Groups "mongodb-user" group.
    To post to this group, send email to mongodb-user@googlegroups.com.
    To unsubscribe from this group, send email to mongodb-user+unsubscribe@googlegroups.com.
    For more options, visit this group at http://groups.google.com/group/mongodb-user?hl=en.
    --
    You received this message because you are subscribed to the Google Groups "mongodb-user" group.
    To post to this group, send email to mongodb-user@googlegroups.com.
    To unsubscribe from this group, send email to mongodb-user+unsubscribe@googlegroups.com.
    For more options, visit this group at http://groups.google.com/group/mongodb-user?hl=en.

Related Discussions

Discussion Navigation
viewthread | post
Discussion Overview
groupmongodb-user @
categoriesmongodb
postedNov 15, '11 at 1:21p
activeNov 15, '11 at 5:01p
posts6
users2
websitemongodb.org
irc#mongodb

2 users in discussion

Silex: 3 posts Eliot Horowitz: 3 posts

People

Translate

site design / logo © 2022 Grokbase