Report slow ops in OSD stats in etcd and show them in vitastor-cli status

src/cmd/cli_osd_tree.cpp

@@ -216,7 +216,7 @@ resume_1:
                 for (uint64_t osd_num: node.child_osds)
                 {
                     auto & osd = placement_tree->osds.at(osd_num);
-                    fmt_items.push_back(json11::Json::object{
+                    auto json_osd = json11::Json::object{
                         { "type", "osd" },
                         { "name", osd.num },
                         { "parent", node.name },
@@ -230,7 +230,16 @@ resume_1:
                         { "bitmap", (uint64_t)osd.bitmap_granularity },
                         { "commit", osd.immediate_commit == IMMEDIATE_NONE ? "none" : (osd.immediate_commit == IMMEDIATE_ALL ? "all" : "small") },
                         { "op_stats", osd_stats[osd_num]["op_stats"] },
-                    });
+                    };
+                    if (osd_stats[osd_num]["slow_ops_primary"].uint64_value() > 0)
+                    {
+                        json_osd["slow_ops_primary"] = osd_stats[osd_num]["slow_ops_primary"];
+                    }
+                    if (osd_stats[osd_num]["slow_ops_secondary"].uint64_value() > 0)
+                    {
+                        json_osd["slow_ops_secondary"] = osd_stats[osd_num]["slow_ops_secondary"];
+                    }
+                    fmt_items.push_back(json_osd);
                 }
             }
             result.data = fmt_items;

src/cmd/cli_status.cpp

@@ -134,6 +134,7 @@ resume_2:
         }
         int osd_count = 0, osd_up = 0;
         uint64_t total_raw = 0, free_raw = 0, free_down_raw = 0, down_raw = 0;
+        std::vector<uint64_t> slow_op_primary_osds, slow_op_secondary_osds;
         parent->iterate_kvs_1(osd_stats, "/osd/stats/", [&](uint64_t stat_osd_num, json11::Json value)
         {
             osd_count++;
@@ -153,6 +154,14 @@ resume_2:
             if (peer_it != parent->cli->st_cli.peer_states.end())
             {
                 osd_up++;
+                if (value["slow_ops_primary"].uint64_value() > 0)
+                {
+                    slow_op_primary_osds.push_back(stat_osd_num);
+                }
+                if (value["slow_ops_secondary"].uint64_value() > 0)
+                {
+                    slow_op_secondary_osds.push_back(stat_osd_num);
+                }
             }
             else
             {
@@ -216,6 +225,10 @@ resume_2:
                 { "mon_master", mon_master },
                 { "osd_up", osd_up },
                 { "osd_count", osd_count },
+                { "osds_full", osds_full },
+                { "osds_nearfull", osds_nearfull },
+                { "osds_primary_slow_ops", slow_op_primary_osds },
+                { "osds_secondary_slow_ops", slow_op_secondary_osds },
                 { "total_raw", total_raw },
                 { "free_raw", free_raw },
                 { "down_raw", down_raw },
@@ -300,6 +313,26 @@ resume_2:
             warning_str += "    "+std::to_string(osds_nearfull)+
                 (osds_nearfull > 1 ? " osds are almost full\n" : " osd is almost full\n");
         }
+        if (slow_op_primary_osds.size() > 0)
+        {
+            warning_str += "    "+std::to_string(slow_op_primary_osds.size());
+            warning_str += (slow_op_primary_osds.size() > 1 ? " osds have" : " osd has");
+            warning_str += " slow client ops: ";
+            for (int i = 0; i < slow_op_primary_osds.size(); i++)
+            {
+                warning_str += (i > 0 ? ", " : "")+std::to_string(slow_op_primary_osds[i])+"\n";
+            }
+        }
+        if (slow_op_secondary_osds.size() > 0)
+        {
+            warning_str += "    "+std::to_string(slow_op_secondary_osds.size());
+            warning_str += (slow_op_secondary_osds.size() > 1 ? " osds have" : " osd has");
+            warning_str += " slow replication ops: ";
+            for (int i = 0; i < slow_op_secondary_osds.size(); i++)
+            {
+                warning_str += (i > 0 ? ", " : "")+std::to_string(slow_op_secondary_osds[i])+"\n";
+            }
+        }
         if (warning_str != "")
         {
             warning_str = "\n  warning:\n"+warning_str;

src/osd/osd.cpp

@@ -535,10 +535,12 @@ void osd_t::print_stats()
 
 void osd_t::print_slow()
 {
-    bool has_slow = false;
+    cur_slow_op_primary = 0;
+    cur_slow_op_secondary = 0;
     char alloc[1024];
     timespec now;
     clock_gettime(CLOCK_REALTIME, &now);
+    // FIXME: Also track slow local blockstore ops and recovery/flush/scrub ops
     for (auto & kv: msgr.clients)
     {
         for (auto op: kv.second->received_ops)
@@ -608,6 +610,7 @@ void osd_t::print_slow()
                     op->req.hdr.opcode == OSD_OP_SEC_STABILIZE || op->req.hdr.opcode == OSD_OP_SEC_ROLLBACK ||
                     op->req.hdr.opcode == OSD_OP_SEC_READ_BMP)
                 {
+                    cur_slow_op_secondary++;
                     bufprintf(" state=%d", op->bs_op ? PRIV(op->bs_op)->op_state : -1);
                     int wait_for = op->bs_op ? PRIV(op->bs_op)->wait_for : 0;
                     if (wait_for)
@@ -618,15 +621,19 @@ void osd_t::print_slow()
                 else if (op->req.hdr.opcode == OSD_OP_READ || op->req.hdr.opcode == OSD_OP_WRITE ||
                     op->req.hdr.opcode == OSD_OP_SYNC || op->req.hdr.opcode == OSD_OP_DELETE)
                 {
+                    cur_slow_op_primary++;
                     bufprintf(" state=%d", !op->op_data ? -1 : op->op_data->st);
                 }
+                else
+                {
+                    cur_slow_op_primary++;
+                }
 #undef bufprintf
                 printf("%s\n", alloc);
-                has_slow = true;
             }
         }
     }
-    if (has_slow && bs)
+    if ((cur_slow_op_primary+cur_slow_op_secondary) > 0 && bs)
     {
         bs->dump_diagnostics();
     }

src/osd/osd.h

@@ -151,6 +151,8 @@ class osd_t
     bool etcd_reporting_pg_state = false;
     bool etcd_reporting_stats = false;
     int print_stats_timer_id = -1, slow_log_timer_id = -1;
+    uint64_t cur_slow_op_primary = 0;
+    uint64_t cur_slow_op_secondary = 0;
 
     // peers and PGs
 

src/osd/osd_cluster.cpp

@@ -201,6 +201,14 @@ json11::Json osd_t::get_statistics()
     st["immediate_commit"] = immediate_commit == IMMEDIATE_ALL ? "all" : (immediate_commit == IMMEDIATE_SMALL ? "small" : "none");
     st["host"] = self_state["host"];
     st["version"] = VITASTOR_VERSION;
+    if (cur_slow_op_primary > 0)
+    {
+        st["slow_ops_primary"] = cur_slow_op_primary;
+    }
+    if (cur_slow_op_secondary > 0)
+    {
+        st["slow_ops_secondary"] = cur_slow_op_secondary;
+    }
     json11::Json::object op_stats, subop_stats;
     for (int i = OSD_OP_MIN; i <= OSD_OP_MAX; i++)
     {