osd: be more verbose in OSD::run_osd_bench_test

Likely build-in OSD benchmarking is a source for bluestore slow ops in
BlueStore at Teuthology runs.
Let's have more logging for this procedure.

Related-to: https://tracker.ceph.com/issues/68337
Signed-off-by: Igor Fedotov <igor.fedotov@croit.io>

diff --git a/src/osd/OSD.cc b/src/osd/OSD.cc
index 2ea6d25f442938defd97819c153ad0fe31df81da..3c2d09ef462e3f1808c4138dd6154dc0b9fda196 100644 (file)
--- a/src/osd/OSD.cc
+++ b/src/osd/OSD.cc
@@ -3488,10 +3488,14 @@ int OSD::run_osd_bench_test(
     bsize = osize;
   }
 
-  dout(1) << " bench count " << count
-          << " bsize " << byte_u_t(bsize) << dendl;
+  dout(0) << " bench count " << count
+          << " bsize " << byte_u_t(bsize)
+          << " onum " << onum
+          << " osize " << byte_u_t(osize)
+          << dendl;
 
   ObjectStore::Transaction cleanupt;
+  utime_t start = ceph_clock_now();
 
   if (osize && onum) {
     bufferlist bl;
@@ -3517,9 +3521,13 @@ int OSD::run_osd_bench_test(
       waiter.wait();
     }
   }
+  dout(0) << __func__
+          << " prefill took " << ceph_clock_now() - start
+          << dendl;
 
+
+  start = ceph_clock_now();
   bufferlist bl;
-  utime_t start = ceph_clock_now();
   for (int64_t pos = 0; pos < count; pos += bsize) {
     char nm[34];
     unsigned offset = 0;
@@ -3552,6 +3560,9 @@ int OSD::run_osd_bench_test(
   }
   utime_t end = ceph_clock_now();
   *elapsed = end - start;
+  dout(0) << __func__
+          << " benchmark took " << *elapsed
+          << dendl;
 
   // clean up
   store->queue_transaction(service.meta_ch, std::move(cleanupt), nullptr);