6.5 CephFS client - ceph_cap_reclaim_work [ceph] / ceph_con_workfn [libceph] hogged CPU
Hi, Since the 6.5 kernel addressed the issue with regards to regression in the readahead handling code... we went ahead and installed this kernel for a couple of mail / web clusters (Ubuntu 6.5.1-060501-generic #202309020842 SMP PREEMPT_DYNAMIC Sat Sep 2 08:48:34 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux). Since then we occasionally see the following being logged by the kernel: [Sun Sep 10 07:19:00 2023] workqueue: delayed_work [ceph] hogged CPU for
10000us 4 times, consider switching to WQ_UNBOUND [Sun Sep 10 08:41:24 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND [Sun Sep 10 11:05:55 2023] workqueue: delayed_work [ceph] hogged CPU for 10000us 8 times, consider switching to WQ_UNBOUND [Sun Sep 10 12:54:38 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 8 times, consider switching to WQ_UNBOUND [Sun Sep 10 19:06:37 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 16 times, consider switching to WQ_UNBOUND [Mon Sep 11 10:53:33 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 32 times, consider switching to WQ_UNBOUND [Tue Sep 12 10:14:03 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 64 times, consider switching to WQ_UNBOUND [Tue Sep 12 11:14:33 2023] workqueue: ceph_cap_reclaim_work [ceph] hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND
We wonder if this is a new phenomenon, or that it's rather logged in the new kernel and it was not before. However, we have hit a few OOM situations since we switched to the new kernel because of ceph_cap_reclaim_work events (OOM is because Apache threads keep piling up as it cannot access CephFS). We then also see MDS slow ops reported. This might be related to a backup job that is running on a backup server. We did not observe this behavior on 5.12.19 kernel. Ceph cluster is on 16.2.11 currently. Anyone has some insight on this? Thanks, Stefan
On Wed, Sep 13, 2023 at 9:20 AM Stefan Kooman <stefan@bit.nl> wrote:
Hi,
Since the 6.5 kernel addressed the issue with regards to regression in the readahead handling code... we went ahead and installed this kernel for a couple of mail / web clusters (Ubuntu 6.5.1-060501-generic #202309020842 SMP PREEMPT_DYNAMIC Sat Sep 2 08:48:34 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux). Since then we occasionally see the following being logged by the kernel:
[Sun Sep 10 07:19:00 2023] workqueue: delayed_work [ceph] hogged CPU for
10000us 4 times, consider switching to WQ_UNBOUND [Sun Sep 10 08:41:24 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND [Sun Sep 10 11:05:55 2023] workqueue: delayed_work [ceph] hogged CPU for 10000us 8 times, consider switching to WQ_UNBOUND [Sun Sep 10 12:54:38 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 8 times, consider switching to WQ_UNBOUND [Sun Sep 10 19:06:37 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 16 times, consider switching to WQ_UNBOUND [Mon Sep 11 10:53:33 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 32 times, consider switching to WQ_UNBOUND [Tue Sep 12 10:14:03 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 64 times, consider switching to WQ_UNBOUND [Tue Sep 12 11:14:33 2023] workqueue: ceph_cap_reclaim_work [ceph] hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND
We wonder if this is a new phenomenon, or that it's rather logged in the new kernel and it was not before.
Hi Stefan, This is something that wasn't logged in older kernels. The kernel workqueue infrastructure is considering Ceph work items CPU intensive and reports that in dmesg. This is new in 6.5 kernel, the threshold can be tweaked with workqueue.cpu_intensive_thresh_us parameter.
However, we have hit a few OOM situations since we switched to the new kernel because of ceph_cap_reclaim_work events (OOM is because Apache threads keep piling up as it cannot access CephFS). We then also see MDS slow ops reported. This might be related to a backup job that is running on a backup server. We did not observe this behavior on 5.12.19 kernel.
Adding Xiubo. Thanks, Ilya
On 13-09-2023 14:58, Ilya Dryomov wrote:
On Wed, Sep 13, 2023 at 9:20 AM Stefan Kooman <stefan@bit.nl> wrote:
Hi,
Since the 6.5 kernel addressed the issue with regards to regression in the readahead handling code... we went ahead and installed this kernel for a couple of mail / web clusters (Ubuntu 6.5.1-060501-generic #202309020842 SMP PREEMPT_DYNAMIC Sat Sep 2 08:48:34 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux). Since then we occasionally see the following being logged by the kernel:
[Sun Sep 10 07:19:00 2023] workqueue: delayed_work [ceph] hogged CPU for
10000us 4 times, consider switching to WQ_UNBOUND [Sun Sep 10 08:41:24 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND [Sun Sep 10 11:05:55 2023] workqueue: delayed_work [ceph] hogged CPU for 10000us 8 times, consider switching to WQ_UNBOUND [Sun Sep 10 12:54:38 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 8 times, consider switching to WQ_UNBOUND [Sun Sep 10 19:06:37 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 16 times, consider switching to WQ_UNBOUND [Mon Sep 11 10:53:33 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 32 times, consider switching to WQ_UNBOUND [Tue Sep 12 10:14:03 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 64 times, consider switching to WQ_UNBOUND [Tue Sep 12 11:14:33 2023] workqueue: ceph_cap_reclaim_work [ceph] hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND
We wonder if this is a new phenomenon, or that it's rather logged in the new kernel and it was not before.
Hi Stefan,
This is something that wasn't logged in older kernels. The kernel workqueue infrastructure is considering Ceph work items CPU intensive and reports that in dmesg. This is new in 6.5 kernel, the threshold can be tweaked with workqueue.cpu_intensive_thresh_us parameter.
Thanks. I was just looking into it (WQ_UNBOUND), alloc_workqueue(), etc. The patch by Tejun Heo on workqueue also mentions this: * Concurrency-managed per-cpu work items that hog CPUs and delay the execution of other work items are now automatically detected and excluded from concurrency management. Reporting on such work items can also be enabled through a config option. This does imply that the Ceph work items are "excluded from concurrency management", is that correct? And if so, what does that mean in practice? Might this make the process of returning / claiming caps to the MDS slower? In 6.6-rc1 more workqueue work is done and more fine tuning seems possible. If there are any recommendations from a cephfs kernel client perspective on what a good policy would be, we would love to hear about that. For now we will just disable the detection (cpu_intensive_thresh_us=0) and see how it goes. Thanks, Gr. Stefan
On Wed, Sep 13, 2023 at 4:49 PM Stefan Kooman <stefan@bit.nl> wrote:
On 13-09-2023 14:58, Ilya Dryomov wrote:
On Wed, Sep 13, 2023 at 9:20 AM Stefan Kooman <stefan@bit.nl> wrote:
Hi,
Since the 6.5 kernel addressed the issue with regards to regression in the readahead handling code... we went ahead and installed this kernel for a couple of mail / web clusters (Ubuntu 6.5.1-060501-generic #202309020842 SMP PREEMPT_DYNAMIC Sat Sep 2 08:48:34 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux). Since then we occasionally see the following being logged by the kernel:
[Sun Sep 10 07:19:00 2023] workqueue: delayed_work [ceph] hogged CPU for
10000us 4 times, consider switching to WQ_UNBOUND [Sun Sep 10 08:41:24 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND [Sun Sep 10 11:05:55 2023] workqueue: delayed_work [ceph] hogged CPU for 10000us 8 times, consider switching to WQ_UNBOUND [Sun Sep 10 12:54:38 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 8 times, consider switching to WQ_UNBOUND [Sun Sep 10 19:06:37 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 16 times, consider switching to WQ_UNBOUND [Mon Sep 11 10:53:33 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 32 times, consider switching to WQ_UNBOUND [Tue Sep 12 10:14:03 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 64 times, consider switching to WQ_UNBOUND [Tue Sep 12 11:14:33 2023] workqueue: ceph_cap_reclaim_work [ceph] hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND
We wonder if this is a new phenomenon, or that it's rather logged in the new kernel and it was not before.
Hi Stefan,
This is something that wasn't logged in older kernels. The kernel workqueue infrastructure is considering Ceph work items CPU intensive and reports that in dmesg. This is new in 6.5 kernel, the threshold can be tweaked with workqueue.cpu_intensive_thresh_us parameter.
Thanks. I was just looking into it (WQ_UNBOUND), alloc_workqueue(), etc. The patch by Tejun Heo on workqueue also mentions this:
* Concurrency-managed per-cpu work items that hog CPUs and delay the execution of other work items are now automatically detected and excluded from concurrency management. Reporting on such work items can also be enabled through a config option.
This does imply that the Ceph work items are "excluded from concurrency management", is that correct? And if so, what does that mean in practice? Might this make the process of returning / claiming caps to the MDS slower?
I haven't had the time to look into this in detail, but I did see a couple of recent changes in the area which I tagged as "something of interest" in my inbox: https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?i... https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?i... Thanks, Ilya
On 13-09-2023 16:49, Stefan Kooman wrote:
On 13-09-2023 14:58, Ilya Dryomov wrote:
On Wed, Sep 13, 2023 at 9:20 AM Stefan Kooman <stefan@bit.nl> wrote:
Hi,
Since the 6.5 kernel addressed the issue with regards to regression in the readahead handling code... we went ahead and installed this kernel for a couple of mail / web clusters (Ubuntu 6.5.1-060501-generic #202309020842 SMP PREEMPT_DYNAMIC Sat Sep 2 08:48:34 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux). Since then we occasionally see the following being logged by the kernel:
[Sun Sep 10 07:19:00 2023] workqueue: delayed_work [ceph] hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND [Sun Sep 10 08:41:24 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND [Sun Sep 10 11:05:55 2023] workqueue: delayed_work [ceph] hogged CPU for >10000us 8 times, consider switching to WQ_UNBOUND [Sun Sep 10 12:54:38 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 8 times, consider switching to WQ_UNBOUND [Sun Sep 10 19:06:37 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 16 times, consider switching to WQ_UNBOUND [Mon Sep 11 10:53:33 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 32 times, consider switching to WQ_UNBOUND [Tue Sep 12 10:14:03 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 64 times, consider switching to WQ_UNBOUND [Tue Sep 12 11:14:33 2023] workqueue: ceph_cap_reclaim_work [ceph] hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND
We wonder if this is a new phenomenon, or that it's rather logged in the new kernel and it was not before.
Hi Stefan,
This is something that wasn't logged in older kernels. The kernel workqueue infrastructure is considering Ceph work items CPU intensive and reports that in dmesg. This is new in 6.5 kernel, the threshold can be tweaked with workqueue.cpu_intensive_thresh_us parameter.
Thanks. I was just looking into it (WQ_UNBOUND), alloc_workqueue(), etc. The patch by Tejun Heo on workqueue also mentions this:
* Concurrency-managed per-cpu work items that hog CPUs and delay the execution of other work items are now automatically detected and excluded from concurrency management. Reporting on such work items can also be enabled through a config option.
This does imply that the Ceph work items are "excluded from concurrency management", is that correct? And if so, what does that mean in practice? Might this make the process of returning / claiming caps to the MDS slower?
In 6.6-rc1 more workqueue work is done and more fine tuning seems possible. If there are any recommendations from a cephfs kernel client perspective on what a good policy would be, we would love to hear about that.
For now we will just disable the detection (cpu_intensive_thresh_us=0) and see how it goes.
Well, the positive thing to mention is that we don't see this happening anymore. However, in the same time window as last week, an event happened. This time it was the MDS that got OOM killed. At the time it was killed it was consuming 249.9 GiB (03:51:33). Just before that it consumed ~ 200 GiB. It acquired ~ 50 GiB of ram in 35 seconds (according to metrics). What MDS / client behaviour can trigger such an amount of increased memory usage? Details: Single MDS (16.2.11), 1 active-standby, no snapshots. MDS server has 256 GiB of RAM. Dedicated node (bare metal). Adding Patrick in CC. Gr. Stefan
On 9/18/23 20:42, Stefan Kooman wrote:
On 13-09-2023 16:49, Stefan Kooman wrote:
On 13-09-2023 14:58, Ilya Dryomov wrote:
On Wed, Sep 13, 2023 at 9:20 AM Stefan Kooman <stefan@bit.nl> wrote:
Hi,
Since the 6.5 kernel addressed the issue with regards to regression in the readahead handling code... we went ahead and installed this kernel for a couple of mail / web clusters (Ubuntu 6.5.1-060501-generic #202309020842 SMP PREEMPT_DYNAMIC Sat Sep 2 08:48:34 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux). Since then we occasionally see the following being logged by the kernel:
[Sun Sep 10 07:19:00 2023] workqueue: delayed_work [ceph] hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND [Sun Sep 10 08:41:24 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND [Sun Sep 10 11:05:55 2023] workqueue: delayed_work [ceph] hogged CPU for >10000us 8 times, consider switching to WQ_UNBOUND [Sun Sep 10 12:54:38 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 8 times, consider switching to WQ_UNBOUND [Sun Sep 10 19:06:37 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 16 times, consider switching to WQ_UNBOUND [Mon Sep 11 10:53:33 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 32 times, consider switching to WQ_UNBOUND [Tue Sep 12 10:14:03 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 64 times, consider switching to WQ_UNBOUND [Tue Sep 12 11:14:33 2023] workqueue: ceph_cap_reclaim_work [ceph] hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND
We wonder if this is a new phenomenon, or that it's rather logged in the new kernel and it was not before.
Hi Stefan,
This is something that wasn't logged in older kernels. The kernel workqueue infrastructure is considering Ceph work items CPU intensive and reports that in dmesg. This is new in 6.5 kernel, the threshold can be tweaked with workqueue.cpu_intensive_thresh_us parameter.
Thanks. I was just looking into it (WQ_UNBOUND), alloc_workqueue(), etc. The patch by Tejun Heo on workqueue also mentions this:
* Concurrency-managed per-cpu work items that hog CPUs and delay the execution of other work items are now automatically detected and excluded from concurrency management. Reporting on such work items can also be enabled through a config option.
This does imply that the Ceph work items are "excluded from concurrency management", is that correct? And if so, what does that mean in practice? Might this make the process of returning / claiming caps to the MDS slower?
In 6.6-rc1 more workqueue work is done and more fine tuning seems possible. If there are any recommendations from a cephfs kernel client perspective on what a good policy would be, we would love to hear about that.
For now we will just disable the detection (cpu_intensive_thresh_us=0) and see how it goes.
Well, the positive thing to mention is that we don't see this happening anymore. However, in the same time window as last week, an event happened. This time it was the MDS that got OOM killed. At the time it was killed it was consuming 249.9 GiB (03:51:33). Just before that it consumed ~ 200 GiB. It acquired ~ 50 GiB of ram in 35 seconds (according to metrics). What MDS / client behaviour can trigger such an amount of increased memory usage?
There are several cases, for example when the pools are near full it could pile the journal logs in MDCache or due to the issues in https://github.com/ceph/ceph/pull/44180. Did you see any warning from ceph status or any suspect logs from the MDS ? Thanks - Xiubo
Details: Single MDS (16.2.11), 1 active-standby, no snapshots. MDS server has 256 GiB of RAM. Dedicated node (bare metal).
Adding Patrick in CC.
Gr. Stefan
On 08-11-2023 01:33, Xiubo Li wrote:
On 9/18/23 20:42, Stefan Kooman wrote:
On 13-09-2023 16:49, Stefan Kooman wrote:
On 13-09-2023 14:58, Ilya Dryomov wrote:
On Wed, Sep 13, 2023 at 9:20 AM Stefan Kooman <stefan@bit.nl> wrote:
Hi,
Since the 6.5 kernel addressed the issue with regards to regression in the readahead handling code... we went ahead and installed this kernel for a couple of mail / web clusters (Ubuntu 6.5.1-060501-generic #202309020842 SMP PREEMPT_DYNAMIC Sat Sep 2 08:48:34 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux). Since then we occasionally see the following being logged by the kernel:
[Sun Sep 10 07:19:00 2023] workqueue: delayed_work [ceph] hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND [Sun Sep 10 08:41:24 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND [Sun Sep 10 11:05:55 2023] workqueue: delayed_work [ceph] hogged CPU for >10000us 8 times, consider switching to WQ_UNBOUND [Sun Sep 10 12:54:38 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 8 times, consider switching to WQ_UNBOUND [Sun Sep 10 19:06:37 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 16 times, consider switching to WQ_UNBOUND [Mon Sep 11 10:53:33 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 32 times, consider switching to WQ_UNBOUND [Tue Sep 12 10:14:03 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 64 times, consider switching to WQ_UNBOUND [Tue Sep 12 11:14:33 2023] workqueue: ceph_cap_reclaim_work [ceph] hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND
We wonder if this is a new phenomenon, or that it's rather logged in the new kernel and it was not before.
Hi Stefan,
This is something that wasn't logged in older kernels. The kernel workqueue infrastructure is considering Ceph work items CPU intensive and reports that in dmesg. This is new in 6.5 kernel, the threshold can be tweaked with workqueue.cpu_intensive_thresh_us parameter.
Thanks. I was just looking into it (WQ_UNBOUND), alloc_workqueue(), etc. The patch by Tejun Heo on workqueue also mentions this:
* Concurrency-managed per-cpu work items that hog CPUs and delay the execution of other work items are now automatically detected and excluded from concurrency management. Reporting on such work items can also be enabled through a config option.
This does imply that the Ceph work items are "excluded from concurrency management", is that correct? And if so, what does that mean in practice? Might this make the process of returning / claiming caps to the MDS slower?
In 6.6-rc1 more workqueue work is done and more fine tuning seems possible. If there are any recommendations from a cephfs kernel client perspective on what a good policy would be, we would love to hear about that.
For now we will just disable the detection (cpu_intensive_thresh_us=0) and see how it goes.
Well, the positive thing to mention is that we don't see this happening anymore. However, in the same time window as last week, an event happened. This time it was the MDS that got OOM killed. At the time it was killed it was consuming 249.9 GiB (03:51:33). Just before that it consumed ~ 200 GiB. It acquired ~ 50 GiB of ram in 35 seconds (according to metrics). What MDS / client behaviour can trigger such an amount of increased memory usage?
There are several cases, for example when the pools are near full it could pile the journal logs in MDCache or due to the issues in https://github.com/ceph/ceph/pull/44180.
Did you see any warning from ceph status or any suspect logs from the MDS ?
We did for sure not hit a near full condition. We did observe a large amount of bandwidth associated with this kclient. The MDS is sending ~ 650 Mb/s of traffic to this one client alone (so more than 80% of all MDS traffic goes to one client). However, no ceph warnings or MDS logging prior to this event. The event starts, MDS continues to work ... until it's killed ~ half a minute later. MDS log settings: "debug_mds": "0/0", "debug_mds_balancer": "1/5", "debug_mds_locker": "1/5", "debug_mds_log": "1/5", "debug_mds_log_expire": "1/5", "debug_mds_migrator": "1/5", Note that we do not see any anomaly regarding CephFS (meta)data read / write traffic. So no excessive writes to a CephFS metadata pool for example. Note, that after we downgraded the kclients again (5.12.19) we did not observe this behavior. So we might be able to reproduce, but we rather don't want to ;-). Gr. Stefan
On 11/8/23 14:41, Stefan Kooman wrote:
On 08-11-2023 01:33, Xiubo Li wrote:
On 9/18/23 20:42, Stefan Kooman wrote:
On 13-09-2023 16:49, Stefan Kooman wrote:
On 13-09-2023 14:58, Ilya Dryomov wrote:
On Wed, Sep 13, 2023 at 9:20 AM Stefan Kooman <stefan@bit.nl> wrote:
Hi,
Since the 6.5 kernel addressed the issue with regards to regression in the readahead handling code... we went ahead and installed this kernel for a couple of mail / web clusters (Ubuntu 6.5.1-060501-generic #202309020842 SMP PREEMPT_DYNAMIC Sat Sep 2 08:48:34 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux). Since then we occasionally see the following being logged by the kernel:
[Sun Sep 10 07:19:00 2023] workqueue: delayed_work [ceph] hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND [Sun Sep 10 08:41:24 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND [Sun Sep 10 11:05:55 2023] workqueue: delayed_work [ceph] hogged CPU for >10000us 8 times, consider switching to WQ_UNBOUND [Sun Sep 10 12:54:38 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 8 times, consider switching to WQ_UNBOUND [Sun Sep 10 19:06:37 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 16 times, consider switching to WQ_UNBOUND [Mon Sep 11 10:53:33 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 32 times, consider switching to WQ_UNBOUND [Tue Sep 12 10:14:03 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 64 times, consider switching to WQ_UNBOUND [Tue Sep 12 11:14:33 2023] workqueue: ceph_cap_reclaim_work [ceph] hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND
We wonder if this is a new phenomenon, or that it's rather logged in the new kernel and it was not before.
Hi Stefan,
This is something that wasn't logged in older kernels. The kernel workqueue infrastructure is considering Ceph work items CPU intensive and reports that in dmesg. This is new in 6.5 kernel, the threshold can be tweaked with workqueue.cpu_intensive_thresh_us parameter.
Thanks. I was just looking into it (WQ_UNBOUND), alloc_workqueue(), etc. The patch by Tejun Heo on workqueue also mentions this:
* Concurrency-managed per-cpu work items that hog CPUs and delay the execution of other work items are now automatically detected and excluded from concurrency management. Reporting on such work items can also be enabled through a config option.
This does imply that the Ceph work items are "excluded from concurrency management", is that correct? And if so, what does that mean in practice? Might this make the process of returning / claiming caps to the MDS slower?
In 6.6-rc1 more workqueue work is done and more fine tuning seems possible. If there are any recommendations from a cephfs kernel client perspective on what a good policy would be, we would love to hear about that.
For now we will just disable the detection (cpu_intensive_thresh_us=0) and see how it goes.
Well, the positive thing to mention is that we don't see this happening anymore. However, in the same time window as last week, an event happened. This time it was the MDS that got OOM killed. At the time it was killed it was consuming 249.9 GiB (03:51:33). Just before that it consumed ~ 200 GiB. It acquired ~ 50 GiB of ram in 35 seconds (according to metrics). What MDS / client behaviour can trigger such an amount of increased memory usage?
There are several cases, for example when the pools are near full it could pile the journal logs in MDCache or due to the issues in https://github.com/ceph/ceph/pull/44180.
Did you see any warning from ceph status or any suspect logs from the MDS ?
We did for sure not hit a near full condition. We did observe a large amount of bandwidth associated with this kclient. The MDS is sending ~ 650 Mb/s of traffic to this one client alone (so more than 80% of all MDS traffic goes to one client).
However, no ceph warnings or MDS logging prior to this event. The event starts, MDS continues to work ... until it's killed ~ half a minute later.
MDS log settings:
"debug_mds": "0/0", "debug_mds_balancer": "1/5", "debug_mds_locker": "1/5", "debug_mds_log": "1/5", "debug_mds_log_expire": "1/5", "debug_mds_migrator": "1/5",
Note that we do not see any anomaly regarding CephFS (meta)data read / write traffic. So no excessive writes to a CephFS metadata pool for example.
Note, that after we downgraded the kclients again (5.12.19) we did not observe this behavior. So we might be able to reproduce, but we rather don't want to ;-).
Okay, BTW how man active MDSs you are running ? Thanks - Xiubo
Gr. Stefan
On 08-11-2023 07:45, Xiubo Li wrote:
On 11/8/23 14:41, Stefan Kooman wrote:
On 08-11-2023 01:33, Xiubo Li wrote:
On 9/18/23 20:42, Stefan Kooman wrote:
On 13-09-2023 16:49, Stefan Kooman wrote:
On 13-09-2023 14:58, Ilya Dryomov wrote:
On Wed, Sep 13, 2023 at 9:20 AM Stefan Kooman <stefan@bit.nl> wrote: > > Hi, > > Since the 6.5 kernel addressed the issue with regards to > regression in > the readahead handling code... we went ahead and installed this > kernel > for a couple of mail / web clusters (Ubuntu 6.5.1-060501-generic > #202309020842 SMP PREEMPT_DYNAMIC Sat Sep 2 08:48:34 UTC 2023 > x86_64 > x86_64 x86_64 GNU/Linux). Since then we occasionally see the > following > being logged by the kernel: > > [Sun Sep 10 07:19:00 2023] workqueue: delayed_work [ceph] hogged > CPU for > >10000us 4 times, consider switching to WQ_UNBOUND > [Sun Sep 10 08:41:24 2023] workqueue: ceph_con_workfn [libceph] > hogged > CPU for >10000us 4 times, consider switching to WQ_UNBOUND > [Sun Sep 10 11:05:55 2023] workqueue: delayed_work [ceph] hogged > CPU for > >10000us 8 times, consider switching to WQ_UNBOUND > [Sun Sep 10 12:54:38 2023] workqueue: ceph_con_workfn [libceph] > hogged > CPU for >10000us 8 times, consider switching to WQ_UNBOUND > [Sun Sep 10 19:06:37 2023] workqueue: ceph_con_workfn [libceph] > hogged > CPU for >10000us 16 times, consider switching to WQ_UNBOUND > [Mon Sep 11 10:53:33 2023] workqueue: ceph_con_workfn [libceph] > hogged > CPU for >10000us 32 times, consider switching to WQ_UNBOUND > [Tue Sep 12 10:14:03 2023] workqueue: ceph_con_workfn [libceph] > hogged > CPU for >10000us 64 times, consider switching to WQ_UNBOUND > [Tue Sep 12 11:14:33 2023] workqueue: ceph_cap_reclaim_work [ceph] > hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND > > We wonder if this is a new phenomenon, or that it's rather logged > in the > new kernel and it was not before.
Hi Stefan,
This is something that wasn't logged in older kernels. The kernel workqueue infrastructure is considering Ceph work items CPU intensive and reports that in dmesg. This is new in 6.5 kernel, the threshold can be tweaked with workqueue.cpu_intensive_thresh_us parameter.
Thanks. I was just looking into it (WQ_UNBOUND), alloc_workqueue(), etc. The patch by Tejun Heo on workqueue also mentions this:
* Concurrency-managed per-cpu work items that hog CPUs and delay the execution of other work items are now automatically detected and excluded from concurrency management. Reporting on such work items can also be enabled through a config option.
This does imply that the Ceph work items are "excluded from concurrency management", is that correct? And if so, what does that mean in practice? Might this make the process of returning / claiming caps to the MDS slower?
In 6.6-rc1 more workqueue work is done and more fine tuning seems possible. If there are any recommendations from a cephfs kernel client perspective on what a good policy would be, we would love to hear about that.
For now we will just disable the detection (cpu_intensive_thresh_us=0) and see how it goes.
Well, the positive thing to mention is that we don't see this happening anymore. However, in the same time window as last week, an event happened. This time it was the MDS that got OOM killed. At the time it was killed it was consuming 249.9 GiB (03:51:33). Just before that it consumed ~ 200 GiB. It acquired ~ 50 GiB of ram in 35 seconds (according to metrics). What MDS / client behaviour can trigger such an amount of increased memory usage?
There are several cases, for example when the pools are near full it could pile the journal logs in MDCache or due to the issues in https://github.com/ceph/ceph/pull/44180.
Did you see any warning from ceph status or any suspect logs from the MDS ?
We did for sure not hit a near full condition. We did observe a large amount of bandwidth associated with this kclient. The MDS is sending ~ 650 Mb/s of traffic to this one client alone (so more than 80% of all MDS traffic goes to one client).
However, no ceph warnings or MDS logging prior to this event. The event starts, MDS continues to work ... until it's killed ~ half a minute later.
MDS log settings:
"debug_mds": "0/0", "debug_mds_balancer": "1/5", "debug_mds_locker": "1/5", "debug_mds_log": "1/5", "debug_mds_log_expire": "1/5", "debug_mds_migrator": "1/5",
Note that we do not see any anomaly regarding CephFS (meta)data read / write traffic. So no excessive writes to a CephFS metadata pool for example.
Note, that after we downgraded the kclients again (5.12.19) we did not observe this behavior. So we might be able to reproduce, but we rather don't want to ;-).
Okay, BTW how man active MDSs you are running ?
Just one. And one standby-replay. Gr. Stefan
On 9/13/23 20:58, Ilya Dryomov wrote:
On Wed, Sep 13, 2023 at 9:20 AM Stefan Kooman <stefan@bit.nl> wrote:
Hi,
Since the 6.5 kernel addressed the issue with regards to regression in the readahead handling code... we went ahead and installed this kernel for a couple of mail / web clusters (Ubuntu 6.5.1-060501-generic #202309020842 SMP PREEMPT_DYNAMIC Sat Sep 2 08:48:34 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux). Since then we occasionally see the following being logged by the kernel:
[Sun Sep 10 07:19:00 2023] workqueue: delayed_work [ceph] hogged CPU for
10000us 4 times, consider switching to WQ_UNBOUND [Sun Sep 10 08:41:24 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND [Sun Sep 10 11:05:55 2023] workqueue: delayed_work [ceph] hogged CPU for 10000us 8 times, consider switching to WQ_UNBOUND [Sun Sep 10 12:54:38 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 8 times, consider switching to WQ_UNBOUND [Sun Sep 10 19:06:37 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 16 times, consider switching to WQ_UNBOUND [Mon Sep 11 10:53:33 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 32 times, consider switching to WQ_UNBOUND [Tue Sep 12 10:14:03 2023] workqueue: ceph_con_workfn [libceph] hogged CPU for >10000us 64 times, consider switching to WQ_UNBOUND [Tue Sep 12 11:14:33 2023] workqueue: ceph_cap_reclaim_work [ceph] hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND
We wonder if this is a new phenomenon, or that it's rather logged in the new kernel and it was not before. Hi Stefan,
This is something that wasn't logged in older kernels. The kernel workqueue infrastructure is considering Ceph work items CPU intensive and reports that in dmesg. This is new in 6.5 kernel, the threshold can be tweaked with workqueue.cpu_intensive_thresh_us parameter.
Hi Stefan, Yeah, as I remembered before I have seen something like this only once in the cephfs qa tests together with other issues, but I just thought it wasn't the root cause so I didn't spent time on it. Just went through the kernel ceph code, such as for 'ceph_cap_reclaim_work' workqueue, it will take the spin lock and if there are too many dentries and directories need to be interated it may hog the cpu for a long time. Anyway this can be improved.
However, we have hit a few OOM situations since we switched to the new kernel because of ceph_cap_reclaim_work events (OOM is because Apache threads keep piling up as it cannot access CephFS). We then also see MDS slow ops reported. This might be related to a backup job that is running on a backup server. We did not observe this behavior on 5.12.19 kernel.
We haven't touch the reclaim related code for a long time. I just suspect the backup slowed down the perf. BTW, do you have the MDS logs about the slow requests ? What are they ? Thanks - Xiubo
Adding Xiubo.
Thanks,
Ilya
On 14-09-2023 03:27, Xiubo Li wrote:
< ----- snip ------>
Hi Stefan,
Yeah, as I remembered before I have seen something like this only once in the cephfs qa tests together with other issues, but I just thought it wasn't the root cause so I didn't spent time on it.
Just went through the kernel ceph code, such as for 'ceph_cap_reclaim_work' workqueue, it will take the spin lock and if there are too many dentries and directories need to be interated it may hog the cpu for a long time. Anyway this can be improved.
These clients have between 400K - 550K CAPS, so quite a bit. It would be great if this can be improved upon. Not sure if the client is a bottleneck for releasing caps in this case. IIRC the MDS internally throttles the amount of caps it can process (per session). Anyway it would be good if the client is not the bottleneck.
However, we have hit a few OOM situations since we switched to the new kernel because of ceph_cap_reclaim_work events (OOM is because Apache threads keep piling up as it cannot access CephFS). We then also see MDS slow ops reported. This might be related to a backup job that is running on a backup server. We did not observe this behavior on 5.12.19 kernel.
We haven't touch the reclaim related code for a long time. I just suspect the backup slowed down the perf.
BTW, do you have the MDS logs about the slow requests ? What are they ?
Sure, here they are: 2023-09-10T03:55:26.057+0200 7f4136001700 0 log_channel(cluster) log [WRN] : 1 slow requests, 1 included below; oldest blocked for > 71.454548 secs 2023-09-10T03:55:26.057+0200 7f4136001700 0 log_channel(cluster) log [WRN] : slow request 32.863580 seconds old, received at 2023-09-10T03:54:53.197778+0200: client_request(client.5352998631:4256989 create #0x1000047707e/temp-write-test-64fd21ed302df3-60967340 2023-09-1 0T03:54:53.190783+0200 caller_uid=3774, caller_gid=3774{3774,}) currently failed to wrlock, waiting 2023-09-10T03:55:31.057+0200 7f4136001700 0 log_channel(cluster) log [WRN] : 2 slow requests, 1 included below; oldest blocked for > 76.454620 secs 2023-09-10T03:55:31.057+0200 7f4136001700 0 log_channel(cluster) log [WRN] : slow request 33.468639 seconds old, received at 2023-09-10T03:54:57.592791+0200: client_request(client.534532764 7:6092614 mkdir #0x1031e9171d1/2 2023-09-10T03:54:40.421282+0200 caller_uid=3747, caller_gid=3747{3747,}) currently failed to rdlock, waiting 2023-09-10T03:55:36.057+0200 7f4136001700 0 log_channel(cluster) log [WRN] : 2 slow requests, 0 included below; oldest blocked for > 81.454678 secs 2023-09-10T03:55:46.058+0200 7f4136001700 0 log_channel(cluster) log [WRN] : 6 slow requests, 5 included below; oldest blocked for > 91.454864 secs 2023-09-10T03:55:46.058+0200 7f4136001700 0 log_channel(cluster) log [WRN] : slow request 43.481559 seconds old, received at 2023-09-10T03:55:02.580113+0200: client_request(client.5352998631:4257081 create #0x100003d98e2/temp-write-test-64fd21f68d9407-10132291 2023-09-10T03:55:02.575054+0200 caller_uid=3588, caller_gid=3588{3588,}) currently failed to wrlock, waiting 2023-09-10T03:55:46.058+0200 7f4136001700 0 log_channel(cluster) log [WRN] : slow request 39.773875 seconds old, received at 2023-09-10T03:55:06.287798+0200: client_request(client.5345383113:3667543 lookup #0x100cdc56321/config.php 2023-09-10T03:55:06.284700+0200 caller_uid=3736, caller_gid=3736{3736,}) currently failed to rdlock, waiting 2023-09-10T03:55:46.058+0200 7f4136001700 0 log_channel(cluster) log [WRN] : slow request 46.176989 seconds old, received at 2023-09-10T03:54:59.884683+0200: client_request(client.5349764075:3342783 getattr As #0x102c1ca48fc 2023-09-10T03:54:59.880459+0200 caller_uid=4093, caller_gid=4093{4093,}) currently failed to rdlock, waiting 2023-09-10T03:55:46.058+0200 7f4136001700 0 log_channel(cluster) log [WRN] : slow request 35.393109 seconds old, received at 2023-09-10T03:55:10.668564+0200: client_request(client.5345383113:3667575 lookup #0x100022c947b/some-file.php 2023-09-10T03:55:10.664810+0200 caller_uid=3747, caller_gid=3747{3747,}) currently failed to rdlock, waiting 2023-09-10T03:55:46.058+0200 7f4136001700 0 log_channel(cluster) log [WRN] : slow request 91.454863 seconds old, received at 2023-09-10T03:54:14.606810+0200: client_request(client.5337202717:50413925 lookup #0x1031c61953d/some-javascript-file.js 2023-09-10T03:54:14.603107+0200 caller_uid=0, caller_gid=0{0,}) currently failed to rdlock, waiting 2023-09-10T03:56:51.055+0200 7f4136001700 0 log_channel(cluster) log [WRN] : 2 slow requests, 2 included below; oldest blocked for > 156.455763 secs 2023-09-10T03:56:51.055+0200 7f4136001700 0 log_channel(cluster) log [WRN] : slow request 34.015403 seconds old, received at 2023-09-10T03:56:17.047169+0200: client_request(client.5349764075:3343607 create #0x100aa849bdb/temp-write-test-64fd22410b6b45-35598524 2023-09-10T03:56:17.046403+0200 caller_uid=3983, caller_gid=3983{3983,}) currently failed to wrlock, waiting 2023-09-10T03:56:51.055+0200 7f4136001700 0 log_channel(cluster) log [WRN] : slow request 55.242778 seconds old, received at 2023-09-10T03:55:55.819794+0200: client_request(client.5345383113:3667692 getattr AsLsXsFs #0x100022c9480 2023-09-10T03:55:55.813948+0200 caller_uid=3747, caller_gid=3747{3747,}) currently dispatched 2023-09-10T03:56:56.055+0200 7f4136001700 0 log_channel(cluster) log [WRN] : 2 slow requests, 1 included below; oldest blocked for > 161.455822 secs 2023-09-10T03:56:56.055+0200 7f4136001700 0 log_channel(cluster) log [WRN] : slow request 60.242837 seconds old, received at 2023-09-10T03:55:55.819794+0200: client_request(client.5345383113:3667692 getattr AsLsXsFs #0x100022c9480 2023-09-10T03:55:55.813948+0200 caller_uid=3747, caller_gid=3747{3747,}) currently dispatched 2023-09-10T03:56:56.135+0200 7f4136001700 0 log_channel(cluster) log [WRN] : client.5345327647 isn't responding to mclientcaps(revoke), ino 0x1031e0642cf pending pAsLsXsxFsxcrwb issued pAsxLsXsxFsxcrwb, sent 60.318560 seconds ago 2023-09-10T03:56:56.135+0200 7f4136001700 0 log_channel(cluster) log [WRN] : client.5345327647 isn't responding to mclientcaps(revoke), ino 0x1027e766cd6 pending pAsLsXsxFsxcrwb issued pAsxLsXsxFsxcrwb, sent 60.318543 seconds ago 2023-09-10T03:56:56.135+0200 7f4136001700 0 log_channel(cluster) log [WRN] : client.5345327647 isn't responding to mclientcaps(revoke), ino 0x100022c9480 pending pAsLsXs issued pAsLsXsFs, sent 60.317304 seconds ago 2023-09-10T03:56:56.135+0200 7f4136001700 0 log_channel(cluster) log [WRN] : client.5345327647 isn't responding to mclientcaps(revoke), ino 0x1027e1fc2e5 pending pAsLsXs issued pAsLsXsFsc, sent 60.311698 seconds ago 2023-09-10T03:57:01.056+0200 7f4136001700 0 log_channel(cluster) log [WRN] : 2 slow requests, 0 included below; oldest blocked for > 166.455888 secs 2023-09-10T03:57:01.112+0200 7f4136001700 0 log_channel(cluster) log [WRN] : evicting unresponsive client the-ubuntu-jammy-webserver-with-6.5-kernel (5345327647), after 85.5223 seconds 2023-09-10T03:57:01.112+0200 7f4136001700 0 log_channel(cluster) log [INF] : Evicting (and blocklisting) client session 5345327647 (v1:[some:ip:v6:addr::ess]:0/2080458178) 2023-09-10T03:57:01.116+0200 7f4136001700 0 log_channel(cluster) log [WRN] : client.5345327647 isn't responding to mclientcaps(revoke), ino 0x1031c610d5a pending pAsLsXsxFsxcrwb issued pAsxLsXsxFsxcrwb, sent 62.595705 seconds ago 2023-09-10T06:32:02.438+0200 7f4136001700 0 log_channel(cluster) log [WRN] : client.3470094190 isn't responding to mclientcaps(revoke), ino 0x1031e1bb30f pending pAsLsXsFr issued pAsLsXsFscr, sent 62.186458 seconds ago The "temp-write-test-string" write requests are apparently from Wordpress sites that perform "let's test if I can write" requests. Thanks, Gr. Stefan
On 9/14/23 14:55, Stefan Kooman wrote:
On 14-09-2023 03:27, Xiubo Li wrote:
< ----- snip ------>
Hi Stefan,
Yeah, as I remembered before I have seen something like this only once in the cephfs qa tests together with other issues, but I just thought it wasn't the root cause so I didn't spent time on it.
Just went through the kernel ceph code, such as for 'ceph_cap_reclaim_work' workqueue, it will take the spin lock and if there are too many dentries and directories need to be interated it may hog the cpu for a long time. Anyway this can be improved.
These clients have between 400K - 550K CAPS, so quite a bit. It would be great if this can be improved upon. Not sure if the client is a bottleneck for releasing caps in this case. IIRC the MDS internally throttles the amount of caps it can process (per session). Anyway it would be good if the client is not the bottleneck.
There is one option in MDS could descrease it and have a try: mds_max_caps_per_client: 1M as default. So 400K ~ 550K hasn't reach the throttle yet. But you can try it and let's see could this help.
However, we have hit a few OOM situations since we switched to the new kernel because of ceph_cap_reclaim_work events (OOM is because Apache threads keep piling up as it cannot access CephFS). We then also see MDS slow ops reported. This might be related to a backup job that is running on a backup server. We did not observe this behavior on 5.12.19 kernel.
We haven't touch the reclaim related code for a long time. I just suspect the backup slowed down the perf.
BTW, do you have the MDS logs about the slow requests ? What are they ?
Sure, here they are:
2023-09-10T03:55:26.057+0200 7f4136001700 0 log_channel(cluster) log [WRN] : 1 slow requests, 1 included below; oldest blocked for > 71.454548 secs 2023-09-10T03:55:26.057+0200 7f4136001700 0 log_channel(cluster) log [WRN] : slow request 32.863580 seconds old, received at 2023-09-10T03:54:53.197778+0200: client_request(client.5352998631:4256989 create #0x1000047707e/temp-write-test-64fd21ed302df3-60967340 2023-09-1 0T03:54:53.190783+0200 caller_uid=3774, caller_gid=3774{3774,}) currently failed to wrlock, waiting 2023-09-10T03:55:31.057+0200 7f4136001700 0 log_channel(cluster) log [WRN] : 2 slow requests, 1 included below; oldest blocked for > 76.454620 secs 2023-09-10T03:55:31.057+0200 7f4136001700 0 log_channel(cluster) log [WRN] : slow request 33.468639 seconds old, received at 2023-09-10T03:54:57.592791+0200: client_request(client.534532764 7:6092614 mkdir #0x1031e9171d1/2 2023-09-10T03:54:40.421282+0200 caller_uid=3747, caller_gid=3747{3747,}) currently failed to rdlock, waiting 2023-09-10T03:55:36.057+0200 7f4136001700 0 log_channel(cluster) log [WRN] : 2 slow requests, 0 included below; oldest blocked for > 81.454678 secs 2023-09-10T03:55:46.058+0200 7f4136001700 0 log_channel(cluster) log [WRN] : 6 slow requests, 5 included below; oldest blocked for > 91.454864 secs 2023-09-10T03:55:46.058+0200 7f4136001700 0 log_channel(cluster) log [WRN] : slow request 43.481559 seconds old, received at 2023-09-10T03:55:02.580113+0200: client_request(client.5352998631:4257081 create #0x100003d98e2/temp-write-test-64fd21f68d9407-10132291 2023-09-10T03:55:02.575054+0200 caller_uid=3588, caller_gid=3588{3588,}) currently failed to wrlock, waiting 2023-09-10T03:55:46.058+0200 7f4136001700 0 log_channel(cluster) log [WRN] : slow request 39.773875 seconds old, received at 2023-09-10T03:55:06.287798+0200: client_request(client.5345383113:3667543 lookup #0x100cdc56321/config.php 2023-09-10T03:55:06.284700+0200 caller_uid=3736, caller_gid=3736{3736,}) currently failed to rdlock, waiting 2023-09-10T03:55:46.058+0200 7f4136001700 0 log_channel(cluster) log [WRN] : slow request 46.176989 seconds old, received at 2023-09-10T03:54:59.884683+0200: client_request(client.5349764075:3342783 getattr As #0x102c1ca48fc 2023-09-10T03:54:59.880459+0200 caller_uid=4093, caller_gid=4093{4093,}) currently failed to rdlock, waiting 2023-09-10T03:55:46.058+0200 7f4136001700 0 log_channel(cluster) log [WRN] : slow request 35.393109 seconds old, received at 2023-09-10T03:55:10.668564+0200: client_request(client.5345383113:3667575 lookup #0x100022c947b/some-file.php 2023-09-10T03:55:10.664810+0200 caller_uid=3747, caller_gid=3747{3747,}) currently failed to rdlock, waiting 2023-09-10T03:55:46.058+0200 7f4136001700 0 log_channel(cluster) log [WRN] : slow request 91.454863 seconds old, received at 2023-09-10T03:54:14.606810+0200: client_request(client.5337202717:50413925 lookup #0x1031c61953d/some-javascript-file.js 2023-09-10T03:54:14.603107+0200 caller_uid=0, caller_gid=0{0,}) currently failed to rdlock, waiting 2023-09-10T03:56:51.055+0200 7f4136001700 0 log_channel(cluster) log [WRN] : 2 slow requests, 2 included below; oldest blocked for > 156.455763 secs 2023-09-10T03:56:51.055+0200 7f4136001700 0 log_channel(cluster) log [WRN] : slow request 34.015403 seconds old, received at 2023-09-10T03:56:17.047169+0200: client_request(client.5349764075:3343607 create #0x100aa849bdb/temp-write-test-64fd22410b6b45-35598524 2023-09-10T03:56:17.046403+0200 caller_uid=3983, caller_gid=3983{3983,}) currently failed to wrlock, waiting 2023-09-10T03:56:51.055+0200 7f4136001700 0 log_channel(cluster) log [WRN] : slow request 55.242778 seconds old, received at 2023-09-10T03:55:55.819794+0200: client_request(client.5345383113:3667692 getattr AsLsXsFs #0x100022c9480 2023-09-10T03:55:55.813948+0200 caller_uid=3747, caller_gid=3747{3747,}) currently dispatched 2023-09-10T03:56:56.055+0200 7f4136001700 0 log_channel(cluster) log [WRN] : 2 slow requests, 1 included below; oldest blocked for > 161.455822 secs 2023-09-10T03:56:56.055+0200 7f4136001700 0 log_channel(cluster) log [WRN] : slow request 60.242837 seconds old, received at 2023-09-10T03:55:55.819794+0200: client_request(client.5345383113:3667692 getattr AsLsXsFs #0x100022c9480 2023-09-10T03:55:55.813948+0200 caller_uid=3747, caller_gid=3747{3747,}) currently dispatched 2023-09-10T03:56:56.135+0200 7f4136001700 0 log_channel(cluster) log [WRN] : client.5345327647 isn't responding to mclientcaps(revoke), ino 0x1031e0642cf pending pAsLsXsxFsxcrwb issued pAsxLsXsxFsxcrwb, sent 60.318560 seconds ago 2023-09-10T03:56:56.135+0200 7f4136001700 0 log_channel(cluster) log [WRN] : client.5345327647 isn't responding to mclientcaps(revoke), ino 0x1027e766cd6 pending pAsLsXsxFsxcrwb issued pAsxLsXsxFsxcrwb, sent 60.318543 seconds ago 2023-09-10T03:56:56.135+0200 7f4136001700 0 log_channel(cluster) log [WRN] : client.5345327647 isn't responding to mclientcaps(revoke), ino 0x100022c9480 pending pAsLsXs issued pAsLsXsFs, sent 60.317304 seconds ago 2023-09-10T03:56:56.135+0200 7f4136001700 0 log_channel(cluster) log [WRN] : client.5345327647 isn't responding to mclientcaps(revoke), ino 0x1027e1fc2e5 pending pAsLsXs issued pAsLsXsFsc, sent 60.311698 seconds ago 2023-09-10T03:57:01.056+0200 7f4136001700 0 log_channel(cluster) log [WRN] : 2 slow requests, 0 included below; oldest blocked for > 166.455888 secs 2023-09-10T03:57:01.112+0200 7f4136001700 0 log_channel(cluster) log [WRN] : evicting unresponsive client the-ubuntu-jammy-webserver-with-6.5-kernel (5345327647), after 85.5223 seconds 2023-09-10T03:57:01.112+0200 7f4136001700 0 log_channel(cluster) log [INF] : Evicting (and blocklisting) client session 5345327647 (v1:[some:ip:v6:addr::ess]:0/2080458178) 2023-09-10T03:57:01.116+0200 7f4136001700 0 log_channel(cluster) log [WRN] : client.5345327647 isn't responding to mclientcaps(revoke), ino 0x1031c610d5a pending pAsLsXsxFsxcrwb issued pAsxLsXsxFsxcrwb, sent 62.595705 seconds ago 2023-09-10T06:32:02.438+0200 7f4136001700 0 log_channel(cluster) log [WRN] : client.3470094190 isn't responding to mclientcaps(revoke), ino 0x1031e1bb30f pending pAsLsXsFr issued pAsLsXsFscr, sent 62.186458 seconds ago
Okay, there were caps revocation stuck, which could cause the create/lookup/getattr requests stuck and then reported as slow requests. This should be a known issue as I am now working on https://tracker.ceph.com/issues/50223. Currently I found one case, which is the unlinking, could cause it, and these warning should disappeared finally after the kclient could release the caps later, more detail please see my comments on this tracker. This tracker not finishes yet and there could be other cases that could cause it, and I will continue working on it this week and next. Thanks - Xiubo
The "temp-write-test-string" write requests are apparently from Wordpress sites that perform "let's test if I can write" requests.
Thanks - Xiubo
Thanks,
Gr. Stefan
On 14-09-2023 10:03, Xiubo Li wrote: <----- snip ----->
Okay, there were caps revocation stuck, which could cause the create/lookup/getattr requests stuck and then reported as slow requests.
This should be a known issue as I am now working on https://tracker.ceph.com/issues/50223. Currently I found one case, which is the unlinking, could cause it, and these warning should disappeared finally after the kclient could release the caps later, more detail please see my comments on this tracker.
This tracker not finishes yet and there could be other cases that could cause it, and I will continue working on it this week and next.
Ah, well, in that case, you're in for a treat ;-). We have a mail cluster (dovecot on CephFS) that is spamming us continuously (during work hours) with this. We could send you (a lot of) logs if you want to have more examples of production setups. This behavior has not changed between all the kernels we have tried (currently 6.5). Shall I upload them to tracker 50223? Would be great to get this fixed. Let us know if you need us to test anything. On a side note: separate metrics for the kclient for "# acquired caps" and # released caps" might be useful as well. As a kclient can both be very busy releasing caps, but also acquiring new ones. Just a total # caps does not give this insight. Thanks, Gr. Stefan
participants (3)
-
Ilya Dryomov
-
Stefan Kooman
-
Xiubo Li