From d934aa294223a798384e51ee5d9902c9b973b774 Mon Sep 17 00:00:00 2001 From: Jason Dillaman Date: Tue, 24 Jan 2017 09:48:43 -0500 Subject: [PATCH] librbd: improve debug logging for lock / watch state machines Signed-off-by: Jason Dillaman --- .../exclusive_lock/PostAcquireRequest.cc | 29 ++++++++-------- .../exclusive_lock/PreAcquireRequest.cc | 11 ++++--- .../exclusive_lock/PreReleaseRequest.cc | 33 ++++++++++--------- src/librbd/managed_lock/AcquireRequest.cc | 2 +- src/librbd/managed_lock/ReleaseRequest.cc | 7 ++-- src/librbd/watcher/RewatchRequest.cc | 2 +- 6 files changed, 44 insertions(+), 40 deletions(-) diff --git a/src/librbd/exclusive_lock/PostAcquireRequest.cc b/src/librbd/exclusive_lock/PostAcquireRequest.cc index 3e262e79291..fb6e4d4d320 100644 --- a/src/librbd/exclusive_lock/PostAcquireRequest.cc +++ b/src/librbd/exclusive_lock/PostAcquireRequest.cc @@ -20,7 +20,8 @@ #define dout_subsys ceph_subsys_rbd #undef dout_prefix -#define dout_prefix *_dout << "librbd::exclusive_lock::PostAcquireRequest: " +#define dout_prefix *_dout << "librbd::exclusive_lock::PostAcquireRequest: " \ + << this << " " << __func__ << ": " namespace librbd { namespace exclusive_lock { @@ -68,7 +69,7 @@ void PostAcquireRequest::send_refresh() { } CephContext *cct = m_image_ctx.cct; - ldout(cct, 10) << __func__ << dendl; + ldout(cct, 10) << dendl; using klass = PostAcquireRequest; Context *ctx = create_async_context_callback( @@ -84,11 +85,11 @@ void PostAcquireRequest::send_refresh() { template void PostAcquireRequest::handle_refresh(int r) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 10) << __func__ << ": r=" << r << dendl; + ldout(cct, 10) << "r=" << r << dendl; if (r == -ERESTART) { // next issued IO or op will (re)-refresh the image and shut down lock - ldout(cct, 5) << ": exclusive lock dynamically disabled" << dendl; + ldout(cct, 5) << "exclusive lock dynamically disabled" << dendl; r = 0; } else if (r < 0) { lderr(cct) << "failed to refresh image: " << cpp_strerror(r) << dendl; @@ -121,7 +122,7 @@ void PostAcquireRequest::send_open_journal() { } CephContext *cct = m_image_ctx.cct; - ldout(cct, 10) << __func__ << dendl; + ldout(cct, 10) << dendl; using klass = PostAcquireRequest; Context *ctx = create_context_callback( @@ -137,7 +138,7 @@ void PostAcquireRequest::send_open_journal() { template void PostAcquireRequest::handle_open_journal(int r) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 10) << __func__ << ": r=" << r << dendl; + ldout(cct, 10) << "r=" << r << dendl; save_result(r); if (r < 0) { @@ -152,7 +153,7 @@ void PostAcquireRequest::handle_open_journal(int r) { template void PostAcquireRequest::send_allocate_journal_tag() { CephContext *cct = m_image_ctx.cct; - ldout(cct, 10) << __func__ << dendl; + ldout(cct, 10) << dendl; RWLock::RLocker snap_locker(m_image_ctx.snap_lock); using klass = PostAcquireRequest; @@ -164,7 +165,7 @@ void PostAcquireRequest::send_allocate_journal_tag() { template void PostAcquireRequest::handle_allocate_journal_tag(int r) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 10) << __func__ << ": r=" << r << dendl; + ldout(cct, 10) << "r=" << r << dendl; save_result(r); if (r < 0) { @@ -180,7 +181,7 @@ void PostAcquireRequest::handle_allocate_journal_tag(int r) { template void PostAcquireRequest::send_close_journal() { CephContext *cct = m_image_ctx.cct; - ldout(cct, 10) << __func__ << dendl; + ldout(cct, 10) << dendl; using klass = PostAcquireRequest; Context *ctx = create_context_callback( @@ -191,7 +192,7 @@ void PostAcquireRequest::send_close_journal() { template void PostAcquireRequest::handle_close_journal(int r) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 10) << __func__ << ": r=" << r << dendl; + ldout(cct, 10) << "r=" << r << dendl; save_result(r); if (r < 0) { @@ -209,7 +210,7 @@ void PostAcquireRequest::send_open_object_map() { } CephContext *cct = m_image_ctx.cct; - ldout(cct, 10) << __func__ << dendl; + ldout(cct, 10) << dendl; using klass = PostAcquireRequest; Context *ctx = create_context_callback( @@ -222,7 +223,7 @@ void PostAcquireRequest::send_open_object_map() { template void PostAcquireRequest::handle_open_object_map(int r) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 10) << __func__ << ": r=" << r << dendl; + ldout(cct, 10) << "r=" << r << dendl; if (r < 0) { lderr(cct) << "failed to open object map: " << cpp_strerror(r) << dendl; @@ -244,7 +245,7 @@ void PostAcquireRequest::send_close_object_map() { } CephContext *cct = m_image_ctx.cct; - ldout(cct, 10) << __func__ << dendl; + ldout(cct, 10) << dendl; using klass = PostAcquireRequest; Context *ctx = create_context_callback< @@ -255,7 +256,7 @@ void PostAcquireRequest::send_close_object_map() { template void PostAcquireRequest::handle_close_object_map(int r) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 10) << __func__ << ": r=" << r << dendl; + ldout(cct, 10) << "r=" << r << dendl; // object map should never result in an error assert(r == 0); diff --git a/src/librbd/exclusive_lock/PreAcquireRequest.cc b/src/librbd/exclusive_lock/PreAcquireRequest.cc index 25ef4809b2d..7711e9e2ef3 100644 --- a/src/librbd/exclusive_lock/PreAcquireRequest.cc +++ b/src/librbd/exclusive_lock/PreAcquireRequest.cc @@ -11,7 +11,8 @@ #define dout_subsys ceph_subsys_rbd #undef dout_prefix -#define dout_prefix *_dout << "librbd::exclusive_lock::PreAcquireRequest: " +#define dout_prefix *_dout << "librbd::exclusive_lock::PreAcquireRequest: " \ + << this << " " << __func__ << ": " namespace librbd { namespace exclusive_lock { @@ -47,7 +48,7 @@ void PreAcquireRequest::send() { template void PreAcquireRequest::send_prepare_lock() { CephContext *cct = m_image_ctx.cct; - ldout(cct, 10) << __func__ << dendl; + ldout(cct, 10) << dendl; // acquire the lock if the image is not busy performing other actions Context *ctx = create_context_callback< @@ -58,7 +59,7 @@ void PreAcquireRequest::send_prepare_lock() { template void PreAcquireRequest::handle_prepare_lock(int r) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 10) << __func__ << ": r=" << r << dendl; + ldout(cct, 10) << "r=" << r << dendl; send_flush_notifies(); } @@ -66,7 +67,7 @@ void PreAcquireRequest::handle_prepare_lock(int r) { template void PreAcquireRequest::send_flush_notifies() { CephContext *cct = m_image_ctx.cct; - ldout(cct, 10) << __func__ << dendl; + ldout(cct, 10) << dendl; using klass = PreAcquireRequest; Context *ctx = create_context_callback( @@ -77,7 +78,7 @@ void PreAcquireRequest::send_flush_notifies() { template void PreAcquireRequest::handle_flush_notifies(int r) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 10) << __func__ << dendl; + ldout(cct, 10) << dendl; assert(r == 0); finish(); diff --git a/src/librbd/exclusive_lock/PreReleaseRequest.cc b/src/librbd/exclusive_lock/PreReleaseRequest.cc index 44f98217201..6d3382dd699 100644 --- a/src/librbd/exclusive_lock/PreReleaseRequest.cc +++ b/src/librbd/exclusive_lock/PreReleaseRequest.cc @@ -14,7 +14,8 @@ #define dout_subsys ceph_subsys_rbd #undef dout_prefix -#define dout_prefix *_dout << "librbd::exclusive_lock::PreReleaseRequest: " +#define dout_prefix *_dout << "librbd::exclusive_lock::PreReleaseRequest: " \ + << this << " " << __func__ << ": " namespace librbd { namespace exclusive_lock { @@ -58,7 +59,7 @@ void PreReleaseRequest::send_prepare_lock() { } CephContext *cct = m_image_ctx.cct; - ldout(cct, 10) << __func__ << dendl; + ldout(cct, 10) << dendl; // release the lock if the image is not busy performing other actions Context *ctx = create_context_callback< @@ -69,7 +70,7 @@ void PreReleaseRequest::send_prepare_lock() { template void PreReleaseRequest::handle_prepare_lock(int r) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 10) << __func__ << ": r=" << r << dendl; + ldout(cct, 10) << "r=" << r << dendl; send_cancel_op_requests(); } @@ -77,7 +78,7 @@ void PreReleaseRequest::handle_prepare_lock(int r) { template void PreReleaseRequest::send_cancel_op_requests() { CephContext *cct = m_image_ctx.cct; - ldout(cct, 10) << __func__ << dendl; + ldout(cct, 10) << dendl; using klass = PreReleaseRequest; Context *ctx = create_context_callback< @@ -88,7 +89,7 @@ void PreReleaseRequest::send_cancel_op_requests() { template void PreReleaseRequest::handle_cancel_op_requests(int r) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 10) << __func__ << ": r=" << r << dendl; + ldout(cct, 10) << "r=" << r << dendl; assert(r == 0); @@ -98,7 +99,7 @@ void PreReleaseRequest::handle_cancel_op_requests(int r) { template void PreReleaseRequest::send_block_writes() { CephContext *cct = m_image_ctx.cct; - ldout(cct, 10) << __func__ << dendl; + ldout(cct, 10) << dendl; using klass = PreReleaseRequest; Context *ctx = create_context_callback< @@ -116,7 +117,7 @@ void PreReleaseRequest::send_block_writes() { template void PreReleaseRequest::handle_block_writes(int r) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 10) << __func__ << ": r=" << r << dendl; + ldout(cct, 10) << "r=" << r << dendl; if (r == -EBLACKLISTED) { // allow clean shut down if blacklisted @@ -141,7 +142,7 @@ void PreReleaseRequest::send_invalidate_cache(bool purge_on_error) { } CephContext *cct = m_image_ctx.cct; - ldout(cct, 10) << __func__ << ": purge_on_error=" << purge_on_error << dendl; + ldout(cct, 10) << "purge_on_error=" << purge_on_error << dendl; RWLock::RLocker owner_lock(m_image_ctx.owner_lock); Context *ctx = create_async_context_callback( @@ -154,7 +155,7 @@ void PreReleaseRequest::send_invalidate_cache(bool purge_on_error) { template void PreReleaseRequest::handle_invalidate_cache(int r) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 10) << __func__ << ": r=" << r << dendl; + ldout(cct, 10) << "r=" << r << dendl; if (r == -EBLACKLISTED) { lderr(cct) << "failed to invalidate cache because client is blacklisted" @@ -179,7 +180,7 @@ void PreReleaseRequest::handle_invalidate_cache(int r) { template void PreReleaseRequest::send_flush_notifies() { CephContext *cct = m_image_ctx.cct; - ldout(cct, 10) << __func__ << dendl; + ldout(cct, 10) << dendl; using klass = PreReleaseRequest; Context *ctx = @@ -190,7 +191,7 @@ void PreReleaseRequest::send_flush_notifies() { template void PreReleaseRequest::handle_flush_notifies(int r) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 10) << __func__ << dendl; + ldout(cct, 10) << dendl; assert(r == 0); send_close_journal(); @@ -209,7 +210,7 @@ void PreReleaseRequest::send_close_journal() { } CephContext *cct = m_image_ctx.cct; - ldout(cct, 10) << __func__ << dendl; + ldout(cct, 10) << dendl; using klass = PreReleaseRequest; Context *ctx = create_context_callback( @@ -220,7 +221,7 @@ void PreReleaseRequest::send_close_journal() { template void PreReleaseRequest::handle_close_journal(int r) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 10) << __func__ << ": r=" << r << dendl; + ldout(cct, 10) << "r=" << r << dendl; if (r < 0) { // error implies some journal events were not flushed -- continue @@ -245,7 +246,7 @@ void PreReleaseRequest::send_close_object_map() { } CephContext *cct = m_image_ctx.cct; - ldout(cct, 10) << __func__ << dendl; + ldout(cct, 10) << dendl; using klass = PreReleaseRequest; Context *ctx = create_context_callback< @@ -256,7 +257,7 @@ void PreReleaseRequest::send_close_object_map() { template void PreReleaseRequest::handle_close_object_map(int r) { CephContext *cct = m_image_ctx.cct; - ldout(cct, 10) << __func__ << ": r=" << r << dendl; + ldout(cct, 10) << "r=" << r << dendl; // object map shouldn't return errors assert(r == 0); @@ -268,7 +269,7 @@ void PreReleaseRequest::handle_close_object_map(int r) { template void PreReleaseRequest::send_unlock() { CephContext *cct = m_image_ctx.cct; - ldout(cct, 10) << __func__ << dendl; + ldout(cct, 10) << dendl; finish(); } diff --git a/src/librbd/managed_lock/AcquireRequest.cc b/src/librbd/managed_lock/AcquireRequest.cc index b89f658275f..e5d9186ca38 100644 --- a/src/librbd/managed_lock/AcquireRequest.cc +++ b/src/librbd/managed_lock/AcquireRequest.cc @@ -104,7 +104,7 @@ void AcquireRequest::handle_get_locker(int r) { template void AcquireRequest::send_lock() { - ldout(m_cct, 10) << dendl; + ldout(m_cct, 10) << "cookie=" << m_cookie << dendl; librados::ObjectWriteOperation op; rados::cls::lock::lock(&op, RBD_LOCK_NAME, diff --git a/src/librbd/managed_lock/ReleaseRequest.cc b/src/librbd/managed_lock/ReleaseRequest.cc index 84446a77041..bf2f5ae91af 100644 --- a/src/librbd/managed_lock/ReleaseRequest.cc +++ b/src/librbd/managed_lock/ReleaseRequest.cc @@ -13,7 +13,8 @@ #define dout_subsys ceph_subsys_rbd #undef dout_prefix -#define dout_prefix *_dout << "librbd::managed_lock::ReleaseRequest: " +#define dout_prefix *_dout << "librbd::managed_lock::ReleaseRequest: " \ + << this << " " << __func__ << ": " namespace librbd { namespace managed_lock { @@ -54,7 +55,7 @@ void ReleaseRequest::send() { template void ReleaseRequest::send_unlock() { CephContext *cct = reinterpret_cast(m_ioctx.cct()); - ldout(cct, 10) << __func__ << dendl; + ldout(cct, 10) << "cookie=" << m_cookie << dendl; librados::ObjectWriteOperation op; rados::cls::lock::unlock(&op, RBD_LOCK_NAME, m_cookie); @@ -70,7 +71,7 @@ void ReleaseRequest::send_unlock() { template void ReleaseRequest::handle_unlock(int r) { CephContext *cct = reinterpret_cast(m_ioctx.cct()); - ldout(cct, 10) << __func__ << ": r=" << r << dendl; + ldout(cct, 10) << "r=" << r << dendl; if (r < 0 && r != -ENOENT) { lderr(cct) << "failed to unlock: " << cpp_strerror(r) << dendl; diff --git a/src/librbd/watcher/RewatchRequest.cc b/src/librbd/watcher/RewatchRequest.cc index 688106960a9..406e22ec9f3 100644 --- a/src/librbd/watcher/RewatchRequest.cc +++ b/src/librbd/watcher/RewatchRequest.cc @@ -9,7 +9,7 @@ #define dout_subsys ceph_subsys_rbd #undef dout_prefix #define dout_prefix *_dout << "librbd::watcher::RewatchRequest: " \ - << this << ": " << __func__ + << this << " " << __func__ << " " namespace librbd {