diff --git a/CHANGELOG b/CHANGELOG index e7fca6371a..1778bf6017 100644 --- a/CHANGELOG +++ b/CHANGELOG @@ -245,6 +245,7 @@ v3.1.19 (XXXX-XX-XX) * fixed issue #2440 + v3.1.18 (2017-04-18) -------------------- diff --git a/arangod/GeneralServer/GeneralCommTask.cpp b/arangod/GeneralServer/GeneralCommTask.cpp index b8b93161d2..58e5505a98 100644 --- a/arangod/GeneralServer/GeneralCommTask.cpp +++ b/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); diff --git a/arangod/GeneralServer/HttpCommTask.cpp b/arangod/GeneralServer/HttpCommTask.cpp index 5763a56c04..2762650c8a 100644 --- a/arangod/GeneralServer/HttpCommTask.cpp +++ b/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(response->responseCode()) << "," + << _originalBodyLength << "," << responseBodyLength << ",\"" << _fullUrl + << "\"," << stat->timingsCsv(); + } + addWriteBuffer(buffer); // and give some request information @@ -700,7 +714,7 @@ std::unique_ptr 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; } } diff --git a/arangod/GeneralServer/VppCommTask.cpp b/arangod/GeneralServer/VppCommTask.cpp index 71681410e9..e96e13edd1 100644 --- a/arangod/GeneralServer/VppCommTask.cpp +++ b/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(response->responseCode()) << "," + << _connectionInfo.clientAddress << "\"," << stat->timingsCsv(); + } + if (buffers.empty()) { if (stat != nullptr) { stat->release(); diff --git a/arangod/Scheduler/JobQueue.cpp b/arangod/Scheduler/JobQueue.cpp index a30cf204ce..765a442c9d 100644 --- a/arangod/Scheduler/JobQueue.cpp +++ b/arangod/Scheduler/JobQueue.cpp @@ -72,6 +72,8 @@ class JobQueueThread final std::shared_ptr 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) { diff --git a/arangod/Scheduler/Scheduler.cpp b/arangod/Scheduler/Scheduler.cpp index 6b6929b105..6fc35d64c0 100644 --- a/arangod/Scheduler/Scheduler.cpp +++ b/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) { + RequestStatistics::SET_QUEUE_START(job->_handler->statistics()); return _jobQueue->queue(std::move(job)); } diff --git a/arangod/Statistics/RequestStatistics.cpp b/arangod/Statistics/RequestStatistics.cpp index 2ef571aa7c..6d42a11674 100644 --- a/arangod/Statistics/RequestStatistics.cpp +++ b/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; diff --git a/arangod/Statistics/RequestStatistics.h b/arangod/Statistics/RequestStatistics.h index a01199742d..85b29c8d75 100644 --- a/arangod/Statistics/RequestStatistics.h +++ b/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();