Project

General

Profile

Bug #23519

mds: mds got laggy because of MDSBeacon stuck in mqueue

Added by dongdong tao 9 months ago. Updated 3 months ago.

Status:
Resolved
Priority:
Normal
Assignee:
Category:
Correctness/Safety
Target version:
Start date:
03/30/2018
Due date:
% Done:

0%

Source:
Community (dev)
Tags:
Backport:
mimic,luminous
Regression:
No
Severity:
2 - major
Reviewed:
Affected Versions:
ceph-qa-suite:
Component(FS):
MDS, MDSMonitor
Labels (FS):
Pull request ID:

Description

the MDSBeacon message from monitor may stuck for long time in mqueue.
because DispatcherQueue is currently dispatching a MDSMap(rejoin) message, most of the time is
spend in process_imported_caps during rejoin.

Below is the log, see the first line and last line.

2018-03-29 12:51:13.600301 7fc0cb280700  0 -- 10.19.248.31:6804/731296555 >> 10.19.248.31:6789/0 conn(0x557cfc0dc800 :-1 s=STATE_OPEN pgs=7475863 cs=1 l=1).taodd beacon enqueue
0x557d0b5e6080 mdsbeacon(31079818/enn-yc-31 up:rejoin seq 29 v8293) v7
2018-03-29 12:51:13.600344 7fc0c8b06700  1 mds.0.8291 handle_mds_map i am now mds.0.8291
2018-03-29 12:51:13.600352 7fc0c8b06700  1 mds.0.8291 handle_mds_map state change up:reconnect --> up:rejoin
2018-03-29 12:51:13.600362 7fc0c8b06700  1 mds.0.8291 rejoin_start
2018-03-29 12:51:17.020712 7fc0cb280700  0 -- 10.19.248.31:6804/731296555 >> 10.19.248.31:6789/0 conn(0x557cfc0dc800 :-1 s=STATE_OPEN pgs=7475863 cs=1 l=1).taodd beacon enqueue
0x557d0b5e63c0 mdsbeacon(31079818/enn-yc-31 up:rejoin seq 30 v8293) v7
2018-03-29 12:51:18.420713 7fc0cb280700  0 -- 10.19.248.31:6804/731296555 >> 10.19.248.31:6789/0 conn(0x557cfc0dc800 :-1 s=STATE_OPEN pgs=7475863 cs=1 l=1).taodd mdsmap enqueue
0x557d266d58c0 mdsmap(e 8295) v1
2018-03-29 12:51:21.041255 7fc0cb280700  0 -- 10.19.248.31:6804/731296555 >> 10.19.248.31:6789/0 conn(0x557cfc0dc800 :-1 s=STATE_OPEN pgs=7475863 cs=1 l=1).taodd beacon enqueue
0x557cfc186340 mdsbeacon(31079818/enn-yc-31 up:rejoin seq 31 v8295) v7
2018-03-29 12:51:25.005205 7fc0cb280700  0 -- 10.19.248.31:6804/731296555 >> 10.19.248.31:6789/0 conn(0x557cfc0dc800 :-1 s=STATE_OPEN pgs=7475863 cs=1 l=1).taodd beacon enqueue
0x557d2d6acd00 mdsbeacon(31079818/enn-yc-31 up:rejoin seq 32 v8295) v7
2018-03-29 12:51:29.024516 7fc0cb280700  0 -- 10.19.248.31:6804/731296555 >> 10.19.248.31:6789/0 conn(0x557cfc0dc800 :-1 s=STATE_OPEN pgs=7475863 cs=1 l=1).taodd beacon enqueue
0x557d2d6ad040 mdsbeacon(31079818/enn-yc-31 up:rejoin seq 33 v8295) v7
2018-03-29 12:51:33.032054 7fc0cb280700  0 -- 10.19.248.31:6804/731296555 >> 10.19.248.31:6789/0 conn(0x557cfc0dc800 :-1 s=STATE_OPEN pgs=7475863 cs=1 l=1).taodd beacon enqueue
0x557d2d6ad380 mdsbeacon(31079818/enn-yc-31 up:rejoin seq 34 v8295) v7
2018-03-29 12:51:37.025607 7fc0cb280700  0 -- 10.19.248.31:6804/731296555 >> 10.19.248.31:6789/0 conn(0x557cfc0dc800 :-1 s=STATE_OPEN pgs=7475863 cs=1 l=1).taodd beacon enqueue
0x557d2d6ad6c0 mdsbeacon(31079818/enn-yc-31 up:rejoin seq 35 v8295) v7
2018-03-29 12:51:41.025065 7fc0cb280700  0 -- 10.19.248.31:6804/731296555 >> 10.19.248.31:6789/0 conn(0x557cfc0dc800 :-1 s=STATE_OPEN pgs=7475863 cs=1 l=1).taodd beacon enqueue
0x557d2d6ada00 mdsbeacon(31079818/enn-yc-31 up:rejoin seq 36 v8295) v7
2018-03-29 12:51:45.024202 7fc0cb280700  0 -- 10.19.248.31:6804/731296555 >> 10.19.248.31:6789/0 conn(0x557cfc0dc800 :-1 s=STATE_OPEN pgs=7475863 cs=1 l=1).taodd beacon enqueue
0x557d2d6add40 mdsbeacon(31079818/enn-yc-31 up:rejoin seq 37 v8295) v7
2018-03-29 12:51:49.137766 7fc0cb280700  0 -- 10.19.248.31:6804/731296555 >> 10.19.248.31:6789/0 conn(0x557cfc0dc800 :-1 s=STATE_OPEN pgs=7475863 cs=1 l=1).taodd beacon enqueue
0x557d2d6ae080 mdsbeacon(31079818/enn-yc-31 up:rejoin seq 38 v8295) v7
2018-03-29 12:51:53.141025 7fc0cb280700  0 -- 10.19.248.31:6804/731296555 >> 10.19.248.31:6789/0 conn(0x557cfc0dc800 :-1 s=STATE_OPEN pgs=7475863 cs=1 l=1).taodd beacon enqueue
0x557d2d6ae3c0 mdsbeacon(31079818/enn-yc-31 up:rejoin seq 39 v8295) v7
2018-03-29 12:51:57.024013 7fc0cb280700  0 -- 10.19.248.31:6804/731296555 >> 10.19.248.31:6789/0 conn(0x557cfc0dc800 :-1 s=STATE_OPEN pgs=7475863 cs=1 l=1).taodd beacon enqueue
0x557d2d6ae700 mdsbeacon(31079818/enn-yc-31 up:rejoin seq 40 v8295) v7
2018-03-29 12:52:01.031026 7fc0cb280700  0 -- 10.19.248.31:6804/731296555 >> 10.19.248.31:6789/0 conn(0x557cfc0dc800 :-1 s=STATE_OPEN pgs=7475863 cs=1 l=1).taodd beacon enqueue
0x557d2d6aea40 mdsbeacon(31079818/enn-yc-31 up:rejoin seq 41 v8295) v7
2018-03-29 12:52:05.027415 7fc0cb280700  0 -- 10.19.248.31:6804/731296555 >> 10.19.248.31:6789/0 conn(0x557cfc0dc800 :-1 s=STATE_OPEN pgs=7475863 cs=1 l=1).taodd beacon enqueue
0x557d2d6aed80 mdsbeacon(31079818/enn-yc-31 up:rejoin seq 42 v8295) v7
2018-03-29 12:52:09.129624 7fc0cb280700  0 -- 10.19.248.31:6804/731296555 >> 10.19.248.31:6789/0 conn(0x557cfc0dc800 :-1 s=STATE_OPEN pgs=7475863 cs=1 l=1).taodd beacon enqueue
0x557d2d6af0c0 mdsbeacon(31079818/enn-yc-31 up:rejoin seq 43 v8295) v7
2018-03-29 12:52:13.124805 7fc0cb280700  0 -- 10.19.248.31:6804/731296555 >> 10.19.248.31:6789/0 conn(0x557cfc0dc800 :-1 s=STATE_OPEN pgs=7475863 cs=1 l=1).taodd beacon enqueue
0x557d2d6af400 mdsbeacon(31079818/enn-yc-31 up:rejoin seq 44 v8295) v7
2018-03-29 12:52:17.039225 7fc0cb280700  0 -- 10.19.248.31:6804/731296555 >> 10.19.248.31:6789/0 conn(0x557cfc0dc800 :-1 s=STATE_OPEN pgs=7475863 cs=1 l=1).taodd beacon enqueue
0x557d2d6af740 mdsbeacon(31079818/enn-yc-31 up:rejoin seq 45 v8295) v7
2018-03-29 12:52:21.025163 7fc0cb280700  0 -- 10.19.248.31:6804/731296555 >> 10.19.248.31:6789/0 conn(0x557cfc0dc800 :-1 s=STATE_OPEN pgs=7475863 cs=1 l=1).taodd beacon enqueue
0x557d2d6afa80 mdsbeacon(31079818/enn-yc-31 up:rejoin seq 46 v8295) v7
2018-03-29 12:52:25.025566 7fc0cb280700  0 -- 10.19.248.31:6804/731296555 >> 10.19.248.31:6789/0 conn(0x557cfc0dc800 :-1 s=STATE_OPEN pgs=7475863 cs=1 l=1).taodd beacon enqueue
0x557d87ba0080 mdsbeacon(31079818/enn-yc-31 up:rejoin seq 47 v8295) v7
2018-03-29 12:52:25.337149 7fc0c8b06700  1 mds.0.8291 rejoin_joint_start
2018-03-29 12:52:25.337199 7fc0c8b06700  0 -- 10.19.248.31:6804/731296555 taodd outqueue beacon 0x557d0b5e6080 mdsbeacon(31079818/enn-yc-31 up:rejoin seq 29 v8293) v7

Related issues

Related to fs - Bug #19706: Laggy mon daemons causing MDS failover (symptom: failed to set counters on mds daemons: set(['mds.dir_split'])) Can't reproduce 04/20/2017
Copied to fs - Backport #26923: mimic: mds: mds got laggy because of MDSBeacon stuck in mqueue Resolved
Copied to fs - Backport #26924: luminous: mds: mds got laggy because of MDSBeacon stuck in mqueue Resolved

History

#1 Updated by dongdong tao 9 months ago

  • Assignee set to dongdong tao

#2 Updated by dongdong tao 9 months ago

currently, there is no incoming mds messages can be fast dispatch.
so, and since the MDSBeacon's handler handle_mds_beacon is really simple.
i'm wondering maybe we can make MDSBeacon fast dispatch to avoid this kind laggy ?
@zheng, @Patrick, what's your opinion ?

#3 Updated by Patrick Donnelly 8 months ago

  • Related to Bug #19706: Laggy mon daemons causing MDS failover (symptom: failed to set counters on mds daemons: set(['mds.dir_split'])) added

#4 Updated by Patrick Donnelly 8 months ago

Dongdong, I think fast dispatch may not be the answer here. We're not yet sure on the cause. Do you have ideas?

#5 Updated by dongdong tao 8 months ago

Patrick Donnelly wrote:

Dongdong, I think fast dispatch may not be the answer here. We're not yet sure on the cause. Do you have ideas?

Because Beacon message is waiting in the mqueue too long for mds taking care of the previous MDSMap message.

#6 Updated by Patrick Donnelly 8 months ago

  • Status changed from New to In Progress
  • Target version set to v13.0.0
  • Source set to Community (dev)
  • Backport set to luminous
  • Severity changed from 3 - minor to 2 - major
  • Component(FS) MDS, MDSMonitor added

#7 Updated by Patrick Donnelly 8 months ago

  • Description updated (diff)
  • Category set to Correctness/Safety

#8 Updated by Patrick Donnelly 8 months ago

dongdong tao wrote:

Patrick Donnelly wrote:

Dongdong, I think fast dispatch may not be the answer here. We're not yet sure on the cause. Do you have ideas?

Because Beacon message is waiting in the mqueue too long for mds taking care of the previous MDSMap message.

Sorry, I didn't have my coffee yet when I was processing your original description. Yes, I think fast dispatch might make sense.

Am I correct that #23530 is a fix for this problem but you're looking for a more robust solution?

#9 Updated by dongdong tao 8 months ago

the two issue are not the same, but they are caused by the same reason: mds take too much time to handle MDSMap message(rejoin)
#23530 is another consequence. #23530's solution can not solve this issue.

#10 Updated by Patrick Donnelly 7 months ago

  • Target version changed from v13.0.0 to v14.0.0
  • Backport changed from luminous to mimic,luminous

#11 Updated by Zheng Yan 4 months ago

  • Status changed from In Progress to Need Review

#12 Updated by Patrick Donnelly 4 months ago

  • Status changed from Need Review to Pending Backport

We've merged the fast dispatch fix but I want to point out for the record that the beacon replies from the monitors are actually high priority. For this reason, the beacons are never actually "stuck" in the message queue behind less important messages. The real problem, for this issue, is that the MDS was taking too long during rejoin.

With that said, faster processing of the beacon replies outside of the mds_lock (via normal dispatch) is still a positive change worth merging.

#13 Updated by Patrick Donnelly 4 months ago

  • Copied to Backport #26923: mimic: mds: mds got laggy because of MDSBeacon stuck in mqueue added

#14 Updated by Patrick Donnelly 4 months ago

  • Copied to Backport #26924: luminous: mds: mds got laggy because of MDSBeacon stuck in mqueue added

#15 Updated by Nathan Cutler 3 months ago

  • Status changed from Pending Backport to Resolved

Also available in: Atom PDF