tursom/memgraph
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

Output profiling data within the summary in JSON format

Browse Source 
Reviewers: mtomic, teon.banek

Reviewed By: mtomic

Subscribers: mferencevic, pullbot

Differential Revision: https://phabricator.memgraph.io/D1801
This commit is contained in:
Lovro Lugovic 2019-01-17 12:28:32 +01:00
parent 49f906f384
commit 5f13b92664
8 changed files with 392 additions and 26 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

1
src/query/context.hpp
View File

@ -43,6 +43,7 @@ struct ExecutionContext {
SymbolTable symbol_table;
EvaluationContext evaluation_context;
bool is_profile_query{false};
std::chrono::duration<double> profile_execution_time;
plan::ProfilingStats stats;
plan::ProfilingStats *stats_root{nullptr};
};

8
src/query/interpreter.cpp
View File

@ -1,8 +1,9 @@
#include "query/interpreter.hpp"
#include <glog/logging.h>
#include <limits>
#include <glog/logging.h>
#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<CachedPlan>(std::make_unique<SingleNodeLogicalPlan>(

7
src/query/interpreter.hpp
View File

@ -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();
}

114
src/query/plan/profile.cpp
View File

@ -4,22 +4,48 @@
#include <chrono>
#include <fmt/format.h>
#include <json/json.hpp>
#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<double>(num_cycles) / total_cycles;
}
double AbsoluteTime(unsigned long long num_cycles,
unsigned long long total_cycles,
std::chrono::duration<double> total_time) {
return (RelativeTime(num_cycles, total_cycles) *
static_cast<std::chrono::duration<double, std::milli>>(total_time))
.count();
}
} // namespace
//////////////////////////////////////////////////////////////////////////////
//
// FormatProfilingStats
// ProfilingStatsToTable
namespace {
class FormatProfilingStatsHelper {
class ProfilingStatsToTableHelper {
public:
FormatProfilingStatsHelper(unsigned long long total_cycles,
std::chrono::duration<double> total_time)
ProfilingStatsToTableHelper(unsigned long long total_cycles,
std::chrono::duration<double> total_time)
: total_cycles_(total_cycles), total_time_(total_time) {}
void Output(const ProfilingStats &cumulative_stats) {
@ -38,6 +64,9 @@ class FormatProfilingStatsHelper {
}
}
std::vector<std::vector<TypedValue>> rows() { return rows_; }
private:
void Branch(const ProfilingStats &cumulative_stats) {
rows_.emplace_back(std::vector<TypedValue>{"|\\", "", "", ""});
@ -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<double>(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<double>(num_cycles) / total_cycles_ *
static_cast<std::chrono::duration<double, std::milli>>(total_time_))
.count());
return fmt::format("{: 10.6f} ms",
AbsoluteTime(num_cycles, total_cycles_, total_time_));
}
std::vector<std::vector<TypedValue>> rows() { return rows_; }
private:
int64_t depth_{0};
std::vector<std::vector<TypedValue>> rows_;
unsigned long long total_cycles_;
@ -93,12 +108,65 @@ class FormatProfilingStatsHelper {
} // namespace
std::vector<std::vector<TypedValue>> FormatProfilingStats(
std::vector<std::vector<TypedValue>> ProfilingStatsToTable(
const ProfilingStats &cumulative_stats,
std::chrono::duration<double> 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<double> 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<double> total_time_;
};
} // namespace
nlohmann::json ProfilingStatsToJson(const ProfilingStats &cumulative_stats,
std::chrono::duration<double> total_time) {
ProfilingStatsToJsonHelper helper{cumulative_stats.num_cycles, total_time};
helper.Output(cumulative_stats);
return helper.ToJson();
}
} // namespace query::plan

7
src/query/plan/profile.hpp
View File

@ -3,6 +3,8 @@
#include <cstdint>
#include <vector>
#include <json/json.hpp>
#include "query/typed_value.hpp"
namespace query {
@ -20,8 +22,11 @@ struct ProfilingStats {
std::vector<ProfilingStats> children;
};
std::vector<std::vector<TypedValue>> FormatProfilingStats(
std::vector<std::vector<TypedValue>> ProfilingStatsToTable(
const ProfilingStats &cumulative_stats, std::chrono::duration<double>);
nlohmann::json ProfilingStatsToJson(const ProfilingStats &cumulative_stats,
std::chrono::duration<double>);
} // namespace plan
} // namespace query

17
tests/benchmark/query/profile.cpp
View File

@ -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<NAryTree> LiftTreeHelper(const std::vector<int64_t> &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: `<node-id> <node-num-children>`. 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: `<root-id> <root-num-children>
* <root-child-1-id> <root-child-1-num-children> <root-child-1-child-1-id>
* <root-child-1-child-1-num-children> ... <root-child-2-id>
* <root-child-2-num-children> ...`.
*/
std::unique_ptr<NAryTree> LiftTree(const std::vector<int64_t> &flattened) {
size_t index = 0;
return LiftTreeHelper(flattened, &index);

3
tests/unit/CMakeLists.txt
View File

@ -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)

261
tests/unit/query_profile.cpp Normal file
View File

@ -0,0 +1,261 @@
#include <chrono>
#include <gtest/gtest.h>
#include "query/plan/profile.hpp"
using namespace query::plan;
TEST(QueryProfileTest, SimpleQuery) {
std::chrono::duration<double> 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<double> 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());
}