Hello Ivan, Do you observe any spikes in the memory utilization of the MDS when the lock happens? Particularly in buffer_anon? We are observing some rdlock issues which are leading to a spinlock on the MDS but it does not seem to be related to a hanging operation on an OSD. Cheers, Enrico On 3/19/24 12:42, Ivan Clayson wrote:

Hello Gregory and Nathan,

Having a look at our resource utilization, there doesn't seem to be a CPU or memory bottleneck as there is plenty of both available for the host which has the blocked OSD as well for the MDS' host.

We've had a repeated of this problem today where the OSD logging slow ops did not have any ops in flight despite: (i) being in an active state, (ii) clients requesting I/O from this OSD, and (iii) the MDS reporting that it was unable to get a rdlock. The blocked op reported by the MDS was initially related to our backups (but is not always) where this takes a snapshot every night and then we back up the snapshot to another Ceph cluster. We then delete this snapshot after we've backed it up.

   # the blocked op on the MDS is related to backing up a snapshot of    the file $FILE:    ~$ ceph tell mds.0 dump_blocked_ops                 "description": "client_request(client.90018803:265050    getattr AsLsXsFs #0x100004e2452//1710815659/... ... caller_uid=...,    caller_gid=...)"                 "initiated_at": "...",                 "age": ...,                 "duration": ...,                 "type_data": {                     "flag_point": "failed to rdlock, waiting",    ...

   ~$ ls -lrt $FILE    .... # ls -lrt hangs as it hangs on a statx syscall on the file    where this then comes up as another blocked op in the MDS op list

   ~$ ceph tell mds.0 dump_blocked_ops    ....    client_request(client.91265572:7 getattr AsLsFs #0x1002fe5d755 ...    caller_uid=..., caller_gid=...)

   root@client-whose-held-active-cap-for-1002fe5d755-the-longest ~$    grep 1002fe5d755 /sys/kernel/debug/ceph/*/osdc    1652    osd7    3.3519a4ff      3.4ffs0    [7,132,61,143,109,98,18,44,269,238]/7    [7,132,61,143,109,98,18,44,269,238]/7   e159072    1002fe5d755.00000011    0x400024        1       write

   ~$ systemctl status --no-pager --full ceph-osd@7    ....    ceph-osd[1184036]:  osd.7 158945 get_health_metrics reporting 8 slow    ops, oldest is osd_op(client.90099026.0:4068839 3.4ffs0    3:ff28a5a4:::1002feddfaa.00000000:head [write 0~4194304 [1@-1]    in=4194304b] snapc 6af1=[] ondisk+write+known_if_redirected e158942)    ceph-osd[1184036]:  osd.7 158945 get_health_metrics reporting 6 slow    ops, oldest is osd_op(client.90099026.0:4068839 3.4ffs0    3:ff28a5a4:::1002feddfaa.00000000:head [write 0~4194304 [1@-1]    in=4194304b] snapc 6af1=[] ondisk+write+known_if_redirected e158942)

There was nothing in dmesg or wrong with the HDD for osd.7 (or any drives for that matter) and osd.7 reported no blocked ops or any ops in flight from the daemon via `ceph tell`. However when looking at the historic slow ops, the oldest one still saved related to this stuck $FILE object (1002fe5d755) and it seems that about half of the recorded historical slow ops are about this PG with them all occurring around the same time the OSD slow ops started occurring:

   ~$ ceph tell osd.7 dump_historic_slow_ops                "description": "osd_op(client.89624569.0:1151567 3.4ffs0    3:ff27ac5d:::1002fea2a90.0000000a:head [write 0~4194304] snapc    6ab9=[6ab9] ondisk+write+known_if_redirected e158919)",                 "initiated_at": "...",                 "age": ...,                 "duration": ...,                 "type_data": {                     "flag_point": "commit sent; apply or cleanup",                 ...                         {                             "event": "header_read",                             "time": "2024-03-18T19:43:41.875596+0000",                             "duration": 4294967295.9999967                         },

I've highlighted this header_read duration as this took apparently ~136 years(!) so there seems to be something off maybe with the messenger layer.

I would be eager to hear what your thoughts are on this as it seems after awhile the OSD "forgets" about this slow op and stops reporting it in the log. I'm also curious about your thoughts on this being related to the number of snapshots we have as we get rid of the snapshot on this filesystem when we've copied over to the backup system but could this still cause problems and or are they issues with snaps?

Kindest regards,

Ivan

On 15/03/2024 18:07, Gregory Farnum wrote:

...

CAUTION: This email originated from outside of the LMB: *.-gfarnum@redhat.com-.* Do not click links or open attachments unless you recognize the sender and know the content is safe. If you think this is a phishing email, please forward it to phishing@mrc-lmb.cam.ac.uk

--

On Fri, Mar 15, 2024 at 6:15 AM Ivan Clayson <ivan@mrc-lmb.cam.ac.uk> wrote:

    Hello everyone,

    We've been experiencing on our quincy CephFS clusters (one 17.2.6 and     another 17.2.7) repeated slow ops with our client kernel mounts     (Ceph 17.2.7 and version 4 Linux kernels on all clients) that seem to     originate from slow ops on osds despite the underlying hardware being     fine. Our 2 clusters are similar and are both Alma8 systems where     more     specifically:

      * Cluster (1) is Alma8.8 running Ceph version 17.2.7 with 7 NVMe SSD         OSDs storing the metadata and 432 spinning SATA disks storing the         bulk data in an EC pool (8 data shards and 2 parity blocks) across         40 nodes. The whole cluster is used to support a single file     system         with 1 active MDS and 2 standby ones.       * Cluster (2) is Alma8.7 running Ceph version 17.2.6 with 4 NVMe SSD         OSDs storing the metadata and 348 spinning SAS disks storing the         bulk data in EC pools  (8 data shards and 2 parity blocks). This         cluster houses multiple filesystems each with their own dedicated         MDS along with 3 communal standby ones.

    Nearly daily we often find that we're get the following error     messages:     MDS_CLIENT_LATE_RELEASE, MDS_SLOW_METADATA_IO, and MDS_SLOW_REQUEST.     Along with these messages, certain files and directory cannot be     stat-ed     and any processes involving these files hang indefinitely. We have     been     fixing this by:

        1. First, finding the oldest blocked MDS op and the inode     listed there:

            ~$ ceph tell mds.${my_mds} dump_blocked_ops 2>> /dev/null     | grep             -c description

                "description": "client_request(client.251247219:662     getattr                 AsLsXsFs #0x100922d1102 2024-03-13T12:51:57.988115+0000                 caller_uid=26983, caller_gid=26983)",

                # inode/ object of interest: 100922d1102

        2. Second, finding all the current clients that have a cap for     this         blocked inode from the faulty MDS' session list (i.e. ceph tell         mds.${my_mds} session ls --cap-dump) and then examining the client         whose had the cap the longest:

            ~$ ceph tell mds.${my_mds} session ls --cap-dump ...

                2024-03-13T13:01:36: client.251247219

                2024-03-13T12:50:28: client.245466949

        3. Then on the aforementioned oldest client, get the current     ops in         flight to the OSDs (via the "/sys/kernel/debug/ceph/*/osdc" files)         and get the op corresponding to the blocked inode along with     the OSD         the I/O is going to:

            root@client245466949 $ grep 100922d1102             /sys/kernel/debug/ceph/*/osdc

                48366  osd79 2.249f8a51  2.a51s0                 [79,351,232,179,107,195,323,14,128,167]/79                 [79,351,232,179,107,195,323,14,128,167]/79 e374191                 100922d1102.000000f5  0x400024  1 write

                # osd causing errors is osd.79

        4. Finally, we restart this "hanging" OSD where this results in ls         and I/O on the previously "stuck" files no longer "hanging" .

    Once we get this OSD for which the blocked inode is waiting for,     we can     see in the system logs that the OSD has slow ops:

    ~$ systemctl --no-pager --full status ceph-osd@79

        ...         2024-03-13T12:49:37 -1 osd.79 374175 get_health_metrics     reporting 3         slow ops, oldest is osd_op(client.245466949.0:41350 2.ca4s0         2.ce648ca4 (undecoded) ondisk+write+known_if_redirected e374173)         ...

Have you dumped_ops_in_flight on the OSD in question to see how far that op got before getting stuck?

This is some kind of RADOS problem, which isn’t great, but I wonder if we’ve exceeded some snapshot threshold that is showing up on hard drives as slow ops, or if there’s a code bug that is just causing them to get lost. :/ -Greg

    Files that these "hanging" inodes correspond to as well as the     directories housing these files can't be opened or stat-ed (causing     directories to hang) where we've found restarting this OSD with     slow ops     to be the least disruptive way of resolving this (compared with a     forced     umount and then re-mount on the client). There are no issues with the     underlying hardware for either the osd reporting these slow ops or     any     other drive within the acting PG and there seems to be no correlation     between what processes are involved or what type of files these are.

    What could be causing these slow ops and certain files and     directories     to "hang"? There aren't workflows being performed that generate a     large     number of small files nor are there directories with a large     number of     files within them. This seems to happen with a wide range of     hard-drives     and we see this on SATA and SAS type drives where our nodes are     interconnected with 25 Gb/s NICs so we can't see how the underlying     hardware would be causing any I/O bottlenecks. Has anyone else     seen this     type of behaviour before and have any ideas? Is there a way to stop     these from happening as we are having to solve these nearly daily now     and we can't seem to find a way to reduce them. We do use     snapshots to     backup our cluster where we've been doing this for ~6 months and     these     issues have only been occurring on and off for a couple of months but     much more frequently now.

    Kindest regards,

    Ivan Clayson

    --     Ivan Clayson     -----------------     Scientific Computing Officer     Room 2N249     Structural Studies     MRC Laboratory of Molecular Biology     Francis Crick Ave, Cambridge     CB2 0QH     _______________________________________________     ceph-users mailing list -- ceph-users@ceph.io     To unsubscribe send an email to ceph-users-leave@ceph.io

-- Enrico Bocchi CERN European Laboratory for Particle Physics IT - Storage & Data Management - General Storage Services Mailbox: G20500 - Office: 31-2-010 1211 Genève 23 Switzerland