[4/6] impala git commit: KUDU-2270: Add a flag to control logging in RpczStore::LogTrace()

[ta...@apache.org]

KUDU-2270: Add a flag to control logging in RpczStore::LogTrace()

This change adds a new flag FLAGS_rpc_duration_too_long_ms
which controls the duration above which a RPC is considered
too long and is logged at INFO level in the log. Previously,
this threshold is hardcoded to 1000ms which may be too short
for a busy Impalad demon, leading to massive log spew.

Change-Id: Ie587ee602e83bb65d74f7ee622a9bc47897f2574
Reviewed-on: http://gerrit.cloudera.org:8080/9117
Reviewed-by: Todd Lipcon <to...@apache.org>
Tested-by: Kudu Jenkins
Reviewed-on: http://gerrit.cloudera.org:8080/9121
Reviewed-by: Lars Volker <lv...@cloudera.com>
Tested-by: Impala Public Jenkins


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

Branch: refs/heads/master
Commit: b38db91b5e463f68efbd7eacf3e719e34d87e2bb
Parents: 0a1d586
Author: Michael Ho <kw...@cloudera.com>
Authored: Wed Jan 24 00:05:11 2018 -0800
Committer: Impala Public Jenkins <im...@gerrit.cloudera.org>
Committed: Thu Jan 25 04:36:06 2018 +0000

----------------------------------------------------------------------
 be/src/kudu/rpc/rpc-test.cc   | 1 +
 be/src/kudu/rpc/rpcz_store.cc | 9 ++++++++-
 2 files changed, 9 insertions(+), 1 deletion(-)
----------------------------------------------------------------------


http://git-wip-us.apache.org/repos/asf/impala/blob/b38db91b/be/src/kudu/rpc/rpc-test.cc
----------------------------------------------------------------------
diff --git a/be/src/kudu/rpc/rpc-test.cc b/be/src/kudu/rpc/rpc-test.cc
index dc29323..6d9d156 100644
--- a/be/src/kudu/rpc/rpc-test.cc
+++ b/be/src/kudu/rpc/rpc-test.cc
@@ -43,6 +43,7 @@ METRIC_DECLARE_histogram(rpc_incoming_queue_time);
 
 DECLARE_bool(rpc_reopen_outbound_connections);
 DECLARE_int32(rpc_negotiation_inject_delay_ms);
+DECLARE_int32(rpc_duration_too_long_ms);
 
 using std::shared_ptr;
 using std::string;

http://git-wip-us.apache.org/repos/asf/impala/blob/b38db91b/be/src/kudu/rpc/rpcz_store.cc
----------------------------------------------------------------------
diff --git a/be/src/kudu/rpc/rpcz_store.cc b/be/src/kudu/rpc/rpcz_store.cc
index b1a0591..710a57e 100644
--- a/be/src/kudu/rpc/rpcz_store.cc
+++ b/be/src/kudu/rpc/rpcz_store.cc
@@ -40,6 +40,13 @@ DEFINE_bool_hidden(rpc_dump_all_traces, false,
 TAG_FLAG(rpc_dump_all_traces, advanced);
 TAG_FLAG(rpc_dump_all_traces, runtime);
 
+DEFINE_int32_hidden(rpc_duration_too_long_ms, 1000,
+             "Threshold (in milliseconds) above which a RPC is considered too long and its "
+             "duration and method name are logged at INFO level. The time measured is between "
+             "when a RPC is accepted and when its call handler completes.");
+TAG_FLAG(rpc_duration_too_long_ms, advanced);
+TAG_FLAG(rpc_duration_too_long_ms, runtime);
+
 using std::pair;
 using std::vector;
 using std::unique_ptr;
@@ -244,7 +251,7 @@ void RpczStore::LogTrace(InboundCall* call) {
   if (PREDICT_FALSE(FLAGS_rpc_dump_all_traces)) {
     LOG(INFO) << call->ToString() << " took " << duration_ms << "ms. Trace:";
     call->trace()->Dump(&LOG(INFO), true);
-  } else if (duration_ms > 1000) {
+  } else if (duration_ms > FLAGS_rpc_duration_too_long_ms) {
     LOG(INFO) << call->ToString() << " took " << duration_ms << "ms. "
               << "Request Metrics: " << call->trace()->MetricsAsJSON();
   }