Add DTRACE points to measure request timings. (#11245)

arangodb · Mar 20, 2020 · 15fad6f · 15fad6f
1 parent 1c6a958
commit 15fad6f
Show file tree

Hide file tree

Showing 14 changed files with 888 additions and 7 deletions.
diff --git a/CHANGELOG b/CHANGELOG
@@ -1,6 +1,8 @@
 devel
 -----
 
+* Add DTRACE points to track a request through the infrastructure.
+
 * Fixed issue #11275: indexes backward compatibility broken in 3.5+.
 
 * Updated snowball dependency to the latest version.

diff --git a/CMakeLists.txt b/CMakeLists.txt
@@ -280,6 +280,12 @@ if (STATIC_EXECUTABLES)
   endif ()
 endif()
 
+# enable dtrace
+option(USE_DTRACE "enable dtrace probes" OFF)
+if (USE_DTRACE)
+  add_definitions("-DUSE_DTRACE=1")
+endif ()
+
 # enable enterprise features
 set(ENTERPRISE_INCLUDE_DIR "enterprise")
 option(USE_ENTERPRISE "enable enterprise build" OFF)

diff --git a/arangod/GeneralServer/CommTask.cpp b/arangod/GeneralServer/CommTask.cpp
@@ -30,6 +30,7 @@
 #include "Basics/HybridLogicalClock.h"
 #include "Basics/StaticStrings.h"
 #include "Basics/compile-time-strlen.h"
+#include "Basics/dtrace-wrapper.h"
 #include "Cluster/ServerState.h"
 #include "GeneralServer/AsyncJobManager.h"
 #include "GeneralServer/AuthenticationFeature.h"
@@ -150,6 +151,8 @@ bool resolveRequestContext(GeneralRequest& req) {
 
 CommTask::Flow CommTask::prepareExecution(auth::TokenCache::Entry const& authToken,
                                           GeneralRequest& req) {
+  DTRACE_PROBE1(arangod, CommTaskPrepareExecution, this);
+
   // Step 1: In the shutdown phase we simply return 503:
   if (_server.server().isStopping()) {
     addErrorResponse(ResponseCode::SERVICE_UNAVAILABLE, req.contentTypeResponse(),
@@ -324,7 +327,8 @@ void CommTask::finishExecution(GeneralResponse& res, std::string const& origin)
 
 void CommTask::executeRequest(std::unique_ptr<GeneralRequest> request,
                               std::unique_ptr<GeneralResponse> response) {
-
+  DTRACE_PROBE1(arangod, CommTaskExecuteRequest, this);
+
   response->setContentTypeRequested(request->contentTypeResponse());
   response->setGenerateBody(request->requestType() != RequestType::HEAD);
 
@@ -516,6 +520,7 @@ void CommTask::addErrorResponse(rest::ResponseCode code,
 // and scheduled later when the number of used threads decreases
 
 bool CommTask::handleRequestSync(std::shared_ptr<RestHandler> handler) {
+  DTRACE_PROBE2(arangod, CommTaskHandleRequestSync, this, handler.get());
   RequestStatistics::SET_QUEUE_START(handler->statistics(), SchedulerFeature::SCHEDULER->queueStatistics()._queued);
 
   RequestLane lane = handler->getRequestLane();

diff --git a/arangod/GeneralServer/H2CommTask.cpp b/arangod/GeneralServer/H2CommTask.cpp
@@ -25,6 +25,7 @@
 #include "Basics/Exceptions.h"
 #include "Basics/ScopeGuard.h"
 #include "Basics/asio_ns.h"
+#include "Basics/dtrace-wrapper.h"
 #include "Cluster/ServerState.h"
 #include "GeneralServer/GeneralServer.h"
 #include "GeneralServer/GeneralServerFeature.h"
@@ -389,8 +390,20 @@ bool H2CommTask<T>::readCallback(asio_ns::error_code ec) {
   return true;  //  continue read lopp
 }
 
+#ifdef USE_DTRACE
+// Moved out to avoid duplication by templates.
+static void __attribute__ ((noinline)) DTraceH2CommTaskProcessStream(size_t th) {
+  DTRACE_PROBE1(arangod, H2CommTaskProcessStream, th);
+}
+#else
+static void DTraceH2CommTaskProcessStream(size_t) {}
+#endif
+
 template <SocketType T>
 void H2CommTask<T>::processStream(H2CommTask<T>::Stream* stream) {
+
+  DTraceH2CommTaskProcessStream((size_t) this);
+
   TRI_ASSERT(stream);
 
   std::unique_ptr<HttpRequest> req = std::move(stream->request);
@@ -463,10 +476,21 @@ bool expectResponseBody(int status_code) {
 }
 }  // namespace
 
+#ifdef USE_DTRACE
+// Moved out to avoid duplication by templates.
+static void __attribute__ ((noinline)) DTraceH2CommTaskSendResponse(size_t th) {
+  DTRACE_PROBE1(arangod, H2CommTaskSendResponse, th);
+}
+#else
+static void DTraceH2CommTaskSendResponse(size_t) {}
+#endif
+
 template <SocketType T>
 void H2CommTask<T>::sendResponse(std::unique_ptr<GeneralResponse> res,
                                  RequestStatistics* stat) {
-
+
+  DTraceH2CommTaskSendResponse((size_t) this);
+
   // TODO the statistics are total bogus here
   double const totalTime = RequestStatistics::ELAPSED_SINCE_READ_START(stat);
   if (stat) {
@@ -630,6 +654,19 @@ void H2CommTask<T>::queueHttp2Responses() {
   }
 }
 
+#ifdef USE_DTRACE
+// Moved out to avoid duplication by templates.
+static void __attribute__ ((noinline)) DTraceH2CommTaskBeforeAsyncWrite(size_t th) {
+  DTRACE_PROBE1(arangod, H2CommTaskBeforeAsyncWrite, th);
+}
+static void __attribute__ ((noinline)) DTraceH2CommTaskAfterAsyncWrite(size_t th) {
+  DTRACE_PROBE1(arangod, H2CommTaskAfterAsyncWrite, th);
+}
+#else 
+static void DTraceH2CommTaskBeforeAsyncWrite(size_t) {}
+static void DTraceH2CommTaskAfterAsyncWrite(size_t) {}
+#endif
+
 // called on IO context thread
 template <SocketType T>
 void H2CommTask<T>::doWrite() {
@@ -685,6 +722,8 @@ void H2CommTask<T>::doWrite() {
     return;
   }
 
+  DTraceH2CommTaskBeforeAsyncWrite((size_t) this);
+
   asio_ns::async_write(this->_protocol->socket, outBuffers,
                        [self = this->shared_from_this()](const asio_ns::error_code& ec,
                                                          std::size_t nwrite) {
@@ -695,6 +734,8 @@ void H2CommTask<T>::doWrite() {
                            return;
                          }
 
+                         DTraceH2CommTaskAfterAsyncWrite((size_t) self.get());
+
                          me.doWrite();
                        });
 }

diff --git a/arangod/GeneralServer/HttpCommTask.cpp b/arangod/GeneralServer/HttpCommTask.cpp
@@ -25,6 +25,7 @@
 
 #include "Basics/ScopeGuard.h"
 #include "Basics/asio_ns.h"
+#include "Basics/dtrace-wrapper.h"
 #include "Cluster/ServerState.h"
 #include "GeneralServer/GeneralServer.h"
 #include "GeneralServer/GeneralServerFeature.h"
@@ -336,8 +337,20 @@ void HttpCommTask<T>::checkVSTPrefix() {
                       asio_ns::transfer_at_least(11), std::move(cb));
 }
 
+#ifdef USE_DTRACE
+// Moved here to prevent multiplicity by template
+static void __attribute__ ((noinline)) DTraceHttpCommTaskProcessRequest(size_t th) {
+  DTRACE_PROBE1(arangod, HttpCommTaskProcessRequest, th);
+}
+#else
+static void DTraceHttpCommTaskProcessRequest(size_t) {}
+#endif
+
 template <SocketType T>
 void HttpCommTask<T>::processRequest() {
+
+  DTraceHttpCommTaskProcessRequest((size_t) this);
+
   TRI_ASSERT(_request);
   this->_protocol->timer.cancel();
 
@@ -414,9 +427,21 @@ void HttpCommTask<T>::processRequest() {
   this->executeRequest(std::move(_request), std::move(resp));
 }
 
+#ifdef USE_DTRACE
+// Moved here to prevent multiplicity by template
+static void __attribute__ ((noinline)) DTraceHttpCommTaskSendResponse(size_t th) {
+  DTRACE_PROBE1(arangod, HttpCommTaskSendResponse, th);
+}
+#else
+static void DTraceHttpCommTaskSendResponse(size_t) {}
+#endif
+
 template <SocketType T>
 void HttpCommTask<T>::sendResponse(std::unique_ptr<GeneralResponse> baseRes,
                                    RequestStatistics* stat) {
+
+  DTraceHttpCommTaskSendResponse((size_t) this);
+
   if (this->_stopped.load(std::memory_order_acquire)) {
     return;
   }
@@ -534,9 +559,25 @@ void HttpCommTask<T>::sendResponse(std::unique_ptr<GeneralResponse> baseRes,
   });
 }
 
+#ifdef USE_DTRACE
+// Moved here to prevent multiplicity by template
+static void __attribute__ ((noinline)) DTraceHttpCommTaskWriteResponse(size_t th) {
+  DTRACE_PROBE1(arangod, HttpCommTaskWriteResponse, th);
+}
+static void __attribute__ ((noinline)) DTraceHttpCommTaskResponseWritten(size_t th) {
+  DTRACE_PROBE1(arangod, HttpCommTaskResponseWritten, th);
+}
+#else
+static void DTraceHttpCommTaskWriteResponse(size_t) {}
+static void DTraceHttpCommTaskResponseWritten(size_t) {}
+#endif
+
 // called on IO context thread
 template <SocketType T>
 void HttpCommTask<T>::writeResponse(RequestStatistics* stat) {
+
+  DTraceHttpCommTaskWriteResponse((size_t) this);
+
   TRI_ASSERT(!_header.empty());
 
   RequestStatistics::SET_WRITE_START(stat);
@@ -551,6 +592,9 @@ void HttpCommTask<T>::writeResponse(RequestStatistics* stat) {
   asio_ns::async_write(this->_protocol->socket, buffers,
                        [self = this->shared_from_this(),
                         stat](asio_ns::error_code ec, size_t nwrite) {
+
+                         DTraceHttpCommTaskResponseWritten((size_t) self.get());
+
                          auto* thisPtr = static_cast<HttpCommTask<T>*>(self.get());
                          RequestStatistics::SET_WRITE_END(stat);
                          RequestStatistics::ADD_SENT_BYTES(stat, nwrite);

diff --git a/arangod/GeneralServer/RestHandler.cpp b/arangod/GeneralServer/RestHandler.cpp
@@ -29,6 +29,7 @@
 #include "ApplicationFeatures/ApplicationServer.h"
 #include "Basics/RecursiveLocker.h"
 #include "Basics/StringUtils.h"
+#include "Basics/dtrace-wrapper.h"
 #include "Cluster/ClusterFeature.h"
 #include "Cluster/ClusterInfo.h"
 #include "Cluster/ClusterMethods.h"
@@ -398,6 +399,7 @@ bool RestHandler::wakeupHandler() {
 }
 
 void RestHandler::executeEngine(bool isContinue) {
+  DTRACE_PROBE1(arangod, RestHandlerExecuteEngine, this);
   ExecContext* exec = static_cast<ExecContext*>(_request->requestContext());
   ExecContextScope scope(exec);
 

diff --git a/arangod/GeneralServer/SslServerFeature.cpp b/arangod/GeneralServer/SslServerFeature.cpp
@@ -73,7 +73,8 @@ SslServerFeature::SslServerFeature(application_features::ApplicationServer& serv
       _sslProtocol(TLS_GENERIC),
       _sslOptions(asio_ns::ssl::context::default_workarounds |
                   asio_ns::ssl::context::single_dh_use),
-      _ecdhCurve("prime256v1") {
+      _ecdhCurve("prime256v1"),
+      _preferHttp11InAlpn(false) {
   setOptional(true);
   startsAfter<application_features::AqlFeaturePhase>();
 }
@@ -116,6 +117,10 @@ void SslServerFeature::collectOptions(std::shared_ptr<ProgramOptions> options) {
       "--ssl.ecdh-curve",
       "SSL ECDH Curve, see the output of \"openssl ecparam -list_curves\"",
       new StringParameter(&_ecdhCurve));
+
+  options->addOption("--ssl.prefer-http1-in-alpn",
+                     "Allows to let the server prefer HTTP/1.1 over HTTP/2 in ALPN protocol negotiations",
+                     new BooleanParameter(&_preferHttp11InAlpn));
 }
 
 void SslServerFeature::validateOptions(std::shared_ptr<ProgramOptions> options) {
@@ -201,12 +206,38 @@ class BIOGuard {
 };
 }  // namespace
 
+static inline bool searchForProtocol(const unsigned char** out, unsigned char* outlen,
+                                     const unsigned char* in, unsigned int inlen,
+                                     const char* proto) {
+  size_t len = strlen(proto);
+  size_t i = 0;
+  while (i + len <= inlen) {
+    if (memcmp(in + i, proto, len) == 0) {
+      *out = (const unsigned char *)(in + i + 1);
+      *outlen = proto[0];
+      return true;
+    }
+    i += in[i] + 1;
+  }
+  return false;
+}
+
 static int alpn_select_proto_cb(SSL* ssl, const unsigned char** out,
                                 unsigned char* outlen, const unsigned char* in,
                                 unsigned int inlen, void* arg) {
-  int rv = nghttp2_select_next_protocol((unsigned char**)out, outlen, in, inlen);
+  int rv = 0;
+  bool const* preferHttp11InAlpn = (bool*) arg;
+  if (*preferHttp11InAlpn) {
+    if (!searchForProtocol(out, outlen, in, inlen, "\x8http/1.1")) {
+      if (!searchForProtocol(out, outlen, in, inlen, "\x2h2")) {
+        rv = -1;
+      }
+    }
+  } else {
+    rv = nghttp2_select_next_protocol((unsigned char **)out, outlen, in, inlen);
+  }
 
-  if (rv != 1) {
+  if (rv < 0) {
     return SSL_TLSEXT_ERR_NOACK;
   }
 
@@ -344,7 +375,7 @@ asio_ns::ssl::context SslServerFeature::createSslContextInternal(std::string key
 
     sslContext.set_verify_mode(SSL_VERIFY_NONE);
 
-    SSL_CTX_set_alpn_select_cb(sslContext.native_handle(), alpn_select_proto_cb, NULL);
+    SSL_CTX_set_alpn_select_cb(sslContext.native_handle(), alpn_select_proto_cb, (void*) (&_preferHttp11InAlpn));
 
     return sslContext;
   } catch (std::exception const& ex) {

diff --git a/arangod/GeneralServer/SslServerFeature.h b/arangod/GeneralServer/SslServerFeature.h
@@ -90,6 +90,7 @@ class SslServerFeature : public application_features::ApplicationFeature {
   uint64_t _sslProtocol;
   uint64_t _sslOptions;
   std::string _ecdhCurve;
+  bool _preferHttp11InAlpn;
 
  private:
   asio_ns::ssl::context createSslContextInternal(std::string keyfileName,