librbd: improve debug output for object map state machines

Signed-off-by: Jason Dillaman <dillaman@redhat.com>

diff --git a/src/librbd/ObjectMap.cc b/src/librbd/ObjectMap.cc
index 6c9ebc73170881e65cc1601f96549a7f9d45963b..469f4e74289a0283f8dff9c093e15e993a5a7a20 100644 (file)
--- a/src/librbd/ObjectMap.cc
+++ b/src/librbd/ObjectMap.cc
@@ -86,7 +86,8 @@ int ObjectMap::lock()
   std::string oid(object_map_name(m_image_ctx.id, CEPH_NOSNAP));
   while (true) {
     int r;
-    ldout(cct, 10) << &m_image_ctx << " locking object map" << dendl;
+    ldout(cct, 10) << &m_image_ctx << " locking object map: "
+                   << oid << dendl;
     r = rados::cls::lock::lock(&m_image_ctx.md_ctx, oid,
                               RBD_LOCK_NAME, LOCK_EXCLUSIVE, "", "", "",
                               utime_t(), 0);
@@ -140,9 +141,9 @@ int ObjectMap::unlock()
     return 0;
   }
 
-  ldout(m_image_ctx.cct, 10) << &m_image_ctx << " unlocking object map"
-                            << dendl;
   std::string oid = object_map_name(m_image_ctx.id, CEPH_NOSNAP);
+  ldout(m_image_ctx.cct, 10) << &m_image_ctx << " unlocking object map: "
+                            << oid << dendl;
   int r = rados::cls::lock::unlock(&m_image_ctx.md_ctx, oid,
                                    RBD_LOCK_NAME, "");
   if (r < 0 && r != -ENOENT) {
@@ -187,12 +188,13 @@ void ObjectMap::refresh(uint64_t snap_id)
   m_enabled = true;
 
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 10) << &m_image_ctx << " refreshing object map" << dendl;
+  std::string oid(object_map_name(m_image_ctx.id, snap_id));
+  ldout(cct, 10) << &m_image_ctx << " refreshing object map: "
+                 << oid << dendl;
 
   uint64_t num_objs = Striper::get_num_objects(
     m_image_ctx.layout, m_image_ctx.get_image_size(snap_id));
 
-  std::string oid(object_map_name(m_image_ctx.id, snap_id));
   int r = cls_client::object_map_load(&m_image_ctx.md_ctx, oid,
                                       &m_object_map);
   if (r == -EINVAL) {
@@ -223,7 +225,7 @@ void ObjectMap::refresh(uint64_t snap_id)
     return;
   }
 
-  ldout(cct, 20) << "refreshed object map: " << m_object_map.size()
+  ldout(cct, 20) << "refreshed object map: num_objs=" << m_object_map.size()
                  << dendl;
 
   if (m_object_map.size() < num_objs) {

diff --git a/src/librbd/object_map/ResizeRequest.cc b/src/librbd/object_map/ResizeRequest.cc
index 8bdb64c4c6ccf069370a24e00fb365954f2da208..afbde42f98b6d8008f4fab510c61a7aebaa8d2ac 100644 (file)
--- a/src/librbd/object_map/ResizeRequest.cc
+++ b/src/librbd/object_map/ResizeRequest.cc
@@ -30,8 +30,9 @@ void ResizeRequest::send() {
   RWLock::WLocker l(m_image_ctx.object_map_lock);
   m_num_objs = Striper::get_num_objects(m_image_ctx.layout, m_new_size);
 
+  std::string oid(ObjectMap::object_map_name(m_image_ctx.id, m_snap_id));
   ldout(cct, 5) << &m_image_ctx << " resizing on-disk object map: "
-               << m_num_objs << dendl;
+                << "oid=" << oid << ", num_objs=" << m_num_objs << dendl;
 
   librados::ObjectWriteOperation op;
   if (m_snap_id == CEPH_NOSNAP) {
@@ -40,7 +41,6 @@ void ResizeRequest::send() {
   cls_client::object_map_resize(&op, m_num_objs, m_default_object_state);
 
   librados::AioCompletion *rados_completion = create_callback_completion();
-  std::string oid(ObjectMap::object_map_name(m_image_ctx.id, m_snap_id));
   int r = m_image_ctx.md_ctx.aio_operate(oid, rados_completion, &op);
   assert(r == 0);
   rados_completion->release();

diff --git a/src/librbd/object_map/SnapshotCreateRequest.cc b/src/librbd/object_map/SnapshotCreateRequest.cc
index 9bf4a7913c65edffee157adc5dbf8cd1f42e093a..abca0e21258ac12277063bddcd18ecf3771a4440 100644 (file)
--- a/src/librbd/object_map/SnapshotCreateRequest.cc
+++ b/src/librbd/object_map/SnapshotCreateRequest.cc
@@ -80,14 +80,14 @@ void SnapshotCreateRequest::send_read_map() {
   assert(m_image_ctx.get_snap_info(m_snap_id) != NULL);
 
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 5) << this << " " << __func__ << dendl;
+  std::string oid(ObjectMap::object_map_name(m_image_ctx.id, CEPH_NOSNAP));
+  ldout(cct, 5) << this << " " << __func__ << ": oid=" << oid << dendl;
   m_state = STATE_READ_MAP;
 
   // IO is blocked due to the snapshot creation -- consistent to read from disk
   librados::ObjectReadOperation op;
   op.read(0, 0, NULL, NULL);
 
-  std::string oid(ObjectMap::object_map_name(m_image_ctx.id, CEPH_NOSNAP));
   librados::AioCompletion *rados_completion = create_callback_completion();
   int r = m_image_ctx.md_ctx.aio_operate(oid, rados_completion, &op,
                                          &m_read_bl);
@@ -96,9 +96,8 @@ void SnapshotCreateRequest::send_read_map() {
 }
 
 void SnapshotCreateRequest::send_write_map() {
-  std::string snap_oid(ObjectMap::object_map_name(m_image_ctx.id, m_snap_id));
-
   CephContext *cct = m_image_ctx.cct;
+  std::string snap_oid(ObjectMap::object_map_name(m_image_ctx.id, m_snap_id));
   ldout(cct, 5) << this << " " << __func__ << ": snap_oid=" << snap_oid
                 << dendl;
   m_state = STATE_WRITE_MAP;
@@ -119,14 +118,14 @@ bool SnapshotCreateRequest::send_add_snapshot() {
   }
 
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 5) << this << " " << __func__ << dendl;
+  std::string oid(ObjectMap::object_map_name(m_image_ctx.id, CEPH_NOSNAP));
+  ldout(cct, 5) << this << " " << __func__ << ": oid=" << oid << dendl;
   m_state = STATE_ADD_SNAPSHOT;
 
   librados::ObjectWriteOperation op;
   rados::cls::lock::assert_locked(&op, RBD_LOCK_NAME, LOCK_EXCLUSIVE, "", "");
   cls_client::object_map_snap_add(&op);
 
-  std::string oid(ObjectMap::object_map_name(m_image_ctx.id, CEPH_NOSNAP));
   librados::AioCompletion *rados_completion = create_callback_completion();
   int r = m_image_ctx.md_ctx.aio_operate(oid, rados_completion, &op);
   assert(r == 0);

diff --git a/src/librbd/object_map/SnapshotRemoveRequest.cc b/src/librbd/object_map/SnapshotRemoveRequest.cc
index 679735f0f34ed882c3f755b07477a15d2fd755d8..b3b145e1a8682dd1266adbc4b8beb0eff003d798 100644 (file)
--- a/src/librbd/object_map/SnapshotRemoveRequest.cc
+++ b/src/librbd/object_map/SnapshotRemoveRequest.cc
@@ -103,17 +103,19 @@ bool SnapshotRemoveRequest::should_complete(int r) {
 
 void SnapshotRemoveRequest::send_load_map() {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 5) << this << " " << __func__ << dendl;
+  std::string snap_oid(ObjectMap::object_map_name(m_image_ctx.id, m_snap_id));
+  ldout(cct, 5) << this << " " << __func__ << ": snap_oid=" << snap_oid
+                << dendl;
   m_state = STATE_LOAD_MAP;
 
-  std::string snap_oid(ObjectMap::object_map_name(m_image_ctx.id, m_snap_id));
   cls_client::object_map_load(&m_image_ctx.md_ctx, snap_oid,
                               &m_snap_object_map, create_callback_context());
 }
 
 void SnapshotRemoveRequest::send_remove_snapshot() {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 5) << this << " " << __func__ << dendl;
+  std::string oid(ObjectMap::object_map_name(m_image_ctx.id, m_next_snap_id));
+  ldout(cct, 5) << this << " " << __func__ << ": oid=" << oid << dendl;
   m_state = STATE_REMOVE_SNAPSHOT;
 
   librados::ObjectWriteOperation op;
@@ -122,7 +124,6 @@ void SnapshotRemoveRequest::send_remove_snapshot() {
   }
   cls_client::object_map_snap_remove(&op, m_snap_object_map);
 
-  std::string oid(ObjectMap::object_map_name(m_image_ctx.id, m_next_snap_id));
   librados::AioCompletion *rados_completion = create_callback_completion();
   int r = m_image_ctx.md_ctx.aio_operate(oid, rados_completion, &op);
   assert(r == 0);
@@ -145,13 +146,13 @@ void SnapshotRemoveRequest::send_invalidate_next_map() {
 
 void SnapshotRemoveRequest::send_remove_map() {
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 5) << this << " " << __func__ << dendl;
+  std::string oid(ObjectMap::object_map_name(m_image_ctx.id, m_snap_id));
+  ldout(cct, 5) << this << " " << __func__ << ": oid=" << oid << dendl;
   m_state = STATE_REMOVE_MAP;
 
   librados::ObjectWriteOperation op;
   op.remove();
 
-  std::string oid(ObjectMap::object_map_name(m_image_ctx.id, m_snap_id));
   librados::AioCompletion *rados_completion = create_callback_completion();
   int r = m_image_ctx.md_ctx.aio_operate(oid, rados_completion, &op);
   assert(r == 0);

diff --git a/src/librbd/object_map/SnapshotRollbackRequest.cc b/src/librbd/object_map/SnapshotRollbackRequest.cc
index 8f5625587eb5e8c6f52b0f34a4eb106218003f66..20cf5e376a45591edc15611b53506d4f86202232 100644 (file)
--- a/src/librbd/object_map/SnapshotRollbackRequest.cc
+++ b/src/librbd/object_map/SnapshotRollbackRequest.cc
@@ -98,14 +98,15 @@ void SnapshotRollbackRequest::send_write_map() {
   RWLock::RLocker owner_locker(m_image_ctx.owner_lock);
 
   CephContext *cct = m_image_ctx.cct;
-  ldout(cct, 5) << this << " " << __func__ << dendl;
+  std::string snap_oid(ObjectMap::object_map_name(m_image_ctx.id, CEPH_NOSNAP));
+  ldout(cct, 5) << this << " " << __func__ << ": snap_oid=" << snap_oid
+                << dendl;
   m_state = STATE_WRITE_MAP;
 
   librados::ObjectWriteOperation op;
   rados::cls::lock::assert_locked(&op, RBD_LOCK_NAME, LOCK_EXCLUSIVE, "", "");
   op.write_full(m_read_bl);
 
-  std::string snap_oid(ObjectMap::object_map_name(m_image_ctx.id, CEPH_NOSNAP));
   librados::AioCompletion *rados_completion = create_callback_completion();
   int r = m_image_ctx.md_ctx.aio_operate(snap_oid, rados_completion, &op);
   assert(r == 0);

diff --git a/src/librbd/object_map/UpdateRequest.cc b/src/librbd/object_map/UpdateRequest.cc
index eef548828f82feed74b71c88b2b3bc28f7053337..fc651ab145ade998ad93734ec6c87f212290b6d2 100644 (file)
--- a/src/librbd/object_map/UpdateRequest.cc
+++ b/src/librbd/object_map/UpdateRequest.cc
@@ -25,10 +25,9 @@ void UpdateRequest::send() {
 
   // safe to update in-memory state first without handling rollback since any
   // failures will invalidate the object map
+  std::string oid(ObjectMap::object_map_name(m_image_ctx.id, m_snap_id));
   ldout(cct, 20) << &m_image_ctx << " updating object map"
-                 << (m_snap_id != CEPH_NOSNAP ?
-                       " snap " + stringify(m_snap_id) : std::string())
-                 << ": ["
+                 << ": oid=" << oid << ", ["
                 << m_start_object_no << "," << m_end_object_no << ") = "
                 << (m_current_state ?
                       stringify(static_cast<uint32_t>(*m_current_state)) : "")
@@ -57,7 +56,6 @@ void UpdateRequest::send() {
                                m_new_state, m_current_state);
 
   librados::AioCompletion *rados_completion = create_callback_completion();
-  std::string oid(ObjectMap::object_map_name(m_image_ctx.id, m_snap_id));
   int r = m_image_ctx.md_ctx.aio_operate(oid, rados_completion, &op);
   assert(r == 0);
   rados_completion->release();