diff --git a/docs/root/configuration/network_filters/redis_proxy_filter.rst b/docs/root/configuration/network_filters/redis_proxy_filter.rst index cb5c3937e026e..a79da1a5faf2c 100644 --- a/docs/root/configuration/network_filters/redis_proxy_filter.rst +++ b/docs/root/configuration/network_filters/redis_proxy_filter.rst @@ -57,7 +57,8 @@ The Redis filter will gather statistics for commands in the total, Counter, Number of commands success, Counter, Number of commands that were successful error, Counter, Number of commands that returned a partial or complete error response - + latency, Histogram, Command execution time in milliseconds + .. _config_network_filters_redis_proxy_per_command_stats: Runtime diff --git a/docs/root/intro/version_history.rst b/docs/root/intro/version_history.rst index 2266a6d1341ab..822fbbf9c9031 100644 --- a/docs/root/intro/version_history.rst +++ b/docs/root/intro/version_history.rst @@ -20,6 +20,7 @@ Version history * http: added new grpc_http1_reverse_bridge filter for converting gRPC requests into HTTP/1.1 requests. * mysql: added a MySQL proxy filter that is capable of parsing SQL queries over MySQL wire protocol. Refer to ::ref:`MySQL proxy` for more details. * redis: added :ref:`success and error stats ` for commands. +* redis: added :ref:`latency stats ` for commands. * router: added ability to configure a :ref:`retry policy ` at the virtual host level. * tls: enabled TLS 1.3 on the server-side (non-FIPS builds). diff --git a/source/extensions/filters/network/redis_proxy/BUILD b/source/extensions/filters/network/redis_proxy/BUILD index 82a49d43dcaa2..2d3767310c6f2 100644 --- a/source/extensions/filters/network/redis_proxy/BUILD +++ b/source/extensions/filters/network/redis_proxy/BUILD @@ -54,6 +54,8 @@ envoy_cc_library( ":command_splitter_interface", ":conn_pool_interface", ":supported_commands_lib", + "//include/envoy/stats:stats_macros", + "//include/envoy/stats:timespan", "//source/common/common:assert_lib", "//source/common/common:minimal_logger_lib", "//source/common/common:to_lower_table_lib", diff --git a/source/extensions/filters/network/redis_proxy/command_splitter_impl.cc b/source/extensions/filters/network/redis_proxy/command_splitter_impl.cc index 7182eee98eff8..52d6f6beeebb8 100644 --- a/source/extensions/filters/network/redis_proxy/command_splitter_impl.cc +++ b/source/extensions/filters/network/redis_proxy/command_splitter_impl.cc @@ -37,6 +37,7 @@ void SplitRequestBase::updateStats(const bool success) { } else { command_stats_.error_.inc(); } + command_latency_ms_->complete(); } SingleServerRequest::~SingleServerRequest() { ASSERT(!handle_); } @@ -60,8 +61,9 @@ void SingleServerRequest::cancel() { SplitRequestPtr SimpleRequest::create(ConnPool::Instance& conn_pool, const RespValue& incoming_request, SplitCallbacks& callbacks, - CommandStats& command_stats) { - std::unique_ptr request_ptr{new SimpleRequest(callbacks, command_stats)}; + CommandStats& command_stats, TimeSource& time_source) { + std::unique_ptr request_ptr{ + new SimpleRequest(callbacks, command_stats, time_source)}; request_ptr->handle_ = conn_pool.makeRequest(incoming_request.asArray()[1].asString(), incoming_request, *request_ptr); @@ -75,7 +77,7 @@ SplitRequestPtr SimpleRequest::create(ConnPool::Instance& conn_pool, SplitRequestPtr EvalRequest::create(ConnPool::Instance& conn_pool, const RespValue& incoming_request, SplitCallbacks& callbacks, - CommandStats& command_stats) { + CommandStats& command_stats, TimeSource& time_source) { // EVAL looks like: EVAL script numkeys key [key ...] arg [arg ...] // Ensure there are at least three args to the command or it cannot be hashed. @@ -85,7 +87,7 @@ SplitRequestPtr EvalRequest::create(ConnPool::Instance& conn_pool, return nullptr; } - std::unique_ptr request_ptr{new EvalRequest(callbacks, command_stats)}; + std::unique_ptr request_ptr{new EvalRequest(callbacks, command_stats, time_source)}; request_ptr->handle_ = conn_pool.makeRequest(incoming_request.asArray()[3].asString(), incoming_request, *request_ptr); if (!request_ptr->handle_) { @@ -120,8 +122,8 @@ void FragmentedRequest::onChildFailure(uint32_t index) { SplitRequestPtr MGETRequest::create(ConnPool::Instance& conn_pool, const RespValue& incoming_request, SplitCallbacks& callbacks, - CommandStats& command_stats) { - std::unique_ptr request_ptr{new MGETRequest(callbacks, command_stats)}; + CommandStats& command_stats, TimeSource& time_source) { + std::unique_ptr request_ptr{new MGETRequest(callbacks, command_stats, time_source)}; request_ptr->num_pending_responses_ = incoming_request.asArray().size() - 1; request_ptr->pending_requests_.reserve(request_ptr->num_pending_responses_); @@ -190,13 +192,13 @@ void MGETRequest::onChildResponse(RespValuePtr&& value, uint32_t index) { SplitRequestPtr MSETRequest::create(ConnPool::Instance& conn_pool, const RespValue& incoming_request, SplitCallbacks& callbacks, - CommandStats& command_stats) { + CommandStats& command_stats, TimeSource& time_source) { if ((incoming_request.asArray().size() - 1) % 2 != 0) { onWrongNumberOfArguments(callbacks, incoming_request); command_stats.error_.inc(); return nullptr; } - std::unique_ptr request_ptr{new MSETRequest(callbacks, command_stats)}; + std::unique_ptr request_ptr{new MSETRequest(callbacks, command_stats, time_source)}; request_ptr->num_pending_responses_ = (incoming_request.asArray().size() - 1) / 2; request_ptr->pending_requests_.reserve(request_ptr->num_pending_responses_); @@ -264,9 +266,10 @@ void MSETRequest::onChildResponse(RespValuePtr&& value, uint32_t index) { SplitRequestPtr SplitKeysSumResultRequest::create(ConnPool::Instance& conn_pool, const RespValue& incoming_request, SplitCallbacks& callbacks, - CommandStats& command_stats) { + CommandStats& command_stats, + TimeSource& time_source) { std::unique_ptr request_ptr{ - new SplitKeysSumResultRequest(callbacks, command_stats)}; + new SplitKeysSumResultRequest(callbacks, command_stats, time_source)}; request_ptr->num_pending_responses_ = incoming_request.asArray().size() - 1; request_ptr->pending_requests_.reserve(request_ptr->num_pending_responses_); @@ -327,11 +330,12 @@ void SplitKeysSumResultRequest::onChildResponse(RespValuePtr&& value, uint32_t i } InstanceImpl::InstanceImpl(ConnPool::InstancePtr&& conn_pool, Stats::Scope& scope, - const std::string& stat_prefix) + const std::string& stat_prefix, TimeSource& time_source) : conn_pool_(std::move(conn_pool)), simple_command_handler_(*conn_pool_), eval_command_handler_(*conn_pool_), mget_handler_(*conn_pool_), mset_handler_(*conn_pool_), split_keys_sum_result_handler_(*conn_pool_), - stats_{ALL_COMMAND_SPLITTER_STATS(POOL_COUNTER_PREFIX(scope, stat_prefix + "splitter."))} { + stats_{ALL_COMMAND_SPLITTER_STATS(POOL_COUNTER_PREFIX(scope, stat_prefix + "splitter."))}, + time_source_(time_source) { for (const std::string& command : SupportedCommands::simpleCommands()) { addHandler(scope, stat_prefix, command, simple_command_handler_); } @@ -388,8 +392,8 @@ SplitRequestPtr InstanceImpl::makeRequest(const RespValue& request, SplitCallbac } ENVOY_LOG(debug, "redis: splitting '{}'", request.toString()); handler->command_stats_.total_.inc(); - SplitRequestPtr request_ptr = - handler->handler_.get().startRequest(request, callbacks, handler->command_stats_); + SplitRequestPtr request_ptr = handler->handler_.get().startRequest( + request, callbacks, handler->command_stats_, time_source_); return request_ptr; } @@ -402,13 +406,12 @@ void InstanceImpl::addHandler(Stats::Scope& scope, const std::string& stat_prefi const std::string& name, CommandHandler& handler) { std::string to_lower_name(name); to_lower_table_.toLowerCase(to_lower_name); + const std::string command_stat_prefix = fmt::format("{}command.{}.", stat_prefix, to_lower_name); handler_lookup_table_.add( to_lower_name.c_str(), std::make_shared(HandlerData{ - CommandStats{ - scope.counter(fmt::format("{}command.{}.total", stat_prefix, to_lower_name)), - scope.counter(fmt::format("{}command.{}.success", stat_prefix, to_lower_name)), - scope.counter(fmt::format("{}command.{}.error", stat_prefix, to_lower_name))}, + CommandStats{ALL_COMMAND_STATS(POOL_COUNTER_PREFIX(scope, command_stat_prefix), + POOL_HISTOGRAM_PREFIX(scope, command_stat_prefix))}, handler})); } diff --git a/source/extensions/filters/network/redis_proxy/command_splitter_impl.h b/source/extensions/filters/network/redis_proxy/command_splitter_impl.h index 131a3b9a60daa..009871bb63e41 100644 --- a/source/extensions/filters/network/redis_proxy/command_splitter_impl.h +++ b/source/extensions/filters/network/redis_proxy/command_splitter_impl.h @@ -6,6 +6,8 @@ #include #include "envoy/stats/scope.h" +#include "envoy/stats/stats_macros.h" +#include "envoy/stats/timespan.h" #include "common/common/logger.h" #include "common/common/to_lower_table.h" @@ -36,11 +38,22 @@ class Utility { static RespValuePtr makeError(const std::string& error); }; -class CommandStats { -public: - Stats::Counter& total_; - Stats::Counter& success_; - Stats::Counter& error_; +/** + * All command level stats. @see stats_macros.h + */ +// clang-format off +#define ALL_COMMAND_STATS(COUNTER, HISTOGRAM) \ + COUNTER(total) \ + COUNTER(success) \ + COUNTER(error) \ + HISTOGRAM(latency) \ +// clang-format on + +/** + * Struct definition for all command stats. @see stats_macros.h + */ +struct CommandStats { + ALL_COMMAND_STATS(GENERATE_COUNTER_STRUCT,GENERATE_HISTOGRAM_STRUCT) }; class CommandHandler { @@ -48,7 +61,7 @@ class CommandHandler { virtual ~CommandHandler() {} virtual SplitRequestPtr startRequest(const RespValue& request, SplitCallbacks& callbacks, - CommandStats& command_stats) PURE; + CommandStats& command_stats, TimeSource& time_source) PURE; }; class CommandHandlerBase { @@ -61,11 +74,14 @@ class CommandHandlerBase { class SplitRequestBase : public SplitRequest { protected: static void onWrongNumberOfArguments(SplitCallbacks& callbacks, const RespValue& request); - void updateStats(const bool success); - SplitRequestBase(CommandStats& command_stats) : command_stats_(command_stats) {} + SplitRequestBase(CommandStats& command_stats, TimeSource& time_source) + : command_stats_(command_stats) { + command_latency_ms_ = std::make_unique(command_stats_.latency_, time_source); + } CommandStats& command_stats_; + Stats::TimespanPtr command_latency_ms_; }; /** @@ -83,8 +99,9 @@ class SingleServerRequest : public SplitRequestBase, public ConnPool::PoolCallba void cancel() override; protected: - SingleServerRequest(SplitCallbacks& callbacks, CommandStats& command_stats) - : SplitRequestBase(command_stats), callbacks_(callbacks) {} + SingleServerRequest(SplitCallbacks& callbacks, CommandStats& command_stats, + TimeSource& time_source) + : SplitRequestBase(command_stats, time_source), callbacks_(callbacks) {} SplitCallbacks& callbacks_; ConnPool::PoolRequest* handle_{}; @@ -96,11 +113,12 @@ class SingleServerRequest : public SplitRequestBase, public ConnPool::PoolCallba class SimpleRequest : public SingleServerRequest { public: static SplitRequestPtr create(ConnPool::Instance& conn_pool, const RespValue& incoming_request, - SplitCallbacks& callbacks, CommandStats& command_stats); + SplitCallbacks& callbacks, CommandStats& command_stats, + TimeSource& time_source); private: - SimpleRequest(SplitCallbacks& callbacks, CommandStats& command_stats) - : SingleServerRequest(callbacks, command_stats) {} + SimpleRequest(SplitCallbacks& callbacks, CommandStats& command_stats, TimeSource& time_source) + : SingleServerRequest(callbacks, command_stats, time_source) {} }; /** @@ -109,11 +127,12 @@ class SimpleRequest : public SingleServerRequest { class EvalRequest : public SingleServerRequest { public: static SplitRequestPtr create(ConnPool::Instance& conn_pool, const RespValue& incoming_request, - SplitCallbacks& callbacks, CommandStats& command_stats); + SplitCallbacks& callbacks, CommandStats& command_stats, + TimeSource& time_source); private: - EvalRequest(SplitCallbacks& callbacks, CommandStats& command_stats) - : SingleServerRequest(callbacks, command_stats) {} + EvalRequest(SplitCallbacks& callbacks, CommandStats& command_stats, TimeSource& time_source) + : SingleServerRequest(callbacks, command_stats, time_source) {} }; /** @@ -129,8 +148,8 @@ class FragmentedRequest : public SplitRequestBase { void cancel() override; protected: - FragmentedRequest(SplitCallbacks& callbacks, CommandStats& command_stats) - : SplitRequestBase(command_stats), callbacks_(callbacks) {} + FragmentedRequest(SplitCallbacks& callbacks, CommandStats& command_stats, TimeSource& time_source) + : SplitRequestBase(command_stats, time_source), callbacks_(callbacks) {} struct PendingRequest : public ConnPool::PoolCallbacks { PendingRequest(FragmentedRequest& parent, uint32_t index) : parent_(parent), index_(index) {} @@ -163,11 +182,12 @@ class FragmentedRequest : public SplitRequestBase { class MGETRequest : public FragmentedRequest, Logger::Loggable { public: static SplitRequestPtr create(ConnPool::Instance& conn_pool, const RespValue& incoming_request, - SplitCallbacks& callbacks, CommandStats& command_stats); + SplitCallbacks& callbacks, CommandStats& command_stats, + TimeSource& time_source); private: - MGETRequest(SplitCallbacks& callbacks, CommandStats& command_stats) - : FragmentedRequest(callbacks, command_stats) {} + MGETRequest(SplitCallbacks& callbacks, CommandStats& command_stats, TimeSource& time_source) + : FragmentedRequest(callbacks, command_stats, time_source) {} // RedisProxy::CommandSplitter::FragmentedRequest void onChildResponse(RespValuePtr&& value, uint32_t index) override; @@ -182,11 +202,13 @@ class MGETRequest : public FragmentedRequest, Logger::Loggable { public: static SplitRequestPtr create(ConnPool::Instance& conn_pool, const RespValue& incoming_request, - SplitCallbacks& callbacks, CommandStats& command_stats); + SplitCallbacks& callbacks, CommandStats& command_stats, + TimeSource& time_source); private: - SplitKeysSumResultRequest(SplitCallbacks& callbacks, CommandStats& command_stats) - : FragmentedRequest(callbacks, command_stats) {} + SplitKeysSumResultRequest(SplitCallbacks& callbacks, CommandStats& command_stats, + TimeSource& time_source) + : FragmentedRequest(callbacks, command_stats, time_source) {} // RedisProxy::CommandSplitter::FragmentedRequest void onChildResponse(RespValuePtr&& value, uint32_t index) override; @@ -202,11 +224,12 @@ class SplitKeysSumResultRequest : public FragmentedRequest, Logger::Loggable { public: static SplitRequestPtr create(ConnPool::Instance& conn_pool, const RespValue& incoming_request, - SplitCallbacks& callbacks, CommandStats& command_stats); + SplitCallbacks& callbacks, CommandStats& command_stats, + TimeSource& time_source); private: - MSETRequest(SplitCallbacks& callbacks, CommandStats& command_stats) - : FragmentedRequest(callbacks, command_stats) {} + MSETRequest(SplitCallbacks& callbacks, CommandStats& command_stats, TimeSource& time_source) + : FragmentedRequest(callbacks, command_stats, time_source) {} // RedisProxy::CommandSplitter::FragmentedRequest void onChildResponse(RespValuePtr&& value, uint32_t index) override; @@ -221,8 +244,8 @@ class CommandHandlerFactory : public CommandHandler, CommandHandlerBase { public: CommandHandlerFactory(ConnPool::Instance& conn_pool) : CommandHandlerBase(conn_pool) {} SplitRequestPtr startRequest(const RespValue& request, SplitCallbacks& callbacks, - CommandStats& command_stats) { - return RequestClass::create(conn_pool_, request, callbacks, command_stats); + CommandStats& command_stats, TimeSource& time_source) { + return RequestClass::create(conn_pool_, request, callbacks, command_stats, time_source); } }; @@ -245,7 +268,7 @@ struct InstanceStats { class InstanceImpl : public Instance, Logger::Loggable { public: InstanceImpl(ConnPool::InstancePtr&& conn_pool, Stats::Scope& scope, - const std::string& stat_prefix); + const std::string& stat_prefix, TimeSource& time_source); // RedisProxy::CommandSplitter::Instance SplitRequestPtr makeRequest(const RespValue& request, SplitCallbacks& callbacks) override; @@ -271,6 +294,7 @@ class InstanceImpl : public Instance, Logger::Loggable { TrieLookupTable handler_lookup_table_; InstanceStats stats_; const ToLowerTable to_lower_table_; + TimeSource& time_source_; }; } // namespace CommandSplitter diff --git a/source/extensions/filters/network/redis_proxy/config.cc b/source/extensions/filters/network/redis_proxy/config.cc index 2555f66dc478b..985ebbd48286e 100644 --- a/source/extensions/filters/network/redis_proxy/config.cc +++ b/source/extensions/filters/network/redis_proxy/config.cc @@ -32,7 +32,7 @@ Network::FilterFactoryCb RedisProxyFilterConfigFactory::createFilterFactoryFromP filter_config->cluster_name_, context.clusterManager(), ConnPool::ClientFactoryImpl::instance_, context.threadLocal(), proto_config.settings())); std::shared_ptr splitter(new CommandSplitter::InstanceImpl( - std::move(conn_pool), context.scope(), filter_config->stat_prefix_)); + std::move(conn_pool), context.scope(), filter_config->stat_prefix_, context.timeSource())); return [splitter, filter_config](Network::FilterManager& filter_manager) -> void { DecoderFactoryImpl factory; filter_manager.addReadFilter(std::make_shared( diff --git a/test/extensions/filters/network/redis_proxy/BUILD b/test/extensions/filters/network/redis_proxy/BUILD index d551829812379..e0a14d9cd3475 100644 --- a/test/extensions/filters/network/redis_proxy/BUILD +++ b/test/extensions/filters/network/redis_proxy/BUILD @@ -36,6 +36,8 @@ envoy_extension_cc_test( "//source/common/stats:stats_lib", "//source/extensions/filters/network/redis_proxy:command_splitter_lib", "//test/mocks:common_lib", + "//test/mocks/stats:stats_mocks", + "//test/test_common:simulated_time_system_lib", ], ) @@ -107,5 +109,6 @@ envoy_extension_cc_test_binary( "//source/common/stats:stats_lib", "//source/extensions/filters/network/redis_proxy:command_splitter_lib", "//test/test_common:printers_lib", + "//test/test_common:simulated_time_system_lib", ], ) diff --git a/test/extensions/filters/network/redis_proxy/command_lookup_speed_test.cc b/test/extensions/filters/network/redis_proxy/command_lookup_speed_test.cc index 0b9f0cd399d5a..be3237e32398a 100644 --- a/test/extensions/filters/network/redis_proxy/command_lookup_speed_test.cc +++ b/test/extensions/filters/network/redis_proxy/command_lookup_speed_test.cc @@ -13,6 +13,7 @@ #include "extensions/filters/network/redis_proxy/supported_commands.h" #include "test/test_common/printers.h" +#include "test/test_common/simulated_time_system.h" #include "testing/base/public/benchmark.h" @@ -64,7 +65,9 @@ class CommandLookUpSpeedTest { ConnPool::Instance* conn_pool_{new NullInstanceImpl()}; Stats::IsolatedStoreImpl store_; - CommandSplitter::InstanceImpl splitter_{ConnPool::InstancePtr{conn_pool_}, store_, "redis.foo."}; + Event::SimulatedTimeSystem time_system_; + CommandSplitter::InstanceImpl splitter_{ConnPool::InstancePtr{conn_pool_}, store_, "redis.foo.", + time_system_}; NoOpSplitCallbacks callbacks_; CommandSplitter::SplitRequestPtr handle_; }; diff --git a/test/extensions/filters/network/redis_proxy/command_splitter_impl_test.cc b/test/extensions/filters/network/redis_proxy/command_splitter_impl_test.cc index b9d552fe069aa..6c7e64314a38e 100644 --- a/test/extensions/filters/network/redis_proxy/command_splitter_impl_test.cc +++ b/test/extensions/filters/network/redis_proxy/command_splitter_impl_test.cc @@ -11,7 +11,9 @@ #include "test/extensions/filters/network/redis_proxy/mocks.h" #include "test/mocks/common.h" +#include "test/mocks/stats/mocks.h" #include "test/test_common/printers.h" +#include "test/test_common/simulated_time_system.h" #include "gmock/gmock.h" #include "gtest/gtest.h" @@ -21,6 +23,8 @@ using testing::ByRef; using testing::DoAll; using testing::Eq; using testing::InSequence; +using testing::NiceMock; +using testing::Property; using testing::Ref; using testing::Return; using testing::WithArg; @@ -45,8 +49,9 @@ class RedisCommandSplitterImplTest : public testing::Test { } ConnPool::MockInstance* conn_pool_{new ConnPool::MockInstance()}; - Stats::IsolatedStoreImpl store_; - InstanceImpl splitter_{ConnPool::InstancePtr{conn_pool_}, store_, "redis.foo."}; + NiceMock store_; + Event::SimulatedTimeSystem time_system_; + InstanceImpl splitter_{ConnPool::InstancePtr{conn_pool_}, store_, "redis.foo.", time_system_}; MockSplitCallbacks callbacks_; SplitRequestPtr handle_; }; @@ -130,17 +135,22 @@ class RedisSingleServerRequestTest : public RedisCommandSplitterImplTest, TEST_P(RedisSingleServerRequestTest, Success) { InSequence s; + ToLowerTable table; + std::string lower_command(GetParam()); + table.toLowerCase(lower_command); + RespValue request; makeBulkStringArray(request, {GetParam(), "hello"}); makeRequest("hello", request); EXPECT_NE(nullptr, handle_); + time_system_.setMonotonicTime(std::chrono::milliseconds(10)); + EXPECT_CALL(store_, deliverHistogramToSinks( + Property(&Stats::Metric::name, + fmt::format("redis.foo.command.{}.latency", lower_command)), + 10)); respond(); - ToLowerTable table; - std::string lower_command(GetParam()); - table.toLowerCase(lower_command); - EXPECT_EQ(1UL, store_.counter(fmt::format("redis.foo.command.{}.total", lower_command)).value()); EXPECT_EQ(1UL, store_.counter(fmt::format("redis.foo.command.{}.success", lower_command)).value()); @@ -154,12 +164,17 @@ TEST_P(RedisSingleServerRequestTest, SuccessMultipleArgs) { makeRequest("hello", request); EXPECT_NE(nullptr, handle_); - respond(); - ToLowerTable table; std::string lower_command(GetParam()); table.toLowerCase(lower_command); + time_system_.setMonotonicTime(std::chrono::milliseconds(10)); + EXPECT_CALL(store_, deliverHistogramToSinks( + Property(&Stats::Metric::name, + fmt::format("redis.foo.command.{}.latency", lower_command)), + 10)); + respond(); + EXPECT_EQ(1UL, store_.counter(fmt::format("redis.foo.command.{}.total", lower_command)).value()); EXPECT_EQ(1UL, store_.counter(fmt::format("redis.foo.command.{}.success", lower_command)).value()); @@ -173,12 +188,17 @@ TEST_P(RedisSingleServerRequestTest, Fail) { makeRequest("hello", request); EXPECT_NE(nullptr, handle_); - fail(); - ToLowerTable table; std::string lower_command(GetParam()); table.toLowerCase(lower_command); + time_system_.setMonotonicTime(std::chrono::milliseconds(5)); + EXPECT_CALL(store_, deliverHistogramToSinks( + Property(&Stats::Metric::name, + fmt::format("redis.foo.command.{}.latency", lower_command)), + 5)); + fail(); + EXPECT_EQ(1UL, store_.counter(fmt::format("redis.foo.command.{}.total", lower_command)).value()); EXPECT_EQ(1UL, store_.counter(fmt::format("redis.foo.command.{}.error", lower_command)).value()); }; @@ -238,12 +258,17 @@ TEST_F(RedisSingleServerRequestTest, EvalSuccess) { makeRequest("key", request); EXPECT_NE(nullptr, handle_); - respond(); - ToLowerTable table; std::string lower_command("eval"); table.toLowerCase(lower_command); + time_system_.setMonotonicTime(std::chrono::milliseconds(10)); + EXPECT_CALL(store_, deliverHistogramToSinks( + Property(&Stats::Metric::name, + fmt::format("redis.foo.command.{}.latency", lower_command)), + 10)); + respond(); + EXPECT_EQ(1UL, store_.counter(fmt::format("redis.foo.command.{}.total", lower_command)).value()); EXPECT_EQ(1UL, store_.counter(fmt::format("redis.foo.command.{}.success", lower_command)).value()); @@ -257,12 +282,17 @@ TEST_F(RedisSingleServerRequestTest, EvalShaSuccess) { makeRequest("keykey", request); EXPECT_NE(nullptr, handle_); - respond(); - ToLowerTable table; std::string lower_command("evalsha"); table.toLowerCase(lower_command); + time_system_.setMonotonicTime(std::chrono::milliseconds(10)); + EXPECT_CALL(store_, deliverHistogramToSinks( + Property(&Stats::Metric::name, + fmt::format("redis.foo.command.{}.latency", lower_command)), + 10)); + respond(); + EXPECT_EQ(1UL, store_.counter(fmt::format("redis.foo.command.{}.total", lower_command)).value()); EXPECT_EQ(1UL, store_.counter(fmt::format("redis.foo.command.{}.success", lower_command)).value()); @@ -361,6 +391,9 @@ TEST_F(RedisMGETCommandHandlerTest, Normal) { RespValuePtr response1(new RespValue()); response1->type(RespType::BulkString); response1->asString() = "response"; + time_system_.setMonotonicTime(std::chrono::milliseconds(10)); + EXPECT_CALL(store_, deliverHistogramToSinks( + Property(&Stats::Metric::name, "redis.foo.command.mget.latency"), 10)); EXPECT_CALL(callbacks_, onResponse_(PointeesEq(&expected_response))); pool_callbacks_[0]->onResponse(std::move(response1)); @@ -451,6 +484,9 @@ TEST_F(RedisMGETCommandHandlerTest, Failure) { RespValuePtr response1(new RespValue()); response1->type(RespType::BulkString); response1->asString() = "response"; + time_system_.setMonotonicTime(std::chrono::milliseconds(5)); + EXPECT_CALL(store_, deliverHistogramToSinks( + Property(&Stats::Metric::name, "redis.foo.command.mget.latency"), 5)); EXPECT_CALL(callbacks_, onResponse_(PointeesEq(&expected_response))); pool_callbacks_[0]->onResponse(std::move(response1)); EXPECT_EQ(1UL, store_.counter("redis.foo.command.mget.total").value()); @@ -477,6 +513,9 @@ TEST_F(RedisMGETCommandHandlerTest, InvalidUpstreamResponse) { RespValuePtr response1(new RespValue()); response1->type(RespType::Integer); response1->asInteger() = 5; + time_system_.setMonotonicTime(std::chrono::milliseconds(10)); + EXPECT_CALL(store_, deliverHistogramToSinks( + Property(&Stats::Metric::name, "redis.foo.command.mget.latency"), 10)); EXPECT_CALL(callbacks_, onResponse_(PointeesEq(&expected_response))); pool_callbacks_[0]->onResponse(std::move(response1)); EXPECT_EQ(1UL, store_.counter("redis.foo.command.mget.total").value()); @@ -550,6 +589,10 @@ TEST_F(RedisMSETCommandHandlerTest, Normal) { RespValuePtr response1(new RespValue()); response1->type(RespType::SimpleString); response1->asString() = Response::get().OK; + + time_system_.setMonotonicTime(std::chrono::milliseconds(10)); + EXPECT_CALL(store_, deliverHistogramToSinks( + Property(&Stats::Metric::name, "redis.foo.command.mset.latency"), 10)); EXPECT_CALL(callbacks_, onResponse_(PointeesEq(&expected_response))); pool_callbacks_[0]->onResponse(std::move(response1)); @@ -669,6 +712,11 @@ TEST_P(RedisSplitKeysSumResultHandlerTest, Normal) { RespValuePtr response1(new RespValue()); response1->type(RespType::Integer); response1->asInteger() = 1; + time_system_.setMonotonicTime(std::chrono::milliseconds(10)); + EXPECT_CALL( + store_, + deliverHistogramToSinks( + Property(&Stats::Metric::name, "redis.foo.command." + GetParam() + ".latency"), 10)); EXPECT_CALL(callbacks_, onResponse_(PointeesEq(&expected_response))); pool_callbacks_[0]->onResponse(std::move(response1));