From 1b7b668066a8b488d18fb75b079969f14d967fc8 Mon Sep 17 00:00:00 2001 From: jsteemann Date: Thu, 2 Mar 2017 13:20:37 +0100 Subject: [PATCH] simplify query list a great deal and use less dynamic memory for its entries --- arangod/Aql/Query.cpp | 28 ++-- arangod/Aql/Query.h | 3 + arangod/Aql/QueryExecutionState.cpp | 8 +- arangod/Aql/QueryExecutionState.h | 2 + arangod/Aql/QueryList.cpp | 179 +++++++++++------------ arangod/Aql/QueryList.h | 26 ++-- arangod/Aql/QueryProfile.cpp | 4 +- arangod/RestHandler/RestQueryHandler.cpp | 9 +- arangod/V8Server/v8-vocbase.cpp | 11 +- 9 files changed, 131 insertions(+), 139 deletions(-) diff --git a/arangod/Aql/Query.cpp b/arangod/Aql/Query.cpp index ebe8f249f3..be4397c957 100644 --- a/arangod/Aql/Query.cpp +++ b/arangod/Aql/Query.cpp @@ -732,7 +732,7 @@ QueryResult Query::execute(QueryRegistry* registry) { // patch stats in place // we do this because "executionTime" should include the whole span of the execution and we have to set it at the very end - basics::VelocyPackHelper::patchDouble(result.stats->slice().get("executionTime"), TRI_microtime() - _startTime); + basics::VelocyPackHelper::patchDouble(result.stats->slice().get("executionTime"), runTime()); LOG_TOPIC(DEBUG, Logger::QUERIES) << TRI_microtime() - _startTime << " " << "Query::execute:returning" @@ -742,22 +742,22 @@ QueryResult Query::execute(QueryRegistry* registry) { } catch (arangodb::basics::Exception const& ex) { setExecutionTime(); cleanupPlanAndEngine(ex.code()); - return QueryResult(ex.code(), ex.message() + QueryExecutionState::toString(_state)); + return QueryResult(ex.code(), ex.message() + QueryExecutionState::toStringWithPrefix(_state)); } catch (std::bad_alloc const&) { setExecutionTime(); cleanupPlanAndEngine(TRI_ERROR_OUT_OF_MEMORY); return QueryResult( TRI_ERROR_OUT_OF_MEMORY, - TRI_errno_string(TRI_ERROR_OUT_OF_MEMORY) + QueryExecutionState::toString(_state)); + TRI_errno_string(TRI_ERROR_OUT_OF_MEMORY) + QueryExecutionState::toStringWithPrefix(_state)); } catch (std::exception const& ex) { setExecutionTime(); cleanupPlanAndEngine(TRI_ERROR_INTERNAL); - return QueryResult(TRI_ERROR_INTERNAL, ex.what() + QueryExecutionState::toString(_state)); + return QueryResult(TRI_ERROR_INTERNAL, ex.what() + QueryExecutionState::toStringWithPrefix(_state)); } catch (...) { setExecutionTime(); cleanupPlanAndEngine(TRI_ERROR_INTERNAL); return QueryResult(TRI_ERROR_INTERNAL, - TRI_errno_string(TRI_ERROR_INTERNAL) + QueryExecutionState::toString(_state)); + TRI_errno_string(TRI_ERROR_INTERNAL) + QueryExecutionState::toStringWithPrefix(_state)); } } @@ -918,7 +918,7 @@ QueryResultV8 Query::executeV8(v8::Isolate* isolate, QueryRegistry* registry) { // patch executionTime stats value in place // we do this because "executionTime" should include the whole span of the execution and we have to set it at the very end - basics::VelocyPackHelper::patchDouble(result.stats->slice().get("executionTime"), TRI_microtime() - _startTime); + basics::VelocyPackHelper::patchDouble(result.stats->slice().get("executionTime"), runTime()); LOG_TOPIC(DEBUG, Logger::QUERIES) << TRI_microtime() - _startTime << " " << "Query::executeV8:returning" @@ -928,22 +928,22 @@ QueryResultV8 Query::executeV8(v8::Isolate* isolate, QueryRegistry* registry) { } catch (arangodb::basics::Exception const& ex) { setExecutionTime(); cleanupPlanAndEngine(ex.code()); - return QueryResultV8(ex.code(), ex.message() + QueryExecutionState::toString(_state)); + return QueryResultV8(ex.code(), ex.message() + QueryExecutionState::toStringWithPrefix(_state)); } catch (std::bad_alloc const&) { setExecutionTime(); cleanupPlanAndEngine(TRI_ERROR_OUT_OF_MEMORY); return QueryResultV8( TRI_ERROR_OUT_OF_MEMORY, - TRI_errno_string(TRI_ERROR_OUT_OF_MEMORY) + QueryExecutionState::toString(_state)); + TRI_errno_string(TRI_ERROR_OUT_OF_MEMORY) + QueryExecutionState::toStringWithPrefix(_state)); } catch (std::exception const& ex) { setExecutionTime(); cleanupPlanAndEngine(TRI_ERROR_INTERNAL); - return QueryResultV8(TRI_ERROR_INTERNAL, ex.what() + QueryExecutionState::toString(_state)); + return QueryResultV8(TRI_ERROR_INTERNAL, ex.what() + QueryExecutionState::toStringWithPrefix(_state)); } catch (...) { setExecutionTime(); cleanupPlanAndEngine(TRI_ERROR_INTERNAL); return QueryResult(TRI_ERROR_INTERNAL, - TRI_errno_string(TRI_ERROR_INTERNAL) + QueryExecutionState::toString(_state)); + TRI_errno_string(TRI_ERROR_INTERNAL) + QueryExecutionState::toStringWithPrefix(_state)); } } @@ -1056,16 +1056,16 @@ QueryResult Query::explain() { return result; } catch (arangodb::basics::Exception const& ex) { - return QueryResult(ex.code(), ex.message() + QueryExecutionState::toString(_state)); + return QueryResult(ex.code(), ex.message() + QueryExecutionState::toStringWithPrefix(_state)); } catch (std::bad_alloc const&) { return QueryResult( TRI_ERROR_OUT_OF_MEMORY, - TRI_errno_string(TRI_ERROR_OUT_OF_MEMORY) + QueryExecutionState::toString(_state)); + TRI_errno_string(TRI_ERROR_OUT_OF_MEMORY) + QueryExecutionState::toStringWithPrefix(_state)); } catch (std::exception const& ex) { - return QueryResult(TRI_ERROR_INTERNAL, ex.what() + QueryExecutionState::toString(_state)); + return QueryResult(TRI_ERROR_INTERNAL, ex.what() + QueryExecutionState::toStringWithPrefix(_state)); } catch (...) { return QueryResult(TRI_ERROR_INTERNAL, - TRI_errno_string(TRI_ERROR_INTERNAL) + QueryExecutionState::toString(_state)); + TRI_errno_string(TRI_ERROR_INTERNAL) + QueryExecutionState::toStringWithPrefix(_state)); } } diff --git a/arangod/Aql/Query.h b/arangod/Aql/Query.h index 6e563cd473..0c56093964 100644 --- a/arangod/Aql/Query.h +++ b/arangod/Aql/Query.h @@ -104,6 +104,9 @@ class Query { /// @brief return the start timestamp of the query double startTime () const { return _startTime; } + + /// @brief return the current runtime of the query + double runTime () const { return TRI_microtime() - _startTime; } /// @brief whether or not the query is killed inline bool killed() const { return _killed; } diff --git a/arangod/Aql/QueryExecutionState.cpp b/arangod/Aql/QueryExecutionState.cpp index ab50736550..9c772ec986 100644 --- a/arangod/Aql/QueryExecutionState.cpp +++ b/arangod/Aql/QueryExecutionState.cpp @@ -26,7 +26,7 @@ using namespace arangodb::aql; /// @brief names of query phases / states -static std::string StateNames[] = { +static std::string const StateNames[] = { "initializing", // INITIALIZATION "parsing", // PARSING "optimizing ast", // AST_OPTIMIZATION @@ -35,6 +35,7 @@ static std::string StateNames[] = { "optimizing plan", // PLAN_OPTIMIZATION "executing", // EXECUTION "finalizing", // FINALIZATION + "finished", // FINISHED "invalid" // INVALID }; @@ -46,6 +47,11 @@ static_assert(sizeof(StateNames) / sizeof(std::string) == /// @brief get a description of the query's current state std::string QueryExecutionState::toString(QueryExecutionState::ValueType state) { + return StateNames[static_cast(state)]; +} + +/// @brief get a description of the query's current state, prefixed with " (while " +std::string QueryExecutionState::toStringWithPrefix(QueryExecutionState::ValueType state) { return std::string(" (while " + StateNames[static_cast(state)] + ")"); } diff --git a/arangod/Aql/QueryExecutionState.h b/arangod/Aql/QueryExecutionState.h index 15955957d9..0e0da97329 100644 --- a/arangod/Aql/QueryExecutionState.h +++ b/arangod/Aql/QueryExecutionState.h @@ -42,11 +42,13 @@ enum class ValueType { PLAN_OPTIMIZATION, EXECUTION, FINALIZATION, + FINISHED, INVALID_STATE }; std::string toString(QueryExecutionState::ValueType state); +std::string toStringWithPrefix(QueryExecutionState::ValueType state); } } diff --git a/arangod/Aql/QueryList.cpp b/arangod/Aql/QueryList.cpp index 938802fdc6..a21ba7da72 100644 --- a/arangod/Aql/QueryList.cpp +++ b/arangod/Aql/QueryList.cpp @@ -31,14 +31,11 @@ using namespace arangodb::aql; -QueryEntry::QueryEntry(arangodb::aql::Query const* query, double started) - : query(query), started(started) {} - QueryEntryCopy::QueryEntryCopy(TRI_voc_tick_t id, std::string const& queryString, double started, - double runTime, std::string const& queryState) + double runTime, QueryExecutionState::ValueType state) : id(id), queryString(queryString), started(started), runTime(runTime), - queryState(queryState) {} + state(state) {} double const QueryList::DefaultSlowQueryThreshold = 10.0; size_t const QueryList::DefaultMaxSlowQueries = 64; @@ -62,32 +59,26 @@ QueryList::QueryList(TRI_vocbase_t*) QueryList::~QueryList() { WRITE_LOCKER(writeLocker, _lock); - for (auto& it : _current) { - delete it.second; - } _current.clear(); _slow.clear(); } /// @brief insert a query -bool QueryList::insert(Query const* query, double stamp) { +bool QueryList::insert(Query const* query) { // not enable or no query string if (!_enabled || query == nullptr || query->queryString() == nullptr) { return false; } try { - auto entry = std::make_unique(query, stamp); - WRITE_LOCKER(writeLocker, _lock); TRI_IF_FAILURE("QueryList::insert") { THROW_ARANGO_EXCEPTION(TRI_ERROR_DEBUG); } - auto it = _current.emplace(query->id(), entry.get()); + auto it = _current.emplace(query->id(), query); if (it.second) { - entry.release(); return true; } } catch (...) { @@ -97,7 +88,7 @@ bool QueryList::insert(Query const* query, double stamp) { } /// @brief remove a query -void QueryList::remove(Query const* query, double now) { +void QueryList::remove(Query const* query) { // we're intentionally not checking _enabled here... // note: there is the possibility that a query got inserted when the @@ -111,78 +102,77 @@ void QueryList::remove(Query const* query, double now) { } size_t const maxLength = _maxQueryStringLength; - QueryEntry* entry = nullptr; - { - WRITE_LOCKER(writeLocker, _lock); - auto it = _current.find(query->id()); + WRITE_LOCKER(writeLocker, _lock); + auto it = _current.find(query->id()); - if (it != _current.end()) { - entry = (*it).second; - _current.erase(it); + if (it != _current.end()) { + Query const* query = (*it).second; + _current.erase(it); - TRI_ASSERT(entry != nullptr); + TRI_ASSERT(query != nullptr); + double const started = query->startTime(); + double const now = TRI_microtime(); - try { - // check if we need to push the query into the list of slow queries - if (_trackSlowQueries && _slowQueryThreshold >= 0.0 && - now - entry->started >= _slowQueryThreshold) { - // yes. + try { + // check if we need to push the query into the list of slow queries + if (_trackSlowQueries && _slowQueryThreshold >= 0.0 && + now - started >= _slowQueryThreshold) { + // yes. - char const* queryString = entry->query->queryString(); - size_t const originalLength = entry->query->queryLength(); - size_t length = originalLength; + std::string q; + char const* queryString = query->queryString(); + size_t length = query->queryLength(); - if (length > maxLength) { - length = maxLength; - TRI_ASSERT(length <= originalLength); + if (length > maxLength) { + // query string needs truncation + length = maxLength; - // do not create invalid UTF-8 sequences - while (length > 0) { - uint8_t c = queryString[length - 1]; - if ((c & 128) == 0) { - // single-byte character - break; - } - --length; + // do not create invalid UTF-8 sequences + while (length > 0) { + uint8_t c = queryString[length - 1]; + if ((c & 128) == 0) { + // single-byte character + break; + } + --length; - // start of a multi-byte sequence - if ((c & 192) == 192) { - // decrease length by one more, so we the string contains the - // last part of the previous (multi-byte?) sequence - break; - } + // start of a multi-byte sequence + if ((c & 192) == 192) { + // decrease length by one more, so we the string contains the + // last part of the previous (multi-byte?) sequence + break; } } - - TRI_IF_FAILURE("QueryList::remove") { - THROW_ARANGO_EXCEPTION(TRI_ERROR_DEBUG); - } - - std::string q(queryString, length); - q.append(originalLength > maxLength ? "..." : ""); - - LOG_TOPIC(WARN, Logger::QUERIES) << "slow query: '" << q << "', took: " << Logger::FIXED(now - entry->started); - - _slow.emplace_back(QueryEntryCopy( - entry->query->id(), - std::move(q), - entry->started, now - entry->started, - std::string(" (while finished)"))); - - if (++_slowCount > _maxSlowQueries) { - // free first element - _slow.pop_front(); - --_slowCount; - } + + q.reserve(length + 3); + q.append(queryString, length); + q.append("...", 3); + } else { + // no truncation + q.append(queryString, length); } - } catch (...) { - } - } - } - if (entry != nullptr) { - delete entry; + TRI_IF_FAILURE("QueryList::remove") { + THROW_ARANGO_EXCEPTION(TRI_ERROR_DEBUG); + } + + LOG_TOPIC(WARN, Logger::QUERIES) << "slow query: '" << q << "', took: " << Logger::FIXED(now - started); + + _slow.emplace_back(QueryEntryCopy( + query->id(), + std::move(q), + started, now - started, + QueryExecutionState::ValueType::FINISHED)); + + if (++_slowCount > _maxSlowQueries) { + // free first element + _slow.pop_front(); + --_slowCount; + } + } + } catch (...) { + } } } @@ -199,10 +189,10 @@ int QueryList::kill(TRI_voc_tick_t id) { return TRI_ERROR_QUERY_NOT_FOUND; } - auto entry = (*it).second; - queryString.assign(entry->query->queryString(), - entry->query->queryLength()); - const_cast(entry->query)->killed(true); + Query const* query = (*it).second; + queryString.assign(query->queryString(), + query->queryLength()); + const_cast(query)->killed(true); } // log outside the lock @@ -218,20 +208,19 @@ uint64_t QueryList::killAll(bool silent) { WRITE_LOCKER(writeLocker, _lock); for (auto& it : _current) { - auto entry = it.second; - const_cast(entry->query)->killed(true); + Query const* query = it.second; - ++killed; - - std::string queryString(entry->query->queryString(), - entry->query->queryLength()); + std::string queryString(query->queryString(), + query->queryLength()); - if (silent) { - LOG_TOPIC(TRACE, arangodb::Logger::FIXME) << "killing AQL query " << entry->query->id() << " '" << queryString << "'"; + LOG_TOPIC(TRACE, arangodb::Logger::FIXME) << "killing AQL query " << query->id() << " '" << queryString << "'"; } else { - LOG_TOPIC(WARN, arangodb::Logger::FIXME) << "killing AQL query " << entry->query->id() << " '" << queryString << "'"; + LOG_TOPIC(WARN, arangodb::Logger::FIXME) << "killing AQL query " << query->id() << " '" << queryString << "'"; } + + const_cast(query)->killed(true); + ++killed; } return killed; @@ -249,14 +238,14 @@ std::vector QueryList::listCurrent() { result.reserve(_current.size()); for (auto const& it : _current) { - auto entry = it.second; + Query const* query = it.second; - if (entry == nullptr || entry->query->queryString() == nullptr) { + if (query == nullptr || query->queryString() == nullptr) { continue; } - char const* queryString = entry->query->queryString(); - size_t const originalLength = entry->query->queryLength(); + char const* queryString = query->queryString(); + size_t const originalLength = query->queryLength(); size_t length = originalLength; if (length > maxLength) { @@ -280,13 +269,15 @@ std::vector QueryList::listCurrent() { } } } + + double const started = query->startTime(); result.emplace_back( - QueryEntryCopy(entry->query->id(), + QueryEntryCopy(query->id(), std::string(queryString, length) .append(originalLength > maxLength ? "..." : ""), - entry->started, now - entry->started, - QueryExecutionState::toString(entry->query->state()))); + started, now - started, + query->state())); } } diff --git a/arangod/Aql/QueryList.h b/arangod/Aql/QueryList.h index a933683123..1981e66027 100644 --- a/arangod/Aql/QueryList.h +++ b/arangod/Aql/QueryList.h @@ -25,6 +25,7 @@ #define ARANGOD_AQL_QUERY_LIST_H 1 #include "Basics/Common.h" +#include "Aql/QueryExecutionState.h" #include "Basics/ReadWriteLock.h" #include "VocBase/voc-types.h" @@ -41,25 +42,18 @@ class Query; // --SECTION-- struct QueryEntry // ----------------------------------------------------------------------------- -struct QueryEntry { - QueryEntry(arangodb::aql::Query const*, double); - - arangodb::aql::Query const* query; - double const started; -}; - struct QueryEntryCopy { - QueryEntryCopy (TRI_voc_tick_t, - std::string const&, - double, - double, - std::string const&); + QueryEntryCopy (TRI_voc_tick_t id, + std::string const& queryString, + double started, + double runTime, + QueryExecutionState::ValueType state); TRI_voc_tick_t id; std::string queryString; double started; double runTime; - std::string queryState; + QueryExecutionState::ValueType state; }; class QueryList { @@ -143,10 +137,10 @@ class QueryList { } /// @brief enter a query - bool insert(Query const*, double); + bool insert(Query const*); /// @brief remove a query - void remove(Query const*, double); + void remove(Query const*); /// @brief kills a query int kill(TRI_voc_tick_t); @@ -168,7 +162,7 @@ class QueryList { arangodb::basics::ReadWriteLock _lock; /// @brief list of current queries - std::unordered_map _current; + std::unordered_map _current; /// @brief list of slow queries std::list _slow; diff --git a/arangod/Aql/QueryProfile.cpp b/arangod/Aql/QueryProfile.cpp index 196c6bea59..fc75fca51d 100644 --- a/arangod/Aql/QueryProfile.cpp +++ b/arangod/Aql/QueryProfile.cpp @@ -39,7 +39,7 @@ QueryProfile::QueryProfile(Query* query) auto queryList = query->vocbase()->queryList(); try { - tracked = queryList->insert(query, stamp); + tracked = queryList->insert(query); } catch (...) { } } @@ -51,7 +51,7 @@ QueryProfile::~QueryProfile() { auto queryList = query->vocbase()->queryList(); try { - queryList->remove(query, stamp); + queryList->remove(query); } catch (...) { } } diff --git a/arangod/RestHandler/RestQueryHandler.cpp b/arangod/RestHandler/RestQueryHandler.cpp index d9bd32f0c2..1edf853caa 100644 --- a/arangod/RestHandler/RestQueryHandler.cpp +++ b/arangod/RestHandler/RestQueryHandler.cpp @@ -106,17 +106,14 @@ bool RestQueryHandler::readQuery(bool slow) { result.add(VPackValue(VPackValueType::Array)); for (auto const& q : queries) { - auto const& timeString = TRI_StringTimeStamp(q.started, Logger::getUseLocalTime()); - - auto const& queryString = q.queryString; - auto const& queryState = q.queryState.substr(8, q.queryState.size() - 9); + auto timeString = TRI_StringTimeStamp(q.started, Logger::getUseLocalTime()); result.add(VPackValue(VPackValueType::Object)); result.add("id", VPackValue(StringUtils::itoa(q.id))); - result.add("query", VPackValue(queryString)); + result.add("query", VPackValue(q.queryString)); result.add("started", VPackValue(timeString)); result.add("runTime", VPackValue(q.runTime)); - result.add("state", VPackValue(queryState)); + result.add("state", VPackValue(QueryExecutionState::toString(q.state))); result.close(); } result.close(); diff --git a/arangod/V8Server/v8-vocbase.cpp b/arangod/V8Server/v8-vocbase.cpp index 05052c0fae..b65e0c4724 100644 --- a/arangod/V8Server/v8-vocbase.cpp +++ b/arangod/V8Server/v8-vocbase.cpp @@ -39,6 +39,7 @@ #include "ApplicationFeatures/HttpEndpointProvider.h" #include "Aql/Query.h" #include "Aql/QueryCache.h" +#include "Aql/QueryExecutionState.h" #include "Aql/QueryList.h" #include "Aql/QueryRegistry.h" #include "Basics/HybridLogicalClock.h" @@ -1475,8 +1476,7 @@ static void JS_QueriesCurrentAql( auto result = v8::Array::New(isolate, static_cast(queries.size())); for (auto q : queries) { - auto const&& timeString = TRI_StringTimeStamp(q.started, false); - auto const& queryState = q.queryState.substr(8, q.queryState.size() - 9); + auto timeString = TRI_StringTimeStamp(q.started, false); v8::Handle obj = v8::Object::New(isolate); obj->Set(TRI_V8_ASCII_STRING("id"), V8TickId(isolate, q.id)); @@ -1484,7 +1484,7 @@ static void JS_QueriesCurrentAql( obj->Set(TRI_V8_ASCII_STRING("started"), TRI_V8_STD_STRING(timeString)); obj->Set(TRI_V8_ASCII_STRING("runTime"), v8::Number::New(isolate, q.runTime)); - obj->Set(TRI_V8_ASCII_STRING("state"), TRI_V8_STD_STRING(queryState)); + obj->Set(TRI_V8_ASCII_STRING("state"), TRI_V8_STD_STRING(aql::QueryExecutionState::toString(q.state))); result->Set(i++, obj); } @@ -1528,8 +1528,7 @@ static void JS_QueriesSlowAql(v8::FunctionCallbackInfo const& args) { auto result = v8::Array::New(isolate, static_cast(queries.size())); for (auto q : queries) { - auto const&& timeString = TRI_StringTimeStamp(q.started, false); - auto const& queryState = q.queryState.substr(8, q.queryState.size() - 9); + auto timeString = TRI_StringTimeStamp(q.started, false); v8::Handle obj = v8::Object::New(isolate); obj->Set(TRI_V8_ASCII_STRING("id"), V8TickId(isolate, q.id)); @@ -1537,7 +1536,7 @@ static void JS_QueriesSlowAql(v8::FunctionCallbackInfo const& args) { obj->Set(TRI_V8_ASCII_STRING("started"), TRI_V8_STD_STRING(timeString)); obj->Set(TRI_V8_ASCII_STRING("runTime"), v8::Number::New(isolate, q.runTime)); - obj->Set(TRI_V8_ASCII_STRING("state"), TRI_V8_STD_STRING(queryState)); + obj->Set(TRI_V8_ASCII_STRING("state"), TRI_V8_STD_STRING(aql::QueryExecutionState::toString(q.state))); result->Set(i++, obj); }