From 54e58d6c1a41ff03aca9d501b7e2d5ecd14622bc Mon Sep 17 00:00:00 2001 From: yixinglu <2520865+yixinglu@users.noreply.github.com> Date: Thu, 17 Nov 2022 00:36:04 +0800 Subject: [PATCH 1/4] Fix graph profiling data format --- src/common/datatypes/HostAddr.h | 3 +- src/graph/executor/StorageAccessExecutor.cpp | 14 ++-- src/graph/executor/StorageAccessExecutor.h | 35 ++++++--- src/graph/executor/algo/ShortestPathBase.cpp | 71 +++++++++---------- src/graph/executor/algo/ShortestPathBase.h | 3 +- src/graph/executor/algo/SubgraphExecutor.cpp | 10 +-- .../executor/query/GetDstBySrcExecutor.cpp | 10 +-- .../executor/query/GetNeighborsExecutor.cpp | 10 +-- src/graph/executor/query/TraverseExecutor.cpp | 17 ++--- 9 files changed, 76 insertions(+), 97 deletions(-) diff --git a/src/common/datatypes/HostAddr.h b/src/common/datatypes/HostAddr.h index 016a6baa112..1af8ddcfb19 100644 --- a/src/common/datatypes/HostAddr.h +++ b/src/common/datatypes/HostAddr.h @@ -40,8 +40,7 @@ struct HostAddr { std::string toString() const { std::stringstream os; - os << "\"" << host << "\"" - << ":" << port; + os << "\"" << host << ":" << port << "\""; return os.str(); } diff --git a/src/graph/executor/StorageAccessExecutor.cpp b/src/graph/executor/StorageAccessExecutor.cpp index bf0cad8efe0..3c0b7cb9b5d 100644 --- a/src/graph/executor/StorageAccessExecutor.cpp +++ b/src/graph/executor/StorageAccessExecutor.cpp @@ -148,15 +148,13 @@ StatusOr> StorageAccessExecutor::buildRequestListByVidType(It return internal::buildRequestList(space, exprCtx, iter, expr, dedup, isCypher); } -std::string StorageAccessExecutor::getStorageDetail( - optional_field_ref &> ref) const { - if (ref.has_value()) { - auto content = util::join(*ref, [](auto &iter) -> std::string { - return folly::sformat("\n {}:{}(us)", iter.first, iter.second); - }); - return "{" + content + "}"; +folly::dynamic StorageAccessExecutor::getStorageDetail( + const std::map &profileDetail) const { + folly::dynamic profileData = folly::dynamic::object(); + for (auto &p : profileDetail) { + profileData.insert(p.first, folly::sformat("{}(us)", p.second)); } - return ""; + return profileData; } } // namespace graph diff --git a/src/graph/executor/StorageAccessExecutor.h b/src/graph/executor/StorageAccessExecutor.h index 56c97604e89..4d8d5991955 100644 --- a/src/graph/executor/StorageAccessExecutor.h +++ b/src/graph/executor/StorageAccessExecutor.h @@ -139,22 +139,37 @@ class StorageAccessExecutor : public Executor { return Status::OK(); } + folly::dynamic collectRespProfileData(const storage::cpp2::ResponseCommon &resp, + const std::tuple &info, + size_t numVertices = 0UL, + size_t totalRpcTime = 0UL) const { + folly::dynamic stat = folly::dynamic::object(); + stat.insert("address", std::get<0>(info).toString()); + stat.insert("exec", folly::sformat("{}(us)", std::get<1>(info))); + stat.insert("total", folly::sformat("{}(us)", std::get<2>(info))); + if (numVertices > 0) { + stat.insert("vertices", numVertices); + } + if (totalRpcTime > 0) { + stat.insert("total_rpc_time", folly::sformat("{}(us)", totalRpcTime)); + } + if (resp.latency_detail_us_ref().has_value()) { + stat.insert("storage_detail", getStorageDetail(*resp.get_latency_detail_us())); + } + return stat; + } + template - void addStats(RESP &resp, std::unordered_map &stats) const { + void addStats(storage::StorageRpcResponse &resp, + std::unordered_map &stats) const { auto &hostLatency = resp.hostLatency(); for (size_t i = 0; i < hostLatency.size(); ++i) { - auto &info = hostLatency[i]; - stats.emplace(folly::sformat("{} exec/total", std::get<0>(info).toString()), - folly::sformat("{}(us)/{}(us)", std::get<1>(info), std::get<2>(info))); - auto detail = getStorageDetail(resp.responses()[i].result_ref()->latency_detail_us_ref()); - if (!detail.empty()) { - stats.emplace("storage_detail", detail); - } + auto info = collectRespProfileData(resp.responses()[i].get_result(), hostLatency[i]); + stats.emplace(folly::sformat("resp[{}]", i), folly::toPrettyJson(info)); } } - std::string getStorageDetail( - apache::thrift::optional_field_ref &> ref) const; + folly::dynamic getStorageDetail(const std::map &profileDetail) const; bool isIntVidType(const SpaceInfo &space) const; diff --git a/src/graph/executor/algo/ShortestPathBase.cpp b/src/graph/executor/algo/ShortestPathBase.cpp index f1af092e34c..4493919fe42 100644 --- a/src/graph/executor/algo/ShortestPathBase.cpp +++ b/src/graph/executor/algo/ShortestPathBase.cpp @@ -70,15 +70,13 @@ std::vector ShortestPathBase::handlePropResp(PropRpcResponse&& resps) { return vertices; } -std::string ShortestPathBase::getStorageDetail( - optional_field_ref&> ref) const { - if (ref.has_value()) { - auto content = util::join(*ref, [](auto& iter) -> std::string { - return folly::sformat("{}:{}(us)", iter.first, iter.second); - }); - return "{" + content + "}"; +folly::dynamic ShortestPathBase::getStorageDetail( + const std::map& profileDetail) const { + folly::dynamic info = folly::dynamic::object(); + for (auto& p : profileDetail) { + info.insert(p.first, folly::sformat("{}(us)", p.second)); } - return ""; + return info; } Status ShortestPathBase::handleErrorCode(nebula::cpp2::ErrorCode code, PartitionID partId) const { @@ -171,9 +169,8 @@ void ShortestPathBase::addStats(RpcResponse& resp, size_t stepNum, int64_t timeInUSec, bool reverse) const { + folly::dynamic stats = folly::dynamic::array(); auto& hostLatency = resp.hostLatency(); - std::stringstream ss; - ss << "{\n"; for (size_t i = 0; i < hostLatency.size(); ++i) { size_t size = 0u; auto& result = resp.responses()[i]; @@ -181,45 +178,43 @@ void ShortestPathBase::addStats(RpcResponse& resp, size = (*result.vertices_ref()).size(); } auto& info = hostLatency[i]; - ss << "{" << folly::sformat("{} exec/total/vertices: ", std::get<0>(info).toString()) - << folly::sformat("{}(us)/{}(us)/{},", std::get<1>(info), std::get<2>(info), size) << "\n" - << folly::sformat("total_rpc_time: {}(us)", timeInUSec) << "\n"; - auto detail = getStorageDetail(result.result.latency_detail_us_ref()); - if (!detail.empty()) { - ss << folly::sformat("storage_detail: {}", detail); + folly::dynamic stat = folly::dynamic::object(); + stat.insert("address", std::get<0>(info).toString()); + stat.insert("exec", folly::sformat("{}(us)", std::get<1>(info))); + stat.insert("total", folly::sformat("{}(us)", std::get<2>(info))); + stat.insert("vertices", size); + stat.insert("total_rpc_time", folly::sformat("{}(us)", timeInUSec)); + if (result.result.latency_detail_us_ref().has_value()) { + stat.insert("storage_detail", getStorageDetail(*result.result.get_latency_detail_us())); } - ss << "\n}"; - } - ss << "\n}"; - if (reverse) { - statsLock_.lock(); - stats_->emplace(folly::sformat("reverse step {}", stepNum), ss.str()); - statsLock_.unlock(); - } else { - statsLock_.lock(); - stats_->emplace(folly::sformat("step {}", stepNum), ss.str()); - statsLock_.unlock(); + stats.push_back(folly::dynamic::object(folly::sformat("resp[{}]", i), stat)); } + + auto key = folly::sformat("{}step[{}]", reverse ? "reverse " : "", stepNum); + statsLock_.lock(); + stats_->emplace(key, folly::toPrettyJson(stats)); + statsLock_.unlock(); } void ShortestPathBase::addStats(PropRpcResponse& resp, int64_t timeInUSec) const { + folly::dynamic stats = folly::dynamic::array(); auto& hostLatency = resp.hostLatency(); - std::stringstream ss; - ss << "{\n"; for (size_t i = 0; i < hostLatency.size(); ++i) { auto& info = hostLatency[i]; - ss << "{" << folly::sformat("{} exec/total: ", std::get<0>(info).toString()) - << folly::sformat("{}(us)/{}(us),", std::get<1>(info), std::get<2>(info)) << "\n" - << folly::sformat("total_rpc_time: {}(us)", timeInUSec) << "\n"; - auto detail = getStorageDetail(resp.responses()[i].result_ref()->latency_detail_us_ref()); - if (!detail.empty()) { - ss << folly::sformat("storage_detail: {}", detail); + folly::dynamic stat = folly::dynamic::object(); + stat.insert("address", std::get<0>(info).toString()); + stat.insert("exec", folly::sformat("{}(us)", std::get<1>(info))); + stat.insert("total", folly::sformat("{}(us)", std::get<2>(info))); + stat.insert("total_rpc_time", folly::sformat("{}(us)", timeInUSec)); + const auto& result = resp.responses()[i].get_result(); + if (result.latency_detail_us_ref().has_value()) { + stat.insert("storage_detail", getStorageDetail(*result.get_latency_detail_us())); } - ss << "\n}"; + stats.push_back(std::move(stat)); } - ss << "\n}"; + statsLock_.lock(); - stats_->emplace(folly::sformat("get_prop "), ss.str()); + stats_->emplace("get_prop", folly::toPrettyJson(stats)); statsLock_.unlock(); } diff --git a/src/graph/executor/algo/ShortestPathBase.h b/src/graph/executor/algo/ShortestPathBase.h index 23e5c2195ea..cba3d58fc66 100644 --- a/src/graph/executor/algo/ShortestPathBase.h +++ b/src/graph/executor/algo/ShortestPathBase.h @@ -74,8 +74,7 @@ class ShortestPathBase { return Result::State::kSuccess; } - std::string getStorageDetail( - apache::thrift::optional_field_ref&> ref) const; + folly::dynamic getStorageDetail(const std::map& profileDetail) const; protected: const ShortestPath* pathNode_{nullptr}; diff --git a/src/graph/executor/algo/SubgraphExecutor.cpp b/src/graph/executor/algo/SubgraphExecutor.cpp index 4a05a4a6b75..8c0f01458df 100644 --- a/src/graph/executor/algo/SubgraphExecutor.cpp +++ b/src/graph/executor/algo/SubgraphExecutor.cpp @@ -59,14 +59,8 @@ folly::Future SubgraphExecutor::getNeighbors() { if (result.vertices_ref().has_value()) { size = (*result.vertices_ref()).size(); } - auto& info = hostLatency[i]; - otherStats_.emplace( - folly::sformat("{} exec/total/vertices", std::get<0>(info).toString()), - folly::sformat("{}(us)/{}(us)/{},", std::get<1>(info), std::get<2>(info), size)); - auto detail = getStorageDetail(result.result.latency_detail_us_ref()); - if (!detail.empty()) { - otherStats_.emplace("storage_detail", detail); - } + auto info = collectRespProfileData(result.result, hostLatency[i], size); + otherStats_.emplace(folly::sformat("resp[{}]", i), folly::toPrettyJson(info)); } vids_.clear(); return handleResponse(std::move(resp)); diff --git a/src/graph/executor/query/GetDstBySrcExecutor.cpp b/src/graph/executor/query/GetDstBySrcExecutor.cpp index 446c51a2435..7c7add52263 100644 --- a/src/graph/executor/query/GetDstBySrcExecutor.cpp +++ b/src/graph/executor/query/GetDstBySrcExecutor.cpp @@ -55,14 +55,8 @@ folly::Future GetDstBySrcExecutor::execute() { if (result.dsts_ref().has_value()) { size = (*result.dsts_ref()).size(); } - auto& info = hostLatency[i]; - otherStats_.emplace( - folly::sformat("{} exec/total/vertices", std::get<0>(info).toString()), - folly::sformat("{}(us)/{}(us)/{},", std::get<1>(info), std::get<2>(info), size)); - auto detail = getStorageDetail(result.result.latency_detail_us_ref()); - if (!detail.empty()) { - otherStats_.emplace("storage_detail", detail); - } + auto info = collectRespProfileData(result.result, hostLatency[i], size); + otherStats_.emplace(folly::sformat("resp[{}]", i), folly::toPrettyJson(info)); } return handleResponse(resp, this->gd_->colNames()); }); diff --git a/src/graph/executor/query/GetNeighborsExecutor.cpp b/src/graph/executor/query/GetNeighborsExecutor.cpp index 00694543acb..7dda012c32e 100644 --- a/src/graph/executor/query/GetNeighborsExecutor.cpp +++ b/src/graph/executor/query/GetNeighborsExecutor.cpp @@ -69,14 +69,8 @@ folly::Future GetNeighborsExecutor::execute() { if (result.vertices_ref().has_value()) { size = (*result.vertices_ref()).size(); } - auto& info = hostLatency[i]; - otherStats_.emplace( - folly::sformat("{} exec/total/vertices", std::get<0>(info).toString()), - folly::sformat("{}(us)/{}(us)/{},", std::get<1>(info), std::get<2>(info), size)); - auto detail = getStorageDetail(result.result.latency_detail_us_ref()); - if (!detail.empty()) { - otherStats_.emplace("storage_detail", detail); - } + auto info = collectRespProfileData(result.result, hostLatency[i], size); + otherStats_.emplace(folly::sformat("resp[{}]", i), folly::toPrettyJson(info)); } return handleResponse(resp); }); diff --git a/src/graph/executor/query/TraverseExecutor.cpp b/src/graph/executor/query/TraverseExecutor.cpp index d9ef3f19a6e..7ff987468b9 100644 --- a/src/graph/executor/query/TraverseExecutor.cpp +++ b/src/graph/executor/query/TraverseExecutor.cpp @@ -120,27 +120,18 @@ Expression* TraverseExecutor::selectFilter() { } void TraverseExecutor::addStats(RpcResponse& resp, int64_t getNbrTimeInUSec) { + folly::dynamic stepInfo = folly::dynamic::array(); auto& hostLatency = resp.hostLatency(); - std::stringstream ss; - ss << "{\n"; for (size_t i = 0; i < hostLatency.size(); ++i) { size_t size = 0u; auto& result = resp.responses()[i]; if (result.vertices_ref().has_value()) { size = (*result.vertices_ref()).size(); } - auto& info = hostLatency[i]; - ss << "{" << folly::sformat("{} exec/total/vertices: ", std::get<0>(info).toString()) - << folly::sformat("{}(us)/{}(us)/{},", std::get<1>(info), std::get<2>(info), size) << "\n" - << folly::sformat("total_rpc_time: {}(us)", getNbrTimeInUSec) << "\n"; - auto detail = getStorageDetail(result.result.latency_detail_us_ref()); - if (!detail.empty()) { - ss << folly::sformat("storage_detail: {}", detail); - } - ss << "\n}"; + auto info = collectRespProfileData(result.result, hostLatency[i], size, getNbrTimeInUSec); + stepInfo.push_back(folly::dynamic::object(folly::sformat("resp[{}]", i), info)); } - ss << "\n}"; - otherStats_.emplace(folly::sformat("step {}", currentStep_), ss.str()); + otherStats_.emplace(folly::sformat("step[{}]", currentStep_), folly::toPrettyJson(stepInfo)); } folly::Future TraverseExecutor::handleResponse(RpcResponse&& resps) { From 6c05d9b66a95121cc745a7607513ee5b76905847 Mon Sep 17 00:00:00 2001 From: yixinglu <2520865+yixinglu@users.noreply.github.com> Date: Thu, 17 Nov 2022 14:17:41 +0800 Subject: [PATCH 2/4] Move to utils --- src/graph/executor/StorageAccessExecutor.cpp | 9 ----- src/graph/executor/StorageAccessExecutor.h | 25 +----------- src/graph/executor/algo/ShortestPathBase.cpp | 35 +++-------------- src/graph/executor/algo/ShortestPathBase.h | 2 - src/graph/executor/algo/SubgraphExecutor.cpp | 3 +- .../executor/query/GetDstBySrcExecutor.cpp | 3 +- .../executor/query/GetNeighborsExecutor.cpp | 3 +- src/graph/executor/query/TraverseExecutor.cpp | 5 ++- src/graph/util/CMakeLists.txt | 1 + src/graph/util/Utils.cpp | 39 +++++++++++++++++++ src/graph/util/Utils.h | 14 +++++++ 11 files changed, 70 insertions(+), 69 deletions(-) create mode 100644 src/graph/util/Utils.cpp diff --git a/src/graph/executor/StorageAccessExecutor.cpp b/src/graph/executor/StorageAccessExecutor.cpp index 3c0b7cb9b5d..721b22fbdeb 100644 --- a/src/graph/executor/StorageAccessExecutor.cpp +++ b/src/graph/executor/StorageAccessExecutor.cpp @@ -148,14 +148,5 @@ StatusOr> StorageAccessExecutor::buildRequestListByVidType(It return internal::buildRequestList(space, exprCtx, iter, expr, dedup, isCypher); } -folly::dynamic StorageAccessExecutor::getStorageDetail( - const std::map &profileDetail) const { - folly::dynamic profileData = folly::dynamic::object(); - for (auto &p : profileDetail) { - profileData.insert(p.first, folly::sformat("{}(us)", p.second)); - } - return profileData; -} - } // namespace graph } // namespace nebula diff --git a/src/graph/executor/StorageAccessExecutor.h b/src/graph/executor/StorageAccessExecutor.h index 4d8d5991955..b6323531131 100644 --- a/src/graph/executor/StorageAccessExecutor.h +++ b/src/graph/executor/StorageAccessExecutor.h @@ -9,6 +9,7 @@ #include "clients/storage/StorageClientBase.h" #include "graph/executor/Executor.h" +#include "graph/util/Utils.h" namespace nebula { @@ -139,38 +140,16 @@ class StorageAccessExecutor : public Executor { return Status::OK(); } - folly::dynamic collectRespProfileData(const storage::cpp2::ResponseCommon &resp, - const std::tuple &info, - size_t numVertices = 0UL, - size_t totalRpcTime = 0UL) const { - folly::dynamic stat = folly::dynamic::object(); - stat.insert("address", std::get<0>(info).toString()); - stat.insert("exec", folly::sformat("{}(us)", std::get<1>(info))); - stat.insert("total", folly::sformat("{}(us)", std::get<2>(info))); - if (numVertices > 0) { - stat.insert("vertices", numVertices); - } - if (totalRpcTime > 0) { - stat.insert("total_rpc_time", folly::sformat("{}(us)", totalRpcTime)); - } - if (resp.latency_detail_us_ref().has_value()) { - stat.insert("storage_detail", getStorageDetail(*resp.get_latency_detail_us())); - } - return stat; - } - template void addStats(storage::StorageRpcResponse &resp, std::unordered_map &stats) const { auto &hostLatency = resp.hostLatency(); for (size_t i = 0; i < hostLatency.size(); ++i) { - auto info = collectRespProfileData(resp.responses()[i].get_result(), hostLatency[i]); + auto info = util::collectRespProfileData(resp.responses()[i].get_result(), hostLatency[i]); stats.emplace(folly::sformat("resp[{}]", i), folly::toPrettyJson(info)); } } - folly::dynamic getStorageDetail(const std::map &profileDetail) const; - bool isIntVidType(const SpaceInfo &space) const; StatusOr buildRequestDataSetByVidType(Iterator *iter, diff --git a/src/graph/executor/algo/ShortestPathBase.cpp b/src/graph/executor/algo/ShortestPathBase.cpp index 4493919fe42..7185ffb3579 100644 --- a/src/graph/executor/algo/ShortestPathBase.cpp +++ b/src/graph/executor/algo/ShortestPathBase.cpp @@ -8,6 +8,7 @@ #include "graph/util/Utils.h" using apache::thrift::optional_field_ref; +using nebula::graph::util::collectRespProfileData; using nebula::storage::StorageClient; namespace nebula { @@ -70,15 +71,6 @@ std::vector ShortestPathBase::handlePropResp(PropRpcResponse&& resps) { return vertices; } -folly::dynamic ShortestPathBase::getStorageDetail( - const std::map& profileDetail) const { - folly::dynamic info = folly::dynamic::object(); - for (auto& p : profileDetail) { - info.insert(p.first, folly::sformat("{}(us)", p.second)); - } - return info; -} - Status ShortestPathBase::handleErrorCode(nebula::cpp2::ErrorCode code, PartitionID partId) const { switch (code) { case nebula::cpp2::ErrorCode::E_KEY_NOT_FOUND: @@ -177,17 +169,8 @@ void ShortestPathBase::addStats(RpcResponse& resp, if (result.vertices_ref().has_value()) { size = (*result.vertices_ref()).size(); } - auto& info = hostLatency[i]; - folly::dynamic stat = folly::dynamic::object(); - stat.insert("address", std::get<0>(info).toString()); - stat.insert("exec", folly::sformat("{}(us)", std::get<1>(info))); - stat.insert("total", folly::sformat("{}(us)", std::get<2>(info))); - stat.insert("vertices", size); - stat.insert("total_rpc_time", folly::sformat("{}(us)", timeInUSec)); - if (result.result.latency_detail_us_ref().has_value()) { - stat.insert("storage_detail", getStorageDetail(*result.result.get_latency_detail_us())); - } - stats.push_back(folly::dynamic::object(folly::sformat("resp[{}]", i), stat)); + auto info = util::collectRespProfileData(result.result, hostLatency[i], size, timeInUSec); + stats.push_back(std::move(info)); } auto key = folly::sformat("{}step[{}]", reverse ? "reverse " : "", stepNum); @@ -200,17 +183,9 @@ void ShortestPathBase::addStats(PropRpcResponse& resp, int64_t timeInUSec) const folly::dynamic stats = folly::dynamic::array(); auto& hostLatency = resp.hostLatency(); for (size_t i = 0; i < hostLatency.size(); ++i) { - auto& info = hostLatency[i]; - folly::dynamic stat = folly::dynamic::object(); - stat.insert("address", std::get<0>(info).toString()); - stat.insert("exec", folly::sformat("{}(us)", std::get<1>(info))); - stat.insert("total", folly::sformat("{}(us)", std::get<2>(info))); - stat.insert("total_rpc_time", folly::sformat("{}(us)", timeInUSec)); const auto& result = resp.responses()[i].get_result(); - if (result.latency_detail_us_ref().has_value()) { - stat.insert("storage_detail", getStorageDetail(*result.get_latency_detail_us())); - } - stats.push_back(std::move(stat)); + auto info = util::collectRespProfileData(result, hostLatency[i], 0, timeInUSec); + stats.push_back(std::move(info)); } statsLock_.lock(); diff --git a/src/graph/executor/algo/ShortestPathBase.h b/src/graph/executor/algo/ShortestPathBase.h index cba3d58fc66..ec94174b2e3 100644 --- a/src/graph/executor/algo/ShortestPathBase.h +++ b/src/graph/executor/algo/ShortestPathBase.h @@ -74,8 +74,6 @@ class ShortestPathBase { return Result::State::kSuccess; } - folly::dynamic getStorageDetail(const std::map& profileDetail) const; - protected: const ShortestPath* pathNode_{nullptr}; QueryContext* qctx_{nullptr}; diff --git a/src/graph/executor/algo/SubgraphExecutor.cpp b/src/graph/executor/algo/SubgraphExecutor.cpp index 8c0f01458df..966a8af4f6b 100644 --- a/src/graph/executor/algo/SubgraphExecutor.cpp +++ b/src/graph/executor/algo/SubgraphExecutor.cpp @@ -5,6 +5,7 @@ #include "graph/executor/algo/SubgraphExecutor.h" #include "graph/service/GraphFlags.h" +#include "graph/util/Utils.h" using nebula::storage::StorageClient; namespace nebula { @@ -59,7 +60,7 @@ folly::Future SubgraphExecutor::getNeighbors() { if (result.vertices_ref().has_value()) { size = (*result.vertices_ref()).size(); } - auto info = collectRespProfileData(result.result, hostLatency[i], size); + auto info = util::collectRespProfileData(result.result, hostLatency[i], size); otherStats_.emplace(folly::sformat("resp[{}]", i), folly::toPrettyJson(info)); } vids_.clear(); diff --git a/src/graph/executor/query/GetDstBySrcExecutor.cpp b/src/graph/executor/query/GetDstBySrcExecutor.cpp index 7c7add52263..ee7f0ea3a27 100644 --- a/src/graph/executor/query/GetDstBySrcExecutor.cpp +++ b/src/graph/executor/query/GetDstBySrcExecutor.cpp @@ -5,6 +5,7 @@ #include "graph/executor/query/GetDstBySrcExecutor.h" #include "graph/service/GraphFlags.h" +#include "graph/util/Utils.h" using nebula::storage::StorageClient; using nebula::storage::StorageRpcResponse; @@ -55,7 +56,7 @@ folly::Future GetDstBySrcExecutor::execute() { if (result.dsts_ref().has_value()) { size = (*result.dsts_ref()).size(); } - auto info = collectRespProfileData(result.result, hostLatency[i], size); + auto info = util::collectRespProfileData(result.result, hostLatency[i], size); otherStats_.emplace(folly::sformat("resp[{}]", i), folly::toPrettyJson(info)); } return handleResponse(resp, this->gd_->colNames()); diff --git a/src/graph/executor/query/GetNeighborsExecutor.cpp b/src/graph/executor/query/GetNeighborsExecutor.cpp index 7dda012c32e..d5c1617ce7a 100644 --- a/src/graph/executor/query/GetNeighborsExecutor.cpp +++ b/src/graph/executor/query/GetNeighborsExecutor.cpp @@ -5,6 +5,7 @@ #include "graph/executor/query/GetNeighborsExecutor.h" #include "graph/service/GraphFlags.h" +#include "graph/util/Utils.h" using nebula::storage::StorageClient; using nebula::storage::StorageRpcResponse; @@ -69,7 +70,7 @@ folly::Future GetNeighborsExecutor::execute() { if (result.vertices_ref().has_value()) { size = (*result.vertices_ref()).size(); } - auto info = collectRespProfileData(result.result, hostLatency[i], size); + auto info = util::collectRespProfileData(result.result, hostLatency[i], size); otherStats_.emplace(folly::sformat("resp[{}]", i), folly::toPrettyJson(info)); } return handleResponse(resp); diff --git a/src/graph/executor/query/TraverseExecutor.cpp b/src/graph/executor/query/TraverseExecutor.cpp index 7ff987468b9..e4c7a9eadd3 100644 --- a/src/graph/executor/query/TraverseExecutor.cpp +++ b/src/graph/executor/query/TraverseExecutor.cpp @@ -7,6 +7,7 @@ #include "clients/storage/StorageClient.h" #include "graph/service/GraphFlags.h" #include "graph/util/SchemaUtil.h" +#include "graph/util/Utils.h" using nebula::storage::StorageClient; using nebula::storage::StorageRpcResponse; @@ -128,8 +129,8 @@ void TraverseExecutor::addStats(RpcResponse& resp, int64_t getNbrTimeInUSec) { if (result.vertices_ref().has_value()) { size = (*result.vertices_ref()).size(); } - auto info = collectRespProfileData(result.result, hostLatency[i], size, getNbrTimeInUSec); - stepInfo.push_back(folly::dynamic::object(folly::sformat("resp[{}]", i), info)); + auto info = util::collectRespProfileData(result.result, hostLatency[i], size, getNbrTimeInUSec); + stepInfo.push_back(std::move(info)); } otherStats_.emplace(folly::sformat("step[{}]", currentStep_), folly::toPrettyJson(stepInfo)); } diff --git a/src/graph/util/CMakeLists.txt b/src/graph/util/CMakeLists.txt index 0a80754d58d..9d3eacc5b6d 100644 --- a/src/graph/util/CMakeLists.txt +++ b/src/graph/util/CMakeLists.txt @@ -14,6 +14,7 @@ nebula_add_library( ParserUtil.cpp PlannerUtil.cpp ValidateUtil.cpp + Utils.cpp ) nebula_add_library( diff --git a/src/graph/util/Utils.cpp b/src/graph/util/Utils.cpp new file mode 100644 index 00000000000..864145e2944 --- /dev/null +++ b/src/graph/util/Utils.cpp @@ -0,0 +1,39 @@ +// Copyright (c) 2022 vesoft inc. All rights reserved. +// +// This source code is licensed under Apache 2.0 License. + +#include "graph/util/Utils.h" + +#include "interface/gen-cpp2/storage_types.h" + +namespace nebula::graph::util { + +folly::dynamic getStorageDetail(const std::map& profileDetail) { + folly::dynamic profileData = folly::dynamic::object(); + for (auto& p : profileDetail) { + profileData.insert(p.first, folly::sformat("{}(us)", p.second)); + } + return profileData; +} + +folly::dynamic collectRespProfileData(const storage::cpp2::ResponseCommon& resp, + const std::tuple& info, + size_t numVertices, + size_t totalRpcTime) { + folly::dynamic stat = folly::dynamic::object(); + stat.insert("address", std::get<0>(info).toString()); + stat.insert("exec", folly::sformat("{}(us)", std::get<1>(info))); + stat.insert("total", folly::sformat("{}(us)", std::get<2>(info))); + if (numVertices > 0) { + stat.insert("vertices", numVertices); + } + if (totalRpcTime > 0) { + stat.insert("total_rpc_time", folly::sformat("{}(us)", totalRpcTime)); + } + if (resp.latency_detail_us_ref().has_value()) { + stat.insert("storage_detail", getStorageDetail(*resp.get_latency_detail_us())); + } + return stat; +} + +} // namespace nebula::graph::util diff --git a/src/graph/util/Utils.h b/src/graph/util/Utils.h index 5c729a720df..c123212bf4f 100644 --- a/src/graph/util/Utils.h +++ b/src/graph/util/Utils.h @@ -6,11 +6,18 @@ #define GRAPH_UTIL_UTILS_H_ #include +#include #include #include #include +#include "common/datatypes/HostAddr.h" + +namespace nebula::storage::cpp2 { +class ResponseCommon; +} + namespace nebula::graph::util { // Iterates the container and for each element, apply the function fn(). Joins the results of the @@ -24,6 +31,13 @@ std::string join(const Container& container, Fn fn, const std::string& delimiter return folly::join(delimiter, strs); } +folly::dynamic getStorageDetail(const std::map& profileDetail); + +folly::dynamic collectRespProfileData(const storage::cpp2::ResponseCommon& resp, + const std::tuple& info, + size_t numVertices = 0UL, + size_t totalRpcTime = 0UL); + } // namespace nebula::graph::util #endif // GRAPH_UTIL_UTILS_H_ From 1a0562ce1e155379507441073caf7c2e794b3c9d Mon Sep 17 00:00:00 2001 From: yixinglu <2520865+yixinglu@users.noreply.github.com> Date: Thu, 17 Nov 2022 18:26:38 +0800 Subject: [PATCH 3/4] Add test cases --- src/common/datatypes/HostAddr.h | 8 +- src/graph/util/Utils.cpp | 2 +- tests/common/plan_differ.py | 74 +++++++++++++++++-- tests/tck/conftest.py | 1 - .../explain/ExplainAndProfile.feature | 19 +++++ 5 files changed, 93 insertions(+), 11 deletions(-) diff --git a/src/common/datatypes/HostAddr.h b/src/common/datatypes/HostAddr.h index 1af8ddcfb19..b326d216d68 100644 --- a/src/common/datatypes/HostAddr.h +++ b/src/common/datatypes/HostAddr.h @@ -40,7 +40,13 @@ struct HostAddr { std::string toString() const { std::stringstream os; - os << "\"" << host << ":" << port << "\""; + os << "\"" << host << "\":" << port; + return os.str(); + } + + std::string toRawString() const { + std::stringstream os; + os << host << ":" << port; return os.str(); } diff --git a/src/graph/util/Utils.cpp b/src/graph/util/Utils.cpp index 864145e2944..6442a336bc8 100644 --- a/src/graph/util/Utils.cpp +++ b/src/graph/util/Utils.cpp @@ -21,7 +21,7 @@ folly::dynamic collectRespProfileData(const storage::cpp2::ResponseCommon& resp, size_t numVertices, size_t totalRpcTime) { folly::dynamic stat = folly::dynamic::object(); - stat.insert("address", std::get<0>(info).toString()); + stat.insert("host", std::get<0>(info).toRawString()); stat.insert("exec", folly::sformat("{}(us)", std::get<1>(info))); stat.insert("total", folly::sformat("{}(us)", std::get<2>(info))); if (numVertices > 0) { diff --git a/tests/common/plan_differ.py b/tests/common/plan_differ.py index d496979dc2f..19cae12dc81 100644 --- a/tests/common/plan_differ.py +++ b/tests/common/plan_differ.py @@ -11,6 +11,7 @@ class PlanDiffer: NAME = "name" DEPENDS = "dependencies" OP_INFO = "operator info" + PROFILING_DATA = "profiling data" PATTERN = re.compile(r"\{\"loopBody\": \"(\d+)\"\}") def __init__(self, resp, expect): @@ -48,6 +49,7 @@ def _diff_plan_node(self, plan_desc, line_num, rows, column_names) -> bool: op = expect_node[column_names.index(self.OP_INFO)] res = self.PATTERN.match(op) if not res: + self._err_msg = "Could not find 'loopBody' info in operator info of the Loop" return False body_id = int(res.group(1)) loop_body_idx = self._loop_body(plan_desc, @@ -60,17 +62,24 @@ def _diff_plan_node(self, plan_desc, line_num, rows, column_names) -> bool: elif self._is_same_node(name, "Select"): # TODO(yee): check select node pass - elif self.OP_INFO in column_names: + + if self.OP_INFO in column_names: op = expect_node[column_names.index(self.OP_INFO)] # Parse expected operator info jsonStr to dict - expect_op_dict = {} - if op: - expect_op_dict = json.loads(op) + expect_op_dict = json.loads(op) if op else {} self._err_msg = self._check_op_info( expect_op_dict, plan_node_desc.description) if self._err_msg: return False + if self.PROFILING_DATA in column_names: + profiling_data = expect_node[column_names.index(self.PROFILING_DATA)] + expect_profiling_data = json.loads(profiling_data) if profiling_data else {} + self._err_msg = self._check_profiling_data( + expect_profiling_data, plan_node_desc.profiles) + if self._err_msg: + return False + if plan_node_desc.dependencies is None: return True @@ -89,8 +98,7 @@ def _diff_plan_node(self, plan_desc, line_num, rows, column_names) -> bool: def _check_op_info(self, exp, resp): if resp is None: - if exp: - return f"expect: {exp} but resp plan node is None" + return f"expect: {exp} but resp plan node is None" if exp else None if exp: resp_dict = { f"{bytes.decode(pair.key)}": f"{bytes.decode(pair.value)}" @@ -101,6 +109,56 @@ def _check_op_info(self, exp, resp): json.dumps(exp), json.dumps(resp_dict)) return None + def _check_profiling_other_stats(self, exp, resp): + if type(exp) != type(resp): + return False + if isinstance(exp, dict): + return self._is_subdict_nested(exp, resp) + return exp == resp + + def _check_profiling_stats(self, exp, resp, version): + if not isinstance(exp, dict): + return False + other_stats = resp.other_stats if resp.other_stats else {} + for k,v in exp.items(): + if k == "version": + if int(v) != version : + return False + elif hasattr(resp, k): + if getattr(resp, k) != v: + return False + else: + if isinstance(k, str): + k = k.encode() + if k not in other_stats: + return False + val = other_stats[k] + try: + val = json.loads(val) + except: + try: + val = val.decode() + except: + pass + if not self._check_profiling_other_stats(v, val): + return False + return True + + def _check_profiling_data(self, exp, resp): + if resp is None: + return f"expect: {exp} but resp profiling data is None" if exp else None + if not exp: + return None + if isinstance(resp, list) and len(resp) > 1: + if (not isinstance(exp, list)) or len(exp) != len(resp): + return f"Expected profiling data has invalid length: {len(exp)} vs. {len(resp)}" + for i, r in enumerate(resp): + if not self._check_profiling_stats(exp[i], r, i): + return f"Fail to diff {json.dumps(exp[i])} and {r}, i: {i}" + elif not self._check_profiling_stats(exp, resp[0], 0): + return f"Fail to diff {json.dumps(exp)} and {resp[0]}" + return None + def _is_same_node(self, lhs: str, rhs: str) -> bool: return lhs.lower().startswith(rhs.lower()) @@ -142,7 +200,7 @@ def _try_convert_json(j): extracted_resp_dict[k] = _try_convert_json(resp[k]) else: extracted_resp_dict = self._convert_jsonStr_to_dict(resp, key_list) - + for k in extracted_expected_dict: extracted_expected_dict[k] = _try_convert_json(extracted_expected_dict[k]) @@ -156,7 +214,7 @@ def _is_subdict(small, big): return not bool(diff) return _is_subdict(extracted_expected_dict, extracted_resp_dict) - + # resp: pair(key, jsonStr) def _convert_jsonStr_to_dict(self, resp, key_list): resp_json_str = '' diff --git a/tests/tck/conftest.py b/tests/tck/conftest.py index 8162bdfc7b8..4a88ea03273 100644 --- a/tests/tck/conftest.py +++ b/tests/tck/conftest.py @@ -822,7 +822,6 @@ def check_plan(request, plan, exec_ctx): f"Location: {location}", differ.err_msg(), ] - assert res, "\n".join(msg) diff --git a/tests/tck/features/explain/ExplainAndProfile.feature b/tests/tck/features/explain/ExplainAndProfile.feature index 4057bed2592..926094493e1 100644 --- a/tests/tck/features/explain/ExplainAndProfile.feature +++ b/tests/tck/features/explain/ExplainAndProfile.feature @@ -70,3 +70,22 @@ Feature: Explain and Profile | explain | | EXPLAIN | | PROFILE | + + Scenario: Test profiling data format + When profiling query: + """ + GO 4 STEPS FROM 'Tim Duncan' OVER like YIELD like._dst AS dst | YIELD count(*) + """ + Then the result should be, in any order: + | count(*) | + | 6 | + And the execution plan should be: + | id | name | dependencies | profiling data | operator info | + | 7 | Aggregate | 6 | {"version":0, "rows": 1} | | + | 6 | Project | 5 | {"version":0, "rows": 6} | | + | 5 | GetNeighbors | 4 | {"version":0, "rows": 6, "resp[0]": {"vertices": 3}} | | + | 4 | Loop | 0 | [{"version":0, "rows": 1},{"version":1, "rows": 1},{"version":2, "rows": 1},{"version":3, "rows": 1}] | {"loopBody": "3"} | + | 3 | Dedup | 2 | [{"version":0, "rows": 2},{"version":1, "rows": 3},{"version":2, "rows": 3}] | | + | 2 | GetDstBySrc | 1 | [{"version":0, "rows": 2, "resp[0]": {"vertices": 2}},{"version":1, "rows": 3, "resp[0]":{"vertices": 3}}, {"version":2, "rows": 3, "resp[0]":{"vertices": 3}}] | | + | 1 | Start | | [{"version":0, "rows": 0},{"version":1, "rows": 0},{"version":2, "rows": 0}] | | + | 0 | Start | | {"version":0, "rows": 0} | | From 70913930ab98df707929dd921255163be39fcf5a Mon Sep 17 00:00:00 2001 From: yixinglu <2520865+yixinglu@users.noreply.github.com> Date: Thu, 17 Nov 2022 18:50:27 +0800 Subject: [PATCH 4/4] Rename GetDstBySrcProcessorDedup --- src/storage/query/GetDstBySrcProcessor.cpp | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/storage/query/GetDstBySrcProcessor.cpp b/src/storage/query/GetDstBySrcProcessor.cpp index e6a86eeeb73..bbeb2832fc9 100644 --- a/src/storage/query/GetDstBySrcProcessor.cpp +++ b/src/storage/query/GetDstBySrcProcessor.cpp @@ -31,7 +31,7 @@ void GetDstBySrcProcessor::doProcess(const cpp2::GetDstBySrcRequest& req) { if (req.common_ref().has_value() && req.get_common()->profile_detail_ref().value_or(false)) { profileDetailFlag_ = true; profileDetail("GetDstBySrcProcessorTotal", 0); - profileDetail("Dedup", 0); + profileDetail("GetDstBySrcProcessorDedup", 0); } spaceId_ = req.get_space_id(); @@ -320,7 +320,7 @@ void GetDstBySrcProcessor::onProcessFinished() { resp_.dsts_ref() = std::move(resultDataSet_); if (profileDetailFlag_) { - profileDetail("Dedup", dedupDuration_.elapsedInUSec()); + profileDetail("GetDstBySrcProcessorDedup", dedupDuration_.elapsedInUSec()); profileDetail("GetDstBySrcProcessorTotal", totalDuration_.elapsedInUSec()); } }