fix query execution times that may have different between batches (#2606)

* fix query execution times that may have different between batches

* applied query statistic change to ui

* do not expose state "finished", as it is useless

arangod/Aql/Query.cpp

@@ -653,25 +653,29 @@ QueryResult Query::execute(QueryRegistry* registry) {
     QueryResult result; 
     result.context = _trx->transactionContext();
 
-    _engine->_stats.setExecutionTime(TRI_microtime() - _startTime);
+    _engine->_stats.setExecutionTime(runTime());
+    enterState(QueryExecutionState::ValueType::FINALIZATION);
+
     auto stats = std::make_shared<VPackBuilder>();
     cleanupPlanAndEngine(TRI_ERROR_NO_ERROR, stats.get());
 
-    enterState(QueryExecutionState::ValueType::FINALIZATION);
- 
     result.warnings = warningsToVelocyPack();
-    result.result = resultBuilder;
-    result.stats = stats;
-
-    if (_profile != nullptr && _queryOptions.profile) {
-      result.profile = _profile->toVelocyPack();
-    }
+    result.result = std::move(resultBuilder);
+    result.stats = std::move(stats);
 
     // 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"), runTime());
+    double now = TRI_microtime();
+    double const rt = runTime(now);
+    basics::VelocyPackHelper::patchDouble(result.stats->slice().get("executionTime"), rt);
 
-    LOG_TOPIC(DEBUG, Logger::QUERIES) << TRI_microtime() - _startTime << " "
+    if (_profile != nullptr && _queryOptions.profile) {
+      _profile->setEnd(QueryExecutionState::ValueType::FINALIZATION, now);
+      result.profile = _profile->toVelocyPack();
+    }
+
+
+    LOG_TOPIC(DEBUG, Logger::QUERIES) << rt << " "
                                       << "Query::execute:returning"
                                       << " this: " << (uintptr_t) this;
     
@@ -840,24 +844,27 @@ QueryResultV8 Query::executeV8(v8::Isolate* isolate, QueryRegistry* registry) {
 
     result.context = _trx->transactionContext();
 
-    _engine->_stats.setExecutionTime(TRI_microtime() - _startTime);
+    _engine->_stats.setExecutionTime(runTime());
+    enterState(QueryExecutionState::ValueType::FINALIZATION);
+
     auto stats = std::make_shared<VPackBuilder>();
     cleanupPlanAndEngine(TRI_ERROR_NO_ERROR, stats.get());
 
-    enterState(QueryExecutionState::ValueType::FINALIZATION);
-
     result.warnings = warningsToVelocyPack();
-    result.stats = stats;
-
-    if (_profile != nullptr && _queryOptions.profile) {
-      result.profile = _profile->toVelocyPack();
-    }
+    result.stats = std::move(stats);
 
     // 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"), runTime());
+    double now = TRI_microtime();
+    double const rt = runTime(now);
+    basics::VelocyPackHelper::patchDouble(result.stats->slice().get("executionTime"), rt);
 
-    LOG_TOPIC(DEBUG, Logger::QUERIES) << TRI_microtime() - _startTime << " "
+    if (_profile != nullptr && _queryOptions.profile) {
+      _profile->setEnd(QueryExecutionState::ValueType::FINALIZATION, now);
+      result.profile = _profile->toVelocyPack();
+    }
+    
+    LOG_TOPIC(DEBUG, Logger::QUERIES) << rt << " "
                                       << "Query::executeV8:returning"
                                       << " this: " << (uintptr_t) this;
 

arangod/Aql/Query.h

@@ -116,7 +116,10 @@ class Query {
   double startTime() const { return _startTime; }
   
   /// @brief return the current runtime of the query
-  double runTime () const { return TRI_microtime() - _startTime; }
+  double runTime(double now) const { return now - _startTime; }
+  
+  /// @brief return the current runtime of the query
+  double runTime() const { return runTime(TRI_microtime()); }
 
   /// @brief whether or not the query is killed
   inline bool killed() const { return _killed; }

arangod/Aql/QueryProfile.cpp

@@ -63,7 +63,7 @@ QueryProfile::~QueryProfile() {
 }
 
 /// @brief sets a state to done
-void QueryProfile::setDone(QueryExecutionState::ValueType state) {
+double QueryProfile::setDone(QueryExecutionState::ValueType state) {
   double const now = TRI_microtime();
 
   if (state != QueryExecutionState::ValueType::INVALID_STATE) {
@@ -73,21 +73,27 @@ void QueryProfile::setDone(QueryExecutionState::ValueType state) {
 
   // set timestamp
   stamp = now;
+  return now;
+}
+
+/// @brief sets the absolute end time for an execution state
+void QueryProfile::setEnd(QueryExecutionState::ValueType state, double time) {
+  timers[static_cast<int>(state)] = time - stamp;
 }
 
 /// @brief convert the profile to VelocyPack
 std::shared_ptr<VPackBuilder> QueryProfile::toVelocyPack() {
   auto result = std::make_shared<VPackBuilder>();
-  {
-    VPackObjectBuilder b(result.get());
   
-    for (auto state : ENUM_ITERATOR(QueryExecutionState::ValueType, INITIALIZATION, FINISHED)) {
+  result->openObject(true);
+  for (auto state : ENUM_ITERATOR(QueryExecutionState::ValueType, INITIALIZATION, FINALIZATION)) {
     double const value = timers[static_cast<size_t>(state)];
 
-      if (value > 0.0) {
+    if (value >= 0.0) {
       result->add(QueryExecutionState::toString(state), VPackValue(value));
     }
   }
-  }
+  result->close();
+  
   return result;
 }

arangod/Aql/QueryProfile.h

@@ -46,7 +46,10 @@ struct QueryProfile {
 
   ~QueryProfile();
 
-  void setDone(QueryExecutionState::ValueType);
+  double setDone(QueryExecutionState::ValueType);
+
+  /// @brief sets the absolute end time for an execution state
+  void setEnd(QueryExecutionState::ValueType state, double time);
 
   /// @brief convert the profile to VelocyPack
   std::shared_ptr<arangodb::velocypack::Builder> toVelocyPack();

arangod/Utils/Cursor.cpp

@@ -49,8 +49,7 @@ Cursor::~Cursor() {}
 
 VPackSlice Cursor::extra() const {
   if (_extra == nullptr) {
-    VPackSlice empty;
-    return empty;
+    return VPackSlice();
   }
   return _extra->slice();
 }

arangod/Utils/Cursor.h

@@ -103,7 +103,7 @@ class Cursor {
   CursorId const _id;
   size_t const _batchSize;
   size_t _position;
-  std::shared_ptr<arangodb::velocypack::Builder> _extra;
+  std::shared_ptr<arangodb::velocypack::Builder> const _extra;
   double _ttl;
   double _expires;
   bool const _hasCount;

js/apps/system/_admin/aardvark/APP/frontend/js/views/queryView.js

@@ -2090,7 +2090,7 @@
           var profileWidth = 590;
 
           var legend = [
-            'A', 'B', 'C', 'D', 'E', 'F', 'G'
+            'A', 'B', 'C', 'D', 'E', 'F', 'G', 'H'
           ];
 
           var colors = [
@@ -2100,7 +2100,8 @@
             'rgb(93, 165, 218)',
             'rgb(250, 164, 58)',
             'rgb(64, 74, 83)',
-            'rgb(96, 189, 104)'
+            'rgb(96, 189, 104)',
+            'rgb(221, 224, 114)'
           ];
 
           var descs = [
@@ -2110,7 +2111,8 @@
             'loading collections',
             'instanciation of initial execution plan',
             'execution plan optimization and permutation',
-            'query execution'
+            'query execution',
+            'query finalization'
           ];
 
           queryProfile.append(
@@ -2123,8 +2125,10 @@
           );
 
           var total = 0;
-          _.each(data, function (value) {
+          _.each(data, function (value, key) {
+            if (key !== 'finished') {
               total += value * 1000;
+            }
           });
 
           var pos = 0;
@@ -2133,6 +2137,7 @@
 
           var time = '';
           _.each(data, function (value, key) {
+            if (key !== 'finished') {
               if (value > 1) {
                 time = numeral(value).format('0.000');
                 time += ' s';
@@ -2156,7 +2161,7 @@
                 adjustWidth++;
               }
 
-            if (pos !== 6) {
+              if (pos !== 7) {
                 queryProfile.find('.prof-progress').append(
                   '<div style="width: ' + width + '%; background-color: ' + colors[pos] + '"></div>'
                 );
@@ -2187,6 +2192,7 @@
                 }
               }
               pos++;
+            }
           });
 
           queryProfile.width(profileWidth);