kudu-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From mpe...@apache.org
Subject [1/2] kudu git commit: Add trace metrics for maintenance ops, LBM writes
Date Wed, 31 Aug 2016 16:21:15 GMT
Repository: kudu
Updated Branches:
  refs/heads/master 3b539b36d -> 1f660ee9f


Add trace metrics for maintenance ops, LBM writes

This adds a trace-scoped counter for LogBlockManager writes, and also
adds traces and counter printing to the maintenance manager.

With this patch, flushes and compactions now output log messages like:

I0830 13:42:28.809852  2208 maintenance_manager.cc:356] Time spent running FlushMRSOp(4301e24175a2469fba37184430567acc):
real 9.510s user 4.432s     sys 0.860s
I0830 13:42:28.810760  2208 maintenance_manager.cc:362] FlushMRSOp(4301e24175a2469fba37184430567acc)
metrics: {"cfile_init":14,"compiler_manager_pool.queue_time_us":106,"compiler_manager_pool.run_cpu_time_us":219218,"compiler_manager_pool.run_wall_time_us":232004,"fdatasync":533,"fdatasync_us":67137,"lbm
root 0.queue_time_us":1605,"lbm root 0.run_cpu_time_us":1280,"lbm root 0.run_wall_time_us":344957,"lbm_read_time_us":94,"lbm_reads_lt_1ms":56,"lbm_write_time_us":709833,"lbm_writes_gt_100_ms":1,"lbm_writes_lt_1ms":11564,"mutex_wait_us":343945,"tcmalloc_contention_cycles":2759552,"thread_start_us":1304,"threads_started":13}

This can be handy for understanding why a particular compaction or flush
was slow.

Change-Id: I39cd9438071aabbd2d7bdeca3269af8b83f2d55b
Reviewed-on: http://gerrit.cloudera.org:8080/4172
Tested-by: Kudu Jenkins
Reviewed-by: Dan Burkert <dan@cloudera.com>


Project: http://git-wip-us.apache.org/repos/asf/kudu/repo
Commit: http://git-wip-us.apache.org/repos/asf/kudu/commit/362a307e
Tree: http://git-wip-us.apache.org/repos/asf/kudu/tree/362a307e
Diff: http://git-wip-us.apache.org/repos/asf/kudu/diff/362a307e

Branch: refs/heads/master
Commit: 362a307e4cd117a1082d2e708bc4c9cd734a39be
Parents: 3b539b3
Author: Todd Lipcon <todd@apache.org>
Authored: Tue Aug 30 13:50:11 2016 -0700
Committer: Todd Lipcon <todd@apache.org>
Committed: Wed Aug 31 00:35:25 2016 +0000

----------------------------------------------------------------------
 src/kudu/fs/log_block_manager.cc     | 19 +++++++++----------
 src/kudu/util/maintenance_manager.cc |  6 ++++++
 src/kudu/util/trace.h                | 15 +++++++++++++++
 3 files changed, 30 insertions(+), 10 deletions(-)
----------------------------------------------------------------------


http://git-wip-us.apache.org/repos/asf/kudu/blob/362a307e/src/kudu/fs/log_block_manager.cc
----------------------------------------------------------------------
diff --git a/src/kudu/fs/log_block_manager.cc b/src/kudu/fs/log_block_manager.cc
index fc9ca64..28b582f 100644
--- a/src/kudu/fs/log_block_manager.cc
+++ b/src/kudu/fs/log_block_manager.cc
@@ -831,7 +831,15 @@ Status LogWritableBlock::Append(const Slice& data) {
   // The metadata change is deferred to Close() or FlushDataAsync(),
   // whichever comes first. We can't do it now because the block's
   // length is still in flux.
+
+  MicrosecondsInt64 start_time = GetMonoTimeMicros();
   RETURN_NOT_OK(container_->WriteData(block_offset_ + block_length_, data));
+  MicrosecondsInt64 end_time = GetMonoTimeMicros();
+
+  int64_t dur = end_time - start_time;
+  TRACE_COUNTER_INCREMENT("lbm_write_time_us", dur);
+  const char* counter = BUCKETED_COUNTER_NAME("lbm_writes", dur);
+  TRACE_COUNTER_INCREMENT(counter, 1);
 
   block_length_ += data.size();
   state_ = DIRTY;
@@ -1019,16 +1027,7 @@ Status LogReadableBlock::Read(uint64_t offset, size_t length,
   int64_t dur = end_time - start_time;
   TRACE_COUNTER_INCREMENT("lbm_read_time_us", dur);
 
-  const char* counter;
-  if (dur >= 100 * 1000) {
-    counter = "lbm_reads_gt_100_ms";
-  } else if (dur >= 10 * 1000) {
-    counter = "lbm_reads_10-100_ms";
-  } else if (dur >= 1000) {
-    counter = "lbm_reads_1-10_ms";
-  } else {
-    counter = "lbm_reads_lt_1ms";
-  }
+  const char* counter = BUCKETED_COUNTER_NAME("lbm_reads", dur);
   TRACE_COUNTER_INCREMENT(counter, 1);
 
   if (container_->metrics()) {

http://git-wip-us.apache.org/repos/asf/kudu/blob/362a307e/src/kudu/util/maintenance_manager.cc
----------------------------------------------------------------------
diff --git a/src/kudu/util/maintenance_manager.cc b/src/kudu/util/maintenance_manager.cc
index 3ff8fe3..b596e0e 100644
--- a/src/kudu/util/maintenance_manager.cc
+++ b/src/kudu/util/maintenance_manager.cc
@@ -32,6 +32,7 @@
 #include "kudu/util/metrics.h"
 #include "kudu/util/stopwatch.h"
 #include "kudu/util/thread.h"
+#include "kudu/util/trace.h"
 
 using std::pair;
 using std::shared_ptr;
@@ -350,11 +351,16 @@ MaintenanceOp* MaintenanceManager::FindBestOp() {
 void MaintenanceManager::LaunchOp(MaintenanceOp* op) {
   MonoTime start_time(MonoTime::Now());
   op->RunningGauge()->Increment();
+
+  scoped_refptr<Trace> trace(new Trace);
   LOG_TIMING(INFO, Substitute("running $0", op->name())) {
+    ADOPT_TRACE(trace.get());
     TRACE_EVENT1("maintenance", "MaintenanceManager::LaunchOp",
                  "name", op->name());
     op->Perform();
   }
+  LOG(INFO) << op->name() << " metrics: " << trace->MetricsAsJSON();
+
   op->RunningGauge()->Decrement();
   MonoTime end_time(MonoTime::Now());
   MonoDelta delta(end_time.GetDeltaSince(start_time));

http://git-wip-us.apache.org/repos/asf/kudu/blob/362a307e/src/kudu/util/trace.h
----------------------------------------------------------------------
diff --git a/src/kudu/util/trace.h b/src/kudu/util/trace.h
index c594461..4d6df24 100644
--- a/src/kudu/util/trace.h
+++ b/src/kudu/util/trace.h
@@ -93,6 +93,21 @@
 #define TRACE_COUNTER_SCOPE_LATENCY_US(counter_name) \
   ::kudu::ScopedTraceLatencyCounter _scoped_latency(counter_name)
 
+// Construct a constant C string counter name which acts as a sort of
+// coarse-grained histogram for trace metrics.
+#define BUCKETED_COUNTER_NAME(prefix, duration_us)      \
+  [=]() -> const char* {                                \
+    if (duration_us >= 100 * 1000) {                    \
+      return prefix "_gt_100_ms";                       \
+    } else if (duration_us >= 10 * 1000) {              \
+      return prefix "_10-100_ms";                       \
+    } else if (duration_us >= 1000) {                   \
+      return prefix "_1-10_ms";                         \
+    } else {                                            \
+      return prefix "_lt_1ms";                          \
+    }                                                   \
+  }();
+
 namespace kudu {
 
 class JsonWriter;


Mime
View raw message