diff --git a/Documentation/Books/Manual/Administration/Configuration/Endpoint.mdpp b/Documentation/Books/Manual/Administration/Configuration/Endpoint.mdpp index fb9091cc55..8af8c0d491 100644 --- a/Documentation/Books/Manual/Administration/Configuration/Endpoint.mdpp +++ b/Documentation/Books/Manual/Administration/Configuration/Endpoint.mdpp @@ -11,6 +11,10 @@ types of endpoints: - ssl://ipv4-address:port - TCP/IP endpoint, using IPv4, SSL encryption - ssl://[ipv6-address]:port - TCP/IP endpoint, using IPv6, SSL encryption - unix:///path/to/socket - Unix domain socket endpoint +- vpp+tcp://ipv4-address:port - TCP/IP endpoint, using IPv4, VelocyStream protocol +- vpp+tcp://[ipv6-address]:port - TCP/IP endpoint, using IPv6, VelocyStream protocol +- vpp+ssl://ipv4-address:port - TCP/IP endpoint, using IPv4, VelocyStream protocol, SSL encryption +- vpp+ssl://[ipv6-address]:port - TCP/IP endpoint, using IPv6, VelocyStream protocol, SSL encryption If a TCP/IP endpoint is specified without a port number, then the default port (8529) will be used. If multiple endpoints need to be used, the option can be @@ -69,6 +73,12 @@ ArangoDB can also do a so called *broadcast bind* using host. This may be useful on development systems that frequently change their network setup like laptops. +Use VelocyStream protocol: + +`--server.endpoint vpp+tcp://hostname:port` + +VelocyStream is the new symmetric binary protocol of ArangoDB. It supports sending messages back and forth, pipelined, multiplexed, uni-directional or bi-directional. The messages themselves are VelocyPack objects. Its specification will be released with ArangoDB 3.2, until that we keep us open to change it. + !SUBSECTION Reuse address `--tcp.reuse-address` diff --git a/arangod/Aql/BasicBlocks.cpp b/arangod/Aql/BasicBlocks.cpp index 5c8aea237a..1f62934a2c 100644 --- a/arangod/Aql/BasicBlocks.cpp +++ b/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 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 diff --git a/arangod/Aql/CalculationBlock.cpp b/arangod/Aql/CalculationBlock.cpp index 7db1d35f3e..c4f36b1d64 100644 --- a/arangod/Aql/CalculationBlock.cpp +++ b/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 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 * diff --git a/arangod/Aql/ClusterBlocks.cpp b/arangod/Aql/ClusterBlocks.cpp index c0cf444108..04bdef3f80 100644 --- a/arangod/Aql/ClusterBlocks.cpp +++ b/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(); diff --git a/arangod/Aql/EnumerateCollectionBlock.cpp b/arangod/Aql/EnumerateCollectionBlock.cpp index 9740573621..8715d3f061 100644 --- a/arangod/Aql/EnumerateCollectionBlock.cpp +++ b/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 diff --git a/arangod/Aql/EnumerateListBlock.cpp b/arangod/Aql/EnumerateListBlock.cpp index af5afe5f6c..e28bf21f95 100644 --- a/arangod/Aql/EnumerateListBlock.cpp +++ b/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(); } diff --git a/arangod/Aql/ExecutionBlock.cpp b/arangod/Aql/ExecutionBlock.cpp index dfa76eb139..f0d4582881 100644 --- a/arangod/Aql/ExecutionBlock.cpp +++ b/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 result( getSomeWithoutRegisterClearout(atLeast, atMost)); clearRegisters(result.get()); + traceGetSomeEnd(result.get()); return result.release(); DEBUG_END_BLOCK(); } diff --git a/arangod/Aql/ExecutionBlock.h b/arangod/Aql/ExecutionBlock.h index 101ea3794b..e7eeba257f 100644 --- a/arangod/Aql/ExecutionBlock.h +++ b/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 diff --git a/arangod/Aql/ExecutionEngine.cpp b/arangod/Aql/ExecutionEngine.cpp index ac08b456d2..ed56003016 100644 --- a/arangod/Aql/ExecutionEngine.cpp +++ b/arangod/Aql/ExecutionEngine.cpp @@ -511,6 +511,8 @@ struct CoordinatorInstanciator : public WalkerWorker { 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(); diff --git a/arangod/Aql/ExecutionNode.h b/arangod/Aql/ExecutionNode.h index 814b71cc49..af41c90150 100644 --- a/arangod/Aql/ExecutionNode.h +++ b/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; diff --git a/arangod/Aql/IndexBlock.cpp b/arangod/Aql/IndexBlock.cpp index 290d70c942..cfb7a078ea 100644 --- a/arangod/Aql/IndexBlock.cpp +++ b/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 diff --git a/arangod/Aql/ModificationBlocks.cpp b/arangod/Aql/ModificationBlocks.cpp index bcb5fff70c..d6b9dea92b 100644 --- a/arangod/Aql/ModificationBlocks.cpp +++ b/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(); } diff --git a/arangod/Aql/Query.cpp b/arangod/Aql/Query.cpp index bd5dd0cf84..49a166bb78 100644 --- a/arangod/Aql/Query.cpp +++ b/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; diff --git a/arangod/Aql/Query.h b/arangod/Aql/Query.h index be84d363bb..768d3dc540 100644 --- a/arangod/Aql/Query.h +++ b/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; diff --git a/arangod/Aql/ShortestPathBlock.cpp b/arangod/Aql/ShortestPathBlock.cpp index cea38ff6a8..a4452cbbe0 100644 --- a/arangod/Aql/ShortestPathBlock.cpp +++ b/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 diff --git a/arangod/Aql/SubqueryBlock.cpp b/arangod/Aql/SubqueryBlock.cpp index 015d101048..b1c1d5241a 100644 --- a/arangod/Aql/SubqueryBlock.cpp +++ b/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 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 diff --git a/arangod/Aql/TraversalBlock.cpp b/arangod/Aql/TraversalBlock.cpp index 9e563e0495..7c73c39071 100644 --- a/arangod/Aql/TraversalBlock.cpp +++ b/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