8000 Show optimizer rules with highest execution times in explain output (… · adamjm/arangodb@d66b611 · GitHub
[go: up one dir, main page]
Skip to content

Commit d66b611

Browse files
jsteemannjsteemann
authored
Show optimizer rules with highest execution times in explain output (arangodb#12455)
1 parent de95505 commit d66b611

File tree

7 files changed

+307
-346
lines changed

7 files changed

+307
-346
lines changed

‎CHANGELOG

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,8 @@
11
devel
22
-----
33

4+
* Show optimizer rules with highest execution times in explain output.
5+
46
* Fixed that dropping a vanished follower works again. An exception response
57
to the replication request is now handled properly.
68

‎arangod/Aql/Optimizer.cpp

Lines changed: 39 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -28,6 +28,7 @@
2828
#include "Aql/OptimizerRule.h"
2929
#include "Aql/OptimizerRulesFeature.h"
3030
#include "Aql/QueryOptions.h"
31+
#include "Basics/system-functions.h"
3132
#include "Cluster/ServerState.h"
3233
#include "Logger/LogMacros.h"
3334
#include "Logger/Logger.h"
@@ -314,17 +315,30 @@ void Optimizer::createPlans(std::unique_ptr<ExecutionPlan> plan,
314315
}
315316

316317
p->findVarUsage();
317-
318-
// all optimizer rule functions must obey the following guidelines:
319-
// - the original plan passed to the rule function must be deleted if
320-
// and only if it has not been added (back) to the optimizer (using
321-
// addPlan).
322-
// - if the rule throws, then the original plan will be deleted by the
323-
// optimizer.
324-
// thus the rule must not have deleted the plan itself or add it
325-
// back to the optimizer
326318
p->setValidity(false);
327-
rule.func(this, std::move(p), rule);
319+
320+
if (queryOptions.getProfileLevel() >= PROFILE_LEVEL_BASIC) {
321+
// run rule with tracing optimizer rule execution time
322+
if (_stats.executionTimes == nullptr) {
323+
// allocate the map lazily, so we can save the initial memory allocation
324+
// in case tracing is disabled.
325+
_stats.executionTimes = std::make_unique<std::unordered_map<int, double>>();
326+
}
327+
TRI_ASSERT(_stats.executionTimes != nullptr);
328+
329+
double time = TRI_microtime();
330+
rule.func(this, std::move(p), rule);
331+
time = TRI_microtime() - time;
332+
auto [it, inserted] = _stats.executionTimes->try_emplace(rule.level, time);
333+
if (!inserted) {
334+
// a rule may have been executed before already. in this case, just add to the
335+
// already tracked time
336+
(*it).second += time;
337+
}
338+
} else {
339+
// run rule without tracing optimizer rules
340+
rule.func(this, std::move(p), rule);
341+
}
328342

329343
if (!rule.isHidden()) {
330344
++_stats.rulesExecuted;
@@ -437,3 +451,18 @@ void Optimizer::enableRule(ExecutionPlan* plan, arangodb::velocypack::StringRef
437451
enableRule(plan, OptimizerRulesFeature::translateRule(name));
438452
}
439453
}
454+
455+
void Optimizer::Stats::toVelocyPack(velocypack::Builder& b) const {
456+
velocypack::ObjectBuilder guard(&b, true);
457+
b.add("rulesExecuted", velocypack::Value(rulesExecuted));
458+
b.add("rulesSkipped", velocypack::Value(rulesSkipped));
459+
b.add("plansCreated", velocypack::Value(plansCreated));
460+
461+
if (executionTimes != nullptr) {
462+
b.add("rules", velocypack::Value(velocypack::ValueType::Object));
463+
for (auto const& it : *executionTimes) {
464+
b.add(OptimizerRulesFeature::translateRule(it.first), velocypack::Value(it.second));
465+
}
466+
b.close();
467+
}
468+
}

‎arangod/Aql/Optimizer.h

Lines changed: 5 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -101,12 +101,11 @@ class Optimizer {
101101
int64_t rulesSkipped = 0;
102102
int64_t plansCreated = 1; // 1 for the initial plan
103103

104-
void toVelocyPack(velocypack::Builder& b) const {
105-
velocypack::ObjectBuilder guard(&b, true);
106-
b.add("rulesExecuted", velocypack::Value(rulesExecuted));
107-
b.add("rulesSkipped", velocypack::Value(rulesSkipped));
108-
b.add("plansCreated", velocypack::Value(plansCreated));
109-
}
104+
/// @brief map with execution times per rule, only populated in
105+
/// case tracing is enabled, a nullptr otherwise!
106+
std::unique_ptr<std::unordered_map<int, double>> executionTimes;
107+
108+
void toVelocyPack(velocypack::Builder& b) const;
110109
};
111110

112111
/// @brief constructor, this will initialize the rules database

‎js/common/modules/@arangodb/aql/explainer.js

Lines changed: 35 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -218,20 +218,48 @@ function printModificationFlags(flags) {
218218
}
219219

220220
/* print optimizer rules */
221-
function printRules(rules) {
221+
function printRules(rules, stats) {
222222
'use strict';
223223

224+
const maxIdLen = String('Id').length;
224225
stringBuilder.appendLine(section('Optimization rules applied:'));
225226
if (rules.length === 0) {
226227
stringBuilder.appendLine(' ' + value('none'));
227228
} else {
228-
var maxIdLen = String('Id').length;
229229
stringBuilder.appendLine(' ' + pad(1 + maxIdLen - String('Id').length) + header('Id') + ' ' + header('RuleName'));
230-
for (var i = 0; i < rules.length; ++i) {
230+
for (let i = 0; i < rules.length; ++i) {
231231
stringBuilder.appendLine(' ' + pad(1 + maxIdLen - String(i + 1).length) + variable(String(i + 1)) + ' ' + keyword(rules[i]));
232232
}
233233
}
234234
stringBuilder.appendLine();
235+
236+
if (!stats || !stats.rules) {
237+
return;
238+
}
239+
240+
let maxNameLength = 0;
241+
let times = Object.keys(stats.rules).map(function(key) {
242+
if (key.length > maxNameLength) {
243+
maxNameLength = key.length;
244+
}
245+
return { name: key, time: stats.rules[key] };
246+
});
247+
times.sort(function(l, r) {
248+
// highest cost first
249+
return r.time - l.time;
250+
});
251+
// top few only
252+
times = times.slice(0, 5);
253+
254+
stringBuilder.appendLine(section('Optimization rules with highest execution times:'));
255+
stringBuilder.appendLine(' ' + header('RuleName') + ' ' + pad(maxNameLength - 'RuleName'.length) + header('Duration [s]'));
256+
times.forEach(function(rule) {
257+
stringBuilder.appendLine(' ' + keyword(rule.name) + ' ' + pad(12 + maxNameLength - rule.name.length - rule.time.toFixed(5).length) + value(rule.time.toFixed(5)));
258+
});
259+
260+
stringBuilder.appendLine();
261+
stringBuilder.appendLine(value(stats.rulesExecuted) + annotation(' rule(s) executed, ') + value(stats.plansCreated) + annotation(' plan(s) created'));
262+
stringBuilder.appendLine();
235263
}
236264

237265
/* print warnings */
@@ -2001,7 +2029,7 @@ function processQuery(query, explain, planIndex) {
20012029
printKShortestPathsDetails(kShortestPathsDetails);
20022030
stringBuilder.appendLine();
20032031

2004-
printRules(plan.rules);
2032+
printRules(plan.rules, explain.stats);
20052033
printModificationFlags(modificationFlags);
20062034
printWarnings(explain.warnings);
20072035
if (profileMode) {
@@ -2027,6 +2055,9 @@ function explain(data, options, shouldPrint) {
20272055
options.verbosePlans = true;
20282056
setColors(options.colors === undefined ? true : options.colors);
20292057

2058+
if (!options.profile) {
2059+
options.profile = 2;
2060+
}
20302061
stringBuilder.clearOutput();
20312062
let stmt = db._createStatement(data);
20322063
let result = stmt.explain(options);

‎tests/js/server/aql/aql-explain-all.js

Lines changed: 208 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,208 @@
1+
/*jshint globalstrict:false, strict:false, maxlen: 500 */
2+
/*global fail, assertEqual, assertTrue, assertFalse, AQL_EXPLAIN */
3+
////////////////////////////////////////////////////////////////////////////////
4+
/// @brief tests for optimizer rules
5+
///
6+
/// @file
7+
///
8+
/// DISCLAIMER
9+
///
10+
/// Copyright 2010-2012 triagens GmbH, Cologne, Germany
11+
///
12+
/// Licensed under the Apache License, Version 2.0 (the "License");
13+
/// you may not use this file except in compliance with the License.
14+
/// You may obtain a copy of the License at
15+
///
16+
/// http://www.apache.org/licenses/LICENSE-2.0
17+
///
18+
/// Unless required by applicable law or agreed to in writing, software
19+
/// distributed under the License is distributed on an "AS IS" BASIS,
20+
/// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
21+
/// See the License for the specific language governing permissions and
22+
/// limitations under the License.
23+
///
24+
/// Copyright holder is triAGENS GmbH, Cologne, Germany
25+
///
26+
/// @author Jan Steemann
27+
/// @author Copyright 2012, triAGENS GmbH, Cologne, Germany
28+
////////////////////////////////////////////////////////////////////////////////
29+
30+
let jsunity = require("jsunity");
31+
let errors = require("internal").errors;
32+
let db = require("@arangodb").db;
33+
34+
/// @brief test suite
35+
function explainSuite () {
36+
const cn = "UnitTestsAhuacatlExplain";
37+
38+
return {
39+
40+
setUpAll : function () {
41+
db._drop(cn);
42+
db._create(cn);
43+
},
44+
45+
tearDownAll : function () {
46+
db._drop(cn);
47+
},
48+
49+
testExplainStats : function () {
50+
let query = "FOR doc IN " + cn + " FILTER doc.value > 33 RETURN doc";
51+
let actual = AQL_EXPLAIN(query).stats;
52+
assertEqual(1, actual.plansCreated);
53+
assertTrue(actual.hasOwnProperty("plansCreated"));
54+
assertTrue(actual.hasOwnProperty("rulesExecuted"));
55+
assertTrue(actual.hasOwnProperty("rulesSkipped"));
56+
assertFalse(actual.hasOwnProperty("rules"));
57+
},
58+
59+
testExplainStatsRules : function () {
60+
let query = "FOR doc IN " + cn + " FILTER doc.value > 33 RETURN doc";
61+
let actual = AQL_EXPLAIN(query, null, { profile: 2 }).stats;
62+
assertEqual(1, actual.plansCreated);
63+
assertTrue(actual.hasOwnProperty("plansCreated"));
64+
assertTrue(actual.hasOwnProperty("rulesExecuted"));
65+
assertTrue(actual.hasOwnProperty("rulesSkipped"));
66+
assertTrue(actual.hasOwnProperty("rules"));
67+
let runRules = actual.rules;
68+
assertTrue(runRules.hasOwnProperty("move-filters-into-enumerate"));
69+
assertTrue(runRules.hasOwnProperty("remove-filter-covered-by-index"));
70+
},
71+
72+
////////////////////////////////////////////////////////////////////////////////
73+
/// @brief test bind parameters
74+
////////////////////////////////////////////////////////////////////////////////
75+
76+
testExplainBindMissing : function () {
77+
const query = "RETURN @foo";
78+
79+
try {
80+
AQL_EXPLAIN(query);
81+
fail();
82+
} catch (err) {
83+
assertEqual(err.errorNum, errors.ERROR_QUERY_BIND_PARAMETER_MISSING.code);
84+
}
85+
},
86+
87+
////////////////////////////////////////////////////////////////////////////////
88+
/// @brief test bind parameters
89+
////////////////////////////////////////////////////////////////////////////////
90+
91+
testExplainBindPresent : function () {
92+
const query = "RETURN @foo";
93+
94+
let actual = AQL_EXPLAIN(query, { foo: "bar" });
95+
assertEqual(3, actual.plan.nodes.length);
96+
assertEqual("SingletonNode", actual.plan.nodes[0].type);
97+
assertEqual("CalculationNode", actual.plan.nodes[1].type);
98+
assertEqual("ReturnNode", actual.plan.nodes[2].type);
99+
},
100+
101+
////////////////////////////////////////////////////////////////////////////////
102+
/// @brief test verbosity w/ single plan
103+
////////////////////////////////////////////////////////////////////////////////
104+
105+
testExplainVerbosity : function () {
106+
const query = "FOR i IN " + cn + " FOR j IN " + cn + " RETURN i";
107+
108+
// single plan, no options
109+
let actual = AQL_EXPLAIN(query);
110+
assertTrue(actual.hasOwnProperty("plan"));
111+
assertFalse(Array.isArray(actual.plan));
112+
assertTrue(actual.plan.hasOwnProperty("nodes"));
113+
assertTrue(Array.isArray(actual.plan.nodes));
114+
assertTrue(actual.plan.hasOwnProperty("rules"));
115+
assertTrue(Array.isArray(actual.plan.rules));
116+
assertTrue(actual.plan.hasOwnProperty("estimatedCost"));
117+
118+
actual.plan.nodes.forEach(function(node) {
119+
assertTrue(node.hasOwnProperty("type"));
120+
assertFalse(node.hasOwnProperty("typeID")); // deactivated if not verbose
121+
assertTrue(node.hasOwnProperty("dependencies"));
122+
assertTrue(Array.isArray(node.dependencies));
123+
assertFalse(node.hasOwnProperty("parents")); // deactivated if not verbose
124+
assertTrue(node.hasOwnProperty("id"));
125+
assertTrue(node.hasOwnProperty("estimatedCost"));
126+
});
127+
128+
// single plan, verbose options
129+
actual = AQL_EXPLAIN(query, { }, { verbosePlans: true });
130+
assertTrue(actual.hasOwnProperty("plan"));
131+
assertFalse(Array.isArray(actual.plan));
132+
assertTrue(actual.plan.hasOwnProperty("nodes"));
133+
assertTrue(Array.isArray(actual.plan.nodes));
134+
assertTrue(actual.plan.hasOwnProperty("rules"));
135+
assertTrue(Array.isArray(actual.plan.rules));
136+
137+
actual.plan.nodes.forEach(function(node) {
138+
assertTrue(node.hasOwnProperty("type"));
139+
assertTrue(node.hasOwnProperty("typeID"));
140+
assertTrue(node.hasOwnProperty("dependencies"));
141+
assertTrue(Array.isArray(node.dependencies));
142+
assertTrue(node.hasOwnProperty("parents"));
143+
assertTrue(Array.isArray(node.parents));
144+
assertTrue(node.hasOwnProperty("id"));
145+
assertTrue(node.hasOwnProperty("estimatedCost"));
146+
});
147+
},
148+
149+
////////////////////////////////////////////////////////////////////////////////
150+
/// @brief test explain w/ a signle plan vs. all plans
151+
////////////////////////////////////////////////////////////////////////////////
152+
153+
testExplainAllPlansVsSingle : function () {
154+
const query = "FOR i IN " + cn + " FOR j IN " + cn + " RETURN i";
155+
156+
// single plan
157+
let actual = AQL_EXPLAIN(query, { }, { verbosePlans: true });
158+
assertTrue(actual.hasOwnProperty("plan"));
159+
assertFalse(actual.hasOwnProperty("plans"));
160+
assertFalse(Array.isArray(actual.plan));
161+
162+
assertTrue(actual.plan.hasOwnProperty("nodes"));
163+
assertTrue(Array.isArray(actual.plan.nodes));
164+
165+
actual.plan.nodes.forEach(function(node) {
166+
assertTrue(node.hasOwnProperty("type"));
167+
assertTrue(node.hasOwnProperty("typeID"));
168+
assertTrue(node.hasOwnProperty("dependencies"));
169+
assertTrue(Array.isArray(node.dependencies));
170+
assertTrue(node.hasOwnProperty("parents"));
171+
assertTrue(node.hasOwnProperty("id"));
172+
assertTrue(node.hasOwnProperty("estimatedCost"));
173+
});
174+
175+
assertTrue(actual.plan.hasOwnProperty("rules"));
176+
assertTrue(Array.isArray(actual.plan.rules));
177+
178+
// multiple plans
179+
actual = AQL_EXPLAIN(query, { }, { allPlans: true, verbosePlans: true });
180+
assertFalse(actual.hasOwnProperty("plan"));
181+
assertTrue(actual.hasOwnProperty("plans"));
182+
assertTrue(Array.isArray(actual.plans));
183+
184+
actual.plans.forEach(function (plan) {
185+
assertTrue(plan.hasOwnProperty("nodes"));
186+
assertTrue(Array.isArray(plan.nodes));
187+
188+
plan.nodes.forEach(function(node) {
189+
assertTrue(node.hasOwnProperty("type"));
190+
assertTrue(node.hasOwnProperty("typeID"));
191+
assertTrue(node.hasOwnProperty("dependencies"));
192+
assertTrue(Array.isArray(node.dependencies));
193+
assertTrue(node.hasOwnProperty("parents"));
194+
assertTrue(node.hasOwnProperty("id"));
195+
assertTrue(node.hasOwnProperty("estimatedCost"));
196+
});
197+
198+
assertTrue(plan.hasOwnProperty("rules"));
199+
assertTrue(Array.isArray(plan.rules));
200+
});
201+
},
202+
203+
};
204+
}
205+
206+
jsunity.run(explainSuite);
207+
208+
return jsunity.done();

0 commit comments

Comments
 (0)
0