rgw/multisite: check for late lease renewals by yuvalif · Pull Request #47728 · ceph/ceph

yuvalif · 2022-08-22T13:40:51Z

also make lease renewal logs more uniform

Signed-off-by: Yuval Lifshitz ylifshit@redhat.com

Checklist

Tracker (select at least one)
- References tracker ticket
- Very recent bug; references commit where it was introduced
- New feature (ticket optional)
- Doc update (no ticket needed)
- Code cleanup (no ticket needed)
Component impact
- Affects Dashboard, opened tracker ticket
- Affects Orchestrator, opened tracker ticket
- No impact that needs to be tracked
Documentation (select at least one)
- Updates relevant documentation
- No doc update is appropriate
Tests (select at least one)
- Includes unit test(s)
- Includes integration test(s)
- Includes bug reproducer
- No tests

Show available Jenkins commands

jenkins retest this please
jenkins test classic perf
jenkins test crimson perf
jenkins test signed
jenkins test make check
jenkins test make check arm64
jenkins test submodules
jenkins test dashboard
jenkins test dashboard cephadm
jenkins test api
jenkins test docs
jenkins render docs
jenkins test ceph-volume all
jenkins test ceph-volume tox
jenkins test windows

yuvalif · 2022-08-22T13:57:12Z

on heavy load setup, the following messages are showing (when lease time is set to 30sec instead of 2 minutes):

2022-08-22T13:03:09.656+0000 7fafb2ffd700  1 cr:s=0x7fb03b48e320:op=0x7fb03b48da30:20RGWContinuousLeaseCR: WARNING: did not renew lock zg1-1.rgw.log:datalog.sync-status.shard.18c8ee82-09f6-4dd2-91fa-51eb9ea32fb4.2:sync_lock: within 90% of
 interval. 45.216434479s > 27.000000000s

mattbenjamin · 2022-08-22T14:06:09Z

@yuvalif great work on this

cbodley

the is_locked() change is great 👍

cbodley · 2022-08-22T17:38:39Z

src/rgw/rgw_cr_rados.h

  int operate(const DoutPrefixProvider *dpp) override;

  bool is_locked() const {
+    if (ceph::real_time::clock::now() - last_renew_try_time > ts_interval) {


i think the ceph::coarse_mono_clock is a better fit for the clock. mono because we only care about intervals, not absolute clock times. and coarse because these intervals are on the order of minutes

cbodley · 2022-08-22T17:43:14Z

src/rgw/rgw_cr_rados.cc

        ldout(store->ctx(), 20) << *this << ": couldn't lock " << obj << ":" << lock_name << ": retcode=" << retcode << dendl;
        return set_state(RGWCoroutine_Error, retcode);
      }
+      ldout(store->ctx(), 20) << *this << ": successfully lock " << obj << ":" << lock_name << dendl;


successfully locked

cbodley · 2022-08-22T18:29:40Z

src/rgw/rgw_cr_rados.h

 #include "common/Throttle.h"

 #include <atomic>
+#include <chrono>


include common/ceph_time.h instead, since we're relying on its clocks and typedefs

cbodley · 2022-08-24T23:22:29Z

src/rgw/rgw_cr_rados.cc

+        // renewal should happen between 50%-90% of interval
+        ldout(store->ctx(), 1) << *this << ": WARNING: did not renew lock " << obj << ":" << lock_name << ": within 90\% of interval. " << 
+          (current_time - last_renew_try_time) << " > " << interval_tolerance << dendl;


i'm not crazy about warning at 90% unless we can offer specific advice to prevent the user from hitting this 100% latency barrier

i'm more concerned that this 100% barrier isn't an actual error. your change to is_locked() helps, but we can't guarantee that is_locked() will be called promptly. another rgw could still acquire and drop the lock in the meantime, and we'd log a warning here but sync would continue on like nothing happened

our lock requests are sent with set_may_renew(true) (see https://github.com/ceph/ceph/blob/f5c21acf/src/rgw/rgw_cr_rados.cc#L217) which means the request can either acquire or renew a lock. if RGWContinuousLeaseCR were to send its renewals with set_must_renew(true) instead, the OSD would reject renewal requests if the previous lock had expired

RGWContinuousLeaseCR would see that as an EBUSY error on renewal. can we put a good log message there instead, with some explanation like "high latency on the pool {obj.pool}"?

i'm not crazy about warning at 90% unless we can offer specific advice to prevent the user from hitting this 100% latency barrier

i'm more concerned that this 100% barrier isn't an actual error. your change to is_locked() helps, but we can't guarantee that is_locked() will be called promptly. another rgw could still acquire and drop the lock in the meantime, and we'd log a warning here but sync would continue on like nothing happened

i can remove this warning. it does not say that lock was not successful, just that it was late.
my idea was to correlate that message with sync issues

our lock requests are sent with set_may_renew(true) (see https://github.com/ceph/ceph/blob/f5c21acf/src/rgw/rgw_cr_rados.cc#L217) which means the request can either acquire or renew a lock. if RGWContinuousLeaseCR were to send its renewals with set_must_renew(true) instead, the OSD would reject renewal requests if the previous lock had expired

RGWContinuousLeaseCR would see that as an EBUSY error on renewal. can we put a good log message there instead, with some explanation like "high latency on the pool {obj.pool}"?

but the same continuous lease CR is used for the initial acquisition of the lock and its renewal.
maybe we can add an API to that class that allows switching between the modes?

but the same continuous lease CR is used for the initial acquisition of the lock and its renewal.
maybe we can add an API to that class that allows switching between the modes?

exactly, right. i opened #47809 (but haven't compiled or tested it) that extends RGWSimpleRadosLockCR to support this. so RGWContinuousLeaseCR could have a rados::cls::lock::Lock member variable, and use set_may_renew() for the initial lock request and set_must_renew() afterwards

i can remove this warning. it does not say that lock was not successful, just that it was late. my idea was to correlate that message with sync issues

yeah, i think the proposed error message meets that same goal. even if is_locked() sees that the lock probably expired, it will use drain_all() to wait for RGWContinuousLeaseCR to receive this lock response and print its error message before returning the -ECANCELED error up the call stack

i'm happy to take up the rest of this work in #47809, we can merge this warning as is

also make lease renewal logs more uniform Signed-off-by: Yuval Lifshitz <ylifshit@redhat.com>

yuvalif · 2022-08-26T11:41:43Z

jenkins test make check

yuvalif · 2022-08-26T11:42:03Z

jenkins test api

yuvalif · 2022-08-27T10:51:50Z

teuthology results: http://pulpito.front.sepia.ceph.com/yuvalif-2022-08-26_11:23:55-rgw-wip-yuval-cont-lease-distro-default-smithi/
with expected failures:

Cannot create secret
multisite failures with AssertionError: failed meta checkpoint for zone=test-zone2
tempest failure
Failed to fetch package version

yuvalif · 2022-08-27T10:58:13Z

jenkins test make check

yuvalif · 2022-08-27T10:58:21Z

jenkins test api

yuvalif added the rgw label Aug 22, 2022

yuvalif requested review from adamemerson, cbodley and ofriedma August 22, 2022 13:40

cbodley reviewed Aug 24, 2022

View reviewed changes

rgw/multisite: check for late lease renewals

c4960aa

also make lease renewal logs more uniform Signed-off-by: Yuval Lifshitz <ylifshit@redhat.com>

yuvalif force-pushed the wip-yuval-cont-lease branch from 7b4a366 to c4960aa Compare August 25, 2022 16:17

cbodley approved these changes Aug 25, 2022

View reviewed changes

cbodley added the needs-qa label Aug 25, 2022

yuvalif removed the needs-qa label Aug 27, 2022

yuvalif merged commit 30078cd into ceph:main Aug 28, 2022

cbodley mentioned this pull request Oct 17, 2022

rgw: Reduce data sync parallelism in response to RADOS lock latency #48451

Closed

14 tasks

Conversation

yuvalif commented Aug 22, 2022

Checklist

Uh oh!

yuvalif commented Aug 22, 2022

Uh oh!

mattbenjamin commented Aug 22, 2022

Uh oh!

cbodley left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

yuvalif commented Aug 26, 2022

Uh oh!

yuvalif commented Aug 26, 2022

Uh oh!

yuvalif commented Aug 27, 2022

Uh oh!

yuvalif commented Aug 27, 2022

Uh oh!

yuvalif commented Aug 27, 2022

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants