[2/2] incubator-kudu git commit: KUDU-966. Add tracing for some network-related functions

[jd...@apache.org]

KUDU-966. Add tracing for some network-related functions

My current theory is that KUDU-966 (slow calls to GetMasterRegistration)
is because this call ends up calling GetFQDN(), which calls getaddrinfo()
which might be slow in the case of a broken DNS setup.

This adds traces and LOG_SLOW_EXECUTION in the relevant code paths to help
diagnose such an issue. I also added traces to other non-perf-critical methods
in the same area of the socket/networking code.

Change-Id: Id4892eb9e7f256811504cb813e539107c765700d
Reviewed-on: http://gerrit.cloudera.org:8080/2051
Reviewed-by: Jean-Daniel Cryans
Tested-by: Kudu Jenkins
(cherry picked from commit b0b051b9af90352023c11019b06e260fcfa171e2)
Reviewed-on: http://gerrit.cloudera.org:8080/2054
Tested-by: Jean-Daniel Cryans


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

Branch: refs/heads/branch-0.7.0
Commit: b664a41f9d589543a52afa58a363984a47f7ff97
Parents: 3b6f40d
Author: Todd Lipcon <to...@cloudera.com>
Authored: Mon Apr 20 17:27:23 2015 -0700
Committer: Jean-Daniel Cryans <jd...@gerrit.cloudera.org>
Committed: Thu Feb 4 23:41:38 2016 +0000

----------------------------------------------------------------------
 src/kudu/util/net/net_util.cc | 15 ++++++++++++---
 src/kudu/util/net/socket.cc   |  6 ++++++
 2 files changed, 18 insertions(+), 3 deletions(-)
----------------------------------------------------------------------


http://git-wip-us.apache.org/repos/asf/incubator-kudu/blob/b664a41f/src/kudu/util/net/net_util.cc
----------------------------------------------------------------------
diff --git a/src/kudu/util/net/net_util.cc b/src/kudu/util/net/net_util.cc
index 2f806d6..7c7ed31 100644
--- a/src/kudu/util/net/net_util.cc
+++ b/src/kudu/util/net/net_util.cc
@@ -33,6 +33,7 @@
 #include "kudu/gutil/strings/strip.h"
 #include "kudu/gutil/strings/substitute.h"
 #include "kudu/gutil/strings/util.h"
+#include "kudu/util/debug/trace_event.h"
 #include "kudu/util/errno.h"
 #include "kudu/util/faststring.h"
 #include "kudu/util/net/net_util.h"
@@ -94,6 +95,8 @@ Status HostPort::ParseString(const string& str, uint16_t default_port) {
 }
 
 Status HostPort::ResolveAddresses(vector<Sockaddr>* addresses) const {
+  TRACE_EVENT1("net", "HostPort::ResolveAddresses",
+               "host", host_);
   struct addrinfo hints;
   memset(&hints, 0, sizeof(hints));
   hints.ai_family = AF_INET;
@@ -178,6 +181,7 @@ Status ParseAddressList(const std::string& addr_list,
 }
 
 Status GetHostname(string* hostname) {
+  TRACE_EVENT0("net", "GetHostname");
   char name[HOST_NAME_MAX];
   int ret = gethostname(name, HOST_NAME_MAX);
   if (ret != 0) {
@@ -190,6 +194,7 @@ Status GetHostname(string* hostname) {
 }
 
 Status GetFQDN(string* hostname) {
+  TRACE_EVENT0("net", "GetFQDN");
   // Start with the non-qualified hostname
   RETURN_NOT_OK(GetHostname(hostname));
 
@@ -199,9 +204,13 @@ Status GetFQDN(string* hostname) {
   hints.ai_flags = AI_CANONNAME;
 
   struct addrinfo* result;
-  int rc = getaddrinfo(hostname->c_str(), nullptr, &hints, &result);
-  if (rc != 0) {
-    return Status::NetworkError("Unable to lookup FQDN", ErrnoToString(errno), errno);
+  LOG_SLOW_EXECUTION(WARNING, 200,
+                     Substitute("looking up canonical hostname for localhost $0", hostname)) {
+    TRACE_EVENT0("net", "getaddrinfo");
+    int rc = getaddrinfo(hostname->c_str(), nullptr, &hints, &result);
+    if (rc != 0) {
+      return Status::NetworkError("Unable to lookup FQDN", ErrnoToString(errno), errno);
+    }
   }
 
   *hostname = result->ai_canonname;

http://git-wip-us.apache.org/repos/asf/incubator-kudu/blob/b664a41f/src/kudu/util/net/socket.cc
----------------------------------------------------------------------
diff --git a/src/kudu/util/net/socket.cc b/src/kudu/util/net/socket.cc
index ed19f28..7a6933b 100644
--- a/src/kudu/util/net/socket.cc
+++ b/src/kudu/util/net/socket.cc
@@ -33,6 +33,7 @@
 #include "kudu/gutil/basictypes.h"
 #include "kudu/gutil/stringprintf.h"
 #include "kudu/gutil/strings/substitute.h"
+#include "kudu/util/debug/trace_event.h"
 #include "kudu/util/errno.h"
 #include "kudu/util/flag_tags.h"
 #include "kudu/util/monotime.h"
@@ -303,6 +304,7 @@ Status Socket::Bind(const Sockaddr& bind_addr) {
 }
 
 Status Socket::Accept(Socket *new_conn, Sockaddr *remote, int flags) {
+  TRACE_EVENT0("net", "Socket::Accept");
   struct sockaddr_in addr;
   socklen_t olen = sizeof(addr);
   DCHECK_GE(fd_, 0);
@@ -330,6 +332,8 @@ Status Socket::Accept(Socket *new_conn, Sockaddr *remote, int flags) {
 #endif // defined(__linux__)
 
   *remote = addr;
+  TRACE_EVENT_INSTANT1("net", "Accepted", TRACE_EVENT_SCOPE_THREAD,
+                       "remote", remote->ToString());
   return Status::OK();
 }
 
@@ -345,6 +349,8 @@ Status Socket::BindForOutgoingConnection() {
 }
 
 Status Socket::Connect(const Sockaddr &remote) {
+  TRACE_EVENT1("net", "Socket::Connect",
+               "remote", remote.ToString());
   if (PREDICT_FALSE(!FLAGS_local_ip_for_outbound_sockets.empty())) {
     RETURN_NOT_OK(BindForOutgoingConnection());
   }