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