[SERVER-19006] mongod hang more than 30s few times a day Created: 17/Jun/15  Updated: 01/Jul/15  Resolved: 01/Jul/15

Status: Closed
Project: Core Server
Component/s: MMAPv1, Replication, Usability
Affects Version/s: 2.6.10
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Jiangcheng Wu Assignee: Ramon Fernandez Marina
Resolution: Cannot Reproduce Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File mongod-gdb-bt.gz     HTML File mongod-psaxl    
Operating System: ALL
Participants:

 Description   

There is only mongod running on the machine. In daylight, mongod instance will hang more than 30s a few times.

When mongod hanging:

  • There is no logs ouputs
  • mongostat which connected to the mongod will stop ouputing stat
  • query get no response( then timeout )
  • no disk read operations, and a few disk write operstions
  • MajorPF decrease from 20~30 to 0, MinPF decrease from 20~30k to less than 10k
  • network read traffic decrease from 600kb+ to 10~150kb, write traffic decrease from 3MB+ to 10~30kb

Here is collected dstat data when mongod(PRIMARY) hanging:

    time     |run blk new|usr sys idl wai hiq siq| read  writ| read  writ| recv  send|  in   out | used  free|files  inodes|tot tcp udp raw frg|majpf minpf alloc  free
17-06 10:13:05|4.0   0 1.0|  9   5  87   0   0   0|3336k 2472k|50.0  15.0 | 786k   13M|   0     0 |  38M  474M|20720  96300 |  2   2   9   0   0|  33  6634  8385  4439 
17-06 10:13:06|3.0   0 1.0| 10   5  85   0   0   0|2728k 2328k|43.0  14.0 | 873k 9604k|   0     0 |  38M  474M|20720  96300 |  2   2   9   0   0|  23    27k   10k   12k
17-06 10:13:07|3.0   0 7.0|  8   5  87   0   0   0|1728k 2204k|28.0  15.0 | 724k 5850k|   0     0 |  38M  474M|20720  96298 |  2   2   9   0   0|  19    31k   10k 8094 
17-06 10:13:08|2.0   0   0|  8   5  87   0   0   0|2136k   65M|31.0  3886 | 609k 9773k|   0     0 |  38M  474M|20720  96298 |  2   2   9   0   0|  21  4047  4987  3614 
17-06 10:13:09|2.0   0   0|  7   5  88   0   0   0|1212k 1248k|17.0  9.00 | 475k 3621k|   0     0 |  38M  474M|20720  96307 |  2   2   9   0   0|   8  7449  6747  4435 
.... hang here .....
17-06 10:13:10|3.0   0   0|  4   4  91   0   0   0|   0     0 |   0     0 | 121k   17k|   0     0 |  38M  474M|20720  96307 |  2   2   9   0   0|   0  1121  1095  1081 
17-06 10:13:11|2.0   0 1.0|  4   4  91   0   0   0|   0     0 |   0     0 | 109k   19k|   0     0 |  38M  474M|20720  96307 |  2   2   9   0   0|   0  1944  1874  1875 
17-06 10:13:12|2.0   0 7.0|  4   5  91   0   0   0|   0    16k|   0  2.00 |  95k   18k|   0     0 |  38M  474M|20720  96298 |  2   2   9   0   0|   0  8095  5435  5427 
17-06 10:13:13|2.0   0   0|  4   4  92   0   0   0|   0     0 |   0     0 | 111k   27k|   0     0 |  38M  474M|20720  96301 |  2   2   9   0   0|   0    88    13    17 
17-06 10:13:14|2.0   0 1.0|  4   5  91   0   0   0|   0   156k|   0  2.00 |  63k   14k|   0     0 |  38M  474M|20720  96307 |  2   2   9   0   0|   0  3235  2951  2951 
17-06 10:13:15|2.0   0   0|  4   5  91   0   0   0|   0     0 |   0     0 |  47k   13k|   0     0 |  38M  474M|20720  96307 |  2   2   9   0   0|   0  3308  2934  2934 
17-06 10:13:16|2.0   0 2.0|  4   4  92   0   0   0|   0     0 |   0     0 |  17k 9630B|   0     0 |  38M  474M|20720  96300 |  2   2   9   0   0|   0   268    18    18 
17-06 10:13:17|3.0   0 5.0|  4   5  91   0   0   0|   0    16k|   0  2.00 |8419B 6844B|   0     0 |  38M  474M|20720  96301 |  2   2   9   0   0|   0  6301  4134  3144 
17-06 10:13:18|2.0   0 3.0|  4   4  91   0   0   0|   0     0 |   0     0 |4435B 4755B|   0     0 |  38M  474M|20720  96299 |  2   2   9   0   0|   0  2101  1437  2418 
17-06 10:13:19|2.0   0   0|  4   5  91   0   0   0|   0     0 |   0     0 |  44k   12k|   0     0 |  38M  474M|20720  96315 |  2   2   9   0   0|   0  3225  2954  2954 
17-06 10:13:20|2.0   0   0|  4   5  91   0   0   0|   0     0 |   0     0 | 158k   29k|   0     0 |  38M  474M|20720  96315 |  2   2   9   0   0|   0  3529  2973  2973 
17-06 10:13:21|2.0   0   0|  4   4  92   0   0   0|   0    12k|   0  2.00 | 117k   27k|   0     0 |  38M  474M|20720  96315 |  2   2   9   0   0|   0    96     2     2 
17-06 10:13:22|2.0   0   0|  4   5  91   0   0   0|   0     0 |   0     0 | 101k   19k|   0     0 |  38M  474M|20720  96315 |  2   2   9   0   0|   0  2967  2946  2944 
17-06 10:13:23|2.0   0 8.0|  5   5  91   0   0   0|   0    16k|   0  2.00 | 166k   28k|   0     0 |  38M  474M|20720  96315 |  2   2   9   0   0|   0  9979  6095  5909 
17-06 10:13:24|2.0   0 1.0|  4   4  92   0   0   0|   0     0 |   0     0 |  90k   20k|   0     0 |  38M  474M|20720  96316 |  2   2   9   0   0|   0    90     8     3 
17-06 10:13:25|2.0   0 5.0|  4   4  91   0   0   0|   0     0 |   0     0 |  52k   17k|   0     0 |  38M  474M|20720  96323 |  2   2   9   0   0|   0  4191  3261  3247 
17-06 10:13:26|2.0   0 1.0|  4   4  92   0   0   0|   0     0 |   0     0 |  16k 8844B|   0     0 |  38M  474M|20720  96323 |  2   2   9   0   0|   0    75     6    11 
17-06 10:13:27|2.0   0   0|  4   4  91   0   0   0|   0     0 |   0     0 |  10k 9190B|   0     0 |  38M  474M|20720  96323 |  2   2   9   0   0|   0  2986  2938  2936 
17-06 10:13:28|2.0   0 7.0|  4   5  91   0   0   0|   0    28k|   0  4.00 |8656B 5238B|   0     0 |  38M  474M|20720  96323 |  2   2   9   0   0|   0  9222  6140  6089 
17-06 10:13:29|2.0   0   0|  4   4  92   0   0   0|   0     0 |   0     0 |  24k 8107B|   0     0 |  38M  474M|20720  96323 |  2   2   9   0   0|   0    85     9     9 
17-06 10:13:30|2.0   0   0|  4   4  91   0   0   0|   0     0 |   0     0 | 131k   27k|   0     0 |  38M  474M|20720  96323 |  2   2   9   0   0|   0  2994  2943  2940 
17-06 10:13:31|2.0   0  25|  4   4  91   0   0   0|   0     0 |   0     0 | 130k   35k|   0     0 |  38M  474M|20720  96432 |  2   2   9   0   0|   0  3113  3207  3025 
17-06 10:13:32|2.0   0  45|  4   4  92   0   0   0|   0     0 |   0     0 | 100k   34k|   0     0 |  38M  474M|20720  96478 |  2   2   9   0   0|   0   454   511    25 
17-06 10:13:33|2.0   0  50|  5   5  91   0   0   0|   0    10M|   0   790 | 112k   34k|   0     0 |  38M  474M|20720  97036 |  2   2   9   0   0|   0    11k 7378  6799 
17-06 10:13:34|3.0   0  62|  4   4  91   0   0   0|   0   112k|   0  8.00 | 157k   44k|   0     0 |  38M  474M|20720  97098 |  2   2   9   0   0|   0  2957  2862  2154 
17-06 10:13:35|2.0   0  20|  4   4  92   0   0   0|   0     0 |   0     0 |  44k   15k|   0     0 |  38M  474M|20720  97719 |  2   2   9   0   0|   0  1853  1544  1321 
17-06 10:13:36|2.0   0 9.0|  4   4  91   0   0   0|   0    52k|   0  6.00 |  20k   11k|   0     0 |  38M  474M|20720  97916 |  2   2   9   0   0|   0  3414  3362  3250 
17-06 10:13:37|2.0   0 3.0|  4   4  92   0   0   0|   0    92k|   0  6.00 |  40k 8092B|   0     0 |  38M  474M|20720  97919 |  2   2   9   0   0|   0   647    67    21 
17-06 10:13:38|2.0   0  11|  5   5  91   0   0   0|   0    44k|   0  2.00 |  10k   10k|   0     0 |  38M  474M|20720  97259 |  2   2   9   0   0|   0    11k 7395    22k
17-06 10:13:39|2.0   0  32|  4   4  91   0   0   0|   0    32k|   0  6.00 |  27k   18k|   0     0 |  38M  474M|20720  97336 |  2   2   9   0   0|   0  7432  4474  4165 
17-06 10:13:40|5.0   0 104|  4   5  91   0   0   0|   0     0 |   0     0 | 170k   63k|   0     0 |  38M  474M|20768  97441 |  2   2   9   0   0|   0  1581  1540    15k
17-06 10:13:41|2.0   0  95|  4   5  91   0   0   0|   0     0 |   0     0 | 159k   59k|   0     0 |  38M  474M|20768  98703 |  2   2   9   0   0|   0  5230  5358    17k
17-06 10:13:42|2.0   0  89|  4   5  91   0   0   0|   0     0 |   0     0 | 132k   54k|   0     0 |  38M  474M|20816  99730 |  3   2   9   0   0|   0  4978  5424  5233 
17-06 10:13:43|2.0   0  83|  4   5  91   0   0   0|   0    32k|   0  4.00 | 109k   43k|   0     0 |  38M  474M|20864  99800 |  3   2   9   0   0|   0  8355  5044  5214 
..... resumed here ....
17-06 10:13:44|5.0   0  78| 17   7  75   0   0   0|8052k   14M| 305  17.7k|1673k   17M|   0     0 |  38M  474M|20912  97331 |  2   2   9   0   0|  92    42k   28k   29k
17-06 10:13:45|7.0   0   0| 20   6  74   0   0   0|2828k 2980k| 118  18.0 |1568k 6635k|   0     0 |  38M  474M|20912  97331 |  2   2   9   0   0|  32    28k   17k   12k
17-06 10:13:46|3.0   0 2.0| 17   6  77   0   0   0|1256k 1852k|37.0  12.0 |1370k 3418k|   0     0 |  38M  474M|20912  97338 |  2   2   9   0   0|  13    21k   12k   11k
17-06 10:13:47|6.0   0   0| 18   6  75   0   0   0|6864k 4564k| 156  22.0 |2001k   27M|   0     0 |  38M  474M|20912  97345 |  2   2   9   0   0|  58    36k   25k   23k



 Comments   
Comment by Ramon Fernandez Marina [ 01/Jul/15 ]

wujiangcheng, in the absence of more information that may help us reproduce the exact behavior you describe I'm going to close this ticket for the time being. Please consider the data points in my last comment: using very large arrays may have an adverse performance impact in some loads, and if that's your case you may want to consider schema updates.

Regards,
Ramón.

Comment by Ramon Fernandez Marina [ 19/Jun/15 ]

wujiangcheng, the log line above shows an update to a document with a very large array. While the document may be smaller than the 16MB limit, embedding large arrays in documents is not a good idea in general.

I was unable to exactly reproduce the 30s hangs you describe, but I think I understand how long delays may happen:

  1. An update to a document with a large array is performed
  2. The field containing the large array is indexed, so the index needs to be updated
  3. Until the index is updated, queries against the collection where this document lives will block

This is what I did to reproduce this behavior on my end; first I added some data:

use test
db.foo.drop()
db.bar.drop()
db.counts.drop()
 
var nDocs = 20
var nRefs = 30000
 
db.counts.insert({ndocs: nDocs, nrefs: nRefs})
 
// On "foo", insert nDocs documents, each with an array of nRefs dbrefs
// On "bar", insert docs referenced in "foo"
print("Insert docs")
for (doc = 0 ; doc < nDocs; doc++) {
    var refs = new Array(nRefs);
    var bardocs = new Array(nRefs)
 
    for (ref = 0 ; ref < nRefs ; ref++) {
        var oid = ObjectId()
        bardocs[ref] = {_id : oid, doc : doc, ref : ref}
        refs[ref] = { "$ref" : "bar", "$id" : oid }
    }
    db.foo.insert({doc : doc, refs : refs})
    db.bar.insert(bardocs)
}
 
// Create some indexes so the test is not affected by collection scans
db.foo.ensureIndex({doc: 1})
db.foo.ensureIndex({refs: 1})
db.bar.ensureIndex({doc: 1})

The foo collection contains documents with large arrays. Then I updated all those documents:

use admin
db.runCommand({setParameter:1, logLevel:2})
db.setProfilingLevel(0,0)
 
use test
var counts = db.counts.findOne()
var nDocs = counts.ndocs
var nRefs = counts.nrefs
 
// Update all documents
print("Update docs")
var newrefs = new Array(nRefs)
 
for (doc = 0; doc < nDocs; doc++) {
    // find some oids from bar and update the dbrefs on foo
    var it = db.bar.find({doc : Math.floor ( Math.random() * nDocs)})
 
    var i = 0;
    while (it.hasNext()) {
        newrefs[i++] = { $ref : "aaa", $id : it.next()._id }
    }
 
    db.foo.update({ doc : doc }, {$set : { refs : newrefs }})
}

What I see in mongostat is a high lock % and choppy output; dstat doesn't show anything remarkable, but I see a CPU usage spike by mongod when using top.

If I'm reading things correctly then the length of the pause may be proportional to CPU and memory speed, so I have some more questions for you to continue troubleshooting this issue:

  • What are the specs of your machine?
  • Can you try the code above in a similar machine and let us know if the behavior you observe corresponds to the behavior you originally reported?
  • Can you confirm that you have an index on the users field in the affected collection?

Thanks,
Ramón.

Comment by Jiangcheng Wu [ 18/Jun/15 ]

It's not a bug, but update a big document( 1623k ) lead to hang. Everything goes well after that document was removed.

# PRIMARY
2015-06-17T16:46:05.104+0800 [conn8494881] update 01i1l2w9vdspol2qhzqvdgkv9zahwu8ovuw29rlokqb2xn8p._Role query: { _id: ObjectId('55652c8be4b0328678ae3bfe') } update: { $set: { updatedAt: new Date(1434530725396) }, $addToSet: { users: { $each: [ { $ref: "_User", $id: ObjectId('558133a5e4b0a83febf20914') } ] } } } nscanned:1 nscannedObjects:1 nMatched:1 nModified:1 keyUpdates:2 numYields:0 locks(micros) w:39710443 39708ms
# SECONDARY
2015-06-17T16:46:05.545+0800 [repl writer worker 3] warning: log line attempted (1623k) over max size (10k), printing beginning and end ... applying op: { ts: Timestamp 1434530
765000|1, h: -7048969912752559951, v: 2, op: "u", ns: "01i1l2w9vdspol2qhzqvdgkv9zahwu8ovuw29rlokqb2xn8p._Role", o2: { _id: ObjectId('55652c8be4b0328678ae3bfe') }, o: { $set: { 
updatedAt: new Date(1434530725396), users: [ { $ref: "_User", $id: ObjectId('552e2d06e4b0c0794dbf8794') }, { $ref: "_User", $id: ObjectId('55653f6be4b0328678afd776') }, { $ref:
 "_User", $id: ObjectId('555d78f2e4b06e8bb82e1694') }, { $ref: "_User", $id: ObjectId('5567d78de4b0349d331272f1') }, { $ref: "_User", $id: ObjectId('5567e862e4b0a9a973e720f9') 
}, { $ref: "_User", $id: ObjectId('5567fa14e4b0349d3314464f') }, { $ref: "_User", $id: ObjectId('5567fa14e4b0349d33144650') }, { $ref: "_User", $id: ObjectId('5567fb9ce4b0349d3
31458f9') }, { $ref: "_User", $id: ObjectId('55680549e4b0349d3314dcef') }, { $ref: "_User", $id: ObjectId('556814bee4b0349d33158559') }, { $ref: "_User", $id: ObjectId('552f629
de4b060d72a8cc0fa') }, { $ref: "_User", $id: ObjectId('5530c384e4b052897f252102') }, { $ref: "_User", $id: ObjectId('5535e90ce4b07b48cfca4b5b') }, { $ref: "_User", $id: ObjectI
d('5538c38ae4b019188efd5d89') }, { $ref: "_User", $id: ObjectId('552d3093e4b00e097d9fa34f') }, { $ref: "_User", $id: ObjectId('5530b437e4b078a906e5cd40') }, { $ref: "_User", $i
d: ObjectId('5530b56ce4b05ce8328d192a') }, { $ref: "_User", $id: ObjectId('555aa87de4b032fcf1906a36') }, { $ref: "_User", $id: ObjectId('5530b3b7e4b052897f2441fa') }, { $ref: "
_User", $id: ObjectId('555db144e4b0283b38a604c0') }, { $ref: "_User", $id: ObjectId('555e0557e4b0ce84eb23be70') }, { $ref: "_User", $id: ObjectId('552e0fb1e4b0c29c3c986e8b') },
 { $ref: "_User", $id: ObjectId('552f5fb7e4b036ba524942e6') }, { $ref: "_User", $id: ObjectId('552e2bcce4b036ba524067ad') }, { $ref: "_User", $id: ObjectId('552e4631e4b060d72a8
4065d') }, { $ref: "_User", $id: ObjectId('5530b426e4b0825685cdc3f6') }, { $ref: "_User", $id: ObjectId('5530b4c1e4b0825685cdd5fa') }, { $ref: "_User", $id: ObjectId('5538be1be
4b0301dbb0cf021') }, { $ref: "_User", $id: ObjectId('5538be4ce4b0301dbb0cf214') }, { $ref: "_User", $id: ObjectId('5538be6de4b0cafb0a1f3bf7') }, { $ref: "_User", $id: ObjectId(
'552f6353e4b060d72a8ccacf') }, { $ref: "_User", $id: ObjectId('5555952fe4b058f8987111d9') }, { $ref: "_User", $id: ObjectId('5556b990e4b0325161229007') }, { $ref: "_User", $id:
 ObjectId('5556cd8ce4b0325161234751') }, { $ref: "_User", $id: ObjectId('5556d76ee4b058f898786495') }, { $ref: "_User", $id: ObjectId('5556d7bce4b058f89878674b') }, { $ref: "_U
ser", $id: ObjectId('552f8aa8e4b060d72a8edaea') }, { $ref: "_User", $id: ObjectId('555950b6e4b0137a4e2bc390') }, { $ref: "_User", $id: ObjectId('555951ace4b0b8cd3b7b1fcb') }, {
 $ref: "_User", $id: ObjectId('555951e9e4b0764298c72e5b') }, { $ref: "_User", $id: ObjectId('55595270e4b0764298c732c9') }, { $ref: "_User", $id: ObjectId('55595292e4b0764298c73
408') }, { $ref: "_User", $id: ObjectId('555953e5e4b0764298c73f23') }, { $ref: "_User", $id: ObjectId('55595610e4b0b8cd3b7b4a23') }, { $ref: "_User", $id: ObjectId('5559587de4b
0b8cd3b7b62cb') }, { $ref: "_User", $id: ObjectId('5555c5c2e4b03251611c1aaf') }, { $ref: "_User", $id: ObjectId('552e104be4b036ba523f9fe2') }, { $ref: "_User", $id: ObjectId('5
5598bdce4b0b8cd3b7e5752') }, { $ref: "_User", $id: ObjectId('5555b08ce4b0a343c5c19cde') }, { $ref: "_User", $id: ObjectId('5530b5f8e4b05ce8328d2758') }, { $ref: "_User", $id: O
bjectId('5559c4d5e4b0764298cb7878 .......... ef: "_User", $id: ObjectId('556d46a2e4b06d91e724891b') }, { $ref: "_User", $id: ObjectId('556c14d5e4b0982c278a5aa1') }, { $ref: "_U
ser", $id: ObjectId('55794c64e4b0f9862a219f0d') }, { $ref: "_User", $id: ObjectId('55682061e4b0349d33164cef') }, { $ref: "_User", $id: ObjectId('5566da7fe4b02c6f9035792c') }, {
 $ref: "_User", $id: ObjectId('55796b01e4b022be6f9ae76c') }, { $ref: "_User", $id: ObjectId('55796ebae4b0283dd00f724e') }, { $ref: "_User", $id: ObjectId('55799f59e4b04876b85fc
497') }, { $ref: "_User", $id: ObjectId('5579b91ce4b0283dd01f15ca') }, { $ref: "_User", $id: ObjectId('557a1167e4b018bc3d4c1776') }, { $ref: "_User", $id: ObjectId('557a3c30e4b
0283dd02ab9cb') }, { $ref: "_User", $id: ObjectId('557a528ae4b0bcc24ad2fbdd') }, { $ref: "_User", $id: ObjectId('557aaf45e4b04876b8725431') }, { $ref: "_User", $id: ObjectId('5
57ab18ce4b052e03140eb3f') }, { $ref: "_User", $id: ObjectId('557bdf8de4b0a83feba70215') }, { $ref: "_User", $id: ObjectId('557bf09ee4b0cc6267b5dcf8') }, { $ref: "_User", $id: O
bjectId('557c735ae4b0bd33aa1b7e58') }, { $ref: "_User", $id: ObjectId('557ced21e4b02f9923710e8a') }, { $ref: "_User", $id: ObjectId('557d314fe4b02f992373bbb8') }, { $ref: "_Use
r", $id: ObjectId('557d3374e4b042e8c09cff91') }, { $ref: "_User", $id: ObjectId('557d339de4b042e8c09d0236') }, { $ref: "_User", $id: ObjectId('557d37bde4b042e8c09d7ed6') }, { $
ref: "_User", $id: ObjectId('557d3fd9e4b035745aa9408f') }, { $ref: "_User", $id: ObjectId('557d74d6e4b0cc6267e99ee9') }, { $ref: "_User", $id: ObjectId('557d96a1e4b007f322aea9f
4') }, { $ref: "_User", $id: ObjectId('557dfc56e4b0a83febc4db2c') }, { $ref: "_User", $id: ObjectId('557e3e8be4b035745aba1a67') }, { $ref: "_User", $id: ObjectId('557e67b4e4b0c
c626801f5a3') }, { $ref: "_User", $id: ObjectId('557e750ee4b035745abcbd7f') }, { $ref: "_User", $id: ObjectId('557e7868e4b0cc6268042ba3') }, { $ref: "_User", $id: ObjectId('557
e7e22e4b035745abd5094') }, { $ref: "_User", $id: ObjectId('557e8bafe4b00c79c4143fc2') }, { $ref: "_User", $id: ObjectId('557e8dc3e4b0a83febcf5573') }, { $ref: "_User", $id: Obj
ectId('557e8df6e4b0a573eb62c20d') }, { $ref: "_User", $id: ObjectId('557e8fdee4b0a83febcf7a56') }, { $ref: "_User", $id: ObjectId('557e903ce4b00c79c414c9f4') }, { $ref: "_User"
, $id: ObjectId('557e91b2e4b00c79c414fa3d') }, { $ref: "_User", $id: ObjectId('557e9ef8e4b00c79c417026c') }, { $ref: "_User", $id: ObjectId('557ea18ae4b00c79c417687c') }, { $re
f: "_User", $id: ObjectId('557f7fd9e4b02f992383a7aa') }, { $ref: "_User", $id: ObjectId('557f9986e4b007f322c429b4') }, { $ref: "_User", $id: ObjectId('557fa29de4b0d02dc2d919e8'
) }, { $ref: "_User", $id: ObjectId('557fa2e2e4b0a83febdd86c9') }, { $ref: "_User", $id: ObjectId('557fa32ae4b0d02dc2d92f58') }, { $ref: "_User", $id: ObjectId('557fd1d3e4b019e
ef75b6774') }, { $ref: "_User", $id: ObjectId('557fd545e4b0a83febe078c8') }, { $ref: "_User", $id: ObjectId('558041e0e4b0d02dc2f9900e') }, { $ref: "_User", $id: ObjectId('55804
2ece4b007f322ce8c59') }, { $ref: "_User", $id: ObjectId('5580d7b4e4b019eef76de640') }, { $ref: "_User", $id: ObjectId('5580e2a7e4b019eef76ecda5') }, { $ref: "_User", $id: Objec
tId('55811352e4b0bd33aa51fdd0') }, { $ref: "_User", $id: ObjectId('55811736e4b035745ad3ef61') }, { $ref: "_User", $id: ObjectId('5581247be4b0bd33aa52fb7d') }, { $ref: "_User", 
$id: ObjectId('5581279be4b0a83febf14d14') }, { $ref: "_User", $id: ObjectId('558133a5e4b0a83febf20914') } ] } } }

The maximum BSON document size is 16 megabytes. 1623kb is much less than 16 megabytes, I wonder know why this update query so slow?

Comment by Ramon Fernandez Marina [ 17/Jun/15 ]

wujiangcheng, we'll need more information to find out what's causing these pauses:

  1. what are the specs on this machine? Disk, memory, etc.
  2. can you please send logs for this server from the last startup?
  3. Also it would be helpful to see the following information during these pauses:
    1. system logs
    2. output of iostat -x 1
    3. output of vmstat -a 1

Thanks,
Ramón.

Comment by Jiangcheng Wu [ 17/Jun/15 ]

I've attached threads-list and stacks of mongod instance. This may help.

This hang will happen on SECONDARY role too.

Generated at Thu Feb 08 03:49:31 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.