added queue time and request tracing with timings

CHANGELOG

@@ -245,6 +245,7 @@ v3.1.19 (XXXX-XX-XX)
 * fixed issue #2440
 
 
+
 v3.1.18 (2017-04-18)
 --------------------
 

arangod/GeneralServer/GeneralCommTask.cpp

@@ -124,7 +124,7 @@ void GeneralCommTask::executeRequest(
       GeneralServerFeature::HANDLER_FACTORY->createHandler(
           std::move(request), std::move(response)));
 
-  // transfer statistics into handler
+  // give up, if we cannot find a handler
   if (handler == nullptr) {
     LOG_TOPIC(TRACE, arangodb::Logger::FIXME) << "no handler is known, giving up";
     handleSimpleError(rest::ResponseCode::NOT_FOUND, messageId);

arangod/GeneralServer/HttpCommTask.cpp

@@ -160,13 +160,27 @@ void HttpCommTask::addResponse(HttpResponse* response,
   if (!buffer._buffer->empty()) {
     LOG_TOPIC(TRACE, Logger::REQUESTS)
         << "\"http-request-response\",\"" << (void*)this << "\",\"" << _fullUrl
-        << "\",\"" << StringUtils::escapeUnicode(std::string(
-                          buffer._buffer->c_str(), buffer._buffer->length()))
+        << "\",\""
+        << StringUtils::escapeUnicode(
+               std::string(buffer._buffer->c_str(), buffer._buffer->length()))
         << "\"";
   }
 
   // append write buffer and statistics
   double const totalTime = RequestStatistics::ELAPSED_SINCE_READ_START(stat);
+
+  if (stat != nullptr && arangodb::Logger::isEnabled(arangodb::LogLevel::TRACE,
+                                                     Logger::REQUESTS)) {
+    LOG_TOPIC(TRACE, Logger::REQUESTS)
+        << "\"http-request-statistics\",\"" << (void*)this << "\",\""
+        << _connectionInfo.clientAddress << "\",\""
+        << HttpRequest::translateMethod(_requestType) << "\",\""
+        << HttpRequest::translateVersion(_protocolVersion) << "\","
+        << static_cast<int>(response->responseCode()) << ","
+        << _originalBodyLength << "," << responseBodyLength << ",\"" << _fullUrl
+        << "\"," << stat->timingsCsv();
+  }
+
   addWriteBuffer(buffer);
 
   // and give some request information
@@ -700,7 +714,7 @@ std::unique_ptr<GeneralResponse> HttpCommTask::createResponse(
 }
 
 void HttpCommTask::compactify() {
-  if (! _newRequest) {
+  if (!_newRequest) {
     return;
   }
 
@@ -731,7 +745,7 @@ void HttpCommTask::compactify() {
       TRI_ASSERT(_bodyPosition >= _readPosition);
       _bodyPosition -= _readPosition;
     }
-    
+
     _readPosition = 0;
   }
 }

arangod/GeneralServer/VppCommTask.cpp

@@ -139,6 +139,15 @@ void VppCommTask::addResponse(VppResponse* response, RequestStatistics* stat) {
   auto buffers = createChunkForNetwork(slices, id, chunkSize, false);
   double const totalTime = RequestStatistics::ELAPSED_SINCE_READ_START(stat);
 
+  if (stat != nullptr && arangodb::Logger::isEnabled(arangodb::LogLevel::TRACE,
+                                                     Logger::REQUESTS)) {
+    LOG_TOPIC(TRACE, Logger::REQUESTS)
+        << "\"vst-request-statistics\",\"" << (void*)this << "\",\""
+        << VppRequest::translateVersion(_protocolVersion) << "\","
+        << static_cast<int>(response->responseCode()) << ","
+        << _connectionInfo.clientAddress << "\"," << stat->timingsCsv();
+  }
+
   if (buffers.empty()) {
     if (stat != nullptr) {
       stat->release();

arangod/Scheduler/JobQueue.cpp

@@ -72,6 +72,8 @@ class JobQueueThread final
         std::shared_ptr<Job> job(jobPtr);
 
         _scheduler->post([this, self, job]() {
+          RequestStatistics::SET_QUEUE_END(job->_handler->statistics());
+
           try {
             job->_callback(std::move(job->_handler));
           } catch (std::exception& e) {

arangod/Scheduler/Scheduler.cpp

@@ -34,6 +34,7 @@
 #include "Basics/MutexLocker.h"
 #include "Basics/StringUtils.h"
 #include "Basics/Thread.h"
+#include "GeneralServer/RestHandler.h"
 #include "Logger/Logger.h"
 #include "Rest/GeneralResponse.h"
 #include "Scheduler/JobGuard.h"
@@ -328,6 +329,7 @@ bool Scheduler::hasQueueCapacity() const {
 }
 
 bool Scheduler::queue(std::unique_ptr<Job> job) {
+  RequestStatistics::SET_QUEUE_START(job->_handler->statistics());
   return _jobQueue->queue(std::move(job));
 }
 

arangod/Statistics/RequestStatistics.cpp

@@ -213,6 +213,19 @@ void RequestStatistics::fill(StatisticsDistribution& totalTime,
   bytesReceived = *TRI_BytesReceivedDistributionStatistics;
 }
 
+std::string RequestStatistics::timingsCsv() {
+  std::stringstream ss;
+
+  ss << std::setprecision(9) << std::fixed
+     << "read," << (_readEnd - _readStart)
+     << ",queue," << (_queueEnd - _queueStart)
+     << ",request," << (_requestEnd - _requestStart)
+     << ",total," << (StatisticsFeature::time() - _readStart)
+     << ",error," << (_executeError ? "true" : "false");
+
+  return ss.str();
+}
+
 std::string RequestStatistics::to_string() {
   std::stringstream ss;
 

arangod/Statistics/RequestStatistics.h

@@ -87,6 +87,18 @@ class RequestStatistics {
     }
   }
 
+  static void SET_QUEUE_START(RequestStatistics* stat) {
+    if (stat != nullptr) {
+      stat->_queueStart = StatisticsFeature::time();
+    }
+  }
+
+  static void SET_QUEUE_END(RequestStatistics* stat) {
+    if (stat != nullptr) {
+      stat->_queueEnd = StatisticsFeature::time();
+    }
+  }
+
   static void ADD_RECEIVED_BYTES(RequestStatistics* stat, size_t bytes) {
     if (stat != nullptr) {
       stat->_receivedBytes += bytes;
@@ -134,6 +146,7 @@ class RequestStatistics {
                    basics::StatisticsDistribution& bytesSent,
                    basics::StatisticsDistribution& bytesReceived);
 
+  std::string timingsCsv();
   std::string to_string();
   void trace_log();