[SERVER-28138] rangeDeleter causes timeout Created: 28/Feb/17  Updated: 31/May/17  Resolved: 21/Mar/17

Status: Closed
Project: Core Server
Component/s: Sharding
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: xihui he Assignee: Mark Agarunov
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File diagnostic.data.tar.gz     File mongodb.log.gz    
Operating System: ALL
Participants:

 Description   

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



 Comments   
Comment by Mark Agarunov [ 16/Mar/17 ]

Hello bydsky

Thank you for the response. From the diagnostic data and your responses, I do not see anything to indicate a bug in the MongoDB server. It appears that a high IO load is causing the queries to time out as rangeDeleter queries are quite expensive and the mongod server appears to be quite heavily loaded.

Thanks,
Mark

Comment by xihui he [ 16/Mar/17 ]

Hi mark.agarunov,

1. We observe very high write IOPS every 60s, about 36000 writes per seconds, up to the limit of our SSD (samsung 850 pro ). After we tune syncPeriodSecs to 30s, the IOPS spike decreases to about 20000 and the timeout is gone.
2. I know it's not recommended to change the setting in the document, but it doesn't give a reason on this. It seems to me very strange that during the checkpoint, the writes are almost random. Per my understanding on WT, it should be sequential?
3. We already set the secondaryThrottle to true. If secondaryThrottle is set to false, during the move chunk, the database is almost service unavailable. However setting the secondaryThrottle to true makes the move chunk extremely slow.

Thanks,
Xihui

Comment by Mark Agarunov [ 13/Mar/17 ]

Hello bydsky,

Thank you for providing this data. Looking over it, it seems that there is a heavy io load on the server, and the timeouts may simply be due to the server being overloaded. To clarify, is there a specific reason that syncPeriodSecs is set to 30 seconds?

Generally we recommend not changing this setting in a production environment. Additionally, consider trying the secondaryThrottle parameter as this may alleviate some of the load on the secondary and allow the rangeDeleter queries to complete.

Thanks,
Mark

Comment by xihui he [ 28/Feb/17 ]

I tuned syncPeriodSecs to 30s, and it works well till now.

Comment by xihui he [ 28/Feb/17 ]

The issue is on the secondary. Attached is the secondary log and diagnostic data.
Below is mongos log:

2017-02-28T12:23:56.986+0800 I NETWORK  [NetworkInterfaceASIO-TaskExecutorPool-31-0] Marking host 10.9.17.32:27317 as failed :: caused by :: ExceededTimeLimit: operation exceeded time limit
2017-02-28T12:31:46.583+0800 I NETWORK  [NetworkInterfaceASIO-TaskExecutorPool-19-0] Marking host 10.9.17.32:27317 as failed :: caused by :: ExceededTimeLimit: operation exceeded time limit
2017-02-28T12:38:26.884+0800 I NETWORK  [NetworkInterfaceASIO-TaskExecutorPool-27-0] Marking host 10.9.17.32:27317 as failed :: caused by :: ExceededTimeLimit: operation exceeded time limit
2017-02-28T12:42:37.928+0800 I NETWORK  [NetworkInterfaceASIO-TaskExecutorPool-21-0] Marking host 10.9.16.75:27317 as failed :: caused by :: ExceededTimeLimit: operation exceeded time limit
2017-02-28T12:42:53.622+0800 I NETWORK  [NetworkInterfaceASIO-TaskExecutorPool-17-0] Marking host 10.9.17.32:27317 as failed :: caused by :: ExceededTimeLimit: operation exceeded time limit
2017-02-28T12:44:00.568+0800 I NETWORK  [NetworkInterfaceASIO-TaskExecutorPool-34-0] Marking host 10.9.17.32:27317 as failed :: caused by :: ExceededTimeLimit: operation exceeded time limit
2017-02-28T13:00:44.337+0800 I NETWORK  [NetworkInterfaceASIO-TaskExecutorPool-35-0] Marking host 10.9.17.32:27317 as failed :: caused by :: ExceededTimeLimit: operation exceeded time limit
2017-02-28T13:06:17.634+0800 I NETWORK  [NetworkInterfaceASIO-TaskExecutorPool-5-0] Marking host 10.9.17.32:27317 as failed :: caused by :: ExceededTimeLimit: operation exceeded time limit
2017-02-28T13:07:59.246+0800 I NETWORK  [NetworkInterfaceASIO-TaskExecutorPool-6-0] Marking host 10.9.16.75:27317 as failed :: caused by :: ExceededTimeLimit: operation exceeded time limit
2017-02-28T13:12:57.690+0800 I NETWORK  [NetworkInterfaceASIO-TaskExecutorPool-3-0] Marking host 10.9.17.32:27317 as failed :: caused by :: ExceededTimeLimit: operation exceeded time limit
2017-02-28T13:24:04.349+0800 I NETWORK  [NetworkInterfaceASIO-TaskExecutorPool-9-0] Marking host 10.9.17.32:27317 as failed :: caused by :: ExceededTimeLimit: operation exceeded time limit
2017-02-28T13:35:11.702+0800 I NETWORK  [NetworkInterfaceASIO-TaskExecutorPool-32-0] Marking host 10.9.17.32:27317 as failed :: caused by :: ExceededTimeLimit: operation exceeded time limit
2017-02-28T13:38:32.682+0800 I NETWORK  [NetworkInterfaceASIO-TaskExecutorPool-21-0] Marking host 10.9.17.32:27317 as failed :: caused by :: ExceededTimeLimit: operation exceeded time limit

primary log:

2017-02-28T13:00:15.042+0800 I SHARDING [RangeDeleter] rangeDeleter deleted 90978 documents for media.media_tags from { _id: -2007990728475156644 } -> { _id: -2007586489143025781 }
2017-02-28T13:12:20.213+0800 I SHARDING [RangeDeleter] rangeDeleter deleted 126144 documents for media.media_tags from { _id: -2007586489143025781 } -> { _id: -2007023626273698015 }
2017-02-28T13:24:15.712+0800 I SHARDING [RangeDeleter] rangeDeleter deleted 126146 documents for media.media_tags from { _id: -2007023626273698015 } -> { _id: -2006459640750053489 }
2017-02-28T13:36:03.623+0800 I SHARDING [RangeDeleter] rangeDeleter deleted 126146 documents for media.media_tags from { _id: -2006459640750053489 } -> { _id: -2005898145338959773 }

Comment by Kelsey Schubert [ 28/Feb/17 ]

Hi bydsky,

So we can continue to investigate this behavior, would you please upload the complete log files as well as an archive of the diagnostic.data for the affected mongod?

Thank you,
Thomas

Generated at Thu Feb 08 04:17:14 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.