[mongodb-user] Too high globalLock ratio: how to decrease it?

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 [email protected].
To unsubscribe from this group, send email to [email protected].
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 [email protected].
To unsubscribe from this group, send email to [email protected].
For more options, visit this group at http://groups.google.com/group/mongodb-user?hl=en.

reply | permalink

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 [email protected].
To unsubscribe from this group, send email to [email protected].
For more options, visit this group at http://groups.google.com/group/mongodb-user?hl=en.

reply | permalink

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 [email protected].
To unsubscribe from this group, send email to [email protected].
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 [email protected].
To unsubscribe from this group, send email to [email protected].
For more options, visit this group at http://groups.google.com/group/mongodb-user?hl=en.

reply | permalink

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 [email protected].
To unsubscribe from this group, send email to [email protected].
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 [email protected].
To unsubscribe from this group, send email to [email protected].
For more options, visit this group at http://groups.google.com/group/mongodb-user?hl=en.

reply | permalink

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 [email protected].
To unsubscribe from this group, send email to [email protected].
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 [email protected].
To unsubscribe from this group, send email to [email protected].
For more options, visit this group at http://groups.google.com/group/mongodb-user?hl=en.

reply | permalink

group	mongodb-user @
categories	mongodb
posted	Nov 15, '11 at 1:21p
active	Nov 15, '11 at 5:01p
posts	6
users	2
website	mongodb.org
irc	#mongodb

responses	expanded	Hotkey: s
font	variable	Hotkey: f
user style	avatars	Hotkey: a

[mongodb-user] Too high globalLock ratio: how to decrease it?

Search Discussions

Related Discussions

2 users in discussion