From e88460efcb87f2a80395c13a1a0e80c99bbfd7a0 Mon Sep 17 00:00:00 2001 From: Jan Steemann Date: Thu, 13 Oct 2016 10:31:16 +0200 Subject: [PATCH] add state "loading collections" to query profile results --- arangod/Aql/ExecutionStats.cpp | 2 +- arangod/Aql/Query.cpp | 34 ++++++++++++++----- arangod/Aql/Query.h | 1 + .../APP/frontend/js/views/queryView.js | 1 + lib/Basics/VelocyPackHelper.cpp | 9 +++++ lib/Basics/VelocyPackHelper.h | 3 ++ 6 files changed, 41 insertions(+), 9 deletions(-) diff --git a/arangod/Aql/ExecutionStats.cpp b/arangod/Aql/ExecutionStats.cpp index 5126ce02f8..d2e58d65d3 100644 --- a/arangod/Aql/ExecutionStats.cpp +++ b/arangod/Aql/ExecutionStats.cpp @@ -21,7 +21,7 @@ /// @author Jan Steemann //////////////////////////////////////////////////////////////////////////////// -#include "Aql/ExecutionStats.h" +#include "ExecutionStats.h" #include "Basics/Exceptions.h" #include diff --git a/arangod/Aql/Query.cpp b/arangod/Aql/Query.cpp index de91c4d322..bd5dd0cf84 100644 --- a/arangod/Aql/Query.cpp +++ b/arangod/Aql/Query.cpp @@ -67,6 +67,7 @@ static std::string StateNames[] = { "initializing", // INITIALIZATION "parsing", // PARSING "optimizing ast", // AST_OPTIMIZATION + "loading collections", // LOADING_COLLECTIONS "instantiating plan", // PLAN_INSTANTIATION "optimizing plan", // PLAN_OPTIMIZATION "executing", // EXECUTION @@ -456,17 +457,19 @@ QueryResult Query::prepare(QueryRegistry* registry) { if (_queryString != nullptr) { // we have an AST + // optimize the ast + enterState(AST_OPTIMIZATION); + + parser->ast()->validateAndOptimize(); + + enterState(LOADING_COLLECTIONS); + int res = trx->begin(); if (res != TRI_ERROR_NO_ERROR) { return transactionError(res); } - // optimize the ast - enterState(AST_OPTIMIZATION); - - parser->ast()->validateAndOptimize(); - enterState(PLAN_INSTANTIATION); plan.reset(ExecutionPlan::instantiateFromAst(parser->ast())); @@ -479,14 +482,14 @@ QueryResult Query::prepare(QueryRegistry* registry) { // Run the query optimizer: enterState(PLAN_OPTIMIZATION); arangodb::aql::Optimizer opt(maxNumberOfPlans()); - // getenabled/disabled rules + // get enabled/disabled rules opt.createPlans(plan.release(), getRulesFromOptions(), inspectSimplePlans()); // Now plan and all derived plans belong to the optimizer plan.reset(opt.stealBest()); // Now we own the best one again planRegisters = true; } else { // no queryString, we are instantiating from _queryBuilder - enterState(PLAN_INSTANTIATION); + enterState(PARSING); VPackSlice const querySlice = _queryBuilder->slice(); ExecutionPlan::getCollectionsFromVelocyPack(parser->ast(), querySlice); @@ -495,7 +498,9 @@ QueryResult Query::prepare(QueryRegistry* registry) { // creating the plan may have produced some collections // we need to add them to the transaction now (otherwise the query will // fail) - + + enterState(LOADING_COLLECTIONS); + int res = trx->addCollectionList(_collections.collections()); if (res == TRI_ERROR_NO_ERROR) { @@ -505,6 +510,8 @@ QueryResult Query::prepare(QueryRegistry* registry) { if (res != TRI_ERROR_NO_ERROR) { return transactionError(res); } + + enterState(PLAN_INSTANTIATION); // we have an execution plan in VelocyPack format plan.reset(ExecutionPlan::instantiateFromVelocyPack( @@ -702,9 +709,14 @@ QueryResult Query::execute(QueryRegistry* registry) { result.profile = _profile->toVelocyPack(); } + // 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); + LOG_TOPIC(DEBUG, Logger::QUERIES) << TRI_microtime() - _startTime << " " << "Query::execute:returning" << " this: " << (uintptr_t) this; + return result; } catch (arangodb::basics::Exception const& ex) { setExecutionTime(); @@ -881,6 +893,10 @@ QueryResultV8 Query::executeV8(v8::Isolate* isolate, QueryRegistry* registry) { if (_profile != nullptr && profiling()) { result.profile = _profile->toVelocyPack(); } + + // 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); return result; } catch (arangodb::basics::Exception const& ex) { @@ -941,6 +957,8 @@ QueryResult Query::explain() { enterState(AST_OPTIMIZATION); // optimize and validate the ast parser.ast()->validateAndOptimize(); + + enterState(LOADING_COLLECTIONS); // create the transaction object, but do not start it yet _trx = new arangodb::AqlTransaction(createTransactionContext(), diff --git a/arangod/Aql/Query.h b/arangod/Aql/Query.h index 48aac1f2f2..be84d363bb 100644 --- a/arangod/Aql/Query.h +++ b/arangod/Aql/Query.h @@ -67,6 +67,7 @@ enum ExecutionState { INITIALIZATION = 0, PARSING, AST_OPTIMIZATION, + LOADING_COLLECTIONS, PLAN_INSTANTIATION, PLAN_OPTIMIZATION, EXECUTION, diff --git a/js/apps/system/_admin/aardvark/APP/frontend/js/views/queryView.js b/js/apps/system/_admin/aardvark/APP/frontend/js/views/queryView.js index 1f46a6d8e0..49959c2a87 100644 --- a/js/apps/system/_admin/aardvark/APP/frontend/js/views/queryView.js +++ b/js/apps/system/_admin/aardvark/APP/frontend/js/views/queryView.js @@ -1915,6 +1915,7 @@ 'startup time for query engine', 'query parsing', 'abstract syntax tree optimizations', + 'loading collections', 'instanciation of initial execution plan', 'execution plan optimization and permutation', 'query execution' diff --git a/lib/Basics/VelocyPackHelper.cpp b/lib/Basics/VelocyPackHelper.cpp index 1752b05c3f..acffd270e7 100644 --- a/lib/Basics/VelocyPackHelper.cpp +++ b/lib/Basics/VelocyPackHelper.cpp @@ -877,6 +877,15 @@ double VelocyPackHelper::toDouble(VPackSlice const& slice, bool& failed) { failed = true; return 0.0; } + +// modify a VPack double value in place +void VelocyPackHelper::patchDouble(VPackSlice slice, double value) { + TRI_ASSERT(slice.isDouble()); + // get pointer to the start of the value + uint8_t* p = const_cast(slice.begin()); + // skip one byte for the header and overwrite + *reinterpret_cast(p + 1) = value; +} #ifndef USE_ENTERPRISE uint64_t VelocyPackHelper::hashByAttributes( diff --git a/lib/Basics/VelocyPackHelper.h b/lib/Basics/VelocyPackHelper.h index 28737cd9cf..3a2c45b40e 100644 --- a/lib/Basics/VelocyPackHelper.h +++ b/lib/Basics/VelocyPackHelper.h @@ -324,6 +324,9 @@ class VelocyPackHelper { static double toDouble(VPackSlice const&, bool&); + // modify a VPack double value in place + static void patchDouble(VPackSlice slice, double value); + static uint64_t hashByAttributes(VPackSlice, std::vector const&, bool, int&, std::string const& key = "");