Ceph » CephFS

Venky Shankar wrote in #note-1:

cc @Xiubo Li

I believe there was an attempt⁰ at fixing this, but the approach wasn't satisfactory and there hasn't been much work done on this lately to find an alternate approach.

[0]: https://github.com/ceph/ceph/pull/57124

This is specifically related to the `FAILED ceph_assert(isolated_inodes.empty())` crash and not the crash mentioned in the tracker related to batch ops.

Venky Shankar wrote in #note-2:

Venky Shankar wrote in #note-1:

cc @Xiubo Li

I believe there was an attempt⁰ at fixing this, but the approach wasn't satisfactory and there hasn't been much work done on this lately to find an alternate approach.

[0]: https://github.com/ceph/ceph/pull/57124

This is specifically related to the `FAILED ceph_assert(isolated_inodes.empty())` crash and not the crash mentioned in the tracker related to batch ops.

Agreed. The only tracker I found related to batch ops is from telemetry: https://tracker.ceph.com/issues/59749 (and similarly for dentry https://tracker.ceph.com/issues/59819)

We had a second crash and investigated a bit further.

• Test cluster (16.2.9) with 2 active MDSs
• 2 clients mounted RW, kernel mount (6.5.5-200.fc38)
• client A runs a custom program (we call it "multiwriter", kudos to @Abhishek Lekshmanan -- https://gist.github.com/theanalyst/436a541e150810cfb20858c0b6713439) to generate load on the cluster using 2000 write threads
  • client A writes into a test directory of the filesystem (/cephfs/gtest), not pinned to any rank
  • client A (also) writes into a subdirectory manually pinned to mds.1 (/cephfs/volumes/_nogroup/multiwriter) with the same custom program
• client B uses the same custom program with 2000 read threads, reading from the subdirectory pinned to mds.1 (/cephfs/volumes/_nogroup/multiwriter)
• client B may use again the custom program, either reading or writing, to put additional pressure on the MDS.

The ceph_assert produces when the CInode gets removed from the LRU cache of the MDS: Cache thrashing (and a deliberately low mds_cache_memory_limit) are required to trigger the problem.
The workload described above makes it such MDS memory allocation grows⁰ well beyond the configured mds_cache_memory_limit (1 GB, in our testbed).

Evicting client A repeatedly (e.g., 10 times in a raw, every 10 seconds) produces slow operations.
If a slow operation with flag_point "cleaned up request" appears, this is likely stuck and not going away until the MDS removes it from its LRU, crashing with the batch_ops.empty() assertion.

Example from `dump_blocked_ops`:

{
    "ops": [
        {
            "description": "client_request(client.6440007:3389928698 getattr Xs #0x2000005ca3e 2024-07-23T16:58:07.545878+0200 caller_uid=0, caller_gid=0{0,})",
            "initiated_at": "2024-07-23T16:58:17.871938+0200",
            "age": 888.87018786199997,
            "duration": 888.87021391400003,
            "type_data": {
                "flag_point": "cleaned up request",
                "reqid": "client.6440007:3389928698",
                "op_type": "client_request",
                "client_info": {
                    "client": "client.6440007",
                    "tid": 3389928698
                },
                "events": [
                    {
                        "time": "2024-07-23T16:58:17.871938+0200",
                        "event": "initiated" 
                    },
                    {
                        "time": "2024-07-23T16:58:17.871939+0200",
                        "event": "throttled" 
                    },
                    {
                        "time": "2024-07-23T16:58:17.871938+0200",
                        "event": "header_read" 
                    },
                    {
                        "time": "2024-07-23T16:58:17.871940+0200",
                        "event": "all_read" 
                    },
                    {
                        "time": "2024-07-23T16:58:17.919792+0200",
                        "event": "dispatched" 
                    },
                    {
                        "time": "2024-07-23T16:58:17.919802+0200",
                        "event": "requesting remote authpins" 
                    },
                    {
                        "time": "2024-07-23T16:59:34.828645+0200",
                        "event": "killing request" 
                    },
                    {
                        "time": "2024-07-23T16:59:34.828649+0200",
                        "event": "cleaned up request" 
                    }
                ]
            }
        },
...

The inode dump is as follows:

{
    "path": "/volumes/_nogroup/multiwriter/test3.out.1303",
    "ino": 2199023635006,
    "rdev": 0,
    "ctime": "2024-07-24T13:29:23.030379+0200",
    "btime": "2024-07-22T15:36:08.831700+0200",
    "mode": 33412,
    "uid": 0,
    "gid": 0,
...

It is not clear to me why mds.0 would serve lookup requests also for directories pinned to mds.1, but it seems to be the case from the MDS logs.
This explains why mds.0 crashes, though the inode belongs to a subtree pinned to another rank.

We have tried to get rid of the slow operation in different ways, all unsuccessful:
- MDS: evict the client
- MDS: session kill
- MDS: blocklist the client
- MDS: cache drop
- Client: "echo 2 > /proc/sys/vm/drop_caches"
- Client: "mount -o,remount /cephfs"

The original issue occurred on a production cluster running the latest pacific release (16.2.15).
There seem to be no relevant code changes in quincy around batch_ops, so maybe those releases may be exposed to this issue as well.

The coredump of mds.0 crashing on batch_ops.empty() assertion is available at:
- abrtd: c25a781a-7cc5-47b3-afd2-dd1eb29c152f
- systemd: 4e402a60-46cf-4749-8e8d-6ac82fa486c4

[0]:
**It is not fully understood if the memory allocation is "normal" and driven by the workload.
We have seen the MDS allocating up to 30x the configured mds_cache_memory_limit during our tests.

Enrico Bocchi wrote:

We observed an MDS crash (looks identical to https://tracker.ceph.com/issues/59819) with a failed ceph assertion on batch_ops.empty():

[...]

The cluster is:
- running pacific 16.2.15
- multi-active MDS (2 active, 2 stand-by)
- manual pinning of several directory trees to mds.1
- no stand-by replay
- no snapshots

`batch_ops` is used by Server::handle_client_getattr.
We suspect the crash is due to a slow operation that has not self-resolved for long (~3h 25m at the time of the crash):
[...]

However, it is unclear to us why this crashed mds.0:
- The slow operation concerns an inode in a directory which is pinned to mds.1 (ceph.dir.pin=1).

So the 0x1000c04a2be just was a child of the pinned directory. But that would make sure that the auth of 0x1000c04a2be inode would be in mds.1.

- The assertion triggers from an inode with outstanding batch_ops being removed from the lru cache
- Why would the cache of mds.0 have an entry for an inode pinned to mds.1?

And the 0x1000c04a2be could be replicated to mds.0, and the getattr client requests won't always be sent to the auth mds.

About the long outstanding rdlock slow operation, we set `mds cap revoke eviction timeout` to 900 seconds but it does not seem to help with this case.
Is there any other configuration option that is worth trying to address slow requests failing to r/w/xlock?

Did you see the caps revoke stuck mds logs or warning ? If not then this getattr reqeust was not a caps revoke bug, so this wouldn't work anyway.

---

Also, mds.1 crashed upon mds.0 rejoin with a different signature (which is being addressed in https://tracker.ceph.com/issues/62036):
[...]

From code (https://github.com/ceph/ceph/blob/v16.2.15/src/mds/MDCache.cc#L5140-L5142):
[...]

{
    "ops": [
        {
            "description": "client_request(client.6440007:3389928698 getattr Xs #0x2000005ca3e 2024-07-23T16:58:07.545878+0200 caller_uid=0, caller_gid=0{0,})",
            "initiated_at": "2024-07-23T16:58:17.871938+0200",
            "age": 888.87018786199997,
            "duration": 888.87021391400003,
            "type_data": {
                "flag_point": "cleaned up request",
                "reqid": "client.6440007:3389928698",
                "op_type": "client_request",
                "client_info": {
                    "client": "client.6440007",
                    "tid": 3389928698
                },
                "events": [
                    {
                        "time": "2024-07-23T16:58:17.871938+0200",
                        "event": "initiated" 
                    },
                    {
                        "time": "2024-07-23T16:58:17.871939+0200",
                        "event": "throttled" 
                    },
                    {
                        "time": "2024-07-23T16:58:17.871938+0200",
                        "event": "header_read" 
                    },
                    {
                        "time": "2024-07-23T16:58:17.871940+0200",
                        "event": "all_read" 
                    },
                    {
                        "time": "2024-07-23T16:58:17.919792+0200",
                        "event": "dispatched" 
                    },
                    {
                        "time": "2024-07-23T16:58:17.919802+0200",
                        "event": "requesting remote authpins" 
                    },
                    {
                        "time": "2024-07-23T16:59:34.828645+0200",
                        "event": "killing request" 
                    },
                    {
                        "time": "2024-07-23T16:59:34.828649+0200",
                        "event": "cleaned up request" 
                    }
                ]
            }
        },
...

This mostly like a similar issue with https://tracker.ceph.com/issues/65536. But the difference is that in 16.2.15-1 there has no the buggy commit https://github.com/ceph/ceph/pull/54581.

Since there is not any debug logs I don't know why this request wasn't retrigger after being killed. I think the https://tracker.ceph.com/issues/65536 could resolve the crash bug, but couldn't resolve the slow request issue.

Xiubo Li wrote in #note-8:

[...]

This mostly like a similar issue with https://tracker.ceph.com/issues/65536. But the difference is that in 16.2.15-1 there has no the buggy commit https://github.com/ceph/ceph/pull/54581.

Since there is not any debug logs I don't know why this request wasn't retrigger after being killed. I think the https://tracker.ceph.com/issues/65536 could resolve the crash bug, but couldn't resolve the slow request issue.

Backported this to quincy, please see https://tracker.ceph.com/issues/67163

Thanks for the pointer, Xiubo.
Are you still interested in the debug logs from the MDS or for you https://tracker.ceph.com/issues/65536 addresses the problem?

Could you enable the debug logs and try to reproduce it again ?

debug_mds = 20
debug_ms = 1

Thanks

• On the server side; client eviction happens:
  • This invokes `journal_close_session` -> `request_kill` -> `request_cleanup`
  • Request cleanup currently doesn't account for if it is a batch op, so batch ops for the inode still maintains a reference to this request
  • Request cleanup completes; Since the request itself is a boost::intrusive_ptr, the reference maintained within the BatchOp is still valid
  • OpTracker will forever complain of a slow op as the request is cleaned up but still around
• MDCache eviction happens at some point
  • Inode destructor is invoked, which asserts on the BatchOp not being empty

Do you think this is correct?

While the request_cleanup with your fix should ideally allow the first case to be protected, I wonder if there are any other code paths that might lead the batch ops list to hold a MDRequestRef that is in a different state?
Do you think it makes sense the `MDCache::remove_inode` also drains the Batch Ops on the inode so that it doesn't explode on delete?

Here is a simple gdb trace on the core:

(gdb) f 8
#8  0x000055b945cf4ef5 in CInode::~CInode (this=0x55ba5023e580, __in_chrg=<optimized out>) at /usr/include/c++/8/bits/atomic_base.h:319
(gdb) p this->batch_ops
$1 = std::map with 1 element = {[64] = std::unique_ptr<BatchOp> = {get() = 0x55ba604b8480}}
(gdb) p *(Batch_Getattr_Lookup *)0x55ba604b8480
$2 = {<BatchOp> = {_vptr.BatchOp = 0x55b9462d86d8 <vtable for Batch_Getattr_Lookup+16>}, server = 0x55b947cb7520, mdr = {px = 0x55ba88956000},
  batch_reqs = std::vector of length 0, capacity 0, res = 0}
(gdb) p *(MDRequestImpl *)0x55ba88956000
$5 = {<MutationImpl> = {<TrackedOp> = {<boost::intrusive::list_base_hook<>>... events = std::vector of length 8, capacity 20 = {{stamp = {tv = {tv_sec = 1721820000, tv_nsec = 613154198}}, str = "initiated"}, {stamp = {tv = {
              tv_sec = 1721820000, tv_nsec = 613154366}}, str = "throttled"}, {stamp = {tv = {tv_sec = 1721820000, tv_nsec = 613154198}},
          str = "header_read"}, {stamp = {tv = {tv_sec = 1721820000, tv_nsec = 613156052}}, str = "all_read"}, {stamp = {tv = {tv_sec = 1721820000,
              tv_nsec = 619693894}}, str = "dispatched"}, {stamp = {tv = {tv_sec = 1721820000, tv_nsec = 619708631}}, str = "requesting remote authpins"}, {
          stamp = {tv = {tv_sec = 1721820000, tv_nsec = 800392644}}, str = "killing request"}, {stamp = {tv = {tv_sec = 1721820000, tv_nsec = 800399595}},
          str = "cleaned up request"}}, lock = {<std::__mutex_base> = {_M_mutex = {__data = {__lock = 0, __count = 0, __owner = 0, __nusers = 0, __kind = 0,
              __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 0x0}}, __size = '\000' <repeats 39 times>, __align = 0}}, <No data fields>},
      seq = 3736590, warn_interval_multiplier = 1, state = {<std::__atomic_base<int>> = {static _S_alignment = 4, _M_i = 1},
        static is_always_lock_free = true},
      desc_str = "client_request(client.6440007:3395045818 getattr Xs #0x2000005c671 2024-07-24T13:20:00.604441+0200 caller_uid=0, caller_gid=0{0,})",
      desc = 0x55ba8670a900 "client_request(client.6440007:3395045818 getattr Xs #0x2000005c671 2024-07-24T13:20:00.604441+0200 caller_uid=0, caller_gid=0{0,})", want_new_desc = {_M_base = {static _S_alignment = 1, _M_i = false}, static is_always_lock_free = true}, osd_trace = {<No data fields>},

Abhishek Lekshmanan wrote in #note-13:

Could you enable the debug logs and try to reproduce it again ?

debug_mds = 20
debug_ms = 1

Thanks

Hi Xiubo,
we notice that when we crank up debug mds to 20 and debug_ms 1 usually it gets very difficult to reproduce the issue

This sounds reasonable.

I just figured out the root cause of it. Just after a client request is killed it will clear all the pin references but leaving the request to be retried, which will clear the batch_ops list, in future. But just before the request is retried the trim is triggered we should see this crash.

And the https://tracker.ceph.com/issues/65536 could resolve this bug.

Thanks