Add DTRACE probes for request infrastructure timing.

So far, we are doing HttpCommTask and H2CommTask. This is optional use -DUSE_DTRACE=1 to activate.
arangodb · jsteemann · Mar 20, 2020 · Mar 3, 2020 · Mar 4, 2020 · Mar 4, 2020
commit 47bacf74c36b1513f1808f8a9bdd7b6089204cdc
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
@@ -25,6 +25,10 @@
 
 #include "CommTask.h"
 
+#ifdef USE_DTRACE
+#include <sys/sdt.h>
+#endif
+
 #include "ApplicationFeatures/ApplicationServer.h"
 #include "Basics/EncodingUtils.h"
 #include "Basics/HybridLogicalClock.h"
@@ -150,6 +154,11 @@ bool resolveRequestContext(GeneralRequest& req) {
 
 CommTask::Flow CommTask::prepareExecution(auth::TokenCache::Entry const& authToken,
                                           GeneralRequest& req) {
+
+#ifdef USE_DTRACE
+  DTRACE_PROBE1(arangod, CommTaskPrepareExecution, this);
+#endif
+
   // Step 1: In the shutdown phase we simply return 503:
   if (_server.server().isStopping()) {
     addErrorResponse(ResponseCode::SERVICE_UNAVAILABLE, req.contentTypeResponse(),
@@ -324,7 +333,11 @@ void CommTask::finishExecution(GeneralResponse& res, std::string const& origin)
 
 void CommTask::executeRequest(std::unique_ptr<GeneralRequest> request,
                               std::unique_ptr<GeneralResponse> response) {
-
+
+#ifdef USE_DTRACE
+  DTRACE_PROBE1(arangod, CommTaskExecuteRequest, this);
+#endif
+
   response->setContentTypeRequested(request->contentTypeResponse());
   response->setGenerateBody(request->requestType() != RequestType::HEAD);
 
@@ -516,6 +529,11 @@ void CommTask::addErrorResponse(rest::ResponseCode code,
 // and scheduled later when the number of used threads decreases
 
 bool CommTask::handleRequestSync(std::shared_ptr<RestHandler> handler) {
+
+#ifdef USE_DTRACE
+  DTRACE_PROBE2(arangod, CommTaskHandleRequestSync, this, handler.get());
+#endif
+
   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
@@ -22,6 +22,10 @@
 
 #include "H2CommTask.h"
 
+#ifdef USE_DTRACE
+#include <sys/sdt.h>
+#endif
+
 #include "Basics/Exceptions.h"
 #include "Basics/ScopeGuard.h"
 #include "Basics/asio_ns.h"
@@ -389,8 +393,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);
+}
+#endif
+
 template <SocketType T>
 void H2CommTask<T>::processStream(H2CommTask<T>::Stream* stream) {
+
+#ifdef USE_DTRACE
+  DTraceH2CommTaskProcessStream((size_t) this);
+#endif
+
   TRI_ASSERT(stream);
 
   std::unique_ptr<HttpRequest> req = std::move(stream->request);
@@ -463,10 +479,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);
+}
+#endif
+
 template <SocketType T>
 void H2CommTask<T>::sendResponse(std::unique_ptr<GeneralResponse> res,
                                  RequestStatistics* stat) {
-
+
+#ifdef USE_DTRACE
+  DTraceH2CommTaskSendResponse((size_t) this);
+#endif
+
   // TODO the statistics are total bogus here
   double const totalTime = RequestStatistics::ELAPSED_SINCE_READ_START(stat);
   if (stat) {
@@ -630,6 +657,16 @@ 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);
+}
+#endif
+
 // called on IO context thread
 template <SocketType T>
 void H2CommTask<T>::doWrite() {
@@ -685,6 +722,10 @@ void H2CommTask<T>::doWrite() {
     return;
   }
 
+#ifdef USE_DTRACE
+  DTraceH2CommTaskBeforeAsyncWrite((size_t) this);
+#endif
+
   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 +736,10 @@ void H2CommTask<T>::doWrite() {
                            return;
                          }
 
+#ifdef USE_DTRACE
+                         DTraceH2CommTaskAfterAsyncWrite((size_t) self.get());
+#endif
+
                          me.doWrite();
                        });
 }

diff --git a/arangod/GeneralServer/HttpCommTask.cpp b/arangod/GeneralServer/HttpCommTask.cpp
@@ -23,6 +23,10 @@
 
 #include "HttpCommTask.h"
 
+#ifdef USE_DTRACE
+#include <sys/sdt.h>
+#endif
+
 #include "Basics/ScopeGuard.h"
 #include "Basics/asio_ns.h"
 #include "Cluster/ServerState.h"
@@ -336,8 +340,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);
+}
+#endif
+
 template <SocketType T>
 void HttpCommTask<T>::processRequest() {
+
+#ifdef USE_DTRACE
+  DTraceHttpCommTaskProcessRequest((size_t) this);
+#endif
+
   TRI_ASSERT(_request);
   this->_protocol->timer.cancel();
 
@@ -414,9 +430,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);
+}
+#endif
+
 template <SocketType T>
 void HttpCommTask<T>::sendResponse(std::unique_ptr<GeneralResponse> baseRes,
                                    RequestStatistics* stat) {
+
+#ifdef USE_DTRACE
+  DTraceHttpCommTaskSendResponse((size_t) this);
+#endif
+
   if (this->_stopped.load(std::memory_order_acquire)) {
     return;
   }
@@ -534,9 +562,24 @@ 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);
+}
+#endif
+
 // called on IO context thread
 template <SocketType T>
 void HttpCommTask<T>::writeResponse(RequestStatistics* stat) {
+
+#ifdef USE_DTRACE
+  DTraceHttpCommTaskWriteResponse((size_t) this);
+#endif
+
   TRI_ASSERT(!_header.empty());
 
   RequestStatistics::SET_WRITE_START(stat);
@@ -551,6 +594,11 @@ 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) {
+
+#ifdef USE_DTRACE
+                         DTraceHttpCommTaskResponseWritten((size_t) self.get());
+#endif
+
                          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
@@ -23,6 +23,10 @@
 
 #include "RestHandler.h"
 
+#ifdef USE_DTRACE
+#include <sys/sdt.h>
+#endif
+
 #include <fuerte/jwt.h>
 #include <velocypack/Exception.h>
 
@@ -398,6 +402,11 @@ bool RestHandler::wakeupHandler() {
 }
 
 void RestHandler::executeEngine(bool isContinue) {
+
+#ifdef USE_DTRACE
+  DTRACE_PROBE1(arangod, RestHandlerExecuteEngine, this);
+#endif
+
   ExecContext* exec = static_cast<ExecContext*>(_request->requestContext());
   ExecContextScope scope(exec);