Ceph » CephFS

I've done some further debugging to understand the MDS performance problem that has been impacting us more. The finisher thread (fn_anonymous) uses 100% CPU on remove operations - it turns out remove directory operations. Stack traces look like this:

#0  0x0000555555787d37 in CInode::is_ancestor_of (this=0x55580f021800, other=0x5557c1b1c300, other@entry=0x5557c9146700) at /usr/src/debug/ceph-14.2.20-0.el8.x86_64/src/mds/CDentry.h:150
#1  0x00005555557e4147 in SnapRealm::split_at (this=this@entry=0x555557ea0280, child=0x55584e1c1b80) at /usr/src/debug/ceph-14.2.20-0.el8.x86_64/src/mds/SnapRealm.cc:593
#2  0x00005555557a1a5f in CInode::open_snaprealm (this=0x55580f021800, nosplit=<optimized out>) at /usr/src/debug/ceph-14.2.20-0.el8.x86_64/src/mds/CInode.cc:2764
#3  0x00005555557a1e96 in CInode::pop_projected_snaprealm (this=0x55580f021800, next_snaprealm=0x55556425f140, early=<optimized out>) at /usr/src/debug/ceph-14.2.20-0.el8.x86_64/src/mds/CInode.cc:586
#4  0x00005555557a2462 in CInode::early_pop_projected_snaprealm (this=this@entry=0x55580f021800) at /usr/include/c++/8/bits/stl_list.h:1122
#5  0x00005555555d1dc0 in Server::_unlink_local_finish (this=0x555556438500, mdr=..., dn=0x5558541e8f00, straydn=0x555946731860, dnpv=77222) at /usr/src/debug/ceph-14.2.20-0.el8.x86_64/src/mds/Server.cc:7025

In SnapRealm::split_at, there are two loops that seem to be the root cause of the MDS performance problem:

  dout(10) << " open_children are " << open_children << dendl;
  for (set<SnapRealm*>::iterator p = open_children.begin();
       p != open_children.end(); ) {
   ...

and

  // split inodes_with_caps
  for (elist<CInode*>::iterator p = inodes_with_caps.begin(member_offset(CInode, item_caps));
       !p.end(); ) {
    CInode *in = *p;
    ++p;
    // does inode fall within the child realm?
    if (child->inode->is_ancestor_of(in)) {
      dout(20) << " child gets " << *in << dendl;
      in->move_to_realm(child);
    } else {
      dout(20) << "    keeping " << *in << dendl;
    }
  }

The second loop goes through hundreds of thousands of inodes and does nothing (ends in the else case of the if since they aren't repated to the directory). For the trace cases I looked at, the first loop over open_children also loops through over ten thousand entries. It looks like these two loops are responsible for tens of milliseconds of time spent.

This is done in the finisher thread, which there is only one of, and looks like many MDS operations go through it to be committed. As a consequence, high latency on directory removes makes the whole MDS quite unresponsive.

• Do we have to call open_snaprealm/split_at for each directory that is removed? If not, when is this called? For our use case, it seems to be called really a lot (especially given how heavy of a loop it needs to do).
• Do these calls have to hold up all other operations in the MDS?
• How would this work with a relatively large MDS cache with hundreds of clients?

And most importantly - what are practical ways we could mitigate/triage this problem?

Thanks for opening a ticket and doing some digging, Andras,

Andras Pataki wrote:

I've done some further debugging to understand the MDS performance problem that has been impacting us more. The finisher thread (fn_anonymous) uses 100% CPU on remove operations - it turns out remove directory operations. Stack traces look like this:

[...]

In SnapRealm::split_at, there are two loops that seem to be the root cause of the MDS performance problem:

[...]

and

[...]

The second loop goes through hundreds of thousands of inodes and does nothing (ends in the else case of the if since they aren't repated to the directory). For the trace cases I looked at, the first loop over open_children also loops through over ten thousand entries. It looks like these two loops are responsible for tens of milliseconds of time spent.

Yes, it seems so.

This is done in the finisher thread, which there is only one of, and looks like many MDS operations go through it to be committed. As a consequence, high latency on directory removes makes the whole MDS quite unresponsive.

Questions I still don't understand:

• Do we have to call open_snaprealm/split_at for each directory that is removed? If not, when is this called? For our use case, it seems to be called really a lot (especially given how heavy of a loop it needs to do).

I'm not sure but it seems at least we could optimize the trivial case of an empty directory.

• Do these calls have to hold up all other operations in the MDS?

The fair_mutex I mentioned in the mailing list thread would help but you'd still have a long queue of operations in the finisher thread which would slow down other things.

• How would this work with a relatively large MDS cache with hundreds of clients?

A large cache adds to the work because, for a snapshot that covers the whole file system, the MDS will look at every inode in cache.

And most importantly - what are practical ways we could mitigate/triage this problem?

Well, you can ask users to move the subtrees to a global trash directory rather than `rm -rf` (yuck!). Then write a script that gently deletes it.

I will try to reproduce this and create a fix.

Thanks Andras.

Just want to share an update that I was able to reproduce the problem. I'll test out a fix soon...

That's great news! I'm also trying to set up a test environment to reproduce the issue outside our main cluster (eyeing to test a potential fix there). Thanks Patrick.

Andras, I think there are other inefficiencies I've not yet identified but this fix addresses your specific problem.

Thanks Patrick! How safe do you feel this patch is? Does it need a lot of testing or is it safe to deploy?

Andras Pataki wrote:

Thanks Patrick! How safe do you feel this patch is? Does it need a lot of testing or is it safe to deploy?

It is safe to deploy in my opinion.

Hmm, the stuff in split_at looks like we can and should just swap the logic -- instead of iterating over all inodes in the parent snaprealm, we should look at all the open inodes underneath the newly-created snaprealm's inode. That logic is slightly more involved (we have to descend the hierarchy instead of iterating through a list) but should not be a big deal.

There are some other uses of the inodes_with_caps list in MDCache which may not all be so easy, but I didn't look at them in as much detail. We're doing notifies to the clients of all inodes in do_realm_invalidate_and_update_notify, for instance, but it looks like that only applies to children of things we're renaming et al -- which is both necessary and also generally a smaller set.

This topic was discussed during the User + Dev meeting on Aug. 8th, 2022. One revelation that came of the meeting (as per Greg) was that unmounting clients at night could help.

Greg also recommended that Andras try out the methods mentioned in note#9, and update the Tracker with any additional findings.

I also looked into Patrick's PR, and I see it's currently in draft form. The last comment there was:

From Patrick:

So this doesn't work because directories may be "empty" because there are no HEAD dentries but some snapshotted dentries exist, i.e. CDir::get_num_snap_items() > 0. So there will be some inodes with caps, potentially, that refer to the snapshotted inodes associated with those dentries.

The solution, I believe, is to create a hierarchical data structure part of CDir which allows tracking child inodes with caps or something that allows us to optimize the common cases (small directories with few or 0 snapshotted dentries).

So it looks like the final solution may just need some more reviews/refactoring.

Has there been any progress on this in the last year? We believe we are hitting the same issue on a production cluster (all NVMe OSDs, v16.2.11), but so far we are unable to reproduce it with an artificial test (see below) on the same cluster.

The symptoms we see are very bad `rm -rf` performance (handfull of ops/s) and also bad access performance for other clients on the same cluster. At the same time we see 100% CPU usage on the active MDS node. Prometheus metrics show that `rmdir` operations that usually complete in 1-2ms, instead take 20ms, 60ms, or in one case even 350ms (for many minutes without change).

One single example from an MDS log dump:

2023-04-18T16:45:18.130+0200 7f8d6e33b700  4 mds.0.server handle_client_request client_request(client.188008615:5997200 readdir #0x1000344befc 2023-04-18T16:45:18.129945+0200 caller_uid=0, caller_gid=0{}) v2
2023-04-18T16:45:18.214+0200 7f8d6732d700  5 mds.0.log _submit_thread 29859233665684~2795 : EUpdate scatter_writebehind [metablob 0x1000344befc, 2 dirs]
2023-04-18T16:45:18.290+0200 7f8d6732d700  5 mds.0.log _submit_thread 29859233668499~5378 : EUpdate unlink_local [metablob 0x1000344befc, 4 dirs]
2023-04-18T16:45:18.294+0200 7f8d6e33b700  4 mds.0.server handle_client_request client_request(client.188008615:5997207 rmdir #0x1000344befc/818 2023-04-18T16:45:18.289945+0200 caller_uid=0, caller_gid=0{}) v2

For the artificial test we create 400k directories (4000 first level, 15 next level, then 3 more levels with 1 directory each, then a file with some random data in each leaf directory) and then run `rm -rf` on the top level directory. However, even if I create and remove a snapshot at the root level of the filesystem and run the `rm -rf` after that, I cannot seem to trigger the bug.

A failover to a standby MDS seems to temporarily fix the problem, but I assume that's mostly related to the cache starting out empty since it comes back eventually.

Does anyone have a reliable way to reproduce this (Patrick mentioned he can repro) or some insight into which parameters affect the likelyhood of this happening? Or even better, has any of the mentioned refactoring happened in other places and would this bug be fixed in newer versions? We are currently running ceph 16.2.11, but it appears that an upgrade to the latest 17.2.x would not yet fix this, correct?

The log I copied is not actually showing the rmdir latency since I filtered incorrectly, sorry about that. This one is just a sample from a grep for `client.188008615` showing consecutive operations from a single client:

2023-04-18T16:45:20.922+0200 7f8d6e33b700  4 mds.0.server handle_client_request client_request(client.188008615:5997269 rmdir #0x10003671e40/d9e 2023-04-18T16:45:20.917957+0200 caller_uid=0, caller_gid=0{}) v2
2023-04-18T16:45:21.014+0200 7f8d6e33b700  4 mds.0.server handle_client_request client_request(client.188008615:5997270 rmdir #0x10003671e3f/daa 2023-04-18T16:45:21.013957+0200 caller_uid=0, caller_gid=0{}) v2
2023-04-18T16:45:21.106+0200 7f8d6e33b700  4 mds.0.server handle_client_request client_request(client.188008615:5997271 rmdir #0x10003671e3e/3f4 2023-04-18T16:45:21.101958+0200 caller_uid=0, caller_gid=0{}) v2
2023-04-18T16:45:21.194+0200 7f8d6e33b700  4 mds.0.server handle_client_request client_request(client.188008615:5997272 rmdir #0x1000353cc7f/0e3 2023-04-18T16:45:21.193958+0200 caller_uid=0, caller_gid=0{}) v2
2023-04-18T16:45:21.282+0200 7f8d6e33b700  4 mds.0.server handle_client_request client_request(client.188008615:5997273 rmdir #0x1000343178d/371 2023-04-18T16:45:21.281959+0200 caller_uid=0, caller_gid=0{}) v2
2023-04-18T16:45:21.370+0200 7f8d6e33b700  4 mds.0.server handle_client_request client_request(client.188008615:5997274 readdir #0x1000401b907 2023-04-18T16:45:21.369959+0200 caller_uid=0, caller_gid=0{}) v2
2023-04-18T16:45:21.374+0200 7f8d6e33b700  4 mds.0.server handle_client_request client_request(client.188008615:5997275 readdir #0x1000401b908 2023-04-18T16:45:21.369959+0200 caller_uid=0, caller_gid=0{}) v2
2023-04-18T16:45:21.374+0200 7f8d6e33b700  4 mds.0.server handle_client_request client_request(client.188008615:5997276 readdir #0x1000401b909 2023-04-18T16:45:21.373959+0200 caller_uid=0, caller_gid=0{}) v2
2023-04-18T16:45:21.378+0200 7f8d6e33b700  4 mds.0.server handle_client_request client_request(client.188008615:5997277 readdir #0x1000401b90a 2023-04-18T16:45:21.373959+0200 caller_uid=0, caller_gid=0{}) v2
2023-04-18T16:45:21.378+0200 7f8d6e33b700  4 mds.0.server handle_client_request client_request(client.188008615:5997278 readdir #0x1000401b90b 2023-04-18T16:45:21.377959+0200 caller_uid=0, caller_gid=0{}) v2

Hi Andras,

Nice to hear from you in the User/Dev monthly meet-up. You had a question related to what exactly is SnapRealm::split_at() function doing (which is the source of latency when snapshots are taken in cephfs) - I replied to it in the PR itself: https://github.com/ceph/ceph/pull/43911#pullrequestreview-883184649

Copying here for brevity:

--
OK, so the "parent" snaprealm tracks all the inodes under its tree which have caps and the root directory always has a snaprealm which implies that every inode under it used by a client is in the inodes_with_caps list for the root directory. And then when a child snapshot is created, the split_at iterates through the entire, probably millions entries and "moves" those inodes which now fall under the child snap realm.
--

As you can see, even when no snapshots exists, the root snaprealm tracks all inodes which have (client) caps (SnapRealm::inodes_with_caps) and when a snapshot is taken anywhere in the tree, this (potentially huge) list is iterated to move inodes which would now fall under the child snaprealm.

If these inode (which have caps) are tracked at the directory level under which they exists, the iteration part when splitting a snaprealm can be avoided, however, there is also the case when these scattered lists would need to be merged (gather).

Hi Venky, Patrick

further to our talk, we saw the MDS growing with a lot of log segments and crashing in the up:replay/resolve loop. I reported what we saw as a new issue, let us know if this is somehow related and what we can do to move things along
https://tracker.ceph.com/issues/64717

Hi Andras,

Patrick has a proposed fix that optimizes the iteration - https://github.com/ceph/ceph/pull/55768

I ran it through fs suite and the qa run looks good. Patrick did a sample benchmark with this change and the results show improvement in the split path. See commit details in a0ccb79fa0806792c7ee666c667328a8aeb09e97 in the above PR.

I'll be merging the change sometime this week once we get some of the unrelated qa failures sorted out. If you are for it, feel free to cherry-pick the changes and run it through the workload (or something similar to it) which initially prompted the creation of this tracker :)

Abhishek Lekshmanan wrote:

Hi Venky, Patrick

further to our talk, we saw the MDS growing with a lot of log segments and crashing in the up:replay/resolve loop. I reported what we saw as a new issue, let us know if this is somehow related and what we can do to move things along
https://tracker.ceph.com/issues/64717

Thanks for the report, Abhishek. I've left some comments on the above tracker. Let's continue the discussion there.