Put tracing of AQL queries in.

Use by setting { tracing: 1} (only calls) or { tracing: 2} (with
result) into 4th argument of db._query

arangod/Aql/BasicBlocks.cpp

@@ -441,14 +441,17 @@ int LimitBlock::getOrSkipSome(size_t atLeast, size_t atMost, bool skipping,
 
 AqlItemBlock* ReturnBlock::getSome(size_t atLeast, size_t atMost) {
   DEBUG_BEGIN_BLOCK();
+  traceGetSomeBegin();
   std::unique_ptr<AqlItemBlock> res(
       ExecutionBlock::getSomeWithoutRegisterClearout(atLeast, atMost));
 
   if (res.get() == nullptr) {
+    traceGetSomeEnd(nullptr);
     return nullptr;
   }
 
   if (_returnInheritedResults) {
+    traceGetSomeEnd(res.get());
     return res.release();
   }
 
@@ -491,6 +494,7 @@ AqlItemBlock* ReturnBlock::getSome(size_t atLeast, size_t atMost) {
   delete res.get();
   res.release();
 
+  traceGetSomeEnd(stripped.get());
   return stripped.release();
 
   // cppcheck-suppress style

arangod/Aql/CalculationBlock.cpp

@@ -190,16 +190,19 @@ void CalculationBlock::doEvaluation(AqlItemBlock* result) {
 
 AqlItemBlock* CalculationBlock::getSome(size_t atLeast, size_t atMost) {
   DEBUG_BEGIN_BLOCK();
+  traceGetSomeBegin();
   std::unique_ptr<AqlItemBlock> res(
       ExecutionBlock::getSomeWithoutRegisterClearout(atLeast, atMost));
 
   if (res.get() == nullptr) {
+    traceGetSomeEnd(nullptr);
     return nullptr;
   }
 
   doEvaluation(res.get());
   // Clear out registers no longer needed later:
   clearRegisters(res.get());
+  traceGetSomeEnd(res.get());
   return res.release();
 
   // cppcheck-suppress *

arangod/Aql/ClusterBlocks.cpp

@@ -223,7 +223,9 @@ bool GatherBlock::hasMore() {
 /// @brief getSome
 AqlItemBlock* GatherBlock::getSome(size_t atLeast, size_t atMost) {
   DEBUG_BEGIN_BLOCK();
+  traceGetSomeBegin();
   if (_done) {
+    traceGetSomeEnd(nullptr);
     return nullptr;
   }
 
@@ -237,6 +239,7 @@ AqlItemBlock* GatherBlock::getSome(size_t atLeast, size_t atMost) {
     if (res == nullptr) {
       _done = true;
     }
+    traceGetSomeEnd(res);
     return res;
   }
 
@@ -266,6 +269,7 @@ AqlItemBlock* GatherBlock::getSome(size_t atLeast, size_t atMost) {
 
   if (available == 0) {
     _done = true;
+    traceGetSomeEnd(nullptr);
     return nullptr;
   }
 
@@ -321,6 +325,7 @@ AqlItemBlock* GatherBlock::getSome(size_t atLeast, size_t atMost) {
     }
   }
 
+  traceGetSomeEnd(res.get());
   return res.release();
 
   // cppcheck-suppress style
@@ -1377,6 +1382,8 @@ int RemoteBlock::shutdown(int errorCode) {
 AqlItemBlock* RemoteBlock::getSome(size_t atLeast, size_t atMost) {
   DEBUG_BEGIN_BLOCK();
   // For every call we simply forward via HTTP
+  
+  traceGetSomeBegin();
 
   VPackBuilder builder;
   builder.openObject();
@@ -1402,10 +1409,13 @@ AqlItemBlock* RemoteBlock::getSome(size_t atLeast, size_t atMost) {
   _deltaStats = newStats;
 
   if (VelocyPackHelper::getBooleanValue(responseBody, "exhausted", true)) {
+    traceGetSomeEnd(nullptr);
     return nullptr;
   }
 
-  return new arangodb::aql::AqlItemBlock(responseBody);
+  auto r = new arangodb::aql::AqlItemBlock(responseBody);
+  traceGetSomeEnd(r);
+  return r;
 
   // cppcheck-suppress style
   DEBUG_END_BLOCK();

arangod/Aql/EnumerateCollectionBlock.cpp

@@ -144,12 +144,14 @@ int EnumerateCollectionBlock::initializeCursor(AqlItemBlock* items,
 AqlItemBlock* EnumerateCollectionBlock::getSome(size_t,  // atLeast,
                                                 size_t atMost) {
   DEBUG_BEGIN_BLOCK();  
+  traceGetSomeBegin();
   // Invariants:
   //   As soon as we notice that _totalCount == 0, we set _done = true.
   //   Otherwise, outside of this method (or skipSome), _documents is
   //   either empty (at the beginning, with _posInDocuments == 0)
   //   or is non-empty and _posInDocuments < _documents.size()
   if (_done) {
+    traceGetSomeEnd(nullptr);
     return nullptr;
   }
   
@@ -225,6 +227,8 @@ AqlItemBlock* EnumerateCollectionBlock::getSome(size_t,  // atLeast,
   // Clear out registers no longer needed later:
   clearRegisters(res.get());
 
+  traceGetSomeEnd(res.get());
+
   return res.release();
 
   // cppcheck-suppress style

arangod/Aql/EnumerateListBlock.cpp

@@ -67,7 +67,9 @@ int EnumerateListBlock::initializeCursor(AqlItemBlock* items, size_t pos) {
 
 AqlItemBlock* EnumerateListBlock::getSome(size_t, size_t atMost) {
   DEBUG_BEGIN_BLOCK();  
+  traceGetSomeBegin();
   if (_done) {
+    traceGetSomeEnd(nullptr);
     return nullptr;
   }
 
@@ -83,6 +85,7 @@ AqlItemBlock* EnumerateListBlock::getSome(size_t, size_t atMost) {
       size_t toFetch = (std::min)(DefaultBatchSize(), atMost);
       if (!ExecutionBlock::getBlock(toFetch, toFetch)) {
         _done = true;
+        traceGetSomeEnd(nullptr);
         return nullptr;
       }
       _pos = 0;  // this is in the first block
@@ -160,6 +163,7 @@ AqlItemBlock* EnumerateListBlock::getSome(size_t, size_t atMost) {
 
   // Clear out registers no longer needed later:
   clearRegisters(res.get());
+  traceGetSomeEnd(res.get());
   return res.release();
   DEBUG_END_BLOCK();  
 }

arangod/Aql/ExecutionBlock.cpp

@@ -24,6 +24,7 @@
 
 #include "ExecutionBlock.h"
 #include "Aql/ExecutionEngine.h"
+#include "Aql/Ast.h"
 
 using namespace arangodb::aql;
 
@@ -32,7 +33,8 @@ ExecutionBlock::ExecutionBlock(ExecutionEngine* engine, ExecutionNode const* ep)
       _trx(engine->getQuery()->trx()),
       _exeNode(ep),
       _pos(0),
-      _done(false) {}
+      _done(false),
+      _tracing(engine->getQuery()->getNumericOption("tracing", 0)) {}
 
 ExecutionBlock::~ExecutionBlock() {
   for (auto& it : _buffer) {
@@ -147,6 +149,37 @@ int ExecutionBlock::shutdown(int errorCode) {
   return ret;
 }
 
+// Trace the start of a getSome call
+void ExecutionBlock::traceGetSomeBegin() const {
+  if (_tracing > 0) {
+    auto node = getPlanNode();
+    LOG_TOPIC(INFO, Logger::QUERIES) << "getSome type="
+      << node->getTypeString() << " this=" << (uintptr_t) this;
+  }
+}
+
+// Trace the end of a getSome call, potentially with result
+void ExecutionBlock::traceGetSomeEnd(AqlItemBlock const* result) const {
+  if (_tracing > 0) {
+    auto node = getPlanNode();
+    LOG_TOPIC(INFO, Logger::QUERIES) << "getSome done type="
+      << node->getTypeString() << " this=" << (uintptr_t) this;
+    if (_tracing > 1) {
+      if (result == nullptr) {
+        LOG_TOPIC(INFO, Logger::QUERIES) << "getSome result: nullptr";
+      } else {
+        VPackBuilder builder;
+        { 
+          VPackObjectBuilder guard(&builder);
+          result->toVelocyPack(_trx, builder);
+        }
+        LOG_TOPIC(INFO, Logger::QUERIES) << "getSome result: "
+          << builder.slice().toJson();
+      }
+    }
+  }
+}
+
 /// @brief getSome, gets some more items, semantic is as follows: not
 /// more than atMost items may be delivered. The method tries to
 /// return a block of at least atLeast items, however, it may return
@@ -154,9 +187,11 @@ int ExecutionBlock::shutdown(int errorCode) {
 /// if it returns an actual block, it must contain at least one item.
 AqlItemBlock* ExecutionBlock::getSome(size_t atLeast, size_t atMost) {
   DEBUG_BEGIN_BLOCK();
+  traceGetSomeBegin();
   std::unique_ptr<AqlItemBlock> result(
       getSomeWithoutRegisterClearout(atLeast, atMost));
   clearRegisters(result.get());
+  traceGetSomeEnd(result.get());
   return result.release();
   DEBUG_END_BLOCK();
 }

arangod/Aql/ExecutionBlock.h

@@ -140,6 +140,9 @@ class ExecutionBlock {
   /// if it returns an actual block, it must contain at least one item.
   virtual AqlItemBlock* getSome(size_t atLeast, size_t atMost);
 
+  void traceGetSomeBegin() const;
+  void traceGetSomeEnd(AqlItemBlock const*) const;
+
  protected:
   /// @brief request an AqlItemBlock from the memory manager
   AqlItemBlock* requestBlock(size_t, RegisterId);
@@ -223,6 +226,9 @@ class ExecutionBlock {
 
   /// @brief if this is set, we are done, this is reset to false by execute()
   bool _done;
+
+  /// A copy of the tracing value in the options:
+  double _tracing;
 };
 
 }  // namespace arangodb::aql

arangod/Aql/ExecutionEngine.cpp

@@ -511,6 +511,8 @@ struct CoordinatorInstanciator : public WalkerWorker<ExecutionNode> {
     result.add(VPackValue("-all"));
     result.close(); // options.optimizer.rules
     result.close(); // options.optimizer
+    double tracing = query->getNumericOption("tracing", 0);
+    result.add("tracing", VPackValue(tracing));
     result.close(); // options
 
     result.close();

arangod/Aql/ExecutionNode.h

@@ -433,6 +433,10 @@ class ExecutionNode {
     return false;
   }
 
+  ExecutionPlan const* plan() const { 
+    return _plan;
+  }
+
   /// @brief static analysis, walker class and information collector
   struct VarInfo {
     unsigned int depth;

arangod/Aql/IndexBlock.cpp

@@ -439,7 +439,9 @@ int IndexBlock::initializeCursor(AqlItemBlock* items, size_t pos) {
 /// @brief getSome
 AqlItemBlock* IndexBlock::getSome(size_t atLeast, size_t atMost) {
   DEBUG_BEGIN_BLOCK();
+  traceGetSomeBegin();
   if (_done) {
+    traceGetSomeEnd(nullptr);
     return nullptr;
   }
 
@@ -455,6 +457,7 @@ AqlItemBlock* IndexBlock::getSome(size_t atLeast, size_t atMost) {
       size_t toFetch = (std::min)(DefaultBatchSize(), atMost);
       if (!ExecutionBlock::getBlock(toFetch, toFetch) || (!initIndexes())) {
         _done = true;
+        traceGetSomeEnd(nullptr);
         return nullptr;
       }
       _pos = 0;  // this is in the first block
@@ -476,6 +479,7 @@ AqlItemBlock* IndexBlock::getSome(size_t atLeast, size_t atMost) {
         if (_buffer.empty()) {
           if (!ExecutionBlock::getBlock(DefaultBatchSize(), DefaultBatchSize())) {
             _done = true;
+            traceGetSomeEnd(nullptr);
             return nullptr;
           }
           _pos = 0;  // this is in the first block
@@ -483,6 +487,7 @@ AqlItemBlock* IndexBlock::getSome(size_t atLeast, size_t atMost) {
 
         if (!initIndexes()) {
           _done = true;
+          traceGetSomeEnd(nullptr);
           return nullptr;
         }
         readIndex(atMost);
@@ -530,6 +535,7 @@ AqlItemBlock* IndexBlock::getSome(size_t atLeast, size_t atMost) {
 
   // Clear out registers no longer needed later:
   clearRegisters(res.get());
+  traceGetSomeEnd(res.get());
   return res.release();
 
   // cppcheck-suppress style

arangod/Aql/ModificationBlocks.cpp

@@ -77,6 +77,7 @@ AqlItemBlock* ModificationBlock::getSome(size_t atLeast, size_t atMost) {
   // found, the UPSERTs INSERT operation may create it. after that, the
   // search document is present and we cannot use an already queried result
   // from the initial search batch
+  traceGetSomeBegin();
   if (getPlanNode()->getType() == ExecutionNode::NodeType::UPSERT) {
     atLeast = 1;
     atMost = 1;
@@ -150,6 +151,7 @@ AqlItemBlock* ModificationBlock::getSome(size_t atLeast, size_t atMost) {
 
   freeBlocks(blocks);
 
+  traceGetSomeEnd(replyBlocks.get());
   return replyBlocks.release();
 }
 

arangod/Aql/Query.cpp

@@ -170,18 +170,36 @@ Query::Query(bool contextOwnedByExterior, TRI_vocbase_t* vocbase,
       _isModificationQuery(false) {
   // std::cout << TRI_CurrentThreadId() << ", QUERY " << this << " CTOR: " <<
   // queryString << "\n";
-  LOG_TOPIC(DEBUG, Logger::QUERIES)
+  double tracing = getNumericOption("tracing", 0);
+  if (tracing > 0) {
+    LOG_TOPIC(INFO, Logger::QUERIES)
       << TRI_microtime() - _startTime << " "
       << "Query::Query queryString: " << std::string(queryString, queryLength)
       << " this: " << (uintptr_t) this;
+  } else {
+    LOG_TOPIC(DEBUG, Logger::QUERIES)
+      << TRI_microtime() - _startTime << " "
+      << "Query::Query queryString: " << std::string(queryString, queryLength)
+      << " this: " << (uintptr_t) this;
+  }
   if (bindParameters != nullptr && !bindParameters->isEmpty() &&
       !bindParameters->slice().isNone()) {
-    LOG_TOPIC(DEBUG, Logger::QUERIES)
-        << "bindParameters: " << bindParameters->slice().toJson();
+    if (tracing > 0) {
+      LOG_TOPIC(INFO, Logger::QUERIES)
+          << "bindParameters: " << bindParameters->slice().toJson();
+    } else {
+      LOG_TOPIC(DEBUG, Logger::QUERIES)
+          << "bindParameters: " << bindParameters->slice().toJson();
+    }
   }
   if (options != nullptr && !options->isEmpty() && !options->slice().isNone()) {
-    LOG_TOPIC(DEBUG, Logger::QUERIES)
-        << "options: " << options->slice().toJson();
+    if (tracing > 0) {
+      LOG_TOPIC(INFO, Logger::QUERIES)
+          << "options: " << options->slice().toJson();
+    } else {
+      LOG_TOPIC(DEBUG, Logger::QUERIES)
+          << "options: " << options->slice().toJson();
+    }
   }
   TRI_ASSERT(_vocbase != nullptr);
 }
@@ -229,7 +247,13 @@ Query::Query(bool contextOwnedByExterior, TRI_vocbase_t* vocbase,
 
 /// @brief destroys a query
 Query::~Query() {
-  // std::cout << TRI_CurrentThreadId() << ", QUERY " << this << " DTOR\r\n";
+  double tracing = getNumericOption("tracing", 0);
+  if (tracing > 0) {
+    LOG_TOPIC(INFO, Logger::QUERIES)
+      << TRI_microtime() - _startTime << " "
+      << "Query::~Query queryString: "
+      << " this: " << (uintptr_t) this;
+  }
   cleanupPlanAndEngine(TRI_ERROR_INTERNAL);  // abort the transaction
 
   delete _profile;

arangod/Aql/Query.h

@@ -320,8 +320,10 @@ class Query {
   bool canUseQueryCache() const;
 
   /// @brief fetch a numeric value from the options
+ public:
   double getNumericOption(char const*, double) const;
 
+ private:
   /// @brief read the "optimizer.inspectSimplePlans" section from the options
   bool inspectSimplePlans() const;
 

arangod/Aql/ShortestPathBlock.cpp

@@ -553,7 +553,9 @@ bool ShortestPathBlock::nextPath(AqlItemBlock const* items) {
 
 AqlItemBlock* ShortestPathBlock::getSome(size_t, size_t atMost) {
   DEBUG_BEGIN_BLOCK();
+  traceGetSomeBegin();
   if (_done) {
+    traceGetSomeEnd(nullptr);
     return nullptr;
   }
 
@@ -561,6 +563,7 @@ AqlItemBlock* ShortestPathBlock::getSome(size_t, size_t atMost) {
     size_t toFetch = (std::min)(DefaultBatchSize(), atMost);
     if (!ExecutionBlock::getBlock(toFetch, toFetch)) {
       _done = true;
+      traceGetSomeEnd(nullptr);
       return nullptr;
     }
     _pos = 0;  // this is in the first block
@@ -580,7 +583,9 @@ AqlItemBlock* ShortestPathBlock::getSome(size_t, size_t atMost) {
         delete cur;
         _pos = 0;
       }
-      return getSome(atMost, atMost);
+      auto r = getSome(atMost, atMost);
+      traceGetSomeEnd(r);
+      return r;
     }
   }
 
@@ -630,6 +635,7 @@ AqlItemBlock* ShortestPathBlock::getSome(size_t, size_t atMost) {
 
   // Clear out registers no longer needed later:
   clearRegisters(res.get());
+  traceGetSomeEnd(res.get());
   return res.release();
 
   // cppcheck-suppress style

arangod/Aql/SubqueryBlock.cpp

@@ -54,10 +54,12 @@ int SubqueryBlock::initialize() {
 /// @brief getSome
 AqlItemBlock* SubqueryBlock::getSome(size_t atLeast, size_t atMost) {
   DEBUG_BEGIN_BLOCK();
+  traceGetSomeBegin();
   std::unique_ptr<AqlItemBlock> res(
       ExecutionBlock::getSomeWithoutRegisterClearout(atLeast, atMost));
 
   if (res.get() == nullptr) {
+    traceGetSomeEnd(nullptr);
     return nullptr;
   }
 
@@ -112,6 +114,7 @@ AqlItemBlock* SubqueryBlock::getSome(size_t atLeast, size_t atMost) {
 
   // Clear out registers no longer needed later:
   clearRegisters(res.get());
+  traceGetSomeEnd(res.get());
   return res.release();
 
   // cppcheck-suppress style

arangod/Aql/TraversalBlock.cpp

@@ -337,7 +337,9 @@ void TraversalBlock::initializePaths(AqlItemBlock const* items, size_t pos) {
 AqlItemBlock* TraversalBlock::getSome(size_t,  // atLeast,
                                       size_t atMost) {
   DEBUG_BEGIN_BLOCK();
+  traceGetSomeBegin();
   if (_done) {
+    traceGetSomeEnd(nullptr);
     return nullptr;
   }
 
@@ -345,6 +347,7 @@ AqlItemBlock* TraversalBlock::getSome(size_t,  // atLeast,
     size_t toFetch = (std::min)(DefaultBatchSize(), atMost);
     if (!ExecutionBlock::getBlock(toFetch, toFetch)) {
       _done = true;
+      traceGetSomeEnd(nullptr);
       return nullptr;
     }
     _pos = 0;  // this is in the first block
@@ -372,7 +375,9 @@ AqlItemBlock* TraversalBlock::getSome(size_t,  // atLeast,
       } else {
         initializePaths(cur, _pos);
       }
-      return getSome(atMost, atMost);
+      auto r = getSome(atMost, atMost);
+      traceGetSomeEnd(r);
+      return r;
     }
   }
 
@@ -424,6 +429,7 @@ AqlItemBlock* TraversalBlock::getSome(size_t,  // atLeast,
 
   // Clear out registers no longer needed later:
   clearRegisters(res.get());
+  traceGetSomeEnd(res.get());
   return res.release();
 
   // cppcheck-suppress style