From 79e2902acdcf1c529f73e80449ac067e4bba2675 Mon Sep 17 00:00:00 2001
From: Deepika Upadhyay <deepika@koor.tech>
Date: Wed, 12 Oct 2022 22:13:01 +0530
Subject: [PATCH] src/crush: extra logging to debug CPU burn in
 test_with_fork()

related: https://tracker.ceph.com/issues/57782

Signed-off-by: Deepika Upadhyay <deepika@koor.tech>
---
 src/crush/CrushTester.cc | 22 +++++++++++++++++++---
 src/crush/CrushTester.h  |  5 +++--
 src/mon/OSDMonitor.cc    |  5 +++--
 src/tools/crushtool.cc   |  2 +-
 4 files changed, 26 insertions(+), 8 deletions(-)

diff --git a/src/crush/CrushTester.cc b/src/crush/CrushTester.cc
index 372e0b9d460..4f99cffaaa9 100644
--- a/src/crush/CrushTester.cc
+++ b/src/crush/CrushTester.cc
@@ -15,8 +15,13 @@
 #include "include/stringify.h"
 #include "CrushTester.h"
 #include "CrushTreeDumper.h"
+#include "common/ceph_context.h"
 #include "include/ceph_features.h"
+#include "common/debug.h"
 
+#define dout_subsys ceph_subsys_crush
+#undef dout_prefix
+#define dout_prefix *_dout << "CrushTester: "
 
 using std::cerr;
 using std::cout;
@@ -365,11 +370,12 @@ void CrushTester::write_integer_indexed_scalar_data_string(vector<string> &dst,
   dst.push_back( data_buffer.str() );
 }
 
-int CrushTester::test_with_fork(int timeout)
+int CrushTester::test_with_fork(CephContext* cct, int timeout)
 {
+  ldout(cct, 20) << __func__ << dendl;
   ostringstream sink;
   int r = fork_function(timeout, sink, [&]() {
-      return test();
+      return test(cct);
     });
   if (r == -ETIMEDOUT) {
     err << "timed out during smoke test (" << timeout << " seconds)";
@@ -429,8 +435,9 @@ bool CrushTester::check_name_maps(unsigned max_id) const
   return true;
 }
 
-int CrushTester::test()
+int CrushTester::test(CephContext* cct)
 {
+  ldout(cct, 20) << dendl;
   if (min_rule < 0 || max_rule < 0) {
     min_rule = 0;
     max_rule = crush.get_max_rules() - 1;
@@ -477,6 +484,8 @@ int CrushTester::test()
     crush.start_choose_profile();
   
   for (int r = min_rule; r < crush.get_max_rules() && r <= max_rule; r++) {
+    ldout(cct, 20) << "rule: " << r << dendl;
+
     if (!crush.rule_exists(r)) {
       if (output_statistics)
         err << "rule " << r << " dne" << std::endl;
@@ -490,6 +499,8 @@ int CrushTester::test()
       << std::endl;
 
     for (int nr = min_rep; nr <= max_rep; nr++) {
+      ldout(cct, 20) << "current numrep: " << nr << dendl;
+
       vector<int> per(crush.get_max_devices());
       map<int,int> sizes;
 
@@ -635,6 +646,8 @@ int CrushTester::test()
           }
         }
 
+      ldout(cct, 20) << "output statistics created" << dendl;
+
       if (output_data_file)
         for (unsigned i = 0; i < per.size(); i++) {
           vector_data_buffer_f.clear();
@@ -655,10 +668,13 @@ int CrushTester::test()
         }
       }
 
+      ldout(cct, 20) << "output data file created" << dendl;
       string rule_tag = crush.get_rule_name(r);
 
       if (output_csv)
         write_data_set_to_csv(output_data_file_name+rule_tag,tester_data);
+
+      ldout(cct, 20) << "successfully written csv" << dendl;
     }
   }
 
diff --git a/src/crush/CrushTester.h b/src/crush/CrushTester.h
index aa3d904b622..54f597651f8 100644
--- a/src/crush/CrushTester.h
+++ b/src/crush/CrushTester.h
@@ -5,6 +5,7 @@
 #define CEPH_CRUSH_TESTER_H
 
 #include "crush/CrushWrapper.h"
+#include "include/common_fwd.h"
 
 #include <fstream>
 
@@ -347,8 +348,8 @@ public:
    *         large, true otherwise
    */
   bool check_name_maps(unsigned max_id = 0) const;
-  int test();
-  int test_with_fork(int timeout);
+  int test(CephContext* cct);
+  int test_with_fork(CephContext* cct, int timeout);
 
   int compare(CrushWrapper& other);
 };
diff --git a/src/mon/OSDMonitor.cc b/src/mon/OSDMonitor.cc
index e9e7ce72a8b..87627f746a6 100644
--- a/src/mon/OSDMonitor.cc
+++ b/src/mon/OSDMonitor.cc
@@ -8041,7 +8041,8 @@ int OSDMonitor::prepare_new_pool(string& name,
     tester.set_rule(crush_rule);
     tester.set_num_rep(size);
     auto start = ceph::coarse_mono_clock::now();
-    r = tester.test_with_fork(g_conf()->mon_lease);
+    r = tester.test_with_fork(cct, g_conf()->mon_lease);
+    dout(10) << __func__ << " crush test_with_fork tester created " << dendl;
     auto duration = ceph::coarse_mono_clock::now() - start;
     if (r < 0) {
       dout(10) << "tester.test_with_fork returns " << r
@@ -10019,7 +10020,7 @@ bool OSDMonitor::prepare_command_impl(MonOpRequestRef op,
       tester.set_max_x(50);
       tester.set_num_rep(3);  // arbitrary
       auto start = ceph::coarse_mono_clock::now();
-      int r = tester.test_with_fork(g_conf()->mon_lease);
+      int r = tester.test_with_fork(cct, g_conf()->mon_lease);
       auto duration = ceph::coarse_mono_clock::now() - start;
       if (r < 0) {
 	dout(10) << " tester.test_with_fork returns " << r
diff --git a/src/tools/crushtool.cc b/src/tools/crushtool.cc
index a7a63d1c45a..acfc9a3c6f7 100644
--- a/src/tools/crushtool.cc
+++ b/src/tools/crushtool.cc
@@ -1289,7 +1289,7 @@ int main(int argc, const char **argv)
 	tester.get_output_utilization())
       tester.set_output_statistics(true);
 
-    int r = tester.test();
+    int r = tester.test(cct->get());
     if (r < 0)
       return EXIT_FAILURE;
   }
-- 
2.39.5