[ceph-users] mimic: MDS standby-replay causing blocked ops (MDS bug?)

Frank Schilder frans at dtu.dk
Wed May 15 06:34:32 PDT 2019


Dear Stefan,

thanks for the fast reply. We encountered the problem again, this time in a much simpler situation; please see below. However, let me start with your questions first:

What bug? -- In a single-active MDS set-up, should there ever occur an operation with "op_name": "fragmentdir"?

Trimming settings: In the version I'm running, mds_log_max_expiring does not exist and mds_log_max_segments is 128 by default. I guess this is fine.

Upgrading: The problem described here is the only issue we observe. Unless the problem is fixed upstream, upgrading won't help us and would be a bit of a waste of time. If someone can confirm that this problem is fixed in a newer version, we will do it. Otherwise, we might prefer to wait until it is.

News on the problem. We encountered it again when one of our users executed a command in parallel with pdsh on all our ~500 client nodes. This command accesses the same file from all these nodes pretty much simultaneously. We did this quite often in the past, but this time, the command got stuck and we started observing the MDS health problem again. Symptoms:

- The pdsh process enters an un-interruptible state.
- It is no longer possible to access the directory where the simultaneously accessed file resides (from any client).
- 'ceph status' reports 'MDS slow requests'
- The 'ceph daemon mds.nnn ops' list contains operations that are waiting for directory fragmentation (see full log below).
- The ops list contains an operation "internal op fragmentdir:mds.0:35" that is dispatched, but apparently never completes.
- Any attempt to access the locked directory adds operations to the ops list that will then also hang indefinitely.
- I/O to other directories continues to work fine.

We waited some time to confirm that ceph does not heal itself. It is a dead-lock situation that seems to be triggered by a large number of clients simultaneously accessing the same file/directory. This problem seems not to occur with 100 or fewer clients. The probability of occurrence seems load dependent.

Temporary fix: Failing the active MDS flushed the stuck operations. The cluster became healthy and all clients rejoined.

This time I captured the MDS ops list (log output does not really contain more info than this list). It contains 12 ops and I will include it here in full length (hope this is acceptable):

{
    "ops": [
        {
            "description": "client_request(client.386087:12791 lookup #0x10000000027/file.pdf 2019-05-15 11:30:47.173526 caller_uid=0, caller_gid=0{})",
            "initiated_at": "2019-05-15 11:30:47.174134",
            "age": 492.800243,
            "duration": 492.800277,
            "type_data": {
                "flag_point": "failed to authpin, dir is being fragmented",
                "reqid": "client.386087:12791",
                "op_type": "client_request",
                "client_info": {
                    "client": "client.386087",
                    "tid": 12791
                },
                "events": [
                    {
                        "time": "2019-05-15 11:30:47.174134",
                        "event": "initiated"
                    },
                    {
                        "time": "2019-05-15 11:30:47.174134",
                        "event": "header_read"
                    },
                    {
                        "time": "2019-05-15 11:30:47.174136",
                        "event": "throttled"
                    },
                    {
                        "time": "2019-05-15 11:30:47.174144",
                        "event": "all_read"
                    },
                    {
                        "time": "2019-05-15 11:30:47.174245",
                        "event": "dispatched"
                    },
                    {
                        "time": "2019-05-15 11:30:47.174271",
                        "event": "failed to authpin, dir is being fragmented"
                    }
                ]
            }
        },
        {
            "description": "client_request(client.62472:6092355 create #0x10000000038/lastnotification.uXMjaLSt 2019-05-15 11:15:02.883027 caller_uid=105731, caller_gid=105731{})",
            "initiated_at": "2019-05-15 11:15:02.884547",
            "age": 1437.089830,
            "duration": 1437.089937,
            "type_data": {
                "flag_point": "failed to authpin, dir is being fragmented",
                "reqid": "client.62472:6092355",
                "op_type": "client_request",
                "client_info": {
                    "client": "client.62472",
                    "tid": 6092355
                },
                "events": [
                    {
                        "time": "2019-05-15 11:15:02.884547",
                        "event": "initiated"
                    },
                    {
                        "time": "2019-05-15 11:15:02.884547",
                        "event": "header_read"
                    },
                    {
                        "time": "2019-05-15 11:15:02.884552",
                        "event": "throttled"
                    },
                    {
                        "time": "2019-05-15 11:15:02.884571",
                        "event": "all_read"
                    },
                    {
                        "time": "2019-05-15 11:15:02.884721",
                        "event": "dispatched"
                    },
                    {
                        "time": "2019-05-15 11:15:02.884857",
                        "event": "failed to authpin, dir is being fragmented"
                    }
                ]
            }
        },
        {
            "description": "client_request(client.386087:12793 lookup #0x10000000027/file.pdf 2019-05-15 11:33:52.499279 caller_uid=0, caller_gid=0{})",
            "initiated_at": "2019-05-15 11:33:52.500354",
            "age": 307.474024,
            "duration": 307.474189,
            "type_data": {
                "flag_point": "failed to authpin, dir is being fragmented",
                "reqid": "client.386087:12793",
                "op_type": "client_request",
                "client_info": {
                    "client": "client.386087",
                    "tid": 12793
                },
                "events": [
                    {
                        "time": "2019-05-15 11:33:52.500354",
                        "event": "initiated"
                    },
                    {
                        "time": "2019-05-15 11:33:52.500354",
                        "event": "header_read"
                    },
                    {
                        "time": "2019-05-15 11:33:52.500356",
                        "event": "throttled"
                    },
                    {
                        "time": "2019-05-15 11:33:52.500393",
                        "event": "all_read"
                    },
                    {
                        "time": "2019-05-15 11:33:52.500458",
                        "event": "dispatched"
                    },
                    {
                        "time": "2019-05-15 11:33:52.500482",
                        "event": "failed to authpin, dir is being fragmented"
                    }
                ]
            }
        },
        {
            "description": "client_request(client.377552:1989 lookup #0x10000000027/file.pdf 2019-05-15 11:40:44.566328 caller_uid=0, caller_gid=0{})",
            "initiated_at": "2019-05-15 11:36:13.509050",
            "age": 166.465328,
            "duration": 166.465529,
            "type_data": {
                "flag_point": "failed to authpin, dir is being fragmented",
                "reqid": "client.377552:1989",
                "op_type": "client_request",
                "client_info": {
                    "client": "client.377552",
                    "tid": 1989
                },
                "events": [
                    {
                        "time": "2019-05-15 11:36:13.509050",
                        "event": "initiated"
                    },
                    {
                        "time": "2019-05-15 11:36:13.509050",
                        "event": "header_read"
                    },
                    {
                        "time": "2019-05-15 11:36:13.509052",
                        "event": "throttled"
                    },
                    {
                        "time": "2019-05-15 11:36:13.509063",
                        "event": "all_read"
                    },
                    {
                        "time": "2019-05-15 11:36:13.509163",
                        "event": "dispatched"
                    },
                    {
                        "time": "2019-05-15 11:36:13.509219",
                        "event": "failed to authpin, dir is being fragmented"
                    }
                ]
            }
        },
        {
            "description": "client_request(client.377552:1990 lookup #0x10000000027/file.pdf 2019-05-15 11:40:46.130328 caller_uid=0, caller_gid=0{})",
            "initiated_at": "2019-05-15 11:36:15.072708",
            "age": 164.901670,
            "duration": 164.901906,
            "type_data": {
                "flag_point": "failed to authpin, dir is being fragmented",
                "reqid": "client.377552:1990",
                "op_type": "client_request",
                "client_info": {
                    "client": "client.377552",
                    "tid": 1990
                },
                "events": [
                    {
                        "time": "2019-05-15 11:36:15.072708",
                        "event": "initiated"
                    },
                    {
                        "time": "2019-05-15 11:36:15.072708",
                        "event": "header_read"
                    },
                    {
                        "time": "2019-05-15 11:36:15.072710",
                        "event": "throttled"
                    },
                    {
                        "time": "2019-05-15 11:36:15.072719",
                        "event": "all_read"
                    },
                    {
                        "time": "2019-05-15 11:36:15.072847",
                        "event": "dispatched"
                    },
                    {
                        "time": "2019-05-15 11:36:15.072881",
                        "event": "failed to authpin, dir is being fragmented"
                    }
                ]
            }
        },
        {
            "description": "client_request(client.62472:6092426 readdir #0x1000000002f 2019-05-15 11:21:53.080524 caller_uid=0, caller_gid=0{})",
            "initiated_at": "2019-05-15 11:21:53.081656",
            "age": 1026.892722,
            "duration": 1026.892997,
            "type_data": {
                "flag_point": "failed to authpin, dir is being fragmented",
                "reqid": "client.62472:6092426",
                "op_type": "client_request",
                "client_info": {
                    "client": "client.62472",
                    "tid": 6092426
                },
                "events": [
                    {
                        "time": "2019-05-15 11:21:53.081656",
                        "event": "initiated"
                    },
                    {
                        "time": "2019-05-15 11:21:53.081656",
                        "event": "header_read"
                    },
                    {
                        "time": "2019-05-15 11:21:53.081658",
                        "event": "throttled"
                    },
                    {
                        "time": "2019-05-15 11:21:53.081669",
                        "event": "all_read"
                    },
                    {
                        "time": "2019-05-15 11:21:53.081772",
                        "event": "dispatched"
                    },
                    {
                        "time": "2019-05-15 11:21:53.081826",
                        "event": "failed to authpin, dir is being fragmented"
                    }
                ]
            }
        },
        {
            "description": "internal op fragmentdir:mds.0:35",
            "initiated_at": "2019-05-15 11:06:33.594105",
            "age": 1946.380273,
            "duration": 1946.380603,
            "type_data": {
                "flag_point": "dispatched",
                "reqid": "mds.0:35",
                "op_type": "internal_op",
                "internal_op": 5376,
                "op_name": "fragmentdir",
                "events": [
                    {
                        "time": "2019-05-15 11:06:33.594105",
                        "event": "initiated"
                    },
                    {
                        "time": "2019-05-15 11:06:33.594105",
                        "event": "header_read"
                    },
                    {
                        "time": "0.000000",
                        "event": "throttled"
                    },
                    {
                        "time": "0.000000",
                        "event": "all_read"
                    },
                    {
                        "time": "0.000000",
                        "event": "dispatched"
                    }
                ]
            }
        },
        {
            "description": "client_request(client.386087:12786 lookup #0x10000000027/file.pdf 2019-05-15 11:22:06.783606 caller_uid=0, caller_gid=0{})",
            "initiated_at": "2019-05-15 11:22:06.784393",
            "age": 1013.189985,
            "duration": 1013.190344,
            "type_data": {
                "flag_point": "failed to authpin, dir is being fragmented",
                "reqid": "client.386087:12786",
                "op_type": "client_request",
                "client_info": {
                    "client": "client.386087",
                    "tid": 12786
                },
                "events": [
                    {
                        "time": "2019-05-15 11:22:06.784393",
                        "event": "initiated"
                    },
                    {
                        "time": "2019-05-15 11:22:06.784393",
                        "event": "header_read"
                    },
                    {
                        "time": "2019-05-15 11:22:06.784394",
                        "event": "throttled"
                    },
                    {
                        "time": "2019-05-15 11:22:06.784405",
                        "event": "all_read"
                    },
                    {
                        "time": "2019-05-15 11:22:06.784506",
                        "event": "dispatched"
                    },
                    {
                        "time": "2019-05-15 11:22:06.784562",
                        "event": "failed to authpin, dir is being fragmented"
                    }
                ]
            }
        },
        {
            "description": "client_request(client.386087:12795 lookup #0x10000000027/file.pdf 2019-05-15 11:37:31.764353 caller_uid=0, caller_gid=0{})",
            "initiated_at": "2019-05-15 11:37:31.765631",
            "age": 88.208747,
            "duration": 88.209160,
            "type_data": {
                "flag_point": "failed to authpin, dir is being fragmented",
                "reqid": "client.386087:12795",
                "op_type": "client_request",
                "client_info": {
                    "client": "client.386087",
                    "tid": 12795
                },
                "events": [
                    {
                        "time": "2019-05-15 11:37:31.765631",
                        "event": "initiated"
                    },
                    {
                        "time": "2019-05-15 11:37:31.765631",
                        "event": "header_read"
                    },
                    {
                        "time": "2019-05-15 11:37:31.765633",
                        "event": "throttled"
                    },
                    {
                        "time": "2019-05-15 11:37:31.765640",
                        "event": "all_read"
                    },
                    {
                        "time": "2019-05-15 11:37:31.765731",
                        "event": "dispatched"
                    },
                    {
                        "time": "2019-05-15 11:37:31.765759",
                        "event": "failed to authpin, dir is being fragmented"
                    }
                ]
            }
        },
        {
            "description": "client_request(client.377552:5446 readdir #0x1000000003a 2019-05-15 11:43:07.569329 caller_uid=0, caller_gid=0{})",
            "initiated_at": "2019-05-15 11:38:36.511381",
            "age": 23.462997,
            "duration": 23.463467,
            "type_data": {
                "flag_point": "failed to authpin, dir is being fragmented",
                "reqid": "client.377552:5446",
                "op_type": "client_request",
                "client_info": {
                    "client": "client.377552",
                    "tid": 5446
                },
                "events": [
                    {
                        "time": "2019-05-15 11:38:36.511381",
                        "event": "initiated"
                    },
                    {
                        "time": "2019-05-15 11:38:36.511381",
                        "event": "header_read"
                    },
                    {
                        "time": "2019-05-15 11:38:36.511383",
                        "event": "throttled"
                    },
                    {
                        "time": "2019-05-15 11:38:36.511392",
                        "event": "all_read"
                    },
                    {
                        "time": "2019-05-15 11:38:36.511561",
                        "event": "dispatched"
                    },
                    {
                        "time": "2019-05-15 11:38:36.511604",
                        "event": "failed to authpin, dir is being fragmented"
                    }
                ]
            }
        },
        {
            "description": "client_request(client.62472:6092368 getattr pAsLsXsFs #0x10000000038 2019-05-15 11:17:21.633854 caller_uid=105731, caller_gid=105731{})",
            "initiated_at": "2019-05-15 11:17:21.635927",
            "age": 1298.338451,
            "duration": 1298.338955,
            "type_data": {
                "flag_point": "failed to authpin, dir is being fragmented",
                "reqid": "client.62472:6092368",
                "op_type": "client_request",
                "client_info": {
                    "client": "client.62472",
                    "tid": 6092368
                },
                "events": [
                    {
                        "time": "2019-05-15 11:17:21.635927",
                        "event": "initiated"
                    },
                    {
                        "time": "2019-05-15 11:17:21.635927",
                        "event": "header_read"
                    },
                    {
                        "time": "2019-05-15 11:17:21.635931",
                        "event": "throttled"
                    },
                    {
                        "time": "2019-05-15 11:17:21.635944",
                        "event": "all_read"
                    },
                    {
                        "time": "2019-05-15 11:17:21.636081",
                        "event": "dispatched"
                    },
                    {
                        "time": "2019-05-15 11:17:21.636118",
                        "event": "failed to authpin, dir is being fragmented"
                    }
                ]
            }
        },
        {
            "description": "client_request(client.62472:6092400 getattr pAsLsXsFs #0x10000000038 2019-05-15 11:21:25.909555 caller_uid=105731, caller_gid=105731{})",
            "initiated_at": "2019-05-15 11:21:25.910514",
            "age": 1054.063864,
            "duration": 1054.064406,
            "type_data": {
                "flag_point": "failed to authpin, dir is being fragmented",
                "reqid": "client.62472:6092400",
                "op_type": "client_request",
                "client_info": {
                    "client": "client.62472",
                    "tid": 6092400
                },
                "events": [
                    {
                        "time": "2019-05-15 11:21:25.910514",
                        "event": "initiated"
                    },
                    {
                        "time": "2019-05-15 11:21:25.910514",
                        "event": "header_read"
                    },
                    {
                        "time": "2019-05-15 11:21:25.910527",
                        "event": "throttled"
                    },
                    {
                        "time": "2019-05-15 11:21:25.910537",
                        "event": "all_read"
                    },
                    {
                        "time": "2019-05-15 11:21:25.910597",
                        "event": "dispatched"
                    },
                    {
                        "time": "2019-05-15 11:21:25.910635",
                        "event": "failed to authpin, dir is being fragmented"
                    }
                ]
            }
        }
    ],
    "num_ops": 12
}

=================
Frank Schilder
AIT Ris? Campus
Bygning 109, rum S14

________________________________________
From: Stefan Kooman <stefan at bit.nl>
Sent: 14 May 2019 09:54:05
To: Frank Schilder
Cc: ceph-users at lists.ceph.com
Subject: Re: [ceph-users] mimic: MDS standby-replay causing blocked ops (MDS bug?)

Quoting Frank Schilder (frans at dtu.dk):

If at all possible I would:

Upgrade to 13.2.5 (there have been quite a few MDS fixes since 13.2.2).
Use more recent kernels on the clients.

Below settings for [mds] might help with trimming (you might already
have changed mds_log_max_segments to 128 according to logs):

[mds]
mds_log_max_expiring = 80      # default 20
# trim max $value segments in parallel
# Defaults are too conservative.
mds_log_max_segments = 120      # default 30


> 1) Is there a bug with having MDS daemons acting as standby-replay?
I can't tell what bug you are referring to based on info below. It does
seem to work as designed.

Gr. Stefan

--
| BIT BV  http://www.bit.nl/        Kamer van Koophandel 09090351
| GPG: 0xD14839C6                   +31 318 648 688 / info at bit.nl


More information about the ceph-users mailing list