From ae0b99de6342d34c4cb1c686c47c2238188bb3d3 Mon Sep 17 00:00:00 2001 From: Jan Date: Thu, 5 Apr 2018 14:06:51 +0200 Subject: [PATCH] added ArangoShell helper function for packaging all information about an AQL query so it can be run and analyzed elsewhere: (#5010) query = "FOR doc IN @@collection FILTER doc.value > @value RETURN doc"; bind = { value: 42, "@collection": "mycollection" }; options = { examples: 10, anonymize: true }; require("@arangodb/aql/explainer").debugDump("/tmp/query-debug-info", query, bind, options); Entitled users can send the generated file to the ArangoDB support to facilitate reproduction and debugging. The data from the generated file can be restored and analyzed via the *inspectDump* function: require("@arangodb/aql/explainer").inspectDump("/tmp/query-debug-info"); --- CHANGELOG | 11 +- .../ExplainingQueries.md | 48 +++++ js/common/modules/@arangodb/aql/explainer.js | 165 +++++++++++++++++- 3 files changed, 218 insertions(+), 6 deletions(-) diff --git a/CHANGELOG b/CHANGELOG index 79df641437..48c8cc073d 100644 --- a/CHANGELOG +++ b/CHANGELOG @@ -1,6 +1,15 @@ -v3.3.6 (2018-XX-XX) +v3.3.6 (XXXX-XX-XX) ------------------- +* added ArangoShell helper function for packaging all information about an + AQL query so it can be run and analyzed elsewhere: + + query = "FOR doc IN mycollection FILTER doc.value > 42 RETURN doc"; + require("@arangodb/aql/explainer").debugDump("/tmp/query-debug-info", query); + + Entitled users can send the generated file to the ArangoDB support to facilitate + reproduction and debugging. + * added hidden option `--server.ask-jwt-secret`. This is an internal option for debugging and should not be exposed to end-users. diff --git a/Documentation/Books/AQL/ExecutionAndPerformance/ExplainingQueries.md b/Documentation/Books/AQL/ExecutionAndPerformance/ExplainingQueries.md index c69691044f..5c932abf86 100644 --- a/Documentation/Books/AQL/ExecutionAndPerformance/ExplainingQueries.md +++ b/Documentation/Books/AQL/ExecutionAndPerformance/ExplainingQueries.md @@ -122,3 +122,51 @@ The above command prints the query's execution plan in the ArangoShell directly, on the most important information. +### Gathering debug information about a query + +If an explain provides no suitable insight into why a query does not perform as +expected, it may be reported to the ArangoDB support. In order to make this as easy +as possible, there is a built-in command in ArangoShell for packaging the query, its +bind parameters and all data required to execute the query elsewhere. + +The command will store all data in a file with a configurable filename: + + @startDocuBlockInline 10_workWithAQL_debugging1 + @EXAMPLE_ARANGOSH_OUTPUT{10_workWithAQL_debugging1} + var query = "FOR doc IN mycollection FILTER doc.value > 42 RETURN doc"; + require("@arangodb/aql/explainer").debugDump("/tmp/query-debug-info", query); + @END_EXAMPLE_ARANGOSH_OUTPUT + @endDocuBlock 10_workWithAQL_debugging1 + +Entitled users can send the generated file to the ArangoDB support to facilitate +reproduction and debugging. + +If a query contains bind parameters, they will need to specified along with the query +string: + + @startDocuBlockInline 10_workWithAQL_debugging2 + @EXAMPLE_ARANGOSH_OUTPUT{10_workWithAQL_debugging2} + var query = "FOR doc IN @@collection FILTER doc.value > @value RETURN doc"; + var bind = { value: 42, "@collection": "mycollection" }; + require("@arangodb/aql/explainer").debugDump("/tmp/query-debug-info", query, bind); + @END_EXAMPLE_ARANGOSH_OUTPUT + @endDocuBlock 10_workWithAQL_debugging2 + +It is also possible to include example documents from the underlying collection in +order to make reproduction even easier. Example documents can be sent as they are, or +in an anonymized form. The number of example documents can be specified in the *examples* +options attribute, and should generally be kept low. The *anonymize* option will replace +the contents of string attributes in the examples with "XXX". It will however not +replace any other types of data (e.g. numeric values) or attribute names. Attribute +names in the examples will always be preserved because they may be indexed and used in +queries: + + @startDocuBlockInline 10_workWithAQL_debugging3 + @EXAMPLE_ARANGOSH_OUTPUT{10_workWithAQL_debugging3} + var query = "FOR doc IN @@collection FILTER doc.value > @value RETURN doc"; + var bind = { value: 42, "@collection": "mycollection" }; + var options = { examples: 10, anonymize: true }; + require("@arangodb/aql/explainer").debugDump("/tmp/query-debug-info", query, bind, options); + @END_EXAMPLE_ARANGOSH_OUTPUT + @endDocuBlock 10_workWithAQL_debugging3 + diff --git a/js/common/modules/@arangodb/aql/explainer.js b/js/common/modules/@arangodb/aql/explainer.js index 007dba37d4..1ecc8f6363 100644 --- a/js/common/modules/@arangodb/aql/explainer.js +++ b/js/common/modules/@arangodb/aql/explainer.js @@ -1254,8 +1254,8 @@ function processQuery (query, explain) { printWarnings(explain.warnings); } -/* the exposed function */ -function explain (data, options, shouldPrint) { +/* the exposed explain function */ +function explain(data, options, shouldPrint) { 'use strict'; if (typeof data === 'string') { data = { query: data }; @@ -1270,9 +1270,8 @@ function explain (data, options, shouldPrint) { options = options || { }; setColors(options.colors === undefined ? true : options.colors); - var stmt = db._createStatement(data); - - var result = stmt.explain(options); + let stmt = db._createStatement(data); + let result = stmt.explain(options); stringBuilder.clearOutput(); processQuery(data.query, result, true); @@ -1284,4 +1283,160 @@ function explain (data, options, shouldPrint) { } } +/* the exposed debug function */ +function debug(query, bindVars, options) { + 'use strict'; + let input = {}; + if (query instanceof Object) { + if (typeof query.toAQL === 'function') { + query = query.toAQL(); + } + input = query; + } else { + input.query = query; + if (bindVars !== undefined) { + input.bindVars = bindVars; + } + if (options !== undefined) { + input.options = options; + } + } + if (!input.options) { + input.options = {}; + } + + let anonymize = function(doc) { + if (Array.isArray(doc)) { + return doc.map(anonymize); + } + if (typeof doc === 'string') { + return Array(doc.length).join("X"); + } + if (doc === null || typeof doc === 'number' || typeof doc === 'boolean') { + return doc; + } + if (typeof doc === 'object') { + let result = {}; + Object.keys(doc).forEach(function(key) { + result[key] = anonymize(doc[key]); + }); + return result; + } + return doc; + }; + + let result = { + engine: db._engine(), + version: db._version(true), + query: input, + collections: {} + }; + + result.fancy = require("@arangodb/aql/explainer").explain(input, { colors: false }, false); + + let stmt = db._createStatement(input); + result.explain = stmt.explain(input.options); + + // add collection information + result.explain.plan.collections.forEach(function(collection) { + let c = db._collection(collection.name); + let examples; + if (input.options.examples) { + // include example data from collections + let max = 10; // default number of documents + if (typeof input.options.examples === 'number') { + max = input.options.examples; + } + if (max > 100) { + max = 100; + } else if (max < 0) { + max = 0; + } + examples = db._query("FOR doc IN @@collection LIMIT @max RETURN doc", { max, "@collection": collection.name }).toArray(); + if (input.options.anonymize) { + examples = examples.map(anonymize); + } + } + result.collections[collection.name] = { + type: c.type() === 2, + properties: c.properties(), + indexes: c.getIndexes(true), + count: c.count(), + counts: c.count(true), + examples + }; + }); + return result; +} + +function debugDump(filename, query, bindVars, options) { + let result = debug(query, bindVars, options); + require("fs").write(filename, JSON.stringify(result)); + require("console").log("stored query debug information in file '" + filename + "'"); +} + +function inspectDump(filename) { + let data = JSON.parse(require("fs").read(filename)); + if (db._engine().name !== data.engine.name) { + print("/* using different storage engine (' " + db._engine().name + "') than in debug information ('" + data.engine.name + "') */"); + } + + // all collections and indexes first, as data insertion may go wrong later + print("/* collections and indexes setup */"); + Object.keys(data.collections).forEach(function(collection) { + let details = data.collections[collection]; + print("db._drop(" + JSON.stringify(collection) + ");"); + if (details.type === 3) { + print("db._createEdgeCollection(" + JSON.stringify(collection) + ", " + JSON.stringify(details.properties) + ");"); + } else { + print("db._create(" + JSON.stringify(collection) + ", " + JSON.stringify(details.properties) + ");"); + } + details.indexes.forEach(function(index) { + delete index.figures; + delete index.selectivityEstimate; + if (index.type !== 'primary' && index.type !== 'edge') { + print("db[" + JSON.stringify(collection) + "].ensureIndex(" + JSON.stringify(index) + ");"); + } + }); + print(); + }); + print(); + + // insert example data + print("/* example data */"); + Object.keys(data.collections).forEach(function(collection) { + let details = data.collections[collection]; + if (details.examples) { + details.examples.forEach(function(example) { + print("db[" + JSON.stringify(collection) + "].insert(" + JSON.stringify(example) + ");"); + }); + } + let missing = details.count; + if (details.examples) { + missing -= details.examples.length; + } + if (missing > 0) { + print("/* collection '" + collection + "' needs " + missing + " more document(s) */"); + } + print(); + }); + print(); + + print("/* explain result */"); + print(data.fancy.trim().split(/\n/).map(function(line) { return "// " + line; }).join("\n")); + print(); + + print("/* explain command */"); + if (data.query.options) { + delete data.query.options.anonymize; + delete data.query.options.colors; + delete data.query.options.examples; + } + print("db._explain(" + JSON.stringify(data.query) + ");"); + print(); +} + exports.explain = explain; +exports.debug = debug; +exports.debugDump = debugDump; +exports.inspectDump = inspectDump;