From 3484ffd5626f9d066d2556a9c3f03ae402a7cd14 Mon Sep 17 00:00:00 2001 From: "J. Eric Ivancich" Date: Fri, 1 Feb 2019 17:57:31 -0500 Subject: [PATCH] rgw: when exclusive lock fails due existing lock, log add'l info This is being added to better understand lock-contention issues in running systems. Here are two sample log output lines: 2019-02-04 14:22:31.228 7f06abb59700 20 /somedir/ceph/src/cls/lock/cls_lock.cc:221: could not exclusive-lock object, already locked by [{name:client.4139, addr:v1:127.0.0.1:0/2034495868, exp:2019-02-04 14:24:31.0.22272s}] 2019-02-04 14:22:37.219 7f06abb59700 20 /somedir/ceph/src/cls/lock/cls_lock.cc:221: could not exclusive-lock object, already locked by [{name:client.4147, addr:v1:127.0.0.1:0/141966515, exp:never}] Fixes: http://tracker.ceph.com/issues/38171 Signed-off-by: J. Eric Ivancich (cherry picked from commit af5c1ed2c0d4687417ce14d342335fa97718f46c) --- src/cls/lock/cls_lock.cc | 23 ++++++++++++++++++++++- src/test/cls_lock/test_cls_lock.cc | 3 +++ 2 files changed, 25 insertions(+), 1 deletion(-) diff --git a/src/cls/lock/cls_lock.cc b/src/cls/lock/cls_lock.cc index 1dab0dd72ac..3f4b84e395a 100644 --- a/src/cls/lock/cls_lock.cc +++ b/src/cls/lock/cls_lock.cc @@ -10,6 +10,7 @@ #include #include +#include #include "include/types.h" #include "include/utime.h" @@ -197,7 +198,27 @@ static int lock_obj(cls_method_context_t hctx, if (!lockers.empty()) { if (exclusive) { - CLS_LOG(20, "could not exclusive-lock object, already locked"); + std::stringstream locker_list; + bool first = true; + // there could be multiple lockers if they are all shared + for (const auto& l : lockers) { + if (first) { + first = false; + } else { + locker_list << ", "; + } + locker_list << "{name:" << l.first.locker << + ", addr:" << l.second.addr << + ", exp:"; + const auto& exp = l.second.expiration; + if (exp.is_zero()) { + locker_list << "never}"; + } else { + locker_list << exp.to_real_time() << "}"; + } + } + CLS_LOG(20, "could not exclusive-lock object, already locked by [%s]", + locker_list.str().c_str()); return -EBUSY; } diff --git a/src/test/cls_lock/test_cls_lock.cc b/src/test/cls_lock/test_cls_lock.cc index 37d10a19cbc..8c67d6aa589 100644 --- a/src/test/cls_lock/test_cls_lock.cc +++ b/src/test/cls_lock/test_cls_lock.cc @@ -85,6 +85,9 @@ TEST(ClsLock, TestMultiLocking) { ASSERT_EQ(0, ioctx.write(oid, bl, bl.length(), 0)); Lock l(lock_name); + // we set the duration, so the log output contains a locker with a + // non-zero expiration time + l.set_duration(utime_t(120, 0)); /* test lock object */ -- 2.47.3