kudu-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From danburk...@apache.org
Subject [5/6] incubator-kudu git commit: rpcz: break out trace metrics into separate PB fields
Date Tue, 24 May 2016 19:30:33 GMT
rpcz: break out trace metrics into separate PB fields

This removes the trace metrics from the textual trace dump and instead adds
some structured metrics information to the /rpcz page. This should be easier
to read in the /rpcz output, and also easier to parse from any future
analysis tools we might build.

I updated the test and also manually verified the new output on a
CreateTableRequestPB on a local instance. Here's the metrics from that call:

 "metrics": [
     {
         "child_path": "txn",
         "key": "apply.queue_time_us",
         "value": 168
     },
     {
         "child_path": "txn",
         "key": "apply.run_wall_time_us",
         "value": 584
     },
     {
         "child_path": "txn",
         "key": "apply.run_cpu_time_us",
         "value": 584
     },
     {
         "child_path": "txn",
         "key": "prepare.run_cpu_time_us",
         "value": 684
     },
     {
         "child_path": "txn",
         "key": "prepare.queue_time_us",
         "value": 168
     },
     {
         "child_path": "txn",
         "key": "prepare.run_wall_time_us",
         "value": 683
     },
     {
         "child_path": "txn",
         "key": "threads_started",
         "value": 2
     },
     {
         "child_path": "txn",
         "key": "thread_start_us",
         "value": 201
     },
     {
         "child_path": "txn",
         "key": "num_ops",
         "value": 2
     },
     {
         "child_path": "txn",
         "key": "replication_time_us",
         "value": 579
     }

Change-Id: I8bd1a249b2f09f8eb63bc64de55147b3d7738a9c
Reviewed-on: http://gerrit.cloudera.org:8080/3092
Tested-by: Kudu Jenkins
Reviewed-by: Jean-Daniel Cryans
Reviewed-by: Adar Dembo <adar@cloudera.com>


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

Branch: refs/heads/master
Commit: 08b66007c7eee301ba7e77ed11a7c48e3eefd72c
Parents: f4a644c
Author: Todd Lipcon <todd@apache.org>
Authored: Mon May 16 18:24:35 2016 -0700
Committer: Todd Lipcon <todd@apache.org>
Committed: Tue May 24 19:05:58 2016 +0000

----------------------------------------------------------------------
 src/kudu/rpc/rpc-test-base.h         |  7 +++++++
 src/kudu/rpc/rpc_introspection.proto | 10 +++++++++
 src/kudu/rpc/rpc_stub-test.cc        | 18 ++++++++++++++--
 src/kudu/rpc/rpcz_store.cc           | 34 ++++++++++++++++++++++++++++++-
 src/kudu/util/trace.cc               |  5 +++++
 src/kudu/util/trace.h                |  6 ++++++
 6 files changed, 77 insertions(+), 3 deletions(-)
----------------------------------------------------------------------


http://git-wip-us.apache.org/repos/asf/incubator-kudu/blob/08b66007/src/kudu/rpc/rpc-test-base.h
----------------------------------------------------------------------
diff --git a/src/kudu/rpc/rpc-test-base.h b/src/kudu/rpc/rpc-test-base.h
index b0afdbe..3f9ed7c 100644
--- a/src/kudu/rpc/rpc-test-base.h
+++ b/src/kudu/rpc/rpc-test-base.h
@@ -257,6 +257,13 @@ class CalculatorService : public CalculatorServiceIf {
   void DoSleep(const SleepRequestPB *req,
                RpcContext *context) {
     TRACE_COUNTER_INCREMENT("test_sleep_us", req->sleep_micros());
+    if (Trace::CurrentTrace()) {
+      scoped_refptr<Trace> child_trace(new Trace());
+      Trace::CurrentTrace()->AddChildTrace("test_child", child_trace.get());
+      ADOPT_TRACE(child_trace.get());
+      TRACE_COUNTER_INCREMENT("related_trace_metric", 1);
+    }
+
     SleepFor(MonoDelta::FromMicroseconds(req->sleep_micros()));
     context->RespondSuccess();
   }

http://git-wip-us.apache.org/repos/asf/incubator-kudu/blob/08b66007/src/kudu/rpc/rpc_introspection.proto
----------------------------------------------------------------------
diff --git a/src/kudu/rpc/rpc_introspection.proto b/src/kudu/rpc/rpc_introspection.proto
index c4b6faa..5a223e6 100644
--- a/src/kudu/rpc/rpc_introspection.proto
+++ b/src/kudu/rpc/rpc_introspection.proto
@@ -55,6 +55,14 @@ message DumpRunningRpcsResponsePB {
 
 //------------------------------------------------------------
 
+// A particular TraceMetric key/value pair from a sampled RPC.
+message TraceMetricPB {
+  // A '.'-separated path through the parent-child trace hierarchy.
+  optional string child_path = 1;
+  optional string key = 2;
+  optional int64 value = 3;
+}
+
 // A single sampled RPC call.
 message RpczSamplePB {
   // The original request header.
@@ -63,6 +71,8 @@ message RpczSamplePB {
   optional string trace = 2;
   // The number of millis that this call took to complete.
   optional int32 duration_ms = 3;
+  // The metrics from the sampled trace.
+  repeated TraceMetricPB metrics = 4;
 }
 
 // A set of samples for a particular RPC method.

http://git-wip-us.apache.org/repos/asf/incubator-kudu/blob/08b66007/src/kudu/rpc/rpc_stub-test.cc
----------------------------------------------------------------------
diff --git a/src/kudu/rpc/rpc_stub-test.cc b/src/kudu/rpc/rpc_stub-test.cc
index 770017a..15d45cf 100644
--- a/src/kudu/rpc/rpc_stub-test.cc
+++ b/src/kudu/rpc/rpc_stub-test.cc
@@ -538,8 +538,22 @@ TEST_F(RpcStubTest, TestDumpSampledCalls) {
   DumpRpczStoreResponsePB sampled_rpcs;
   server_messenger_->rpcz_store()->DumpPB(DumpRpczStoreRequestPB(), &sampled_rpcs);
   EXPECT_EQ(sampled_rpcs.methods_size(), 1);
-  ASSERT_STR_CONTAINS(sampled_rpcs.DebugString(), "{\\\"test_sleep_us\\\":150000");
-  ASSERT_STR_CONTAINS(sampled_rpcs.DebugString(), "{\\\"test_sleep_us\\\":1500000}");
+  ASSERT_STR_CONTAINS(sampled_rpcs.DebugString(),
+                      "    metrics {\n"
+                      "      key: \"test_sleep_us\"\n"
+                      "      value: 150000\n"
+                      "    }\n");
+  ASSERT_STR_CONTAINS(sampled_rpcs.DebugString(),
+                      "    metrics {\n"
+                      "      key: \"test_sleep_us\"\n"
+                      "      value: 1500000\n"
+                      "    }\n");
+  ASSERT_STR_CONTAINS(sampled_rpcs.DebugString(),
+                      "    metrics {\n"
+                      "      child_path: \"test_child\"\n"
+                      "      key: \"related_trace_metric\"\n"
+                      "      value: 1\n"
+                      "    }");
   ASSERT_STR_CONTAINS(sampled_rpcs.DebugString(), "SleepRequestPB");
   ASSERT_STR_CONTAINS(sampled_rpcs.DebugString(), "duration_ms");
 }

http://git-wip-us.apache.org/repos/asf/incubator-kudu/blob/08b66007/src/kudu/rpc/rpcz_store.cc
----------------------------------------------------------------------
diff --git a/src/kudu/rpc/rpcz_store.cc b/src/kudu/rpc/rpcz_store.cc
index 1938ece..0587869 100644
--- a/src/kudu/rpc/rpcz_store.cc
+++ b/src/kudu/rpc/rpcz_store.cc
@@ -70,6 +70,13 @@ class MethodSampler {
   void GetSamplePBs(RpczMethodPB* pb);
 
  private:
+  // Convert the trace metrics from 't' into protobuf entries in 'sample_pb'.
+  // This function recurses through the parent-child relationship graph,
+  // keeping the current tree path in 'child_path' (empty at the root).
+  static void GetTraceMetrics(const Trace& t,
+                              const std::string& child_path,
+                              RpczSamplePB* sample_pb);
+
   // An individual recorded sample.
   struct Sample {
     RequestHeader header;
@@ -146,6 +153,29 @@ void MethodSampler::SampleCall(InboundCall* call) {
   }
 }
 
+void MethodSampler::GetTraceMetrics(const Trace& t,
+                                    const string& child_path,
+                                    RpczSamplePB* sample_pb) {
+  auto m = t.metrics().Get();
+  for (const auto& e : m) {
+    auto* pb = sample_pb->add_metrics();
+    pb->set_key(e.first);
+    pb->set_value(e.second);
+    if (!child_path.empty()) {
+      pb->set_child_path(child_path);
+    }
+  }
+
+  for (const auto& child_pair : t.ChildTraces()) {
+    string path = child_path;
+    if (!path.empty()) {
+      path += ".";
+    }
+    path += child_pair.first.ToString();
+    GetTraceMetrics(*child_pair.second.get(), path, sample_pb);
+  }
+}
+
 void MethodSampler::GetSamplePBs(RpczMethodPB* method_pb) {
   for (auto& bucket : buckets_) {
     if (bucket.last_sample_time.Load() == 0) continue;
@@ -153,7 +183,9 @@ void MethodSampler::GetSamplePBs(RpczMethodPB* method_pb) {
     std::unique_lock<simple_spinlock> lock(bucket.sample_lock);
     auto* sample_pb = method_pb->add_samples();
     sample_pb->mutable_header()->CopyFrom(bucket.sample.header);
-    sample_pb->set_trace(bucket.sample.trace->DumpToString(Trace::INCLUDE_ALL));
+    sample_pb->set_trace(bucket.sample.trace->DumpToString(Trace::INCLUDE_TIME_DELTAS));
+
+    GetTraceMetrics(*bucket.sample.trace.get(), "", sample_pb);
     sample_pb->set_duration_ms(bucket.sample.duration_ms);
   }
 }

http://git-wip-us.apache.org/repos/asf/incubator-kudu/blob/08b66007/src/kudu/util/trace.cc
----------------------------------------------------------------------
diff --git a/src/kudu/util/trace.cc b/src/kudu/util/trace.cc
index 6ca1254..9b556b5 100644
--- a/src/kudu/util/trace.cc
+++ b/src/kudu/util/trace.cc
@@ -246,4 +246,9 @@ void Trace::AddChildTrace(StringPiece label, Trace* child_trace) {
   child_traces_.emplace_back(label, ptr);
 }
 
+std::vector<std::pair<StringPiece, scoped_refptr<Trace>>> Trace::ChildTraces()
const {
+  lock_guard<simple_spinlock> l(&lock_);
+  return child_traces_;
+}
+
 } // namespace kudu

http://git-wip-us.apache.org/repos/asf/incubator-kudu/blob/08b66007/src/kudu/util/trace.h
----------------------------------------------------------------------
diff --git a/src/kudu/util/trace.h b/src/kudu/util/trace.h
index fd43d87..324c1c4 100644
--- a/src/kudu/util/trace.h
+++ b/src/kudu/util/trace.h
@@ -166,6 +166,9 @@ class Trace : public RefCountedThreadSafe<Trace> {
   // into this trace's arena.
   void AddChildTrace(StringPiece label, Trace* child_trace);
 
+  // Return a copy of the current set of related "child" traces.
+  std::vector<std::pair<StringPiece, scoped_refptr<Trace>>> ChildTraces()
const;
+
   // Return the current trace attached to this thread, if there is one.
   static Trace* CurrentTrace() {
     return threadlocal_trace_;
@@ -179,6 +182,9 @@ class Trace : public RefCountedThreadSafe<Trace> {
   TraceMetrics* metrics() {
     return &metrics_;
   }
+  const TraceMetrics& metrics() const {
+    return metrics_;
+  }
 
  private:
   friend class ScopedAdoptTrace;


Mime
View raw message