Some update operations caused mongo locked for a long time.

28 views

Skip to first unread message

agen

unread,

Jul 10, 2014, 3:13:36 AM7/10/14

to mongod...@googlegroups.com

The java logs show the operation had done but the MongoDB's locked status had spent for about 30 seconds. The page was always waiting for the lock release.

The mongodb version is 2.6.3 and runing stand along. The java code like these

UpdateOperations<KeywordStatus> uo = datastore.createUpdateOperations(KeywordStatus.class);

uo.set("status", "1");

Query<KeywordStatus> query = datastore.createQuery(KeywordStatus.class);

query.field("keywordId").equal(Long.parseLong(keywordId));

UpdateResults<KeywordStatus> ret = datastore.update(query, uo, false, WriteConcern.SAFE);

There are 484573 records in the keywords table and the keywordId has been indexed. I have no idea about this for serveral days.

[2014-07-10 14:52:56,469] DEBUG

update.size:5

[2014-07-10 14:52:56,469] DEBUG

start updateKeywords.

[2014-07-10 14:52:56,562] DEBUG

Write Success, keywordId: 67699606245

[2014-07-10 14:52:56,562] DEBUG

Write Success, keywordId: 67699606248

[2014-07-10 14:52:56,563] DEBUG

Write Success, keywordId: 67699606257

[2014-07-10 14:52:56,563] DEBUG

Write Success, keywordId: 67699606316

[2014-07-10 14:52:56,564] DEBUG

Write Success, keywordId: 67843238610

insert query update delete getmore command flushes mapped vsize res faults locked db idx miss % qr|qw ar|aw netIn netOut conn time

*0 *0 4 *0 0 2|0 0 6.03g 12.4g 1.95g 0 test:172.7% 0 0|0 0|1 664b 6k 13 14:53:59

*0 *0 4 *0 0 2|0 0 6.03g 12.4g 1.95g 0 test:190.1% 0 0|0 0|1 664b 6k 13 14:54:00

*0 *0 4 *0 0 2|0 0 6.03g 12.4g 1.95g 0 test:179.6% 0 0|0 0|1 664b 6k 13 14:54:01

*0 *0 4 *0 0 2|0 0 6.03g 12.4g 1.95g 0 test:179.6% 0 0|0 0|1 664b 6k 13 14:54:02

*0 *0 3 *0 0 2|0 0 6.03g 12.4g 1.95g 0 test:180.0% 0 0|0 0|1 529b 6k 13 14:54:03

*0 *0 4 *0 0 2|0 0 6.03g 12.4g 1.95g 0 test:169.0% 0 0|0 0|1 664b 6k 13 14:54:04

*0 *0 4 *0 0 2|0 0 6.03g 12.4g 1.94g 0 test:171.4% 0 1|0 0|1 664b 6k 13 14:54:05

*0 *0 4 *0 0 2|0 0 6.03g 12.4g 1.95g 0 test:190.2% 0 0|0 0|1 664b 6k 13 14:54:06

*0 *0 4 *0 0 2|0 0 6.03g 12.4g 1.83g 0 test:170.4% 0 0|0 0|1 664b 6k 13 14:54:07

*0 *0 4 *0 0 2|0 0 6.03g 12.4g 1.95g 0 test:182.3% 0 0|0 0|1 664b 6k 13 14:54:08

insert query update delete getmore command flushes mapped vsize res faults locked db idx miss % qr|qw ar|aw netIn netOut conn time

*0 *0 4 *0 0 2|0 0 6.03g 12.4g 1.95g 0 test:172.9% 0 0|0 0|1 664b 6k 13 14:54:09

*0 *0 3 *0 0 2|0 0 6.03g 12.4g 1.95g 0 test:191.7% 0 0|0 0|1 529b 6k 13 14:54:10

*0 *0 4 *0 0 2|0 0 6.03g 12.4g 1.95g 0 test:170.6% 0 0|0 0|1 664b 6k 13 14:54:11

*0 *0 4 *0 0 2|0 0 6.03g 12.4g 1.95g 0 test:168.4% 0 0|0 0|1 664b 6k 13 14:54:12

*0 *0 4 *0 0 2|0 0 6.03g 12.4g 1.95g 0 test:198.1% 0 0|0 0|1 664b 6k 13 14:54:13

*0 *0 4 *0 0 2|0 0 6.03g 12.4g 1.95g 0 test:161.5% 0 0|0 0|1 664b 6k 13 14:54:14

*0 *0 4 *0 0 2|0 0 6.03g 12.4g 1.95g 0 test:175.2% 0 0|0 0|1 664b 6k 13 14:54:15

*0 *0 3 *0 0 2|0 0 6.03g 12.4g 1.95g 0 test:168.3% 0 0|0 0|1 529b 6k 13 14:54:16

*0 *0 4 *0 0 2|0 0 6.03g 12.4g 1.95g 0 test:192.7% 0 0|0 0|1 664b 6k 13 14:54:17

*0 *0 4 *0 0 2|0 0 6.03g 12.4g 1.96g 1 test:167.0% 0 0|0 0|1 664b 6k 13 14:54:18

insert query update delete getmore command flushes mapped vsize res faults locked db idx miss % qr|qw ar|aw netIn netOut conn time

*0 7 *0 *0 0 3|0 0 6.03g 12.4g 1.96g 0 test:9.8% 0 0|0 0|0 1k 119k 13 14:54:19

*0 *0 *0 *0 0 2|0 0 6.03g 12.4g 1.72g 0 .:1.0% 0 0|0 0|0 124b 6k 13 14:54:20

*0 *0 *0 *0 0 2|0 0 6.03g 12.4g 1.72g 0 .:0.1% 0 0|0 0|0 124b 6k 13 14:54:21

agen

unread,

Jul 10, 2014, 10:19:56 PM7/10/14

to mongod...@googlegroups.com

I have solved this problem. We didn't index the condition field of query so mongo costed much time on query. The locked percentage was down to 7% after indexed the two fields.