Loading...

Type: Bug
Resolution: Done
Priority: Major - P3
Fix Version/s: None
Affects Version/s: None
Component/s: Sharding
Labels:
None

Operating System:
ALL
CAR Domain/s:
None

Aha! Reference:
None
Tracking Level:
None
Risk Status:
None
Exec Notes:
None
Goal Name(s):
None
Goal Link:
None

version: mongodb-linux-x86_64-debian81-3.4.2

We periodically got operation exceeded time limit (8500ms) after moveChunk. It seems it's caused by rangeDeleter. During the range delete, the iostat shows w/s suddenly increase from 200 to 30000.

2017-02-28T11:39:21.285+0800 I SHARDING [RangeDeleter] rangeDeleter deleted 126145 documents for media.media_tags from { _id: -2014043904481584736 } -> { _id: -2013480085714135420 }

2017-02-28T11:39:21.064+0800 I COMMAND  [conn4336687] command media.media_tags command: find { find: "media_tags", filter: { _id: { $in: [ 6391998629359387141 ] } }, maxTimeMS: 5500, shardVersion: [ Timestamp 2812000|1, ObjectId('579a1adf7da6fc22e14e5ce0') ] } planSummary: IXSCAN { _id: 1 } keysExamined:0 docsExamined:0 cursorExhausted:1 numYields:0 nreturned:0 reslen:201 locks:{ Global: { acquireCount: { r: 2 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 5372778 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_command 5380ms
2017-02-28T11:39:21.064+0800 I COMMAND  [conn4336864] command media.media_tags command: find { find: "media_tags", filter: { _id: { $in: [ 6391990642146279942 ] } }, maxTimeMS: 5500, shardVersion: [ Timestamp 2812000|1, ObjectId('579a1adf7da6fc22e14e5ce0') ] } planSummary: IXSCAN { _id: 1 } keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:324 locks:{ Global: { acquireCount: { r: 2 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 5956125 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_command 5964ms
2017-02-28T11:39:21.059+0800 I COMMAND  [conn4337153] command media.media_tags command: find { find: "media_tags", filter: { _id: { $in: [ 6391998586543931909 ] } }, maxTimeMS: 8500, shardVersion: [ Timestamp 2812000|1, ObjectId('579a1adf7da6fc22e14e5ce0') ] } planSummary: IXSCAN { _id: 1 } keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:324 locks:{ Global: { acquireCount: { r: 2 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 3522470 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_command 3524ms
2017-02-28T11:39:21.059+0800 I COMMAND  [conn4336967] command media.media_tags command: find { find: "media_tags", filter: { _id: 6391998563672392198 }, limit: 1, maxTimeMS: 5500, shardVersion: [ Timestamp 2812000|1, ObjectId('579a1adf7da6fc22e14e5ce0') ] } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:324 locks:{ Global: { acquireCount: { r: 2 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 4802194 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_command 4805ms
2017-02-28T11:39:21.064+0800 I COMMAND  [conn4337415] command media.media_tags command: find { find: "media_tags", filter: { _id: 6391998570349724165 }, limit: 1, maxTimeMS: 5500, shardVersion: [ Timestamp 2812000|1, ObjectId('579a1adf7da6fc22e14e5ce0') ] } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:331 locks:{ Global: { acquireCount: { r: 2 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 1090055 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_command 1096ms
2017-02-28T11:39:21.064+0800 I COMMAND  [conn4336713] command media.media_tags command: find { find: "media_tags", filter: { _id: { $in: [ 6391998617212682757, 6391998630017892869 ] } }, maxTimeMS: 5500, shardVersion: [ Timestamp 2812000|1, ObjectId('579a1adf7da6fc22e14e5ce0') ] } planSummary: IXSCAN { _id: "hashed" } keysExamined:3 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:338 locks:{ Global: { acquireCount: { r: 2 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 5374038 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_command 5382ms

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sda               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
sdb               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
sdc               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           2.95    0.00    2.38    0.00    0.00   94.67

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sda               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
sdb               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
sdc               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           1.28    0.00    3.08    0.73    0.00   94.91

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sda               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
sdb               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
sdc               0.00     5.00    0.00 22046.00     0.00 235984.00    21.41    73.18    3.27    0.00    3.27   0.03  64.40

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           3.00    0.00    2.37    1.38    0.00   93.25

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sda               0.00     0.00    0.00    3.00     0.00    12.00     8.00     0.00    0.00    0.00    0.00   0.00   0.00
sdb               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
sdc               0.00    53.00  492.00 27173.00  5336.00 206907.00    15.34    63.30    2.33    2.30    2.33   0.04  98.40

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           0.88    0.00    0.45    1.08    0.00   97.60

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sda               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
sdb               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
sdc               0.00    82.00  227.00  206.00  2664.00   928.50    16.59     1.63    3.76    2.82    4.80   2.30  99.60

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           0.85    0.00    0.40    1.10    0.00   97.64

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sda               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
sdb               0.00     2.00    0.00    2.00     0.00    16.00    16.00     0.02   12.00    0.00   12.00  12.00   2.40
sdc               1.00    82.00  254.00  208.00  2772.00   924.00    16.00     1.84    3.99    3.42    4.69   2.15  99.20

- - Sort By Name
  - Sort By Date
  - Ascending
  - Descending
  - Thumbnails
  - List
  - Download All

diagnostic.data.tar.gz
31.58 MB
Feb 28 2017 05:38:41 AM UTC
mongodb.log.gz
2.45 MB
Feb 28 2017 05:38:42 AM UTC

Details

Description

Attachments

Attachments

Activity

People

Dates