radosgw daemons with "stuck ops"
Hello, We are experiencing slowdowns on one of our radosgw clusters. We restart the radosgw daemons every 2 hours and things start getting slow after an hour and a half. The avg get/put latencies go from 20ms/400ms to 1s/5s+ according to the metrics. When I stop traffic to one of the radosgw daemon by setting it to DRAIN in HAProxy and HAProxy reports 0 sessions to the daemon, I still see the objecter_requests still going up and down 15 min later. linger_ops seems to stay at a constant 10 the whole time.
[root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 46 [root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 211 [root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 427 [root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 0 [root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 26 [root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 190
The requests say they are "call rgw.bucket_list in=234b" and mostly reference ".dir.5e9bc383-f7bd-4fd1-b607-1e563bfe0011.886814949.1.N" where N is 1-149 (the shard count for the bucket).
{ "tid": 2583119, "pg": "8.579482b0", "osd": 208, "object_id": ".dir.5e9bc383-f7bd-4fd1-b607-1e563bfe0011.886814949.1.124", "object_locator": "@8", "target_object_id": ".dir.5e9bc383-f7bd-4fd1-b607-1e563bfe0011.886814949.1.124", "target_object_locator": "@8", "paused": 0, "used_replica": 0, "precalc_pgid": 0, "last_sent": "1796975.496664s", "age": 0.350012616, "attempts": 1, "snapid": "head", "snap_context": "0=[]", "mtime": "1970-01-01T00:00:00.000000+0000", "osd_ops": [ "call rgw.bucket_list in=234b" ] },
I don't think it should be other rgw processes because we have this daemon's ceph.conf set to disable the other threads.
rgw enable gc threads = false rgw enable lc threads = false rgw dynamic resharding = false
When I restart the service while it is still in a DRAINED state in HAProxy, checking the objecter_requests yields 0 even a few minutes after it has been up.
[root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 0 [root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 0 [root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 0 [root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 0 [root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 0 [root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 0
Any thoughts on why these ops appear to be stuck/recurring until restarting the daemon? I think this is related to our performance issues but I don't know what the fix is. The rgws are 18.2.4 running as containers in Podman on Debian 11. Our other clusters do not exhibit this behavior. Thanks! Reid
Hey Reid, This sounds similar to what we saw in https://tracker.ceph.com/issues/62256, in case that helps with your investigation. Josh On Mon, Jan 27, 2025 at 8:07 AM Reid Guyett <reid.guyett@gmail.com> wrote:
Hello,
We are experiencing slowdowns on one of our radosgw clusters. We restart the radosgw daemons every 2 hours and things start getting slow after an hour and a half. The avg get/put latencies go from 20ms/400ms to 1s/5s+ according to the metrics. When I stop traffic to one of the radosgw daemon by setting it to DRAIN in HAProxy and HAProxy reports 0 sessions to the daemon, I still see the objecter_requests still going up and down 15 min later. linger_ops seems to stay at a constant 10 the whole time.
[root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 46 [root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 211 [root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 427 [root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 0 [root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 26 [root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 190
The requests say they are "call rgw.bucket_list in=234b" and mostly reference ".dir.5e9bc383-f7bd-4fd1-b607-1e563bfe0011.886814949.1.N" where N is 1-149 (the shard count for the bucket).
{ "tid": 2583119, "pg": "8.579482b0", "osd": 208, "object_id": ".dir.5e9bc383-f7bd-4fd1-b607-1e563bfe0011.886814949.1.124", "object_locator": "@8", "target_object_id": ".dir.5e9bc383-f7bd-4fd1-b607-1e563bfe0011.886814949.1.124", "target_object_locator": "@8", "paused": 0, "used_replica": 0, "precalc_pgid": 0, "last_sent": "1796975.496664s", "age": 0.350012616, "attempts": 1, "snapid": "head", "snap_context": "0=[]", "mtime": "1970-01-01T00:00:00.000000+0000", "osd_ops": [ "call rgw.bucket_list in=234b" ] },
I don't think it should be other rgw processes because we have this daemon's ceph.conf set to disable the other threads.
rgw enable gc threads = false rgw enable lc threads = false rgw dynamic resharding = false
When I restart the service while it is still in a DRAINED state in HAProxy, checking the objecter_requests yields 0 even a few minutes after it has been up.
[root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 0 [root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 0 [root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 0 [root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 0 [root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 0 [root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 0
Any thoughts on why these ops appear to be stuck/recurring until restarting the daemon? I think this is related to our performance issues but I don't know what the fix is.
The rgws are 18.2.4 running as containers in Podman on Debian 11. Our other clusters do not exhibit this behavior.
Thanks!
Reid _______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
Hi, Looking at that tracker, I see that you were seeing some errors. I don't really see any errors that stick out to me. When I turn the logs up to 20, I see the following types of logs over and over:
... 2025-01-27T19:36:25.989+0000 7f657bb17640 20 req 3636357367581543624 4066.843017578s s3:list_bucket list_objects_ordered: skipping past namespaced objects, including "_multipart_Data/<OBJECTNAME>2~a9lvduIp8rv3_btbiGEfOgAC-EvF85n.36" 2025-01-27T19:36:25.989+0000 7f657bb17640 20 req 3636357367581543624 4066.843017578s s3:list_bucket list_objects_ordered: considering entry _multipart_Data/<OBJECTNAME>2~a9lvduIp8rv3_btbiGEfOgAC-EvF85n.39 2025-01-27T19:36:25.989+0000 7f657bb17640 20 req 3636357367581543624 4066.843017578s s3:list_bucket list_objects_ordered: skipping past namespaced objects, including "_multipart_Data/<OBJECTNAME>2~a9lvduIp8rv3_btbiGEfOgAC-EvF85n.39" 2025-01-27T19:36:25.989+0000 7f657bb17640 20 req 3636357367581543624 4066.843017578s s3:list_bucket list_objects_ordered: considering entry _multipart_Data/<OBJECTNAME>2~a9lvduIp8rv3_btbiGEfOgAC-EvF85n.5 2025-01-27T19:36:25.989+0000 7f657bb17640 20 req 3636357367581543624 4066.843017578s s3:list_bucket list_objects_ordered: skipping past namespaced objects, including "_multipart_Data/<OBJECTNAME>2~a9lvduIp8rv3_btbiGEfOgAC-EvF85n.5" 2025-01-27T19:36:25.989+0000 7f657bb17640 10 req 3636357367581543624 4066.843017578s s3:list_bucket list_objects_ordered: end of outer loop, truncated=1, count=0, attempt=4829 2025-01-27T19:36:25.989+0000 7f657bb17640 20 req 3636357367581543624 4066.843017578s s3:list_bucket list_objects_ordered: starting attempt 4830 2025-01-27T19:36:25.989+0000 7f657bb17640 10 req 3636357367581543624 4066.843017578s s3:list_bucket cls_bucket_list_ordered: request from each of 149 shard(s) for 1001 entries to get 1001 total entries
... 2025-01-27T19:40:53.704+0000 7f64a716e640 20 req 8762048560071224804 5187.776367188s s3:list_bucket list_objects_ordered: skipping past namespaced objects, including "_multipart_Data/<OBJECTNAME2>2~XSOCVgidHCMfywQ8-Z3kestTOwfqJ--.6" 2025-01-27T19:40:53.704+0000 7f64a716e640 20 req 8762048560071224804 5187.776367188s s3:list_bucket list_objects_ordered: considering entry _multipart_Data/<OBJECTNAME2>2~XSOCVgidHCMfywQ8-Z3kestTOwfqJ--.7 2025-01-27T19:40:53.704+0000 7f64a716e640 20 req 8762048560071224804 5187.776367188s s3:list_bucket list_objects_ordered: skipping past namespaced objects, including "_multipart_Data/<OBJECTNAME2>2~XSOCVgidHCMfywQ8-Z3kestTOwfqJ--.7" 2025-01-27T19:40:53.704+0000 7f64a716e640 10 req 8762048560071224804 5187.776367188s s3:list_bucket list_objects_ordered: end of outer loop, truncated=1, count=0, attempt=9134 2025-01-27T19:40:53.704+0000 7f64a716e640 20 req 8762048560071224804 5187.776367188s s3:list_bucket list_objects_ordered: starting attempt 9135 2025-01-27T19:40:53.704+0000 7f64a716e640 10 req 8762048560071224804 5187.776367188s s3:list_bucket cls_bucket_list_ordered: request from each of 149 shard(s) for 1001 entries to get 1001 total entries
... 2025-01-27T19:40:53.093+0000 7f657bb17640 20 req 3636357367581543624 4333.946777344s s3:list_bucket cls_bucket_list_ordered: currently processing _multipart_Data/<OBJECTNAME3>.2~r5PVFujVZq_hkwZea-hrYgE13OI1MXP.19 from shard 8 2025-01-27T19:40:53.093+0000 7f657bb17640 10 req 3636357367581543624 4333.946777344s s3:list_bucket cls_bucket_list_ordered: got _multipart_Data/<OBJECTNAME3>.2~r5PVFujVZq_hkwZea-hrYgE13OI1MXP.19 2025-01-27T19:40:53.093+0000 7f657bb17640 20 req 3636357367581543624 4333.946777344s s3:list_bucket cls_bucket_list_ordered: currently processing _multipart_Data/<OBJECTNAME3>.2~r5PVFujVZq_hkwZea-hrYgE13OI1MXP.2 from shard 8 2025-01-27T19:40:53.093+0000 7f657bb17640 10 req 3636357367581543624 4333.946777344s s3:list_bucket cls_bucket_list_ordered: got _multipart_Data/<OBJECTNAME3>.2~r5PVFujVZq_hkwZea-hrYgE13OI1MXP.2 2025-01-27T19:40:53.093+0000 7f657bb17640 10 req 3636357367581543624 4333.946777344s s3:list_bucket cls_bucket_list_ordered: stopped accumulating results at count=1001, dirent="", because its shard is truncated and exhausted 2025-01-27T19:40:53.093+0000 7f657bb17640 20 req 3636357367581543624 4333.946777344s s3:list_bucket cls_bucket_list_ordered: returning, count=1001, is_truncated=1
The logs make it seem like it is attempting to list a bucket thousands of times and 5187s is around 86 minutes. I only checked on one radosgw out of 6 but I suspect all are doing this in the background. I am assuming that this isn't normal. Anybody shed some light on what the logs mean? Also is there a way to link the req 3636357367581543624 to logs at lower levels? I thought that I would just need to convert to hex but it doesn't line up with the started/completed requests. Thanks, Reid On Mon, Jan 27, 2025 at 11:36 AM Joshua Baergen <jbaergen@digitalocean.com> wrote:
Hey Reid,
This sounds similar to what we saw in https://tracker.ceph.com/issues/62256, in case that helps with your investigation.
Josh
On Mon, Jan 27, 2025 at 8:07 AM Reid Guyett <reid.guyett@gmail.com> wrote:
Hello,
We are experiencing slowdowns on one of our radosgw clusters. We restart the radosgw daemons every 2 hours and things start getting slow after an hour and a half. The avg get/put latencies go from 20ms/400ms to 1s/5s+ according to the metrics. When I stop traffic to one of the radosgw
daemon
by setting it to DRAIN in HAProxy and HAProxy reports 0 sessions to the daemon, I still see the objecter_requests still going up and down 15 min later. linger_ops seems to stay at a constant 10 the whole time.
[root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 46 [root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 211 [root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 427 [root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 0 [root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 26 [root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 190
The requests say they are "call rgw.bucket_list in=234b" and mostly reference ".dir.5e9bc383-f7bd-4fd1-b607-1e563bfe0011.886814949.1.N" where N is 1-149 (the shard count for the bucket).
{ "tid": 2583119, "pg": "8.579482b0", "osd": 208, "object_id": ".dir.5e9bc383-f7bd-4fd1-b607-1e563bfe0011.886814949.1.124", "object_locator": "@8", "target_object_id": ".dir.5e9bc383-f7bd-4fd1-b607-1e563bfe0011.886814949.1.124", "target_object_locator": "@8", "paused": 0, "used_replica": 0, "precalc_pgid": 0, "last_sent": "1796975.496664s", "age": 0.350012616, "attempts": 1, "snapid": "head", "snap_context": "0=[]", "mtime": "1970-01-01T00:00:00.000000+0000", "osd_ops": [ "call rgw.bucket_list in=234b" ] },
I don't think it should be other rgw processes because we have this daemon's ceph.conf set to disable the other threads.
rgw enable gc threads = false rgw enable lc threads = false rgw dynamic resharding = false
When I restart the service while it is still in a DRAINED state in HAProxy, checking the objecter_requests yields 0 even a few minutes after it has been up.
[root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 0 [root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 0 [root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 0 [root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 0 [root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 0 [root@rgw1 ~]# ceph daemon client.rgw.rgw1 objecter_requests | jq '.ops | length' 0
Any thoughts on why these ops appear to be stuck/recurring until restarting the daemon? I think this is related to our performance issues but I don't know what the fix is.
The rgws are 18.2.4 running as containers in Podman on Debian 11. Our other clusters do not exhibit this behavior.
Thanks!
Reid _______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
participants (2)
-
Joshua Baergen
-
Reid Guyett