[ceph-users] Re: MDS_TRIM 1 MDSs behind on trimming and

21 Apr 2021


      You don't pin subtrees ?
I would guess that something in the workload changed and it's triggering a
particularly bad behavior in the md balancer.
Increase debug_mds gradually on both mds's; hopefully that gives a hint as
to what it's doing.

.. dan


On Wed, Apr 21, 2021, 8:48 PM Flemming Frandsen <dren.dk@gmail.com> wrote:
...
Not as of yet, it's steadily getting further behind.
We're now up to 6797 segments and there's still the same 14 long-running
operations that are all "cleaned up request".
Something is blocking trimming, normally I'd follow the advice of
restarting the mds:
https://docs.ceph.com/en/latest/cephfs/troubleshooting/#slow-requests-mds
... but I just did that and replaying 1200 segments took two hours, so if
the same happens again, then I'm looking at 12 hours of downtime, which
would be very unpopular.
On Wed, 21 Apr 2021 at 20:26, Dan van der Ster <dan@vanderster.com> wrote:
...
Did this eventually clear?
We had something like this happen once when we changed an md export pin
for a very top level directory from mds.3 to mds.0. This triggered so much
subtree export work that it took something like 30 minutes to complete. In
our case the md segments kept growing into a few 10k, iirc. As soon as the
exports completed the md log trimmed quickly.
.. Dan
On Wed, Apr 21, 2021, 7:38 PM Flemming Frandsen <dren.dk@gmail.com>
wrote:
...
I've gone through the clients mentioned by the ops in flight and none of
them are connected any more.
The number of segments that the MDS is behind on is rising steadily and
the
ops_in_flight remain, this feels a lot like a catastrophe brewing.
The documentation suggests trying to restart the MDS server, but the last
time I did replay took two hours before any cephfs worked again, so I'd
rather not risk that, if I can help it.
Any hints are appreciated.
# ceph health detail
HEALTH_WARN 1 MDSs report slow metadata IOs; 1 MDSs report slow
requests; 1
MDSs behind on trimming
MDS_SLOW_METADATA_IO 1 MDSs report slow metadata IOs
   mds.dalmore(mds.0): 1 slow metadata IOs are blocked > 30 secs, oldest
blocked for 6046 secs
MDS_SLOW_REQUEST 1 MDSs report slow requests
   mds.dalmore(mds.0): 14 slow requests are blocked > 30 secs
MDS_TRIM 1 MDSs behind on trimming
   mds.dalmore(mds.0): Behind on trimming (4515/128) max_segments: 128,
num_segments: 4515
On Wed, 21 Apr 2021 at 19:09, Flemming Frandsen <dren.dk@gmail.com>
wrote:
...
I've just spent a couple of hours waiting for an MDS server to replay a
journal that it was behind on and it seems to be getting worse.
The system is not terribly busy, but there are 14 ops in flight that
are
very old and do not seem to go away on their own.
Is there anything I can do to unwedge the mds server?
root@dalmore:~# ceph health detail
HEALTH_WARN 1 MDSs report slow metadata IOs; 1 MDSs report slow
requests;
1 MDSs behind on trimming
MDS_SLOW_METADATA_IO 1 MDSs report slow metadata IOs
   mds.dalmore(mds.0): 1 slow metadata IOs are blocked > 30 secs,
oldest
blocked for 4107 secs
MDS_SLOW_REQUEST 1 MDSs report slow requests
   mds.dalmore(mds.0): 14 slow requests are blocked > 30 secs
MDS_TRIM 1 MDSs behind on trimming
   mds.dalmore(mds.0): Behind on trimming (3443/128) max_segments: 128,
num_segments: 3443
root@dalmore:~#  ceph daemon mds.dalmore dump_ops_in_flight
{
   "ops": [
       {
           "description": "client_request(client.9801215:348401522
readdir
#0x2001fba1c83 2021-04-21 15:46:30.820531 caller_uid=1000,
caller_gid=1000{})",
           "initiated_at": "2021-04-21 15:46:30.822084",
           "age": 4020.3439449050002,
           "duration": 4020.343998116,
           "type_data": {
               "flag_point": "cleaned up request",
               "reqid": "client.9801215:348401522",
               "op_type": "client_request",
               "client_info": {
                   "client": "client.9801215",
                   "tid": 348401522
               },
               "events": [
                   {
                       "time": "2021-04-21 15:46:30.822084",
                       "event": "initiated"
                   },
                   {
                       "time": "2021-04-21 15:46:30.822084",
                       "event": "header_read"
                   },
                   {
                       "time": "2021-04-21 15:46:30.822090",
                       "event": "throttled"
                   },
                   {
                       "time": "2021-04-21 15:46:30.822108",
                       "event": "all_read"
                   },
                   {
                       "time": "2021-04-21 15:46:30.966336",
                       "event": "dispatched"
                   },
                   {
                       "time": "2021-04-21 15:46:30.966419",
                       "event": "acquired locks"
                   },
                   {
                       "time": "2021-04-21 16:01:40.084378",
                       "event": "killing request"
                   },
                   {
                       "time": "2021-04-21 16:01:40.084438",
                       "event": "cleaned up request"
                   }
               ]
           }
       },
       {
           "description": "client_request(client.9801215:348454506
setfilelock rule 1, type 4, owner 14336643358275911908, pid 32085,
start 0,
length 0, wait 0 #0x1001e694623 20
21-04-21 15:55:50.829175 caller_uid=1000, caller_gid=1000{})",
           "initiated_at": "2021-04-21 15:55:50.832432",
           "age": 3460.3335972099999,
           "duration": 3460.333751787,
           "type_data": {
               "flag_point": "cleaned up request",
               "reqid": "client.9801215:348454506",
               "op_type": "client_request",
               "client_info": {
                   "client": "client.9801215",
                   "tid": 348454506
               },
               "events": [
                   {
                       "time": "2021-04-21 15:55:50.832432",
                       "event": "initiated"
                   },
                   {
                       "time": "2021-04-21 15:55:50.832432",
                       "event": "header_read"
                   },
                   {
                       "time": "2021-04-21 15:55:50.832439",
                       "event": "throttled"
                   },
                   {
                       "time": "2021-04-21 15:55:50.832465",
                       "event": "all_read"
                   },
                   {
                       "time": "2021-04-21 15:55:50.832608",
                       "event": "dispatched"
                   },
                   {
                       "time": "2021-04-21 16:01:40.084448",
                       "event": "killing request"
                   },
                   {
                       "time": "2021-04-21 16:01:40.084451",
                       "event": "cleaned up request"
                   }
               ]
           }
       },
       {
           "description": "client_request(client.9143865:2383945773
getattr pAsLsXsFs #0x10004f6a16b 2021-04-21 16:35:30.075110
caller_uid=0,
caller_gid=0{})",
           "initiated_at": "2021-04-21 16:35:30.077995",
           "age": 1081.0880337159999,
           "duration": 1081.0882681850001,
           "type_data": {
               "flag_point": "failed to authpin, subtree is being
exported",
               "reqid": "client.9143865:2383945773",
               "op_type": "client_request",
               "client_info": {
                   "client": "client.9143865",
                   "tid": 2383945773
               },
               "events": [
                   {
                       "time": "2021-04-21 16:35:30.077995",
                       "event": "initiated"
                   },
                   {
                       "time": "2021-04-21 16:35:30.077995",
                       "event": "header_read"
                   },
                   {
                       "time": "2021-04-21 16:35:30.077999",
                       "event": "throttled"
                   },
                   {
                       "time": "2021-04-21 16:35:30.078018",
                       "event": "all_read"
                   },
                   {
                       "time": "2021-04-21 16:35:30.078091",
                       "event": "dispatched"
                   },
                   {
                       "time": "2021-04-21 16:35:30.078156",
                       "event": "failed to authpin, subtree is being
exported"
                   }
               ]
           }
       },
       {
           "description": "client_request(client.9801215:348417261
lookup
#0x10004cd0675/tasks 2021-04-21 15:49:09.248696 caller_uid=1000,
caller_gid=1000{})",
           "initiated_at": "2021-04-21 15:49:09.252834",
           "age": 3861.9131950870001,
           "duration": 3861.9135065690002,
           "type_data": {
               "flag_point": "cleaned up request",
               "reqid": "client.9801215:348417261",
               "op_type": "client_request",
               "client_info": {
                   "client": "client.9801215",
                   "tid": 348417261
               },
               "events": [
                   {
                       "time": "2021-04-21 15:49:09.252834",
                       "event": "initiated"
                   },
                   {
                       "time": "2021-04-21 15:49:09.252834",
                       "event": "header_read"
                   },
                   {
                       "time": "2021-04-21 15:49:09.252839",
                       "event": "throttled"
                   },
                   {
                       "time": "2021-04-21 15:49:09.252856",
                       "event": "all_read"
                   },
                   {
                       "time": "2021-04-21 15:49:09.252982",
                       "event": "dispatched"
                   },
                   {
                       "time": "2021-04-21 15:49:09.253070",
                       "event": "failed to authpin, subtree is being
exported"
                   },
                   {
                       "time": "2021-04-21 16:01:40.084439",
                       "event": "killing request"
                   },
                   {
                       "time": "2021-04-21 16:01:40.084444",
                       "event": "cleaned up request"
                   }
               ]
           }
       },
       {
           "description": "client_request(client.9143865:2383945793
getattr pAsLsXsFs #0x10004f6a16b 2021-04-21 16:40:33.868658
caller_uid=0,
caller_gid=0{})",
           "initiated_at": "2021-04-21 16:40:33.871565",
           "age": 777.29446343799998,
           "duration": 777.29486169500001,
           "type_data": {
               "flag_point": "failed to authpin, subtree is being
exported",
               "reqid": "client.9143865:2383945793",
               "op_type": "client_request",
               "client_info": {
                   "client": "client.9143865",
                   "tid": 2383945793
               },
               "events": [
                   {
                       "time": "2021-04-21 16:40:33.871565",
                       "event": "initiated"
                   },
                   {
                       "time": "2021-04-21 16:40:33.871565",
                       "event": "header_read"
                   },
                   {
                       "time": "2021-04-21 16:40:33.871572",
                       "event": "throttled"
                   },
                   {
                       "time": "2021-04-21 16:40:33.871617",
                       "event": "all_read"
                   },
                   {
                       "time": "2021-04-21 16:40:33.871699",
                       "event": "dispatched"
                   },
                   {
                       "time": "2021-04-21 16:40:33.871909",
                       "event": "failed to authpin, subtree is being
exported"
                   }
               ]
           }
       },
       {
           "description": "client_request(client.9801215:348424659
lookup
#0x10004cd0675/slaves 2021-04-21 15:50:01.592755 caller_uid=1000,
caller_gid=1000{})",
           "initiated_at": "2021-04-21 15:50:01.595195",
           "age": 3809.5708340870001,
           "duration": 3809.5713271260001,
           "type_data": {
               "flag_point": "cleaned up request",
               "reqid": "client.9801215:348424659",
               "op_type": "client_request",
               "client_info": {
                   "client": "client.9801215",
                   "tid": 348424659
               },
               "events": [
                   {
                       "time": "2021-04-21 15:50:01.595195",
                       "event": "initiated"
                   },
                   {
                       "time": "2021-04-21 15:50:01.595195",
                       "event": "header_read"
                   },
                   {
                       "time": "2021-04-21 15:50:01.595198",
                       "event": "throttled"
                   },
                   {
                       "time": "2021-04-21 15:50:01.595210",
                       "event": "all_read"
                   },
                   {
                       "time": "2021-04-21 15:50:01.595307",
                       "event": "dispatched"
                   },
                   {
                       "time": "2021-04-21 15:50:01.595389",
                       "event": "failed to authpin, subtree is being
exported"
                   },
                   {
                       "time": "2021-04-21 16:01:40.084444",
                       "event": "killing request"
                   },
                   {
                       "time": "2021-04-21 16:01:40.084448",
                       "event": "cleaned up request"
                   }
               ]
           }
       },
       {
           "description": "client_request(client.9801215:348456034
setfilelock rule 1, type 4, owner 14336643483181153700, pid 32085,
start 0,
length 0, wait 0 #0x1001e694623 20
21-04-21 15:56:20.849213 caller_uid=1000, caller_gid=1000{})",
           "initiated_at": "2021-04-21 15:56:20.851803",
           "age": 3430.3142257680001,
           "duration": 3430.3148090620002,
           "type_data": {
               "flag_point": "cleaned up request",
               "reqid": "client.9801215:348456034",
               "op_type": "client_request",
               "client_info": {
                   "client": "client.9801215",
                   "tid": 348456034
               },
               "events": [
                   {
                       "time": "2021-04-21 15:56:20.851803",
                       "event": "initiated"
                   },
                   {
                       "time": "2021-04-21 15:56:20.851803",
                       "event": "header_read"
                   },
                   {
                       "time": "2021-04-21 15:56:20.851815",
                       "event": "throttled"
                   },
                   {
                       "time": "2021-04-21 15:56:20.851853",
                       "event": "all_read"
                   },
                   {
                       "time": "2021-04-21 15:56:20.851983",
                       "event": "dispatched"
                   },
                   {
                       "time": "2021-04-21 16:01:40.084452",
                       "event": "killing request"
                   },
                   {
                       "time": "2021-04-21 16:01:40.084454",
                       "event": "cleaned up request"
                   }
               ]
           }
       },
       {
           "description": "client_request(client.9801215:348456035
lookup
#0x10004cd0675/tasks 2021-04-21 15:56:20.849213 caller_uid=1000,
caller_gid=1000{})",
           "initiated_at": "2021-04-21 15:56:20.851899",
           "age": 3430.314129722,
           "duration": 3430.3147965909998,
           "type_data": {
               "flag_point": "cleaned up request",
               "reqid": "client.9801215:348456035",
               "op_type": "client_request",
               "client_info": {
                   "client": "client.9801215",
                   "tid": 348456035
               },
               "events": [
                   {
                       "time": "2021-04-21 15:56:20.851899",
                       "event": "initiated"
                   },
                   {
                       "time": "2021-04-21 15:56:20.851899",
                       "event": "header_read"
                   },
                   {
                       "time": "2021-04-21 15:56:20.851900",
                       "event": "throttled"
                   },
                   {
                       "time": "2021-04-21 15:56:20.851908",
                       "event": "all_read"
                   },
                   {
                       "time": "2021-04-21 15:56:20.852165",
                       "event": "dispatched"
                   },
                   {
                       "time": "2021-04-21 15:56:20.852254",
                       "event": "failed to authpin, subtree is being
exported"
                   },
                   {
                       "time": "2021-04-21 16:01:40.084455",
                       "event": "killing request"
                   },
                   {
                       "time": "2021-04-21 16:01:40.084457",
                       "event": "cleaned up request"
                   }
               ]
           }
       },
       {
           "description": "client_request(client.9801215:348456036
lookup
#0x10004cd0675/slaves 2021-04-21 15:56:20.849213 caller_uid=1000,
caller_gid=1000{})",
           "initiated_at": "2021-04-21 15:56:20.879287",
           "age": 3430.2867415639998,
           "duration": 3430.287496596,
           "type_data": {
               "flag_point": "cleaned up request",
               "reqid": "client.9801215:348456036",
               "op_type": "client_request",
               "client_info": {
                   "client": "client.9801215",
                   "tid": 348456036
               },
               "events": [
                   {
                       "time": "2021-04-21 15:56:20.879287",
                       "event": "initiated"
                   },
                   {
                       "time": "2021-04-21 15:56:20.879287",
                       "event": "header_read"
                   },
                   {
                       "time": "2021-04-21 15:56:20.879292",
                       "event": "throttled"
                   },
                   {
                       "time": "2021-04-21 15:56:20.879306",
                       "event": "all_read"
                   },
                   {
                       "time": "2021-04-21 15:56:20.879408",
                       "event": "dispatched"
                   },
                   {
                       "time": "2021-04-21 15:56:20.879502",
                       "event": "failed to authpin, subtree is being
exported"
                   },
                   {
                       "time": "2021-04-21 16:01:40.084458",
                       "event": "killing request"
                   },
                   {
                       "time": "2021-04-21 16:01:40.084460",
                       "event": "cleaned up request"
                   }
               ]
           }
       },
       {
           "description": "client_request(client.9801215:348456042
lookup
#0x10004cd0675/jul 2021-04-21 15:58:53.729411 caller_uid=1000,
caller_gid=1000{})",
           "initiated_at": "2021-04-21 15:58:53.740318",
           "age": 3277.4257106780001,
           "duration": 3277.4265688219998,
           "type_data": {
               "flag_point": "cleaned up request",
               "reqid": "client.9801215:348456042",
               "op_type": "client_request",
               "client_info": {
                   "client": "client.9801215",
                   "tid": 348456042
               },
               "events": [
                   {
                       "time": "2021-04-21 15:58:53.740318",
                       "event": "initiated"
                   },
                   {
                       "time": "2021-04-21 15:58:53.740318",
                       "event": "header_read"
                   },
                   {
                       "time": "2021-04-21 15:58:53.740324",
                       "event": "throttled"
                   },
                   {
                       "time": "2021-04-21 15:58:53.740345",
                       "event": "all_read"
                   },
                   {
                       "time": "2021-04-21 15:58:53.743424",
                       "event": "dispatched"
                   },
                   {
                       "time": "2021-04-21 15:58:53.750527",
                       "event": "failed to authpin, subtree is being
exported"
                   },
                   {
                       "time": "2021-04-21 16:01:40.084465",
                       "event": "killing request"
                   },
                   {
                       "time": "2021-04-21 16:01:40.084468",
                       "event": "cleaned up request"
                   }
               ]
           }
       },
       {
           "description": "client_request(client.9143865:2383914038
getattr pAsLsXsFs #0x10004f6a16b 2021-04-21 16:29:35.332632
caller_uid=903,
caller_gid=1003{})",
           "initiated_at": "2021-04-21 16:29:35.333838",
           "age": 1435.8321910940001,
           "duration": 1435.833136707,
           "type_data": {
               "flag_point": "failed to authpin, subtree is being
exported",
               "reqid": "client.9143865:2383914038",
               "op_type": "client_request",
               "client_info": {
                   "client": "client.9143865",
                   "tid": 2383914038
               },
               "events": [
                   {
                       "time": "2021-04-21 16:29:35.333838",
                       "event": "initiated"
                   },
                   {
                       "time": "2021-04-21 16:29:35.333838",
                       "event": "header_read"
                   },
                   {
                       "time": "2021-04-21 16:29:35.333841",
                       "event": "throttled"
                   },
                   {
                       "time": "2021-04-21 16:29:35.333854",
                       "event": "all_read"
                   },
                   {
                       "time": "2021-04-21 16:29:35.335013",
                       "event": "dispatched"
                   },
                   {
                       "time": "2021-04-21 16:29:35.335091",
                       "event": "failed to authpin, subtree is being
exported"
                   }
               ]
           }
       },
       {
           "description": "client_request(client.10439445:7 lookup
#0x10004cd0675/jul 2021-04-21 16:26:17.334272 caller_uid=1000,
caller_gid=1000{})",
           "initiated_at": "2021-04-21 16:26:17.352448",
           "age": 1633.813581226,
           "duration": 1633.8146036109999,
           "type_data": {
               "flag_point": "cleaned up request",
               "reqid": "client.10439445:7",
               "op_type": "client_request",
               "client_info": {
                   "client": "client.10439445",
                   "tid": 7
               },
               "events": [
                   {
                       "time": "2021-04-21 16:26:17.352448",
                       "event": "initiated"
                   },
                   {
                       "time": "2021-04-21 16:26:17.352448",
                       "event": "header_read"
                   },
                   {
                       "time": "2021-04-21 16:26:17.352450",
                       "event": "throttled"
                   },
                   {
                       "time": "2021-04-21 16:26:17.352460",
                       "event": "all_read"
                   },
                   {
                       "time": "2021-04-21 16:26:17.356901",
                       "event": "dispatched"
                   },
                   {
                       "time": "2021-04-21 16:26:17.357337",
                       "event": "failed to authpin, subtree is being
exported"
                   },
                   {
                       "time": "2021-04-21 16:38:08.054109",
                       "event": "killing request"
                   },
                   {
                       "time": "2021-04-21 16:38:08.054120",
                       "event": "cleaned up request"
                   }
               ]
           }
       },
       {
           "description": "client_request(client.9801215:348456041
lookup
#0x10004cd0675/jul 2021-04-21 15:56:23.089216 caller_uid=1000,
caller_gid=1000{})",
           "initiated_at": "2021-04-21 15:56:23.091531",
           "age": 3428.0744974170002,
           "duration": 3428.0756079930002,
           "type_data": {
               "flag_point": "cleaned up request",
               "reqid": "client.9801215:348456041",
               "op_type": "client_request",
               "client_info": {
                   "client": "client.9801215",
                   "tid": 348456041
               },
               "events": [
                   {
                       "time": "2021-04-21 15:56:23.091531",
                       "event": "initiated"
                   },
                   {
                       "time": "2021-04-21 15:56:23.091531",
                       "event": "header_read"
                   },
                   {
                       "time": "2021-04-21 15:56:23.091536",
                       "event": "throttled"
                   },
                   {
                       "time": "2021-04-21 15:56:23.091555",
                       "event": "all_read"
                   },
                   {
                       "time": "2021-04-21 15:56:23.091660",
                       "event": "dispatched"
                   },
                   {
                       "time": "2021-04-21 15:56:23.091763",
                       "event": "failed to authpin, subtree is being
exported"
                   },
                   {
                       "time": "2021-04-21 16:01:40.084461",
                       "event": "killing request"
                   },
                   {
                       "time": "2021-04-21 16:01:40.084465",
                       "event": "cleaned up request"
                   }
               ]
           }
       },
       {
           "description": "client_request(client.9143865:2383885743
getattr pAsLsXsFs #0x10004f6a16b 2021-04-21 16:26:36.713371
caller_uid=903,
caller_gid=1003{})",
           "initiated_at": "2021-04-21 16:26:36.716418",
           "age": 1614.4496113350001,
           "duration": 1614.4508114350001,
           "type_data": {
               "flag_point": "failed to authpin, subtree is being
exported",
               "reqid": "client.9143865:2383885743",
               "op_type": "client_request",
               "client_info": {
                   "client": "client.9143865",
                   "tid": 2383885743
               },
               "events": [
                   {
                       "time": "2021-04-21 16:26:36.716418",
                       "event": "initiated"
                   },
                   {
                       "time": "2021-04-21 16:26:36.716418",
                       "event": "header_read"
                   },
                   {
                       "time": "2021-04-21 16:26:36.716421",
                       "event": "throttled"
                   },
                   {
                       "time": "2021-04-21 16:26:36.716435",
                       "event": "all_read"
                   },
                   {
                       "time": "2021-04-21 16:26:36.716526",
                       "event": "dispatched"
                   },
                   {
                       "time": "2021-04-21 16:26:36.716632",
                       "event": "failed to authpin, subtree is being
exported"
                   }
               ]
           }
       }
   ],
   "num_ops": 14
}
--
Flemming Frandsen - YAPH - http://osaa.dk - http://dren.dk/
--
Flemming Frandsen - YAPH - http://osaa.dk - http://dren.dk/
_______________________________________________
ceph-users mailing list -- ceph-users@ceph.io
To unsubscribe send an email to ceph-users-leave@ceph.io
--
Flemming Frandsen - YAPH - http://osaa.dk - http://dren.dk/