From bb1e8aa1640e9081f8ca2ffb3b3b2e97163a8aeb Mon Sep 17 00:00:00 2001 From: Tyler Neely Date: Tue, 1 Nov 2022 10:46:25 +0000 Subject: [PATCH] Improve histogram output by adding a pretty table printing function --- src/io/local_transport/local_transport.hpp | 4 +-- .../local_transport_handle.hpp | 2 +- src/io/message_histogram_collector.hpp | 34 +++++++++++++++++-- src/io/simulator/simulator_handle.cpp | 2 +- src/io/simulator/simulator_handle.hpp | 2 +- src/io/simulator/simulator_transport.hpp | 4 +-- src/io/transport.hpp | 4 +-- tests/unit/1k_shards_1k_create_scanall.cpp | 26 +++++++++++--- 8 files changed, 59 insertions(+), 19 deletions(-) diff --git a/src/io/local_transport/local_transport.hpp b/src/io/local_transport/local_transport.hpp index 4fc6a4361..bf1991d21 100644 --- a/src/io/local_transport/local_transport.hpp +++ b/src/io/local_transport/local_transport.hpp @@ -61,8 +61,6 @@ class LocalTransport { return distrib(rng); } - std::unordered_map ResponseLatencies() { - return local_transport_handle_->ResponseLatencies(); - } + LatencyHistogramSummaries ResponseLatencies() { return local_transport_handle_->ResponseLatencies(); } }; }; // namespace memgraph::io::local_transport diff --git a/src/io/local_transport/local_transport_handle.hpp b/src/io/local_transport/local_transport_handle.hpp index ad257c926..6cab1a24f 100644 --- a/src/io/local_transport/local_transport_handle.hpp +++ b/src/io/local_transport/local_transport_handle.hpp @@ -56,7 +56,7 @@ class LocalTransportHandle { return should_shut_down_; } - std::unordered_map ResponseLatencies() { + LatencyHistogramSummaries ResponseLatencies() { std::unique_lock lock(mu_); return histograms_.ResponseLatencies(); } diff --git a/src/io/message_histogram_collector.hpp b/src/io/message_histogram_collector.hpp index 4c99f7f1f..542767568 100644 --- a/src/io/message_histogram_collector.hpp +++ b/src/io/message_histogram_collector.hpp @@ -20,6 +20,7 @@ #include "io/time.hpp" #include "utils/histogram.hpp" #include "utils/logging.hpp" +#include "utils/print_helpers.hpp" #include "utils/type_info_ref.hpp" namespace memgraph::io { @@ -57,6 +58,35 @@ struct LatencyHistogramSummary { } }; +struct LatencyHistogramSummaries { + std::unordered_map latencies; + + std::string SummaryTable() { + std::string output = ""; + + const auto row = [&output](const auto &c1, const auto &c2, const auto &c3, const auto &c4, const auto &c5, + const auto &c6, const auto &c7) { + output += + fmt::format("{: >50} | {: >8} | {: >8} | {: >8} | {: >8} | {: >8} | {: >8}\n", c1, c2, c3, c4, c5, c6, c7); + }; + row("name", "count", "min (μs)", "med (μs)", "p99 (μs)", "max (μs)", "sum (μs)"); + + for (const auto &[name, histo] : latencies) { + row(name, histo.count, histo.p0.count(), histo.p50.count(), histo.p99.count(), histo.p100.count(), + histo.sum.count()); + } + + output += "\n"; + return output; + } + + friend std::ostream &operator<<(std::ostream &in, const LatencyHistogramSummaries &histo) { + using memgraph::utils::print_helpers::operator<<; + in << histo.latencies; + return in; + } +}; + class MessageHistogramCollector { std::unordered_map histograms_; @@ -66,7 +96,7 @@ class MessageHistogramCollector { histo.Measure(duration.count()); } - std::unordered_map ResponseLatencies() { + LatencyHistogramSummaries ResponseLatencies() { std::unordered_map ret{}; for (const auto &[type_id, histo] : histograms_) { @@ -90,7 +120,7 @@ class MessageHistogramCollector { ret.emplace(demangled_name, latency_histogram_summary); } - return ret; + return LatencyHistogramSummaries{.latencies = ret}; } }; diff --git a/src/io/simulator/simulator_handle.cpp b/src/io/simulator/simulator_handle.cpp index d71ecd0a9..74b2854a0 100644 --- a/src/io/simulator/simulator_handle.cpp +++ b/src/io/simulator/simulator_handle.cpp @@ -31,7 +31,7 @@ bool SimulatorHandle::ShouldShutDown() const { return should_shut_down_; } -std::unordered_map SimulatorHandle::ResponseLatencies() { +LatencyHistogramSummaries SimulatorHandle::ResponseLatencies() { std::unique_lock lock(mu_); return histograms_.ResponseLatencies(); } diff --git a/src/io/simulator/simulator_handle.hpp b/src/io/simulator/simulator_handle.hpp index 75bf8fb5e..a781f6ee6 100644 --- a/src/io/simulator/simulator_handle.hpp +++ b/src/io/simulator/simulator_handle.hpp @@ -78,7 +78,7 @@ class SimulatorHandle { explicit SimulatorHandle(SimulatorConfig config) : cluster_wide_time_microseconds_(config.start_time), rng_(config.rng_seed), config_(config) {} - std::unordered_map ResponseLatencies(); + LatencyHistogramSummaries ResponseLatencies(); ~SimulatorHandle() { for (auto it = promises_.begin(); it != promises_.end();) { diff --git a/src/io/simulator/simulator_transport.hpp b/src/io/simulator/simulator_transport.hpp index f1c68230d..1aacfed9a 100644 --- a/src/io/simulator/simulator_transport.hpp +++ b/src/io/simulator/simulator_transport.hpp @@ -64,8 +64,6 @@ class SimulatorTransport { return distrib(rng_); } - std::unordered_map ResponseLatencies() { - return simulator_handle_->ResponseLatencies(); - } + LatencyHistogramSummaries ResponseLatencies() { return simulator_handle_->ResponseLatencies(); } }; }; // namespace memgraph::io::simulator diff --git a/src/io/transport.hpp b/src/io/transport.hpp index a1a337ddb..7640e07ac 100644 --- a/src/io/transport.hpp +++ b/src/io/transport.hpp @@ -143,8 +143,6 @@ class Io { Io ForkLocal() { return Io(implementation_, address_.ForkUniqueAddress()); } - std::unordered_map ResponseLatencies() { - return implementation_.ResponseLatencies(); - } + LatencyHistogramSummaries ResponseLatencies() { return implementation_.ResponseLatencies(); } }; }; // namespace memgraph::io diff --git a/tests/unit/1k_shards_1k_create_scanall.cpp b/tests/unit/1k_shards_1k_create_scanall.cpp index 5fdbfafa8..cba9cc8ab 100644 --- a/tests/unit/1k_shards_1k_create_scanall.cpp +++ b/tests/unit/1k_shards_1k_create_scanall.cpp @@ -31,7 +31,6 @@ #include "machine_manager/machine_manager.hpp" #include "query/v2/requests.hpp" #include "query/v2/shard_request_manager.hpp" -#include "utils/print_helpers.hpp" #include "utils/variant_helpers.hpp" namespace memgraph::tests::simulation { @@ -95,7 +94,7 @@ MachineManager MkMm(LocalSystem &local_system, std::vector mm) { mm.Run(); } @@ -225,7 +224,9 @@ TEST(MachineManager, ManyShards) { auto replication_factor = 1; auto create_ops = 1000; + auto time_before_shard_map_creation = cli_io_2.Now(); ShardMap initialization_sm = TestShardMap(shard_splits, replication_factor); + auto time_after_shard_map_creation = cli_io_2.Now(); auto mm_1 = MkMm(local_system, coordinator_addresses, machine_1_addr, initialization_sm); Address coordinator_address = mm_1.CoordinatorAddress(); @@ -233,7 +234,10 @@ TEST(MachineManager, ManyShards) { auto mm_thread_1 = std::jthread(RunMachine, std::move(mm_1)); CoordinatorClient coordinator_client(cli_io, coordinator_address, {coordinator_address}); + + auto time_before_shard_stabilization = cli_io_2.Now(); WaitForShardsToInitialize(coordinator_client); + auto time_after_shard_stabilization = cli_io_2.Now(); msgs::ShardRequestManager shard_request_manager(std::move(coordinator_client), std::move(cli_io)); @@ -241,18 +245,30 @@ TEST(MachineManager, ManyShards) { auto correctness_model = std::set{}; + auto time_before_creates = cli_io_2.Now(); + for (int i = 0; i < create_ops; i++) { ExecuteOp(shard_request_manager, correctness_model, CreateVertex{.first = i, .second = i}); } + auto time_after_creates = cli_io_2.Now(); + ExecuteOp(shard_request_manager, correctness_model, ScanAll{}); + auto time_after_scan = cli_io_2.Now(); + local_system.ShutDown(); - auto histo = cli_io_2.ResponseLatencies(); + auto latencies = cli_io_2.ResponseLatencies(); - using memgraph::utils::print_helpers::operator<<; - std::cout << "response latencies: " << histo << std::endl; + std::cout << "response latencies: \n" << latencies.SummaryTable(); + + std::cout << "split shard map: " << (time_after_shard_map_creation - time_before_shard_map_creation).count() + << std::endl; + std::cout << "shard stabilization: " << (time_after_shard_stabilization - time_before_shard_stabilization).count() + << std::endl; + std::cout << "create nodes: " << (time_after_creates - time_before_creates).count() << std::endl; + std::cout << "scan nodes: " << (time_after_scan - time_after_creates).count() << std::endl; } } // namespace memgraph::tests::simulation