Merge pull request #500 from ceph/wip-5910

Resolves #5910.

Reviewed-by: Greg Farnum <greg@inktank.com>

14 files changed, 199 insertions, 4 deletions

diff --git a/src/Makefile.am b/src/Makefile.am
index 856c6c24dc1..e93bbb8f537 100644
--- a/src/Makefile.am
+++ b/src/Makefile.am
@@ -1617,7 +1617,8 @@ libmon_a_SOURCES = \
 	mon/HealthMonitor.cc \
 	mon/DataHealthService.cc \
 	mon/ConfigKeyService.cc \
-	common/util.cc
+	common/util.cc \
+	common/TextTable.cc
 libmon_a_CXXFLAGS= ${AM_CXXFLAGS}
 noinst_LIBRARIES += libmon.a
 
diff --git a/src/common/perf_counters.cc b/src/common/perf_counters.cc
index 1dd4cdabd9d..339ff6a372b 100644
--- a/src/common/perf_counters.cc
+++ b/src/common/perf_counters.cc
@@ -203,6 +203,22 @@ utime_t PerfCounters::tget(int idx) const
   return utime_t(data.u64 / 1000000000ull, data.u64 % 1000000000ull);
 }
 
+pair<uint64_t, uint64_t> PerfCounters::get_tavg_ms(int idx) const
+{
+  if (!m_cct->_conf->perf)
+    return make_pair(0, 0);
+
+  Mutex::Locker lck(m_lock);
+  assert(idx > m_lower_bound);
+  assert(idx < m_upper_bound);
+  const perf_counter_data_any_d& data(m_data[idx - m_lower_bound - 1]);
+  if (!(data.type & PERFCOUNTER_TIME))
+    return make_pair(0, 0);
+  if (!(data.type & PERFCOUNTER_LONGRUNAVG))
+    return make_pair(0, 0);
+  return make_pair(data.avgcount, data.u64/1000000);
+}
+
 void PerfCounters::dump_formatted(Formatter *f, bool schema)
 {
   Mutex::Locker lck(m_lock);
diff --git a/src/common/perf_counters.h b/src/common/perf_counters.h
index ec10f9a9282..f4651c69f1c 100644
--- a/src/common/perf_counters.h
+++ b/src/common/perf_counters.h
@@ -65,6 +65,24 @@ enum perfcounter_type_d
 class PerfCounters
 {
 public:
+  template <typename T>
+  struct avg_tracker {
+    pair<uint64_t, T> last;
+    pair<uint64_t, T> cur;
+    avg_tracker() : last(0, 0), cur(0, 0) {}
+    T avg() const {
+      if (cur.first == last.first)
+	return cur.first ?
+	  cur.second / cur.first :
+	  0; // no change, report avg over all time
+      return (cur.second - last.second) / (cur.first - last.first);
+    }
+    void consume_next(const pair<uint64_t, T> &next) {
+      last = cur;
+      cur = next;
+    }
+  };
+
   ~PerfCounters();
 
   void inc(int idx, uint64_t v = 1);
@@ -78,6 +96,8 @@ public:
 
   void dump_formatted(ceph::Formatter *f, bool schema);
 
+  pair<uint64_t, uint64_t> get_tavg_ms(int idx) const;
+
   const std::string& get_name() const;
   void set_name(std::string s) {
     m_name = s;
diff --git a/src/mon/MonCommands.h b/src/mon/MonCommands.h
index 8e9c2bb333b..e4cb9ce45ed 100644
--- a/src/mon/MonCommands.h
+++ b/src/mon/MonCommands.h
@@ -325,6 +325,11 @@ COMMAND("osd getmap " \
 COMMAND("osd getcrushmap " \
 	"name=epoch,type=CephInt,range=0,req=false", \
 	"get CRUSH map", "osd", "r", "cli,rest")
+COMMAND("osd perf", \
+        "print dump of OSD perf summary stats", \
+        "osd", \
+        "r", \
+        "cli,rest")
 COMMAND("osd getmaxosd", "show largest OSD id", "osd", "r", "cli,rest")
 COMMAND("osd find " \
 	"name=id,type=CephInt,range=0", \
diff --git a/src/mon/OSDMonitor.cc b/src/mon/OSDMonitor.cc
index bad405fa6f3..7b9258b1730 100644
--- a/src/mon/OSDMonitor.cc
+++ b/src/mon/OSDMonitor.cc
@@ -1972,7 +1972,8 @@ bool OSDMonitor::preprocess_command(MMonCommand *m)
 	   prefix == "osd tree" ||
 	   prefix == "osd ls" ||
 	   prefix == "osd getmap" ||
-	   prefix == "osd getcrushmap") {
+	   prefix == "osd getcrushmap" ||
+	   prefix == "osd perf") {
     string val;
 
     epoch_t epoch = 0;
@@ -2044,6 +2045,17 @@ bool OSDMonitor::preprocess_command(MMonCommand *m)
     } else if (prefix == "osd getcrushmap") {
       p->crush->encode(rdata);
       ss << "got crush map from osdmap epoch " << p->get_epoch();
+    } else if (prefix == "osd perf") {
+      const PGMap &pgm = mon->pgmon()->pg_map;
+      if (f) {
+	f->open_object_section("osdstats");
+	pgm.dump_osd_perf_stats(f.get());
+	f->close_section();
+	f->flush(ds);
+      } else {
+	pgm.print_osd_perf_stats(&ds);
+      }
+      rdata.append(ds);
     }
     if (p != &osdmap)
       delete p;
diff --git a/src/mon/PGMap.cc b/src/mon/PGMap.cc
index f6b88fcbfe0..9da4bbc71d9 100644
--- a/src/mon/PGMap.cc
+++ b/src/mon/PGMap.cc
@@ -5,6 +5,7 @@
 
 #define dout_subsys ceph_subsys_mon
 #include "common/debug.h"
+#include "common/TextTable.h"
 #include "include/stringify.h"
 #include "common/Formatter.h"
 #include "include/ceph_features.h"
@@ -698,6 +699,40 @@ void PGMap::dump_stuck_plain(ostream& ss, PGMap::StuckPG type, utime_t cutoff) c
   dump_pg_stats_plain(ss, stuck_pg_stats);
 }
 
+void PGMap::dump_osd_perf_stats(Formatter *f) const
+{
+  f->open_array_section("osd_perf_infos");
+  for (hash_map<int32_t, osd_stat_t>::const_iterator i = osd_stat.begin();
+       i != osd_stat.end();
+       ++i) {
+    f->open_object_section("osd");
+    f->dump_int("id", i->first);
+    {
+      f->open_object_section("perf_stats");
+      i->second.fs_perf_stat.dump(f);
+      f->close_section();
+    }
+    f->close_section();
+  }
+  f->close_section();
+}
+void PGMap::print_osd_perf_stats(std::ostream *ss) const
+{
+  TextTable tab;
+  tab.define_column("osdid", TextTable::LEFT, TextTable::RIGHT);
+  tab.define_column("fs_commit_latency(ms)", TextTable::LEFT, TextTable::RIGHT);
+  tab.define_column("fs_apply_latency(ms)", TextTable::LEFT, TextTable::RIGHT);
+  for (hash_map<int32_t, osd_stat_t>::const_iterator i = osd_stat.begin();
+       i != osd_stat.end();
+       ++i) {
+    tab << i->first;
+    tab << i->second.fs_perf_stat.filestore_commit_latency;
+    tab << i->second.fs_perf_stat.filestore_apply_latency;
+    tab << TextTable::endrow;
+  }
+  (*ss) << tab;
+}
+
 void PGMap::recovery_summary(Formatter *f, ostream *out) const
 {
   bool first = true;
diff --git a/src/mon/PGMap.h b/src/mon/PGMap.h
index e59d1b81a20..465531335d3 100644
--- a/src/mon/PGMap.h
+++ b/src/mon/PGMap.h
@@ -168,6 +168,9 @@ public:
 
   void dump(ostream& ss) const;
 
+  void dump_osd_perf_stats(Formatter *f) const;
+  void print_osd_perf_stats(std::ostream *ss) const;
+
   void recovery_summary(Formatter *f, ostream *out) const;
   void print_summary(Formatter *f, ostream *out) const;
 
diff --git a/src/os/FileStore.cc b/src/os/FileStore.cc
index 108a857ab9f..e442dd4fe2b 100644
--- a/src/os/FileStore.cc
+++ b/src/os/FileStore.cc
@@ -126,6 +126,17 @@ static const __SWORD_TYPE XFS_SUPER_MAGIC(0x58465342);
 #define ALIGNED(x, by) (!((x) % (by)))
 #define ALIGN_UP(x, by) (ALIGNED((x), (by)) ? (x) : (ALIGN_DOWN((x), (by)) + (by)))
 
+void FileStore::FSPerfTracker::update_from_perfcounters(
+  PerfCounters &logger)
+{
+  os_commit_latency.consume_next(
+    logger.get_tavg_ms(
+      l_os_commit_lat));
+  os_apply_latency.consume_next(
+    logger.get_tavg_ms(
+      l_os_apply_lat));
+}
+
 
 ostream& operator<<(ostream& out, const FileStore::OpSequencer& s)
 {
diff --git a/src/os/FileStore.h b/src/os/FileStore.h
index 86d267dddf1..ba428093cda 100644
--- a/src/os/FileStore.h
+++ b/src/os/FileStore.h
@@ -55,6 +55,25 @@ class FileStore : public JournalingObjectStore,
                   public md_config_obs_t
 {
 public:
+
+  struct FSPerfTracker {
+    PerfCounters::avg_tracker<uint64_t> os_commit_latency;
+    PerfCounters::avg_tracker<uint64_t> os_apply_latency;
+
+    filestore_perf_stat_t get_cur_stats() const {
+      filestore_perf_stat_t ret;
+      ret.filestore_commit_latency = os_commit_latency.avg();
+      ret.filestore_apply_latency = os_apply_latency.avg();
+      return ret;
+    }
+
+    void update_from_perfcounters(PerfCounters &logger);
+  } perf_tracker;
+  filestore_perf_stat_t get_cur_stats() {
+    perf_tracker.update_from_perfcounters(*logger);
+    return perf_tracker.get_cur_stats();
+  }
+
   static const uint32_t on_disk_version = 3;
 private:
   string internal_name;         ///< internal name, used to name the perfcounter instance
diff --git a/src/os/ObjectStore.h b/src/os/ObjectStore.h
index 6bfefa09a47..eb5b40c5a69 100644
--- a/src/os/ObjectStore.h
+++ b/src/os/ObjectStore.h
@@ -81,6 +81,8 @@ public:
 
   Logger *logger;
 
+  virtual filestore_perf_stat_t get_cur_stats() = 0;
+
   /**
    * a sequencer orders transactions
    *
diff --git a/src/osd/OSD.cc b/src/osd/OSD.cc
index 1a77dae730a..14bdc87487c 100644
--- a/src/osd/OSD.cc
+++ b/src/osd/OSD.cc
@@ -3648,6 +3648,8 @@ void OSD::send_pg_stats(const utime_t &now)
   stat_lock.Lock();
   osd_stat_t cur_stat = osd_stat;
   stat_lock.Unlock();
+
+  osd_stat.fs_perf_stat = store->get_cur_stats();
    
   pg_stat_queue_lock.Lock();
 
diff --git a/src/osd/osd_types.cc b/src/osd/osd_types.cc
index 0e8ecb99086..ea3e5d5c3eb 100644
--- a/src/osd/osd_types.cc
+++ b/src/osd/osd_types.cc
@@ -136,6 +136,36 @@ void pow2_hist_t::generate_test_instances(list<pow2_hist_t*>& ls)
   ls.back()->h.push_back(2);
 }
 
+void filestore_perf_stat_t::dump(Formatter *f) const
+{
+  f->dump_unsigned("commit_latency_ms", filestore_commit_latency);
+  f->dump_unsigned("apply_latency_ms", filestore_apply_latency);
+}
+
+void filestore_perf_stat_t::encode(bufferlist &bl) const
+{
+  ENCODE_START(1, 1, bl);
+  ::encode(filestore_commit_latency, bl);
+  ::encode(filestore_apply_latency, bl);
+  ENCODE_FINISH(bl);
+}
+
+void filestore_perf_stat_t::decode(bufferlist::iterator &bl)
+{
+  DECODE_START(1, bl);
+  ::decode(filestore_commit_latency, bl);
+  ::decode(filestore_apply_latency, bl);
+  DECODE_FINISH(bl);
+}
+
+void filestore_perf_stat_t::generate_test_instances(std::list<filestore_perf_stat_t*>& o)
+{
+  o.push_back(new filestore_perf_stat_t());
+  o.push_back(new filestore_perf_stat_t());
+  o.back()->filestore_commit_latency = 20;
+  o.back()->filestore_apply_latency = 30;
+}
+
 // -- osd_stat_t --
 void osd_stat_t::dump(Formatter *f) const
 {
@@ -155,11 +185,14 @@ void osd_stat_t::dump(Formatter *f) const
   f->open_object_section("op_queue_age_hist");
   op_queue_age_hist.dump(f);
   f->close_section();
+  f->open_object_section("fs_perf_stat");
+  fs_perf_stat.dump(f);
+  f->close_section();
 }
 
 void osd_stat_t::encode(bufferlist &bl) const
 {
-  ENCODE_START(3, 2, bl);
+  ENCODE_START(4, 2, bl);
   ::encode(kb, bl);
   ::encode(kb_used, bl);
   ::encode(kb_avail, bl);
@@ -168,12 +201,13 @@ void osd_stat_t::encode(bufferlist &bl) const
   ::encode(hb_in, bl);
   ::encode(hb_out, bl);
   ::encode(op_queue_age_hist, bl);
+  ::encode(fs_perf_stat, bl);
   ENCODE_FINISH(bl);
 }
 
 void osd_stat_t::decode(bufferlist::iterator &bl)
 {
-  DECODE_START_LEGACY_COMPAT_LEN(3, 2, 2, bl);
+  DECODE_START_LEGACY_COMPAT_LEN(4, 2, 2, bl);
   ::decode(kb, bl);
   ::decode(kb_used, bl);
   ::decode(kb_avail, bl);
@@ -183,6 +217,8 @@ void osd_stat_t::decode(bufferlist::iterator &bl)
   ::decode(hb_out, bl);
   if (struct_v >= 3)
     ::decode(op_queue_age_hist, bl);
+  if (struct_v >= 4)
+    ::decode(fs_perf_stat, bl);
   DECODE_FINISH(bl);
 }
 
diff --git a/src/osd/osd_types.h b/src/osd/osd_types.h
index bf04e8e11e3..3cafdc2b035 100644
--- a/src/osd/osd_types.h
+++ b/src/osd/osd_types.h
@@ -569,6 +569,34 @@ public:
 };
 WRITE_CLASS_ENCODER(pow2_hist_t)
 
+/**
+ * filestore_perf_stat_t
+ *
+ * current perf information about the osd
+ */
+struct filestore_perf_stat_t {
+  // cur_op_latency is in ms since double add/sub are not associative
+  uint32_t filestore_commit_latency;
+  uint32_t filestore_apply_latency;
+
+  filestore_perf_stat_t() :
+    filestore_commit_latency(0), filestore_apply_latency(0) {}
+
+  void add(const filestore_perf_stat_t &o) {
+    filestore_commit_latency += o.filestore_commit_latency;
+    filestore_apply_latency += o.filestore_apply_latency;
+  }
+  void sub(const filestore_perf_stat_t &o) {
+    filestore_commit_latency -= o.filestore_commit_latency;
+    filestore_apply_latency -= o.filestore_apply_latency;
+  }
+  void dump(Formatter *f) const;
+  void encode(bufferlist &bl) const;
+  void decode(bufferlist::iterator &bl);
+  static void generate_test_instances(std::list<filestore_perf_stat_t*>& o);
+};
+WRITE_CLASS_ENCODER(filestore_perf_stat_t)
+
 /** osd_stat
  * aggregate stats for an osd
  */
@@ -579,6 +607,8 @@ struct osd_stat_t {
 
   pow2_hist_t op_queue_age_hist;
 
+  filestore_perf_stat_t fs_perf_stat;
+
   osd_stat_t() : kb(0), kb_used(0), kb_avail(0),
 		 snap_trim_queue_len(0), num_snap_trimming(0) {}
 
@@ -589,6 +619,7 @@ struct osd_stat_t {
     snap_trim_queue_len += o.snap_trim_queue_len;
     num_snap_trimming += o.num_snap_trimming;
     op_queue_age_hist.add(o.op_queue_age_hist);
+    fs_perf_stat.add(o.fs_perf_stat);
   }
   void sub(const osd_stat_t& o) {
     kb -= o.kb;
@@ -597,6 +628,7 @@ struct osd_stat_t {
     snap_trim_queue_len -= o.snap_trim_queue_len;
     num_snap_trimming -= o.num_snap_trimming;
     op_queue_age_hist.sub(o.op_queue_age_hist);
+    fs_perf_stat.sub(o.fs_perf_stat);
   }
 
   void dump(Formatter *f) const;
diff --git a/src/test/encoding/types.h b/src/test/encoding/types.h
index e0bc0a149a8..213da6fcccc 100644
--- a/src/test/encoding/types.h
+++ b/src/test/encoding/types.h
@@ -35,6 +35,7 @@ TYPE(object_locator_t)
 TYPE(pg_t)
 TYPE(coll_t)
 TYPE(pow2_hist_t)
+TYPE(filestore_perf_stat_t)
 TYPE(osd_stat_t)
 TYPE(OSDSuperblock)
 TYPE_FEATUREFUL(pool_snap_info_t)