kudu-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From t...@apache.org
Subject [1/2] kudu git commit: mini_kdc: log when MiniKDC operations are slow
Date Thu, 02 Mar 2017 06:38:04 GMT
Repository: kudu
Updated Branches:
  refs/heads/master 55c3db350 -> 13ea03146


mini_kdc: log when MiniKDC operations are slow

ExternalMiniClusterTest seems to occasionally fail due to a very slow
startup sequence of the MiniKDC. This patch adds some scoped logging to
try to pinpoint it.

Change-Id: Ibf332b1a2759b74e60fb1fa0408b609d4c833411
Reviewed-on: http://gerrit.cloudera.org:8080/6214
Reviewed-by: Dan Burkert <danburkert@apache.org>
Tested-by: Kudu Jenkins


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

Branch: refs/heads/master
Commit: 479cf7f4b33c0d0b77cbf537c8fa77b2110101c0
Parents: 55c3db3
Author: Todd Lipcon <todd@apache.org>
Authored: Wed Mar 1 12:54:59 2017 -0800
Committer: Todd Lipcon <todd@apache.org>
Committed: Wed Mar 1 23:36:10 2017 +0000

----------------------------------------------------------------------
 src/kudu/security/test/mini_kdc.cc | 7 +++++++
 src/kudu/util/stopwatch.h          | 5 +++++
 2 files changed, 12 insertions(+)
----------------------------------------------------------------------


http://git-wip-us.apache.org/repos/asf/kudu/blob/479cf7f4/src/kudu/security/test/mini_kdc.cc
----------------------------------------------------------------------
diff --git a/src/kudu/security/test/mini_kdc.cc b/src/kudu/security/test/mini_kdc.cc
index abbb9d5..dc70f52 100644
--- a/src/kudu/security/test/mini_kdc.cc
+++ b/src/kudu/security/test/mini_kdc.cc
@@ -35,6 +35,7 @@
 #include "kudu/util/env.h"
 #include "kudu/util/monotime.h"
 #include "kudu/util/path_util.h"
+#include "kudu/util/stopwatch.h"
 #include "kudu/util/subprocess.h"
 #include "kudu/util/test_util.h"
 
@@ -139,6 +140,7 @@ Status GetBinaryPath(const string& binary, string* path) {
 
 
 Status MiniKdc::Start() {
+  SCOPED_LOG_SLOW_EXECUTION(WARNING, 100, "starting KDC");
   CHECK(!kdc_process_);
   VLOG(1) << "Starting Kerberos KDC: " << options_.ToString();
 
@@ -254,6 +256,7 @@ Status MiniKdc::CreateKrb5Conf() const {
 }
 
 Status MiniKdc::WaitForKdcPorts() {
+  SCOPED_LOG_SLOW_EXECUTION(WARNING, 100, Substitute("waiting for KDC ports"));
   // We have to use 'lsof' to figure out which ports the KDC bound to if we
   // requested ephemeral ones. The KDC doesn't log the bound port or expose it
   // in any other fashion, and re-implementing lsof involves parsing a lot of
@@ -307,6 +310,7 @@ Status MiniKdc::WaitForKdcPorts() {
 }
 
 Status MiniKdc::CreateUserPrincipal(const string& username) {
+  SCOPED_LOG_SLOW_EXECUTION(WARNING, 100, Substitute("creating user principal $0", username));
   string kadmin;
   RETURN_NOT_OK(GetBinaryPath("kadmin.local", &kadmin));
   RETURN_NOT_OK(Subprocess::Call(MakeArgv({
@@ -316,6 +320,7 @@ Status MiniKdc::CreateUserPrincipal(const string& username) {
 
 Status MiniKdc::CreateServiceKeytab(const string& spn,
                                     string* path) {
+  SCOPED_LOG_SLOW_EXECUTION(WARNING, 100, Substitute("creating service keytab for $0", spn));
   string kt_path = spn;
   StripString(&kt_path, "/", '_');
   kt_path = JoinPathSegments(options_.data_root, kt_path) + ".keytab";
@@ -331,6 +336,7 @@ Status MiniKdc::CreateServiceKeytab(const string& spn,
 }
 
 Status MiniKdc::Kinit(const string& username) {
+  SCOPED_LOG_SLOW_EXECUTION(WARNING, 100, Substitute("kinit for $0", username));
   string kinit;
   RETURN_NOT_OK(GetBinaryPath("kinit", &kinit));
   Subprocess::Call(MakeArgv({ kinit, username }), username);
@@ -338,6 +344,7 @@ Status MiniKdc::Kinit(const string& username) {
 }
 
 Status MiniKdc::Kdestroy() {
+  SCOPED_LOG_SLOW_EXECUTION(WARNING, 100, "kdestroy");
   string kdestroy;
   RETURN_NOT_OK(GetBinaryPath("kdestroy", &kdestroy));
   return Subprocess::Call(MakeArgv({ kdestroy, "-A" }));

http://git-wip-us.apache.org/repos/asf/kudu/blob/479cf7f4/src/kudu/util/stopwatch.h
----------------------------------------------------------------------
diff --git a/src/kudu/util/stopwatch.h b/src/kudu/util/stopwatch.h
index d539895..e86d90c 100644
--- a/src/kudu/util/stopwatch.h
+++ b/src/kudu/util/stopwatch.h
@@ -63,6 +63,11 @@ namespace kudu {
   kudu::sw_internal::LogTiming VARNAME_LINENUM(_log_timing)(__FILE__, __LINE__, \
       google::severity, "", description, -1, true);
 
+// Scoped version of LOG_SLOW_EXECUTION().
+#define SCOPED_LOG_SLOW_EXECUTION(severity, max_expected_millis, description) \
+  kudu::sw_internal::LogTiming VARNAME_LINENUM(_log_timing)(__FILE__, __LINE__, \
+      google::severity, "", description, max_expected_millis, true)
+
 // Scoped version of LOG_SLOW_EXECUTION() but with a prefix.
 #define SCOPED_LOG_SLOW_EXECUTION_PREFIX(severity, max_expected_millis, prefix, description)
\
   kudu::sw_internal::LogTiming VARNAME_LINENUM(_log_timing)(__FILE__, __LINE__, \


Mime
View raw message