1#include "duckdb/main/query_profiler.hpp"
2
3#include "duckdb/common/fstream.hpp"
4#include "duckdb/common/printer.hpp"
5#include "duckdb/common/string_util.hpp"
6#include "duckdb/execution/physical_operator.hpp"
7#include "duckdb/parser/sql_statement.hpp"
8
9#include <iostream>
10#include <utility>
11
12using namespace duckdb;
13using namespace std;
14
15constexpr idx_t TREE_RENDER_WIDTH = 20;
16constexpr idx_t REMAINING_RENDER_WIDTH = TREE_RENDER_WIDTH - 2;
17constexpr idx_t MAX_EXTRA_LINES = 10;
18
19void QueryProfiler::StartQuery(string query, SQLStatement &statement) {
20 if (!enabled) {
21 return;
22 }
23 if (statement.type != StatementType::SELECT_STATEMENT && statement.type != StatementType::EXECUTE_STATEMENT) {
24 return;
25 }
26 this->running = true;
27 this->query = query;
28 tree_map.clear();
29 execution_stack = stack<PhysicalOperator *>();
30 root = nullptr;
31 phase_timings.clear();
32 phase_stack.clear();
33
34 main_query.Start();
35 op.Start();
36}
37
38void QueryProfiler::EndQuery() {
39 if (!enabled || !running) {
40 return;
41 }
42
43 main_query.End();
44 this->running = false;
45 // print the query after termination, if this is enabled
46 if (automatic_print_format != ProfilerPrintFormat::NONE) {
47 string query_info;
48 if (automatic_print_format == ProfilerPrintFormat::JSON) {
49 query_info = ToJSON();
50 } else if (automatic_print_format == ProfilerPrintFormat::QUERY_TREE) {
51 query_info = ToString();
52 }
53
54 if (save_location.empty()) {
55 cout << query_info << "\n";
56 } else {
57 WriteToFile(save_location.c_str(), query_info);
58 }
59 }
60}
61
62void QueryProfiler::StartPhase(string new_phase) {
63 if (!enabled || !running) {
64 return;
65 }
66
67 if (!phase_stack.empty()) {
68 // there are active phases
69 phase_profiler.End();
70 // add the timing to all phases prior to this one
71 string prefix = "";
72 for (auto &phase : phase_stack) {
73 phase_timings[phase] += phase_profiler.Elapsed();
74 prefix += phase + " > ";
75 }
76 // when there are previous phases, we prefix the current phase with those phases
77 new_phase = prefix + new_phase;
78 }
79
80 // start a new phase
81 phase_stack.push_back(new_phase);
82 // restart the timer
83 phase_profiler.Start();
84}
85
86void QueryProfiler::EndPhase() {
87 if (!enabled || !running) {
88 return;
89 }
90 assert(phase_stack.size() > 0);
91
92 // end the timer
93 phase_profiler.End();
94 // add the timing to all currently active phases
95 for (auto &phase : phase_stack) {
96 phase_timings[phase] += phase_profiler.Elapsed();
97 }
98 // now remove the last added phase
99 phase_stack.pop_back();
100
101 if (phase_stack.size() > 0) {
102 phase_profiler.Start();
103 }
104}
105
106void QueryProfiler::StartOperator(PhysicalOperator *phys_op) {
107 if (!enabled || !running) {
108 return;
109 }
110
111 if (!root) {
112 // start of execution: create operator tree
113 root = CreateTree(phys_op);
114 }
115 if (!execution_stack.empty()) {
116 // add timing for the previous element
117 op.End();
118 assert(tree_map.count(execution_stack.top()) > 0);
119 auto &info = tree_map[execution_stack.top()]->info;
120 info.time += op.Elapsed();
121 }
122 if (tree_map.count(phys_op) == 0) {
123 // element does not exist in the tree! this only happens with a subquery
124 // create a new tree
125 assert(execution_stack.size() > 0);
126 auto node = tree_map[execution_stack.top()];
127 auto new_tree = CreateTree(phys_op, node->depth + 1);
128 // add it to the current node
129 node->children.push_back(move(new_tree));
130 }
131 execution_stack.push(phys_op);
132
133 // start timing for current element
134 op.Start();
135}
136
137void QueryProfiler::EndOperator(DataChunk &chunk) {
138 if (!enabled || !running) {
139 return;
140 }
141
142 // finish timing for the current element
143 op.End();
144 auto &info = tree_map[execution_stack.top()]->info;
145 info.time += op.Elapsed();
146 info.elements += chunk.size();
147
148 assert(!execution_stack.empty());
149 execution_stack.pop();
150
151 // start timing again for the previous element, if any
152 if (!execution_stack.empty()) {
153 op.Start();
154 }
155}
156
157string QueryProfiler::ToString() const {
158 if (!enabled) {
159 return "Query profiling is disabled. Call "
160 "Connection::EnableProfiling() to enable profiling!";
161 }
162
163 if (query.empty()) {
164 return "<<Empty Profiling Information>>";
165 }
166 string result = "<<Query Profiling Information>>\n";
167 result += StringUtil::Replace(query, "\n", " ") + "\n";
168 result += "<<Timing>>\n";
169 result += "Total Time: " + to_string(main_query.Elapsed()) + "s\n";
170 // print phase timings
171 for (const auto &entry : GetOrderedPhaseTimings()) {
172 result += entry.first + ": " + to_string(entry.second) + "s\n";
173 }
174 // render the main operator tree
175 result += "<<Operator Tree>>\n";
176 if (!root) {
177 result += "<<ERROR RENDERING ROOT>";
178 } else {
179 result += RenderTree(*root);
180 }
181 return result;
182}
183
184static string ToJSONRecursive(QueryProfiler::TreeNode &node) {
185 string result = "{ \"name\": \"" + node.name + "\",\n";
186 result += "\"timing\":" + StringUtil::Format("%.2f", node.info.time) + ",\n";
187 result += "\"cardinality\":" + to_string(node.info.elements) + ",\n";
188 result += "\"extra_info\": \"" + StringUtil::Replace(node.extra_info, "\n", "\\n") + "\",\n";
189 result += "\"children\": [";
190 result +=
191 StringUtil::Join(node.children, node.children.size(), ",\n",
192 [](const unique_ptr<QueryProfiler::TreeNode> &child) { return ToJSONRecursive(*child); });
193 result += "]\n}\n";
194 return result;
195}
196
197string QueryProfiler::ToJSON() const {
198 if (!enabled) {
199 return "{ \"result\": \"disabled\" }\n";
200 }
201 if (query.empty()) {
202 return "{ \"result\": \"empty\" }\n";
203 }
204 if (!root) {
205 return "{ \"result\": \"error\" }\n";
206 }
207 string result = "{ \"result\": " + to_string(main_query.Elapsed()) + ",\n";
208 // print the phase timings
209 result += "\"timings\": {\n";
210 const auto &ordered_phase_timings = GetOrderedPhaseTimings();
211 result +=
212 StringUtil::Join(ordered_phase_timings, ordered_phase_timings.size(), ",\n", [](const PhaseTimingItem &entry) {
213 return "\"" + entry.first + "\": " + to_string(entry.second);
214 });
215 result += "},\n";
216 // recursively print the physical operator tree
217 result += "\"tree\": ";
218 result += ToJSONRecursive(*root);
219 return result + "}";
220}
221
222void QueryProfiler::WriteToFile(const char *path, string &info) const {
223 ofstream out(path);
224 out << info;
225 out.close();
226}
227
228static bool is_non_split_char(char l) {
229 return (l >= 65 && l <= 90) || (l >= 97 && l <= 122) || l == 95 || l == ']' || l == ')';
230}
231
232static bool is_padding(char l) {
233 return l == ' ' || l == '(' || l == ')';
234}
235
236static string remove_padding(string l) {
237 idx_t start = 0, end = l.size();
238 while (start < l.size() && is_padding(l[start])) {
239 start++;
240 }
241 while (end > 0 && is_padding(l[end - 1])) {
242 end--;
243 }
244 return l.substr(start, end - start);
245}
246
247unique_ptr<QueryProfiler::TreeNode> QueryProfiler::CreateTree(PhysicalOperator *root, idx_t depth) {
248 auto node = make_unique<QueryProfiler::TreeNode>();
249 node->name = PhysicalOperatorToString(root->type);
250 node->extra_info = root->ExtraRenderInformation();
251 if (!node->extra_info.empty()) {
252 auto splits = StringUtil::Split(node->extra_info, '\n');
253 for (auto &split : splits) {
254 string str = remove_padding(split);
255 constexpr idx_t max_segment_size = REMAINING_RENDER_WIDTH - 2;
256 idx_t location = 0;
257 while (location < str.size() && node->split_extra_info.size() < MAX_EXTRA_LINES) {
258 bool has_to_split = (str.size() - location) > max_segment_size;
259 if (has_to_split) {
260 // look for a split character
261 idx_t i;
262 for (i = 8; i < max_segment_size; i++) {
263 if (!is_non_split_char(str[location + i])) {
264 // split here
265 break;
266 }
267 }
268 node->split_extra_info.push_back(str.substr(location, i));
269 location += i;
270 } else {
271 node->split_extra_info.push_back(str.substr(location));
272 break;
273 }
274 }
275 }
276 }
277 node->depth = depth;
278 tree_map[root] = node.get();
279 for (auto &child : root->children) {
280 auto child_node = CreateTree(child.get(), depth + 1);
281 node->children.push_back(move(child_node));
282 }
283 return node;
284}
285
286static string DrawPadded(string text, char padding_character = ' ') {
287 auto remaining_width = REMAINING_RENDER_WIDTH;
288 if (text.size() > remaining_width) {
289 text = text.substr(0, remaining_width);
290 }
291 assert(text.size() <= (idx_t)numeric_limits<int32_t>::max());
292
293 auto right_padding = (remaining_width - text.size()) / 2;
294 auto left_padding = remaining_width - text.size() - right_padding;
295 return "|" + string(left_padding, padding_character) + text + string(right_padding, padding_character) + "|";
296}
297
298idx_t QueryProfiler::RenderTreeRecursive(QueryProfiler::TreeNode &node, vector<string> &render,
299 vector<idx_t> &render_heights, idx_t base_render_x, idx_t start_depth,
300 idx_t depth) {
301 auto render_height = render_heights[depth];
302 auto width = base_render_x;
303 // render this node
304 // first add any padding to render at this location
305 auto start_position = width * TREE_RENDER_WIDTH;
306 for (idx_t i = 0; i < render_height; i++) {
307 if (render[start_depth + i].size() > start_position) {
308 // something has already been rendered here!
309 throw Exception("Tree rendering error, overlapping nodes!");
310 } else {
311 // add the padding
312 render[start_depth + i] += string(start_position - render[start_depth + i].size(), ' ');
313 }
314 }
315
316 // draw the boundaries of the box
317 render[start_depth] += string(TREE_RENDER_WIDTH, '-');
318 render[start_depth + render_height - 1] += string(TREE_RENDER_WIDTH, '-');
319
320 // draw the name
321 string name = node.name;
322 render[start_depth + 1] += DrawPadded(name);
323 // draw extra information
324 for (idx_t i = 2; i < render_height - 3; i++) {
325 auto split_index = i - 2;
326 string string = split_index < node.split_extra_info.size() ? node.split_extra_info[split_index] : "";
327 render[start_depth + i] += DrawPadded(string);
328 }
329 // draw the timing information
330 string timing = StringUtil::Format("%.2f", node.info.time);
331 render[start_depth + render_height - 3] += DrawPadded("(" + timing + "s)");
332 // draw the intermediate count
333 render[start_depth + render_height - 2] += DrawPadded(to_string(node.info.elements));
334
335 for (auto &child : node.children) {
336 // render all the children
337 width =
338 RenderTreeRecursive(*child, render, render_heights, width, start_depth + render_heights[depth], depth + 1);
339 width++;
340 }
341 if (node.children.size() > 0) {
342 width--;
343 }
344 return width;
345}
346
347idx_t QueryProfiler::GetDepth(QueryProfiler::TreeNode &node) {
348 idx_t depth = 0;
349 for (auto &child : node.children) {
350 depth = max(depth, GetDepth(*child));
351 }
352 return depth + 1;
353}
354
355static void GetRenderHeight(QueryProfiler::TreeNode &node, vector<idx_t> &render_heights, int depth = 0) {
356 render_heights[depth] = max(render_heights[depth], (5 + (idx_t)node.split_extra_info.size()));
357 for (auto &child : node.children) {
358 GetRenderHeight(*child, render_heights, depth + 1);
359 }
360}
361
362string QueryProfiler::RenderTree(QueryProfiler::TreeNode &node) {
363 vector<idx_t> render_heights;
364 // compute the height of each level
365 auto depth = GetDepth(node);
366
367 // compute the render height
368 render_heights.resize(depth);
369 GetRenderHeight(node, render_heights);
370 int32_t total_height = 0;
371 for (auto height : render_heights) {
372 total_height += height;
373 }
374
375 // now actually render the tree
376 vector<string> render;
377 render.resize(total_height);
378
379 RenderTreeRecursive(node, render, render_heights);
380 string text;
381 for (auto &str : render) {
382 text += str + "\n";
383 }
384 return text;
385}
386
387void QueryProfiler::Print() {
388 Printer::Print(ToString());
389}
390
391vector<QueryProfiler::PhaseTimingItem> QueryProfiler::GetOrderedPhaseTimings() const {
392 vector<PhaseTimingItem> result;
393 // first sort the phases alphabetically
394 vector<string> phases;
395 for (auto &entry : phase_timings) {
396 phases.push_back(entry.first);
397 }
398 std::sort(phases.begin(), phases.end());
399 for (const auto &phase : phases) {
400 auto entry = phase_timings.find(phase);
401 assert(entry != phase_timings.end());
402 result.emplace_back(entry->first, entry->second);
403 }
404 return result;
405}
406