diff --git a/src/query/context.hpp b/src/query/context.hpp index 559361b28..755699f24 100644 --- a/src/query/context.hpp +++ b/src/query/context.hpp @@ -43,6 +43,7 @@ struct ExecutionContext { SymbolTable symbol_table; EvaluationContext evaluation_context; bool is_profile_query{false}; + std::chrono::duration profile_execution_time; plan::ProfilingStats stats; plan::ProfilingStats *stats_root{nullptr}; }; diff --git a/src/query/interpreter.cpp b/src/query/interpreter.cpp index fb055d0e2..f19ec99d7 100644 --- a/src/query/interpreter.cpp +++ b/src/query/interpreter.cpp @@ -1,8 +1,9 @@ #include "query/interpreter.hpp" -#include #include +#include + #include "auth/auth.hpp" #include "glue/auth.hpp" #include "glue/communication.hpp" @@ -757,8 +758,11 @@ Interpreter::Results Interpreter::operator()( // Pull everything to profile the execution utils::Timer timer; while (cursor->Pull(*frame, *context)) continue; + auto execution_time = timer.Elapsed(); - return FormatProfilingStats(context->stats, timer.Elapsed()); + context->profile_execution_time = execution_time; + + return ProfilingStatsToTable(context->stats, execution_time); }); plan = std::make_shared(std::make_unique( diff --git a/src/query/interpreter.hpp b/src/query/interpreter.hpp index c7e825f5e..c12670677 100644 --- a/src/query/interpreter.hpp +++ b/src/query/interpreter.hpp @@ -144,6 +144,13 @@ class Interpreter { if (!return_value) { summary_["plan_execution_time"] = execution_time_; + + if (ctx_.is_profile_query) { + summary_["profile"] = + ProfilingStatsToJson(ctx_.stats, ctx_.profile_execution_time) + .dump(); + } + cursor_->Shutdown(); } diff --git a/src/query/plan/profile.cpp b/src/query/plan/profile.cpp index 97ae5a1c9..df52c41b3 100644 --- a/src/query/plan/profile.cpp +++ b/src/query/plan/profile.cpp @@ -4,22 +4,48 @@ #include #include +#include #include "query/context.hpp" #include "utils/likely.hpp" namespace query::plan { +namespace { + +unsigned long long IndividualCycles(const ProfilingStats &cumulative_stats) { + return cumulative_stats.num_cycles - + std::accumulate( + cumulative_stats.children.begin(), cumulative_stats.children.end(), + 0ULL, + [](auto acc, auto &stats) { return acc + stats.num_cycles; }); +} + +double RelativeTime(unsigned long long num_cycles, + unsigned long long total_cycles) { + return static_cast(num_cycles) / total_cycles; +} + +double AbsoluteTime(unsigned long long num_cycles, + unsigned long long total_cycles, + std::chrono::duration total_time) { + return (RelativeTime(num_cycles, total_cycles) * + static_cast>(total_time)) + .count(); +} + +} // namespace + ////////////////////////////////////////////////////////////////////////////// // -// FormatProfilingStats +// ProfilingStatsToTable namespace { -class FormatProfilingStatsHelper { +class ProfilingStatsToTableHelper { public: - FormatProfilingStatsHelper(unsigned long long total_cycles, - std::chrono::duration total_time) + ProfilingStatsToTableHelper(unsigned long long total_cycles, + std::chrono::duration total_time) : total_cycles_(total_cycles), total_time_(total_time) {} void Output(const ProfilingStats &cumulative_stats) { @@ -38,6 +64,9 @@ class FormatProfilingStatsHelper { } } + std::vector> rows() { return rows_; } + + private: void Branch(const ProfilingStats &cumulative_stats) { rows_.emplace_back(std::vector{"|\\", "", "", ""}); @@ -46,14 +75,6 @@ class FormatProfilingStatsHelper { --depth_; } - unsigned long long IndividualCycles(const ProfilingStats &cumulative_stats) { - return cumulative_stats.num_cycles - - std::accumulate( - cumulative_stats.children.begin(), - cumulative_stats.children.end(), 0ULL, - [](auto acc, auto &stats) { return acc + stats.num_cycles; }); - } - std::string Format(const char *str) { std::ostringstream ss; for (int i = 0; i < depth_; ++i) { @@ -71,20 +92,14 @@ class FormatProfilingStatsHelper { std::string FormatRelativeTime(unsigned long long num_cycles) { return fmt::format("{: 10.6f} %", - static_cast(num_cycles) / total_cycles_ * 100); + RelativeTime(num_cycles, total_cycles_) * 100); } std::string FormatAbsoluteTime(unsigned long long num_cycles) { - return fmt::format( - "{: 10.6f} ms", - (static_cast(num_cycles) / total_cycles_ * - static_cast>(total_time_)) - .count()); + return fmt::format("{: 10.6f} ms", + AbsoluteTime(num_cycles, total_cycles_, total_time_)); } - std::vector> rows() { return rows_; } - - private: int64_t depth_{0}; std::vector> rows_; unsigned long long total_cycles_; @@ -93,12 +108,65 @@ class FormatProfilingStatsHelper { } // namespace -std::vector> FormatProfilingStats( +std::vector> ProfilingStatsToTable( const ProfilingStats &cumulative_stats, std::chrono::duration total_time) { - FormatProfilingStatsHelper helper{cumulative_stats.num_cycles, total_time}; + ProfilingStatsToTableHelper helper{cumulative_stats.num_cycles, total_time}; helper.Output(cumulative_stats); return helper.rows(); } +////////////////////////////////////////////////////////////////////////////// +// +// ProfilingStatsToJson + +namespace { + +class ProfilingStatsToJsonHelper { + private: + using json = nlohmann::json; + + public: + ProfilingStatsToJsonHelper(unsigned long long total_cycles, + std::chrono::duration total_time) + : total_cycles_(total_cycles), total_time_(total_time) {} + + void Output(const ProfilingStats &cumulative_stats) { + return Output(cumulative_stats, &json_); + } + + json ToJson() { return json_; } + + private: + void Output(const ProfilingStats &cumulative_stats, json *obj) { + auto cycles = IndividualCycles(cumulative_stats); + + obj->emplace("name", cumulative_stats.name); + obj->emplace("actual_hits", cumulative_stats.actual_hits); + obj->emplace("relative_time", RelativeTime(cycles, total_cycles_)); + obj->emplace("absolute_time", + AbsoluteTime(cycles, total_cycles_, total_time_)); + obj->emplace("children", json::array()); + + for (size_t i = 0; i < cumulative_stats.children.size(); ++i) { + json child; + Output(cumulative_stats.children[i], &child); + obj->at("children").emplace_back(std::move(child)); + } + } + + json json_; + unsigned long long total_cycles_; + std::chrono::duration total_time_; +}; + +} // namespace + +nlohmann::json ProfilingStatsToJson(const ProfilingStats &cumulative_stats, + std::chrono::duration total_time) { + ProfilingStatsToJsonHelper helper{cumulative_stats.num_cycles, total_time}; + helper.Output(cumulative_stats); + return helper.ToJson(); +} + } // namespace query::plan diff --git a/src/query/plan/profile.hpp b/src/query/plan/profile.hpp index 6f03ea9ba..f9c482472 100644 --- a/src/query/plan/profile.hpp +++ b/src/query/plan/profile.hpp @@ -3,6 +3,8 @@ #include #include +#include + #include "query/typed_value.hpp" namespace query { @@ -20,8 +22,11 @@ struct ProfilingStats { std::vector children; }; -std::vector> FormatProfilingStats( +std::vector> ProfilingStatsToTable( const ProfilingStats &cumulative_stats, std::chrono::duration); +nlohmann::json ProfilingStatsToJson(const ProfilingStats &cumulative_stats, + std::chrono::duration); + } // namespace plan } // namespace query diff --git a/tests/benchmark/query/profile.cpp b/tests/benchmark/query/profile.cpp index a61c43dde..f0f41077d 100644 --- a/tests/benchmark/query/profile.cpp +++ b/tests/benchmark/query/profile.cpp @@ -27,6 +27,10 @@ namespace { // // NAryTree +/* + * A utility to help us imitate the traversal of a plan (and therefore the + * profiling statistics as well). + */ struct NAryTree { NAryTree(int64_t id) : id(id) {} @@ -51,6 +55,19 @@ std::unique_ptr LiftTreeHelper(const std::vector &flattened, return node; } +/* + * A utility that produces instances of `NAryTree` given its "flattened" + * (serialized) form. A node (without its children) is serialized as a sequence + * of integers: ` `. A tree is serialized by + * serializing its root node and then recursively (depth-first) serializing its + * subtrees (children). + * + * As an example, here's the general form of the produced serialization, + * starting from some root node: ` + * + * ... + * ...`. + */ std::unique_ptr LiftTree(const std::vector &flattened) { size_t index = 0; return LiftTreeHelper(flattened, &index); diff --git a/tests/unit/CMakeLists.txt b/tests/unit/CMakeLists.txt index d139f3795..0c1654d64 100644 --- a/tests/unit/CMakeLists.txt +++ b/tests/unit/CMakeLists.txt @@ -176,6 +176,9 @@ target_link_libraries(${test_prefix}query_expression_evaluator mg-single-node kv add_unit_test(query_pretty_print.cpp) target_link_libraries(${test_prefix}query_pretty_print mg-single-node kvstore_dummy_lib) +add_unit_test(query_profile.cpp) +target_link_libraries(${test_prefix}query_profile mg-single-node kvstore_dummy_lib) + add_unit_test(query_plan_accumulate_aggregate.cpp) target_link_libraries(${test_prefix}query_plan_accumulate_aggregate mg-single-node kvstore_dummy_lib) diff --git a/tests/unit/query_profile.cpp b/tests/unit/query_profile.cpp new file mode 100644 index 000000000..6f80f3812 --- /dev/null +++ b/tests/unit/query_profile.cpp @@ -0,0 +1,261 @@ +#include + +#include + +#include "query/plan/profile.hpp" + +using namespace query::plan; + +TEST(QueryProfileTest, SimpleQuery) { + std::chrono::duration total_time{0.001}; + ProfilingStats once{2, 25, 0, "Once", {}}; + ProfilingStats produce{2, 100, 0, "Produce", {once}}; + + // clang-format: off + // +---------------+---------------+---------------+---------------+ + // | OPERATOR | ACTUAL HITS | RELATIVE TIME | ABSOLUTE TIME | + // +---------------+---------------+---------------+---------------+ + // | * Produce | 2 | 75.000000 % | 0.750000 ms | + // | * Once | 2 | 25.000000 % | 0.250000 ms | + // +---------------+---------------+---------------+---------------+ + // clang-format: on + auto table = ProfilingStatsToTable(produce, total_time); + + EXPECT_EQ(table[0][0].ValueString(), "* Produce"); + EXPECT_EQ(table[0][1].ValueInt(), 2); + EXPECT_EQ(table[0][2].ValueString(), " 75.000000 %"); + EXPECT_EQ(table[0][3].ValueString(), " 0.750000 ms"); + + EXPECT_EQ(table[1][0].ValueString(), "* Once"); + EXPECT_EQ(table[1][1].ValueInt(), 2); + EXPECT_EQ(table[1][2].ValueString(), " 25.000000 %"); + EXPECT_EQ(table[1][3].ValueString(), " 0.250000 ms"); + + // clang-format: off + // { + // "absolute_time": 0.75, + // "actual_hits": 2, + // "children": [ + // { + // "absolute_time": 0.25, + // "actual_hits": 2, + // "children": [], + // "name": "Once", + // "relative_time": 0.25 + // } + // ], + // "name": "Produce", + // "relative_time": 0.75 + // } + // clang-format: on + auto json = ProfilingStatsToJson(produce, total_time); + + /* + * NOTE: When one of these comparions fails and Google Test tries to report + * the failure, it will try to print out the JSON object. For some reason this + * ends up recursing infinitely within Google Test's printing internals and we + * get a segfault (stack overflow most likely). + */ + EXPECT_EQ(json["actual_hits"], 2); + EXPECT_EQ(json["relative_time"], 0.75); + EXPECT_EQ(json["absolute_time"], 0.75); + EXPECT_EQ(json["name"], "Produce"); + + EXPECT_EQ(json["children"][0]["actual_hits"], 2); + EXPECT_EQ(json["children"][0]["relative_time"], 0.25); + EXPECT_EQ(json["children"][0]["absolute_time"], 0.25); + EXPECT_EQ(json["children"][0]["name"], "Once"); +} + +TEST(QueryProfileTest, ComplicatedQuery) { + std::chrono::duration total_time{0.001}; + ProfilingStats once1{2, 5, 0, "Once", {}}; + ProfilingStats once2{1, 5, 0, "Once", {}}; + ProfilingStats once3{2, 5, 0, "Once", {}}; + ProfilingStats create_node{1, 55, 0, "CreateNode", {once2}}; + ProfilingStats scan_all{1, 20, 0, "ScanAll", {once3}}; + ProfilingStats merge{2, 85, 0, "Merge", {once1, scan_all, create_node}}; + ProfilingStats accumulate{2, 90, 0, "Accumulate", {merge}}; + ProfilingStats produce{2, 100, 0, "Produce", {accumulate}}; + + // clang-format: off + // +----------------+----------------+----------------+----------------+ + // | OPERATOR | ACTUAL HITS | RELATIVE TIME | ABSOLUTE TIME | + // +----------------+----------------+----------------+----------------+ + // | * Produce | 2 | 10.000000 % | 0.100000 ms | + // | * Accumulate | 2 | 5.000000 % | 0.050000 ms | + // | * Merge | 2 | 5.000000 % | 0.050000 ms | + // | |\ | | | | + // | | * ScanAll | 1 | 15.000000 % | 0.150000 ms | + // | | * Once (3) | 2 | 5.000000 % | 0.050000 ms | + // | |\ | | | | + // | | * CreateNode | 1 | 50.000000 % | 0.500000 ms | + // | | * Once (2) | 1 | 5.000000 % | 0.050000 ms | + // | * Once (1) | 2 | 5.000000 % | 0.050000 ms | + // +----------------+----------------+----------------+----------------+ + // clang-format: on + auto table = ProfilingStatsToTable(produce, total_time); + + EXPECT_EQ(table[0][0].ValueString(), "* Produce"); + EXPECT_EQ(table[0][1].ValueInt(), 2); + EXPECT_EQ(table[0][2].ValueString(), " 10.000000 %"); + EXPECT_EQ(table[0][3].ValueString(), " 0.100000 ms"); + + EXPECT_EQ(table[1][0].ValueString(), "* Accumulate"); + EXPECT_EQ(table[1][1].ValueInt(), 2); + EXPECT_EQ(table[1][2].ValueString(), " 5.000000 %"); + EXPECT_EQ(table[1][3].ValueString(), " 0.050000 ms"); + + EXPECT_EQ(table[2][0].ValueString(), "* Merge"); + EXPECT_EQ(table[2][1].ValueInt(), 2); + EXPECT_EQ(table[2][2].ValueString(), " 5.000000 %"); + EXPECT_EQ(table[2][3].ValueString(), " 0.050000 ms"); + + EXPECT_EQ(table[3][0].ValueString(), "|\\"); + EXPECT_EQ(table[3][1].ValueString(), ""); + EXPECT_EQ(table[3][2].ValueString(), ""); + EXPECT_EQ(table[3][3].ValueString(), ""); + + EXPECT_EQ(table[4][0].ValueString(), "| * ScanAll"); + EXPECT_EQ(table[4][1].ValueInt(), 1); + EXPECT_EQ(table[4][2].ValueString(), " 15.000000 %"); + EXPECT_EQ(table[4][3].ValueString(), " 0.150000 ms"); + + EXPECT_EQ(table[5][0].ValueString(), "| * Once"); + EXPECT_EQ(table[5][1].ValueInt(), 2); + EXPECT_EQ(table[5][2].ValueString(), " 5.000000 %"); + EXPECT_EQ(table[5][3].ValueString(), " 0.050000 ms"); + + EXPECT_EQ(table[6][0].ValueString(), "|\\"); + EXPECT_EQ(table[6][1].ValueString(), ""); + EXPECT_EQ(table[6][2].ValueString(), ""); + EXPECT_EQ(table[6][3].ValueString(), ""); + + EXPECT_EQ(table[7][0].ValueString(), "| * CreateNode"); + EXPECT_EQ(table[7][1].ValueInt(), 1); + EXPECT_EQ(table[7][2].ValueString(), " 50.000000 %"); + EXPECT_EQ(table[7][3].ValueString(), " 0.500000 ms"); + + EXPECT_EQ(table[8][0].ValueString(), "| * Once"); + EXPECT_EQ(table[8][1].ValueInt(), 1); + EXPECT_EQ(table[8][2].ValueString(), " 5.000000 %"); + EXPECT_EQ(table[8][3].ValueString(), " 0.050000 ms"); + + EXPECT_EQ(table[9][0].ValueString(), "* Once"); + EXPECT_EQ(table[9][1].ValueInt(), 2); + EXPECT_EQ(table[9][2].ValueString(), " 5.000000 %"); + EXPECT_EQ(table[9][3].ValueString(), " 0.050000 ms"); + + // clang-format: off + // { + // "absolute_time": 0.1, + // "actual_hits": 2, + // "children": [ + // { + // "absolute_time": 0.05, + // "actual_hits": 2, + // "children": [ + // { + // "absolute_time": 0.05, + // "actual_hits": 2, + // "children": [ + // { + // "absolute_time": 0.05, + // "actual_hits": 2, + // "children": [], + // "name": "Once", + // "relative_time": 0.05 + // }, + // { + // "absolute_time": 0.15 + // "actual_hits": 1, + // "children": [ + // { + // "absolute_time": 0.05, + // "actual_hits": 2, + // "children": [], + // "name": "Once", + // "relative_time": 0.05 + // } + // ], + // "name": "ScanAll", + // "relative_time": 0.15 + // }, + // { + // "absolute_time": 0.50, + // "actual_hits": 1, + // "children": [ + // { + // "absolute_time": 0.05, + // "actual_hits": 1, + // "children": [], + // "name": "Once", + // "relative_time": 0.05 + // } + // ], + // "name": "CreateNode", + // "relative_time": 0.50 + // } + // ], + // "name": "Merge", + // "relative_time": 0.05 + // } + // ], + // "name": "Accumulate", + // "relative_time": 0.05 + // } + // ], + // "name": "Produce", + // "relative_time": 0.1, + // } + // clang-format: on + auto json = ProfilingStatsToJson(produce, total_time); + + EXPECT_EQ(json["actual_hits"], 2); + EXPECT_EQ(json["relative_time"], 0.1); + EXPECT_EQ(json["absolute_time"], 0.1); + EXPECT_EQ(json["name"], "Produce"); + + auto children1 = json["children"]; + EXPECT_EQ(children1[0]["actual_hits"], 2); + EXPECT_EQ(children1[0]["relative_time"], 0.05); + EXPECT_EQ(children1[0]["absolute_time"], 0.05); + EXPECT_EQ(children1[0]["name"], "Accumulate"); + + auto children2 = children1[0]["children"]; + EXPECT_EQ(children2[0]["actual_hits"], 2); + EXPECT_EQ(children2[0]["relative_time"], 0.05); + EXPECT_EQ(children2[0]["absolute_time"], 0.05); + EXPECT_EQ(children2[0]["name"], "Merge"); + + auto children3 = children2[0]["children"]; + EXPECT_EQ(children3[0]["actual_hits"], 2); + EXPECT_EQ(children3[0]["relative_time"], 0.05); + EXPECT_EQ(children3[0]["absolute_time"], 0.05); + EXPECT_EQ(children3[0]["name"], "Once"); + EXPECT_TRUE(children3[0]["children"].empty()); + + EXPECT_EQ(children3[1]["actual_hits"], 1); + EXPECT_EQ(children3[1]["relative_time"], 0.15); + EXPECT_EQ(children3[1]["absolute_time"], 0.15); + EXPECT_EQ(children3[1]["name"], "ScanAll"); + + EXPECT_EQ(children3[2]["actual_hits"], 1); + EXPECT_EQ(children3[2]["relative_time"], 0.50); + EXPECT_EQ(children3[2]["absolute_time"], 0.50); + EXPECT_EQ(children3[2]["name"], "CreateNode"); + + auto children4 = children3[1]["children"]; + EXPECT_EQ(children4[0]["actual_hits"], 2); + EXPECT_EQ(children4[0]["relative_time"], 0.05); + EXPECT_EQ(children4[0]["absolute_time"], 0.05); + EXPECT_EQ(children4[0]["name"], "Once"); + EXPECT_TRUE(children4[0]["children"].empty()); + + auto children5 = children3[2]["children"]; + EXPECT_EQ(children5[0]["actual_hits"], 1); + EXPECT_EQ(children5[0]["relative_time"], 0.05); + EXPECT_EQ(children5[0]["absolute_time"], 0.05); + EXPECT_EQ(children5[0]["name"], "Once"); + EXPECT_TRUE(children5[0]["children"].empty()); +}