rgw: bucket index transaction instrumentation clean-ups

Add a series of clean-ups to the instrumentation code. Keep this as a
separate commit so it will be easier to reconcile other code streams.

Signed-off-by: J. Eric Ivancich <ivancich@redhat.com>

diff --git a/src/cls/rgw/cls_rgw.cc b/src/cls/rgw/cls_rgw.cc
index b103b8a1a3519e2f373d74d559e2a289e229c99a..f83432fc6399a0892a08c8ec60f16e85fb8ff84e 100644 (file)
--- a/src/cls/rgw/cls_rgw.cc
+++ b/src/cls/rgw/cls_rgw.cc
@@ -856,6 +856,14 @@ static int read_key_entry(cls_method_context_t hctx, const cls_rgw_obj_key& key,
                          string *idx, rgw_bucket_dir_entry *entry,
                           bool special_delete_marker_name = false);
 
+static std::string modify_op_str(RGWModifyOp op) {
+  return std::string(to_string(op));
+}
+
+static std::string modify_op_str(uint8_t op) {
+  return modify_op_str((RGWModifyOp) op);
+}
+
 int rgw_bucket_prepare_op(cls_method_context_t hctx, bufferlist *in, bufferlist *out)
 {
   const ConfigProxy& conf = cls_get_config(hctx);
@@ -865,7 +873,7 @@ int rgw_bucket_prepare_op(cls_method_context_t hctx, bufferlist *in, bufferlist
   const bool bitx_inst =
     conf->rgw_bucket_index_transaction_instrumentation;
 
-  CLS_LOG_BITX(bitx_inst, 1, "ENTERING %s for object oid=%s key=%s",
+  CLS_LOG_BITX(bitx_inst, 10, "ENTERING %s for object oid=%s key=%s",
               __func__, oi.soid.oid.name.c_str(), oi.soid.get_key().c_str());
 
   // decode request
@@ -885,8 +893,8 @@ int rgw_bucket_prepare_op(cls_method_context_t hctx, bufferlist *in, bufferlist
   }
 
   CLS_LOG_BITX(bitx_inst, 1,
-              "INFO: %s: request: op=%d name=%s instance=%s tag=%s", __func__,
-              op.op, op.key.name.c_str(), op.key.instance.c_str(), op.tag.c_str());
+              "INFO: %s: request: op=%s name=%s tag=%s", __func__,
+              modify_op_str(op.op).c_str(), op.key.to_string().c_str(), op.tag.c_str());
 
   // get on-disk state
   std::string idx;
@@ -895,8 +903,8 @@ int rgw_bucket_prepare_op(cls_method_context_t hctx, bufferlist *in, bufferlist
   int rc = read_key_entry(hctx, op.key, &idx, &entry);
   if (rc < 0 && rc != -ENOENT) {
     CLS_LOG_BITX(bitx_inst, 1,
-                "ERROR: %s could not read key entry, key=%s(%s), rc=%d",
-                __func__, op.key.name.c_str(), op.key.instance.c_str(), rc);
+                "ERROR: %s could not read key entry, key=%s, rc=%d",
+                __func__, op.key.to_string().c_str(), rc);
     return rc;
   }
 
@@ -917,8 +925,9 @@ int rgw_bucket_prepare_op(cls_method_context_t hctx, bufferlist *in, bufferlist
   info.state = CLS_RGW_STATE_PENDING_MODIFY;
   info.op = op.op;
   CLS_LOG_BITX(bitx_inst, 20,
-              "INFO: %s: inserting tag %s op %c into pending map for entry %s",
-              __func__, op.tag, info.op, entry.key.to_string().c_str());
+              "INFO: %s: inserting tag %s op %s into pending map for entry %s",
+              __func__, op.tag.c_str(), modify_op_str(info.op).c_str(),
+              entry.key.to_string().c_str());
   entry.pending_map.insert(pair<string, rgw_bucket_pending_info>(op.tag, info));
 
   // write out new key to disk
@@ -926,19 +935,18 @@ int rgw_bucket_prepare_op(cls_method_context_t hctx, bufferlist *in, bufferlist
   encode(entry, info_bl);
   CLS_LOG_BITX(bitx_inst, 20,
               "INFO: %s: setting map entry at key=%s",
-              __func__, idx.c_str());
+              __func__, escape_str(idx).c_str());
   rc = cls_cxx_map_set_val(hctx, idx, &info_bl);
   if (rc < 0) {
     CLS_LOG_BITX(bitx_inst, 1,
                 "ERROR: %s could not set value for key, key=%s, rc=%d",
-                __func__, idx.c_str(), rc);
+                __func__, escape_str(idx).c_str(), rc);
     return rc;
   }
 
-
-  CLS_LOG_BITX(bitx_inst, 1, "EXITING %s, returning 0", __func__);
+  CLS_LOG_BITX(bitx_inst, 10, "EXITING %s, returning 0", __func__);
   return 0;
-}
+} // rgw_bucket_prepare_op
 
 static void unaccount_entry(rgw_bucket_dir_header& header,
                            rgw_bucket_dir_entry& entry)
@@ -1079,7 +1087,7 @@ int rgw_bucket_complete_op(cls_method_context_t hctx, bufferlist *in, bufferlist
   const bool bitx_inst =
     conf->rgw_bucket_index_transaction_instrumentation;
 
-  CLS_LOG_BITX(bitx_inst, 1, "ENTERING %s for object oid=%s key=%s",
+  CLS_LOG_BITX(bitx_inst, 10, "ENTERING %s for object oid=%s key=%s",
               __func__, oi.soid.oid.name.c_str(), oi.soid.get_key().c_str());
 
   // decode request
@@ -1093,16 +1101,17 @@ int rgw_bucket_complete_op(cls_method_context_t hctx, bufferlist *in, bufferlist
   }
 
   CLS_LOG_BITX(bitx_inst, 1,
-              "INFO: %s: request: op=%d name=%s instance=%s ver=%lu:%llu tag=%s",
+              "INFO: %s: request: op=%s name=%s ver=%lu:%llu tag=%s",
               __func__,
-              op.op, op.key.name.c_str(), op.key.instance.c_str(),
+              modify_op_str(op.op).c_str(), op.key.to_string().c_str(),
               (unsigned long)op.ver.pool, (unsigned long long)op.ver.epoch,
               op.tag.c_str());
 
   rgw_bucket_dir_header header;
   int rc = read_bucket_header(hctx, &header);
   if (rc < 0) {
-    CLS_LOG_BITX(bitx_inst, 1, "ERROR: %s: failed to read header", __func__);
+    CLS_LOG_BITX(bitx_inst, 1, "ERROR: %s: failed to read header, rc=%d",
+                __func__, rc);
     return -EINVAL;
   }
 
@@ -1119,8 +1128,8 @@ int rgw_bucket_complete_op(cls_method_context_t hctx, bufferlist *in, bufferlist
     ondisk = false;
   } else if (rc < 0) {
     CLS_LOG_BITX(bitx_inst, 1,
-                "ERROR: %s: read key entry failed, key=%s(%s), rc=%d",
-                __func__, op.key.name.c_str(), op.key.instance.c_str(), rc);
+                "ERROR: %s: read key entry failed, key=%s, rc=%d",
+                __func__, op.key.to_string().c_str(), rc);
     return rc;
   }
 
@@ -1133,7 +1142,7 @@ int rgw_bucket_complete_op(cls_method_context_t hctx, bufferlist *in, bufferlist
     auto pinter = entry.pending_map.find(op.tag);
     if (pinter == entry.pending_map.end()) {
       CLS_LOG_BITX(bitx_inst, 1,
-                  "ERROR: %s: couldn't find tag for pending operation with tag:\"%s\"",
+                  "ERROR: %s: couldn't find tag for pending operation with tag %s",
                   __func__, op.tag.c_str());
       return -EINVAL;
     }
@@ -1148,7 +1157,7 @@ int rgw_bucket_complete_op(cls_method_context_t hctx, bufferlist *in, bufferlist
   } else if (op.ver.pool == entry.ver.pool &&
              op.ver.epoch && op.ver.epoch <= entry.ver.epoch) {
     CLS_LOG_BITX(bitx_inst, 20,
-                "%s: skipping request, old epoch", __func__);
+                "INFO: %s: skipping request, old epoch", __func__);
     op.op = CLS_RGW_OP_CANCEL;
   }
 
@@ -1164,14 +1173,14 @@ int rgw_bucket_complete_op(cls_method_context_t hctx, bufferlist *in, bufferlist
       // we removed this tag from pending_map so need to write the changes
       CLS_LOG_BITX(bitx_inst, 20,
                   "INFO: %s: setting map entry at key=%s",
-                  __func__, idx.c_str());
+                  __func__, escape_str(idx).c_str());
       bufferlist new_key_bl;
       encode(entry, new_key_bl);
       rc = cls_cxx_map_set_val(hctx, idx, &new_key_bl);
       if (rc < 0) {
        CLS_LOG_BITX(bitx_inst, 1,
                     "ERROR: %s: unable to set map val, key=%s, rc=%d",
-                    __func__, idx.c_str(), rc);
+                    __func__, escape_str(idx).c_str(), rc);
         return rc;
       }
     }
@@ -1182,23 +1191,23 @@ int rgw_bucket_complete_op(cls_method_context_t hctx, bufferlist *in, bufferlist
 
     CLS_LOG_BITX(bitx_inst, 20,
                 "INFO: %s: delete op, key=%s",
-                __func__, idx.c_str());
+                __func__, escape_str(idx).c_str());
     entry.meta = op.meta;
     if (!ondisk) {
       // no entry to erase
       CLS_LOG_BITX(bitx_inst, 20,
                   "INFO: %s: key=%s not on disk, no action",
-                  __func__, idx.c_str());
+                  __func__, escape_str(idx).c_str());
       log_op = false;
     } else if (!entry.pending_map.size()) {
        CLS_LOG_BITX(bitx_inst, 20,
                     "INFO: %s: removing map entry with key=%s",
-                    __func__, idx.c_str());
+                    __func__, escape_str(idx).c_str());
       rc = cls_cxx_map_remove_key(hctx, idx);
       if (rc < 0) {
          CLS_LOG_BITX(bitx_inst, 1,
                       "ERROR: %s: unable to remove map key, key=%s, rc=%d",
-                      __func__, idx.c_str(), rc);
+                      __func__, escape_str(idx).c_str(), rc);
         return rc;
       }
     } else {
@@ -1207,12 +1216,12 @@ int rgw_bucket_complete_op(cls_method_context_t hctx, bufferlist *in, bufferlist
       encode(entry, new_key_bl);
       CLS_LOG_BITX(bitx_inst, 20,
                   "INFO: %s: setting map entry at key=%s",
-                  __func__, idx.c_str());
+                  __func__, escape_str(idx).c_str());
       rc = cls_cxx_map_set_val(hctx, idx, &new_key_bl);
       if (rc < 0) {
        CLS_LOG_BITX(bitx_inst, 1,
                     "ERROR: %s: unable to set map val, key=%s, rc=%d",
-                    __func__, idx.c_str(), rc);
+                    __func__, escape_str(idx).c_str(), rc);
         return rc;
       }
     }
@@ -1220,7 +1229,7 @@ int rgw_bucket_complete_op(cls_method_context_t hctx, bufferlist *in, bufferlist
   else if (op.op == CLS_RGW_OP_ADD) {
     CLS_LOG_BITX(bitx_inst, 20,
                 "INFO: %s: add op, key=%s",
-                __func__, idx.c_str());
+                __func__, escape_str(idx).c_str());
     // unaccount overwritten entry
     unaccount_entry(header, entry);
 
@@ -1239,12 +1248,12 @@ int rgw_bucket_complete_op(cls_method_context_t hctx, bufferlist *in, bufferlist
     encode(entry, new_key_bl);
     CLS_LOG_BITX(bitx_inst, 20,
                 "INFO: %s: setting map entry at key=%s",
-                __func__, idx.c_str());
+                __func__, escape_str(idx).c_str());
     rc = cls_cxx_map_set_val(hctx, idx, &new_key_bl);
     if (rc < 0) {
       CLS_LOG_BITX(bitx_inst, 1,
-                  "ERROR: %s: unable to log index operation, key=%s(%s), tag=%s, rc=%d",
-                  __func__, op.key.name.c_str(), op.key.instance.c_str(), op.tag.c_str(), rc);
+                  "ERROR: %s: unable to set map value at key=%s, rc=%d",
+                  __func__, escape_str(idx).c_str(), rc);
       return rc;
     }
   } // CLS_RGW_OP_ADD
@@ -1256,25 +1265,24 @@ int rgw_bucket_complete_op(cls_method_context_t hctx, bufferlist *in, bufferlist
                             &op.zones_trace);
     if (rc < 0) {
       CLS_LOG_BITX(bitx_inst, 0,
-                  "%s: log_index_operation failed with rc=%d",
+                  "ERROR: %s: log_index_operation failed with rc=%d",
                   __func__, rc);
       return rc;
     }
   }
 
-  CLS_LOG(20, "rgw_bucket_complete_op(): remove_objs.size()=%d",
-          (int)op.remove_objs.size());
+  CLS_LOG_BITX(bitx_inst, 20, "INFO: %s: remove_objs.size()=%d",
+              __func__, (int)op.remove_objs.size());
   for (const auto& remove_key : op.remove_objs) {
     CLS_LOG_BITX(bitx_inst, 20,
                 "INFO: %s: completing object remove key=%s",
-                __func__, remove_key.to_string().c_str());
+                __func__, escape_str(remove_key.to_string()).c_str());
     rc = complete_remove_obj(hctx, header, remove_key, default_log_op);
     if (rc < 0) {
       CLS_LOG_BITX(bitx_inst, 1,
                   "WARNING: %s: complete_remove_obj, failed to remove entry, "
-                  "name=%s instance=%s read_index_entry ret=%d, continuing",
-                  __func__, remove_key.name.c_str(),
-                  remove_key.instance.c_str(), rc);
+                  "name=%s read_index_entry ret=%d, continuing",
+                  __func__, escape_str(remove_key.to_string()).c_str(), rc);
       continue; // part cleanup errors are not fatal
     }
   } // remove loop
@@ -1288,7 +1296,7 @@ int rgw_bucket_complete_op(cls_method_context_t hctx, bufferlist *in, bufferlist
                 __func__, rc);
   }
 
-  CLS_LOG_BITX(bitx_inst, 20,
+  CLS_LOG_BITX(bitx_inst, 10,
               "EXITING %s: returning %d", __func__, rc);
   return rc;
 } // rgw_bucket_complete_op
@@ -2276,7 +2284,7 @@ int rgw_dir_suggest_changes(cls_method_context_t hctx,
   const bool bitx_inst =
     conf->rgw_bucket_index_transaction_instrumentation;
 
-  CLS_LOG_BITX(bitx_inst, 1, "ENTERING %s for object oid=%s key=%s",
+  CLS_LOG_BITX(bitx_inst, 10, "ENTERING %s for object oid=%s key=%s",
               __func__, oi.soid.oid.name.c_str(), oi.soid.get_key().c_str());
 
   bufferlist header_bl;
@@ -2361,7 +2369,7 @@ int rgw_dir_suggest_changes(cls_method_context_t hctx,
       // these pending entries will prevent us from applying suggested changes
       real_time cur_time = real_clock::now();
       auto iter = cur_disk.pending_map.begin();
-      while(iter != cur_disk.pending_map.end()) {
+      while (iter != cur_disk.pending_map.end()) {
         auto cur_iter = iter++; // IMPORTANT, cur_iter might be invalidated
         if (cur_time > (cur_iter->second.timestamp + timespan(tag_timeout))) {
          CLS_LOG_BITX(bitx_inst, 0,
@@ -2370,16 +2378,16 @@ int rgw_dir_suggest_changes(cls_method_context_t hctx,
                       __func__,
                       cur_iter->first.c_str(),
                       cur_iter->second.state,
-                      std::string(to_string((RGWModifyOp) iter->second.op)).c_str());
+                      modify_op_str(iter->second.op).c_str());
           cur_disk.pending_map.erase(cur_iter);
         }
       } // while
     } // if
 
     CLS_LOG_BITX(bitx_inst, 20,
-                "INFO: %s: cur_disk.pending_map.empty()=%d op=%c cur_disk.exists=%d "
+                "INFO: %s: op=%c cur_disk.pending_map.empty()=%d cur_disk.exists=%d "
                 "cur_disk.index_ver=%d cur_change.exists=%d cur_change.index_ver=%d",
-                __func__, cur_disk.pending_map.empty(), op, cur_disk.exists,
+                __func__, op, cur_disk.pending_map.empty(), cur_disk.exists,
                 (int)cur_disk.index_ver, cur_change.exists,
                 (int)cur_change.index_ver);
 
@@ -2394,7 +2402,8 @@ int rgw_dir_suggest_changes(cls_method_context_t hctx,
       CLS_LOG_BITX(bitx_inst, 10, "INFO: %s: cur_disk.pending_map is empty", __func__);
       if (cur_disk.exists) {
         rgw_bucket_category_stats& old_stats = header.stats[cur_disk.meta.category];
-       CLS_LOG_BITX(bitx_inst, 10, "INFO: %s: stats.num_entries: %ld -> %ld", __func__, old_stats.num_entries, old_stats.num_entries - 1);
+       CLS_LOG_BITX(bitx_inst, 10, "INFO: %s: stats.num_entries: %ld -> %ld",
+                    __func__, old_stats.num_entries, old_stats.num_entries - 1);
         old_stats.num_entries--;
         old_stats.total_size -= cur_disk.meta.accounted_size;
         old_stats.total_size_rounded -= cls_rgw_get_rounded_size(cur_disk.meta.accounted_size);
@@ -2406,9 +2415,8 @@ int rgw_dir_suggest_changes(cls_method_context_t hctx,
       switch(op) {
       case CEPH_RGW_REMOVE:
        CLS_LOG_BITX(bitx_inst, 10,
-                    "INFO: %s: CEPH_RGW_REMOVE name=%s instance=%s encoded=%s",
-                    __func__, cur_change.key.name.c_str(),
-                    cur_change.key.instance.c_str(),
+                    "INFO: %s: CEPH_RGW_REMOVE name=%s encoded=%s",
+                    __func__, escape_str(cur_change.key.to_string()).c_str(),
                     escape_str(cur_change_key).c_str());
 
        CLS_LOG_BITX(bitx_inst, 20,
@@ -2432,8 +2440,8 @@ int rgw_dir_suggest_changes(cls_method_context_t hctx,
         break;
       case CEPH_RGW_UPDATE:
        CLS_LOG_BITX(bitx_inst, 10,
-                    "INFO: %s: CEPH_RGW_UPDATE name=%s instance=%s stats.num_entries: %ld -> %ld",
-                    __func__, cur_change.key.name.c_str(), cur_change.key.instance.c_str(),
+                    "INFO: %s: CEPH_RGW_UPDATE name=%s stats.num_entries: %ld -> %ld",
+                    __func__, escape_str(cur_change.key.to_string()).c_str(),
                     stats.num_entries, stats.num_entries + 1);
 
         stats.num_entries++;
@@ -2447,7 +2455,7 @@ int rgw_dir_suggest_changes(cls_method_context_t hctx,
 
        CLS_LOG_BITX(bitx_inst, 20,
                     "INFO: %s: setting map entry at key=%s",
-                    __func__, cur_change.key.name.c_str());
+                    __func__, escape_str(cur_change.key.to_string()).c_str());
         ret = cls_cxx_map_set_val(hctx, cur_change_key, &cur_state_bl);
         if (ret < 0) {
          CLS_LOG_BITX(bitx_inst, 0, "ERROR: %s: unable to set value for key, key=%s, error=%d",
@@ -2468,19 +2476,19 @@ int rgw_dir_suggest_changes(cls_method_context_t hctx,
   } // while (!in_iter.end())
 
   if (header_changed) {
-    CLS_LOG_BITX(bitx_inst, 10, "INFO: %s: header changed, writing", __func__);
+    CLS_LOG_BITX(bitx_inst, 10, "INFO: %s: bucket header changed, writing", __func__);
     int ret = write_bucket_header(hctx, &header);
     if (ret < 0) {
       CLS_LOG_BITX(bitx_inst, 0,
                   "ERROR: %s: failed to write bucket header ret=%d",
                   __func__, ret);
     } else {
-      CLS_LOG_BITX(bitx_inst, 1, "EXITING %s, returning %d", __func__, ret);
+      CLS_LOG_BITX(bitx_inst, 10, "EXITING %s, returning %d", __func__, ret);
     }
     return ret;
   }
 
-  CLS_LOG_BITX(bitx_inst, 1, "EXITING %s, returning 0", __func__);
+  CLS_LOG_BITX(bitx_inst, 10, "EXITING %s, returning 0", __func__);
   return 0;
 } // rgw_dir_suggest_changes
 

diff --git a/src/rgw/rgw_rados.cc b/src/rgw/rgw_rados.cc
index 68d99a08738cbfa35399ca11012039339a2c4623..d9bc8d1e8d854ce53e1aa103acf8c50b5188253c 100644 (file)
--- a/src/rgw/rgw_rados.cc
+++ b/src/rgw/rgw_rados.cc
@@ -895,11 +895,22 @@ void RGWIndexCompletionManager::process()
 
       r = store->guard_reshard(&dpp, &bs, c->obj, bucket_info,
                             [&](RGWRados::BucketShard *bs) -> int {
+                              const bool bitx = ctx()->_conf->rgw_bucket_index_transaction_instrumentation;
+                              ldout_bitx(bitx, ctx(), 10) <<
+                                "ENTERING " << __func__ << ": bucket-shard=" << bs <<
+                                " obj=" << c->obj << " tag=" << c->tag <<
+                                " op=" << c->op << ", remove_objs=" << c->remove_objs << dendl_bitx;
+                              ldout_bitx(bitx, ctx(), 25) <<
+                                "BACKTRACE: " << __func__ << ": " << ClibBackTrace(1) << dendl_bitx;
+
                               librados::ObjectWriteOperation o;
                               cls_rgw_guard_bucket_resharding(o, -ERR_BUSY_RESHARDING);
                               cls_rgw_bucket_complete_op(o, c->op, c->tag, c->ver, c->key, c->dir_meta, &c->remove_objs,
                                                          c->log_op, c->bilog_op, &c->zones_trace);
-                              return bs->bucket_obj.operate(&dpp, &o, null_yield);
+                              int ret = bs->bucket_obj.operate(&dpp, &o, null_yield);
+                              ldout_bitx(bitx, ctx(), 10) <<
+                                "EXITING " << __func__ << ": ret=" << dendl_bitx;
+                              return ret;
                              });
       if (r < 0) {
         ldpp_dout(&dpp, 0) << "ERROR: " << __func__ << "(): bucket index completion failed, obj=" << c->obj << " r=" << r << dendl;
@@ -8376,7 +8387,7 @@ int RGWRados::cls_obj_prepare_op(const DoutPrefixProvider *dpp, BucketShard& bs,
 {
   const bool bitx = cct->_conf->rgw_bucket_index_transaction_instrumentation;
   ldout_bitx(bitx, cct, 10) << "ENTERING " << __func__ << ": bucket-shard=" << bs << " obj=" << obj << " tag=" << tag << " op=" << op << dendl_bitx;
-  ldout_bitx(bitx, cct, 10) << "BACKTRACE: " << __func__ << ": " << BackTrace(0) << dendl_bitx;
+  ldout_bitx(bitx, cct, 25) << "BACKTRACE: " << __func__ << ": " << ClibBackTrace(0) << dendl_bitx;
 
   rgw_zone_set zones_trace;
   if (_zones_trace) {
@@ -8402,7 +8413,7 @@ int RGWRados::cls_obj_complete_op(BucketShard& bs, const rgw_obj& obj, RGWModify
   ldout_bitx(bitx, cct, 10) << "ENTERING " << __func__ << ": bucket-shard=" << bs <<
     " obj=" << obj << " tag=" << tag << " op=" << op <<
     ", remove_objs=" << (remove_objs ? *remove_objs : std::list<rgw_obj_index_key>()) << dendl_bitx;
-  ldout_bitx(bitx, cct, 10) << "BACKTRACE: " << __func__ << ": " << BackTrace(0) << dendl_bitx;
+  ldout_bitx(bitx, cct, 25) << "BACKTRACE: " << __func__ << ": " << ClibBackTrace(0) << dendl_bitx;
 
   ObjectWriteOperation o;
   rgw_bucket_dir_entry_meta dir_meta;
@@ -8535,17 +8546,16 @@ int RGWRados::cls_bucket_list_ordered(const DoutPrefixProvider *dpp,
    * namespaced entries */
 
   ldout_bitx(bitx, cct, 10) << "ENTERING " << __func__ << ": " << bucket_info.bucket <<
-    " start_after=\"" << start_after.name <<
-    "[" << start_after.instance <<
-    "]\", prefix=\"" << prefix <<
+    " start_after=\"" << start_after.to_string() <<
+    "\", prefix=\"" << prefix <<
     ", delimiter=\"" << delimiter <<
     "\", shard_id=" << shard_id <<
-    "\" num_entries=" << num_entries <<
+    "\", num_entries=" << num_entries <<
     ", list_versions=" << list_versions <<
     ", expansion_factor=" << expansion_factor <<
     ", force_check_filter is " <<
     (force_check_filter ? "set" : "unset") << dendl_bitx;
-  ldout_bitx(bitx, cct, 20) << "BACKTRACE: " << __func__ << ": " << BackTrace(0) << dendl_bitx;
+  ldout_bitx(bitx, cct, 25) << "BACKTRACE: " << __func__ << ": " << ClibBackTrace(0) << dendl_bitx;
 
   m.clear();
 
@@ -8773,7 +8783,7 @@ int RGWRados::cls_bucket_list_ordered(const DoutPrefixProvider *dpp,
        librados::Rados::aio_create_completion(nullptr, nullptr);
 
       ldout_bitx(bitx, cct, 10) << "INFO: " << __func__ <<
-       " doing dir_suggest on " << miter.first << dendl_bitx;
+       ": doing dir_suggest on " << miter.first << dendl_bitx;
       ioctx.aio_operate(miter.first, c, &o);
       c->release();
     }
@@ -8851,7 +8861,7 @@ int RGWRados::cls_bucket_list_unordered(const DoutPrefixProvider *dpp,
     "\", num_entries=" << num_entries <<
     ", list_versions=" << list_versions <<
     (force_check_filter ? "set" : "unset") << dendl_bitx;
-  ldout_bitx(bitx, cct, 20) << "BACKTRACE: " << __func__ << ": " << BackTrace(0) << dendl_bitx;
+  ldout_bitx(bitx, cct, 25) << "BACKTRACE: " << __func__ << ": " << ClibBackTrace(0) << dendl_bitx;
 
   ent_list.clear();
   static MultipartMetaFilter multipart_meta_filter;
@@ -8936,7 +8946,7 @@ int RGWRados::cls_bucket_list_unordered(const DoutPrefixProvider *dpp,
     r = rgw_rados_operate(dpp, ioctx, oid, &op, nullptr, null_yield);
     if (r < 0) {
       ldpp_dout(dpp, 0) << "ERROR: " << __func__ <<
-       " error in rgw_rados_operate (bucket list op), r=" << r << dendl;
+       ": error in rgw_rados_operate (bucket list op), r=" << r << dendl;
       return r;
     }
 
@@ -8953,12 +8963,12 @@ int RGWRados::cls_bucket_list_unordered(const DoutPrefixProvider *dpp,
        librados::IoCtx sub_ctx;
        sub_ctx.dup(ioctx);
        ldout_bitx(bitx, cct, 20) << "INFO: " << __func__ <<
-         " calling check_disk_state bucket=" << bucket_info.bucket <<
+         ": calling check_disk_state bucket=" << bucket_info.bucket <<
          " entry=" << dirent.key << dendl_bitx;
        r = check_disk_state(dpp, sub_ctx, bucket_info, dirent, dirent, updates[oid], y);
        if (r < 0 && r != -ENOENT) {
          ldpp_dout(dpp, 0) << "ERROR: " << __func__ <<
-           " error in check_disk_state, r=" << r << dendl;
+           ": error in check_disk_state, r=" << r << dendl;
          return r;
        }
       } else {
@@ -9113,8 +9123,8 @@ int RGWRados::remove_objs_from_index(const DoutPrefixProvider *dpp, RGWBucketInf
 {
   const bool bitx = cct->_conf->rgw_bucket_index_transaction_instrumentation;
   ldout_bitx(bitx, cct, 10) << "ENTERING " << __func__ << ": bucket=" << bucket_info.bucket <<
-    " entry_key_list.size()=" << entry_key_list.size() << dendl_bitx;
-  ldout_bitx(bitx, cct, 20) << "BACKTRACE: " << __func__ << ": " << BackTrace(0) << dendl_bitx;
+    " oid_list.size()=" << oid_list.size() << dendl_bitx;
+   ldout_bitx(bitx, cct, 25) << "BACKTRACE: " << __func__ << ": " << ClibBackTrace(0) << dendl_bitx;
 
   RGWSI_RADOS::Pool index_pool;
   string dir_oid;
@@ -9132,7 +9142,6 @@ int RGWRados::remove_objs_from_index(const DoutPrefixProvider *dpp, RGWBucketInf
     entry.key = *iter;
     ldout_bitx(bitx, cct, 5) << "INFO: " << __func__ <<
       ": encoding removal of bucket=" << bucket_info.bucket <<
-      " shard=" << shard <<
       " entry=" << entry.key << " in updates" << dendl_bitx;
     entry.ver.epoch = (uint64_t)-1; // ULLONG_MAX, needed to that objclass doesn't skip out request
     updates.append(CEPH_RGW_REMOVE | suggest_flag);
@@ -9145,7 +9154,7 @@ int RGWRados::remove_objs_from_index(const DoutPrefixProvider *dpp, RGWBucketInf
   bufferlist out;
   r = index_pool.ioctx().exec(dir_oid, RGW_CLASS, RGW_DIR_SUGGEST_CHANGES, updates, out);
 
-  ldout_bitx(bitx, cct, 20) <<
+  ldout_bitx(bitx, cct, 10) <<
     "EXITING " << __func__ << " and returning " << r << dendl_bitx;
   return r;
 }
@@ -9159,7 +9168,7 @@ int RGWRados::check_disk_state(const DoutPrefixProvider *dpp,
                                optional_yield y)
 {
   const bool bitx = cct->_conf->rgw_bucket_index_transaction_instrumentation;
-  ldout_bitx(bitx, cct, 10) << "ENTERING " << __func__ << " bucket=" <<
+  ldout_bitx(bitx, cct, 10) << "ENTERING " << __func__ << ": bucket=" <<
     bucket_info.bucket << " dir_entry=" << list_state.key << dendl_bitx;
 
   std::unique_ptr<rgw::sal::Bucket> bucket;
@@ -9188,11 +9197,11 @@ int RGWRados::check_disk_state(const DoutPrefixProvider *dpp,
 
   list_state.pending_map.clear(); // we don't need this and it inflates size
   if (!list_state.is_delete_marker() && !astate->exists) {
-    ldout_bitx(bitx, cct, 10) << "INFO: " << __func__ << " disk state exists" << dendl_bitx;
+    ldout_bitx(bitx, cct, 10) << "INFO: " << __func__ << ": disk state exists" << dendl_bitx;
       /* object doesn't exist right now -- hopefully because it's
        * marked as !exists and got deleted */
     if (list_state.exists) {
-      ldout_bitx(bitx, cct, 10) << "INFO: " << __func__ << " index list state exists" << dendl_bitx;
+      ldout_bitx(bitx, cct, 10) << "INFO: " << __func__ << ": index list state exists" << dendl_bitx;
       /* FIXME: what should happen now? Work out if there are any
        * non-bad ways this could happen (there probably are, but annoying
        * to handle!) */
@@ -9201,7 +9210,7 @@ int RGWRados::check_disk_state(const DoutPrefixProvider *dpp,
     // encode a suggested removal of that key
     list_state.ver.epoch = io_ctx.get_last_version();
     list_state.ver.pool = io_ctx.get_id();
-    ldout_bitx(bitx, cct, 10) << "INFO: " << __func__ << " encoding remove of " << list_state.key << " on suggested_updates" << dendl_bitx;
+    ldout_bitx(bitx, cct, 10) << "INFO: " << __func__ << ": encoding remove of " << list_state.key << " on suggested_updates" << dendl_bitx;
     cls_rgw_encode_suggestion(CEPH_RGW_REMOVE | suggest_flag, list_state, suggested_updates);
     return -ENOENT;
   }
@@ -9283,7 +9292,7 @@ int RGWRados::check_disk_state(const DoutPrefixProvider *dpp,
   list_state.exists = true;
 
   ldout_bitx(bitx, cct, 10) << "INFO: " << __func__ <<
-    " encoding update of " << list_state.key << " on suggested_updates" << dendl_bitx;
+    ": encoding update of " << list_state.key << " on suggested_updates" << dendl_bitx;
   cls_rgw_encode_suggestion(CEPH_RGW_UPDATE | suggest_flag, list_state, suggested_updates);
 
   ldout_bitx(bitx, cct, 10) << "EXITING " << __func__ << dendl_bitx;