diff --git a/api/server/response_options.proto b/api/server/response_options.proto index 0644d3d0e..79c9e2dc9 100644 --- a/api/server/response_options.proto +++ b/api/server/response_options.proto @@ -32,4 +32,10 @@ message ResponseOptions { // Concurrency based linear delay configuration. ConcurrencyBasedLinearDelay concurrency_based_linear_delay = 5; } + // If set, makes the extension include timing data in the supplied response header name. + // For example, when set to "x-abc", and 3 requests are performed, the test server will respond + // with: Response 1: No x-abc header because there's no previous response. Response 2: Header + // x-abc: . Response 3: Header x-abc: . + string emit_previous_request_delta_in_response_header = 6; } diff --git a/include/nighthawk/common/BUILD b/include/nighthawk/common/BUILD index c6eb60b40..de672823a 100644 --- a/include/nighthawk/common/BUILD +++ b/include/nighthawk/common/BUILD @@ -59,3 +59,15 @@ envoy_basic_cc_library( "@envoy//source/common/http:headers_lib", ], ) + +envoy_basic_cc_library( + name = "stopwatch_lib", + hdrs = [ + "stopwatch.h", + ], + include_prefix = "nighthawk/common", + deps = [ + "@envoy//include/envoy/common:base_includes", + "@envoy//include/envoy/common:time_interface", + ], +) diff --git a/include/nighthawk/common/stopwatch.h b/include/nighthawk/common/stopwatch.h new file mode 100644 index 000000000..87177962a --- /dev/null +++ b/include/nighthawk/common/stopwatch.h @@ -0,0 +1,22 @@ +#pragma once + +#include "envoy/common/pure.h" +#include "envoy/common/time.h" + +namespace Nighthawk { + +/** + * Interface for measuring elapsed time between events. + */ +class Stopwatch { +public: + virtual ~Stopwatch() = default; + /** + * @param time_source used to obtain a sample of the current time. + * @return uint64_t 0 on the first invocation, and the number of elapsed nanoseconds since the + * last invocation otherwise. + */ + virtual uint64_t getElapsedNsAndReset(Envoy::TimeSource& time_source) PURE; +}; + +} // namespace Nighthawk \ No newline at end of file diff --git a/source/client/benchmark_client_impl.cc b/source/client/benchmark_client_impl.cc index e93c31779..7c7dd1fab 100644 --- a/source/client/benchmark_client_impl.cc +++ b/source/client/benchmark_client_impl.cc @@ -30,14 +30,16 @@ BenchmarkClientStatistic::BenchmarkClientStatistic(BenchmarkClientStatistic&& st latency_3xx_statistic(std::move(statistic.latency_3xx_statistic)), latency_4xx_statistic(std::move(statistic.latency_4xx_statistic)), latency_5xx_statistic(std::move(statistic.latency_5xx_statistic)), - latency_xxx_statistic(std::move(statistic.latency_xxx_statistic)) {} + latency_xxx_statistic(std::move(statistic.latency_xxx_statistic)), + origin_latency_statistic(std::move(statistic.origin_latency_statistic)) {} BenchmarkClientStatistic::BenchmarkClientStatistic( StatisticPtr&& connect_stat, StatisticPtr&& response_stat, StatisticPtr&& response_header_size_stat, StatisticPtr&& response_body_size_stat, StatisticPtr&& latency_1xx_stat, StatisticPtr&& latency_2xx_stat, StatisticPtr&& latency_3xx_stat, StatisticPtr&& latency_4xx_stat, - StatisticPtr&& latency_5xx_stat, StatisticPtr&& latency_xxx_stat) + StatisticPtr&& latency_5xx_stat, StatisticPtr&& latency_xxx_stat, + StatisticPtr&& origin_latency_stat) : connect_statistic(std::move(connect_stat)), response_statistic(std::move(response_stat)), response_header_size_statistic(std::move(response_header_size_stat)), response_body_size_statistic(std::move(response_body_size_stat)), @@ -46,7 +48,8 @@ BenchmarkClientStatistic::BenchmarkClientStatistic( latency_3xx_statistic(std::move(latency_3xx_stat)), latency_4xx_statistic(std::move(latency_4xx_stat)), latency_5xx_statistic(std::move(latency_5xx_stat)), - latency_xxx_statistic(std::move(latency_xxx_stat)) {} + latency_xxx_statistic(std::move(latency_xxx_stat)), + origin_latency_statistic(std::move(origin_latency_stat)) {} Envoy::Http::ConnectionPool::Cancellable* Http1PoolImpl::newStream(Envoy::Http::ResponseDecoder& response_decoder, @@ -97,6 +100,7 @@ BenchmarkClientHttpImpl::BenchmarkClientHttpImpl( statistic_.latency_4xx_statistic->setId("benchmark_http_client.latency_4xx"); statistic_.latency_5xx_statistic->setId("benchmark_http_client.latency_5xx"); statistic_.latency_xxx_statistic->setId("benchmark_http_client.latency_xxx"); + statistic_.origin_latency_statistic->setId("benchmark_http_client.origin_latency_statistic"); } void BenchmarkClientHttpImpl::terminate() { @@ -121,6 +125,7 @@ StatisticPtrMap BenchmarkClientHttpImpl::statistics() const { statistics[statistic_.latency_4xx_statistic->id()] = statistic_.latency_4xx_statistic.get(); statistics[statistic_.latency_5xx_statistic->id()] = statistic_.latency_5xx_statistic.get(); statistics[statistic_.latency_xxx_statistic->id()] = statistic_.latency_xxx_statistic.get(); + statistics[statistic_.origin_latency_statistic->id()] = statistic_.origin_latency_statistic.get(); return statistics; }; @@ -160,7 +165,8 @@ bool BenchmarkClientHttpImpl::tryStartRequest(CompletionCallback caller_completi dispatcher_, api_.timeSource(), *this, std::move(caller_completion_callback), *statistic_.connect_statistic, *statistic_.response_statistic, *statistic_.response_header_size_statistic, *statistic_.response_body_size_statistic, - request->header(), shouldMeasureLatencies(), content_length, generator_, http_tracer_); + *statistic_.origin_latency_statistic, request->header(), shouldMeasureLatencies(), + content_length, generator_, http_tracer_); requests_initiated_++; pool_ptr->newStream(*stream_decoder, *stream_decoder); return true; diff --git a/source/client/benchmark_client_impl.h b/source/client/benchmark_client_impl.h index 7afc59034..1fa052135 100644 --- a/source/client/benchmark_client_impl.h +++ b/source/client/benchmark_client_impl.h @@ -57,7 +57,8 @@ struct BenchmarkClientStatistic { StatisticPtr&& response_body_size_stat, StatisticPtr&& latency_1xx_stat, StatisticPtr&& latency_2xx_stat, StatisticPtr&& latency_3xx_stat, StatisticPtr&& latency_4xx_stat, StatisticPtr&& latency_5xx_stat, - StatisticPtr&& latency_xxx_stat); + StatisticPtr&& latency_xxx_stat, + StatisticPtr&& origin_latency_statistic); // These are declared order dependent. Changing ordering may trigger on assert upon // destruction when tls has been involved during usage. @@ -71,6 +72,7 @@ struct BenchmarkClientStatistic { StatisticPtr latency_4xx_statistic; StatisticPtr latency_5xx_statistic; StatisticPtr latency_xxx_statistic; + StatisticPtr origin_latency_statistic; }; class Http1PoolImpl : public Envoy::Http::Http1::ProdConnPoolImpl { diff --git a/source/client/factories_impl.cc b/source/client/factories_impl.cc index eb1187c87..33b3b3f2a 100644 --- a/source/client/factories_impl.cc +++ b/source/client/factories_impl.cc @@ -47,6 +47,7 @@ BenchmarkClientPtr BenchmarkClientFactoryImpl::create( std::make_unique(scope, worker_id), std::make_unique(scope, worker_id), std::make_unique(scope, worker_id), + std::make_unique(scope, worker_id), std::make_unique(scope, worker_id)); auto benchmark_client = std::make_unique( api, dispatcher, scope, statistic, options_.h2(), cluster_manager, http_tracer, cluster_name, diff --git a/source/client/stream_decoder.cc b/source/client/stream_decoder.cc index 6dc63e65a..f70109608 100644 --- a/source/client/stream_decoder.cc +++ b/source/client/stream_decoder.cc @@ -19,6 +19,20 @@ void StreamDecoder::decodeHeaders(Envoy::Http::ResponseHeaderMapPtr&& headers, b response_header_sizes_statistic_.addValue(response_headers_->byteSize()); const uint64_t response_code = Envoy::Http::Utility::getResponseStatus(*response_headers_); stream_info_.response_code_ = static_cast(response_code); + const auto timing_header_name = + Envoy::Http::LowerCaseString("x-nighthawk-do-not-use-origin-timings"); + const Envoy::Http::HeaderEntry* timing_header = response_headers_->get(timing_header_name); + if (timing_header != nullptr) { + absl::string_view timing_value = timing_header->value().getStringView(); + int64_t origin_delta; + if (absl::SimpleAtoi(timing_value, &origin_delta) && origin_delta >= 0) { + origin_latency_statistic_.addValue(origin_delta); + } else { + // TODO(#484): avoid high frequency logging. + ENVOY_LOG(warn, "Bad origin delta: '{}'.", timing_value); + } + } + if (complete_) { onComplete(true); } diff --git a/source/client/stream_decoder.h b/source/client/stream_decoder.h index 0f6d4aeae..890ffcc28 100644 --- a/source/client/stream_decoder.h +++ b/source/client/stream_decoder.h @@ -43,8 +43,8 @@ class StreamDecoder : public Envoy::Http::ResponseDecoder, StreamDecoderCompletionCallback& decoder_completion_callback, OperationCallback caller_completion_callback, Statistic& connect_statistic, Statistic& latency_statistic, Statistic& response_header_sizes_statistic, - Statistic& response_body_sizes_statistic, HeaderMapPtr request_headers, - bool measure_latencies, uint32_t request_body_size, + Statistic& response_body_sizes_statistic, Statistic& origin_latency_statistic, + HeaderMapPtr request_headers, bool measure_latencies, uint32_t request_body_size, Envoy::Random::RandomGenerator& random_generator, Envoy::Tracing::HttpTracerSharedPtr& http_tracer) : dispatcher_(dispatcher), time_source_(time_source), @@ -53,6 +53,7 @@ class StreamDecoder : public Envoy::Http::ResponseDecoder, connect_statistic_(connect_statistic), latency_statistic_(latency_statistic), response_header_sizes_statistic_(response_header_sizes_statistic), response_body_sizes_statistic_(response_body_sizes_statistic), + origin_latency_statistic_(origin_latency_statistic), request_headers_(std::move(request_headers)), connect_start_(time_source_.monotonicTime()), complete_(false), measure_latencies_(measure_latencies), request_body_size_(request_body_size), stream_info_(time_source_), @@ -103,6 +104,7 @@ class StreamDecoder : public Envoy::Http::ResponseDecoder, Statistic& latency_statistic_; Statistic& response_header_sizes_statistic_; Statistic& response_body_sizes_statistic_; + Statistic& origin_latency_statistic_; HeaderMapPtr request_headers_; Envoy::Http::ResponseHeaderMapPtr response_headers_; Envoy::Http::ResponseTrailerMapPtr trailer_headers_; diff --git a/source/common/BUILD b/source/common/BUILD index a18abb833..28fa33a75 100644 --- a/source/common/BUILD +++ b/source/common/BUILD @@ -70,6 +70,24 @@ envoy_cc_library( ], ) +envoy_cc_library( + name = "thread_safe_monotonic_time_stopwatch_lib", + srcs = [ + "thread_safe_monotonic_time_stopwatch.cc", + ], + hdrs = [ + "thread_safe_monotonic_time_stopwatch.h", + ], + repository = "@envoy", + visibility = ["//visibility:public"], + deps = [ + "//include/nighthawk/common:stopwatch_lib", + "@envoy//include/envoy/common:time_interface", + "@envoy//source/common/common:lock_guard_lib_with_external_headers", + "@envoy//source/common/common:thread_lib_with_external_headers", + ], +) + envoy_cc_library( name = "nighthawk_common_lib", srcs = [ diff --git a/source/common/thread_safe_monotonic_time_stopwatch.cc b/source/common/thread_safe_monotonic_time_stopwatch.cc new file mode 100644 index 000000000..e1048f1c5 --- /dev/null +++ b/source/common/thread_safe_monotonic_time_stopwatch.cc @@ -0,0 +1,16 @@ +#include "common/thread_safe_monotonic_time_stopwatch.h" + +namespace Nighthawk { + +uint64_t ThreadSafeMontonicTimeStopwatch::getElapsedNsAndReset(Envoy::TimeSource& time_source) { + Envoy::Thread::LockGuard guard(lock_); + // Note that we obtain monotonic time under lock, to ensure that start_ will be updated + // monotonically. + const Envoy::MonotonicTime new_time = time_source.monotonicTime(); + const uint64_t elapsed_ns = + start_ == Envoy::MonotonicTime::min() ? 0 : (new_time - start_).count(); + start_ = new_time; + return elapsed_ns; +} + +} // namespace Nighthawk \ No newline at end of file diff --git a/source/common/thread_safe_monotonic_time_stopwatch.h b/source/common/thread_safe_monotonic_time_stopwatch.h new file mode 100644 index 000000000..2e7b57d44 --- /dev/null +++ b/source/common/thread_safe_monotonic_time_stopwatch.h @@ -0,0 +1,40 @@ +#pragma once + +#include "nighthawk/common/stopwatch.h" + +#include "external/envoy/source/common/common/lock_guard.h" +#include "external/envoy/source/common/common/thread.h" + +namespace Nighthawk { + +/** + * Utility class for thread safe tracking of elapsed monotonic time. + * Example usage: + * + * ThreadSafeMontonicTimeStopwatch stopwatch; + * int i = 0; + * do { + * std::cerr << stopwatch.getElapsedNsAndReset() << + * "ns elapsed since last iteration." << std::endl; + * } while (++i < 100); + */ +class ThreadSafeMontonicTimeStopwatch : public Stopwatch { +public: + /** + * Construct a new ThreadSafe & MontonicTime-based Stopwatch object. + */ + ThreadSafeMontonicTimeStopwatch() : start_(Envoy::MonotonicTime::min()) {} + + /** + * @param time_source used to obtain a sample of the current monotonic time. + * @return uint64_t 0 on the first invocation, and the number of elapsed nanoseconds since the + * last invocation otherwise. + */ + uint64_t getElapsedNsAndReset(Envoy::TimeSource& time_source) override; + +private: + Envoy::Thread::MutexBasicLockable lock_; + Envoy::MonotonicTime start_ GUARDED_BY(lock_); +}; + +} // namespace Nighthawk \ No newline at end of file diff --git a/source/server/BUILD b/source/server/BUILD index a2d2c0857..dde36af5a 100644 --- a/source/server/BUILD +++ b/source/server/BUILD @@ -44,6 +44,21 @@ envoy_cc_library( ], ) +envoy_cc_library( + name = "http_time_tracking_filter_lib", + srcs = ["http_time_tracking_filter.cc"], + hdrs = ["http_time_tracking_filter.h"], + repository = "@envoy", + deps = [ + ":configuration_lib", + ":well_known_headers_lib", + "//api/server:response_options_proto_cc_proto", + "//source/common:thread_safe_monotonic_time_stopwatch_lib", + "@envoy//source/exe:envoy_common_lib_with_external_headers", + "@envoy//source/extensions/filters/http/common:pass_through_filter_lib_with_external_headers", + ], +) + envoy_cc_library( name = "http_dynamic_delay_filter_lib", srcs = ["http_dynamic_delay_filter.cc"], @@ -77,3 +92,13 @@ envoy_cc_library( "@envoy//include/envoy/server:filter_config_interface_with_external_headers", ], ) + +envoy_cc_library( + name = "http_time_tracking_filter_config", + srcs = ["http_time_tracking_filter_config.cc"], + repository = "@envoy", + deps = [ + ":http_time_tracking_filter_lib", + "@envoy//include/envoy/server:filter_config_interface_with_external_headers", + ], +) diff --git a/source/server/http_time_tracking_filter.cc b/source/server/http_time_tracking_filter.cc new file mode 100644 index 000000000..a17b9cb98 --- /dev/null +++ b/source/server/http_time_tracking_filter.cc @@ -0,0 +1,71 @@ +#include "server/http_time_tracking_filter.h" + +#include + +#include "envoy/server/filter_config.h" + +#include "common/thread_safe_monotonic_time_stopwatch.h" + +#include "server/configuration.h" +#include "server/well_known_headers.h" + +#include "absl/strings/numbers.h" +#include "absl/strings/str_cat.h" + +namespace Nighthawk { +namespace Server { + +HttpTimeTrackingFilterConfig::HttpTimeTrackingFilterConfig( + nighthawk::server::ResponseOptions proto_config) + : server_config_(std::move(proto_config)), + stopwatch_(std::make_unique()) {} + +uint64_t +HttpTimeTrackingFilterConfig::getElapsedNanosSinceLastRequest(Envoy::TimeSource& time_source) { + return stopwatch_->getElapsedNsAndReset(time_source); +} + +HttpTimeTrackingFilter::HttpTimeTrackingFilter(HttpTimeTrackingFilterConfigSharedPtr config) + : config_(std::move(config)) {} + +Envoy::Http::FilterHeadersStatus +HttpTimeTrackingFilter::decodeHeaders(Envoy::Http::RequestHeaderMap& headers, bool /*end_stream*/) { + base_config_ = config_->server_config(); + const auto* request_config_header = headers.get(TestServer::HeaderNames::get().TestServerConfig); + if (request_config_header) { + json_merge_error_ = !Configuration::mergeJsonConfig( + request_config_header->value().getStringView(), base_config_, error_message_); + if (json_merge_error_) { + decoder_callbacks_->sendLocalReply( + static_cast(500), + fmt::format("time-tracking didn't understand the request: {}", error_message_), nullptr, + absl::nullopt, ""); + return Envoy::Http::FilterHeadersStatus::StopIteration; + } + } + return Envoy::Http::FilterHeadersStatus::Continue; +} + +Envoy::Http::FilterHeadersStatus +HttpTimeTrackingFilter::encodeHeaders(Envoy::Http::ResponseHeaderMap& response_headers, bool) { + if (!json_merge_error_) { + const std::string previous_request_delta_in_response_header = + base_config_.emit_previous_request_delta_in_response_header(); + if (!previous_request_delta_in_response_header.empty() && last_request_delta_ns_ > 0) { + response_headers.appendCopy( + Envoy::Http::LowerCaseString(previous_request_delta_in_response_header), + absl::StrCat(last_request_delta_ns_)); + } + } + return Envoy::Http::FilterHeadersStatus::Continue; +} + +void HttpTimeTrackingFilter::setDecoderFilterCallbacks( + Envoy::Http::StreamDecoderFilterCallbacks& callbacks) { + Envoy::Http::PassThroughFilter::setDecoderFilterCallbacks(callbacks); + last_request_delta_ns_ = + config_->getElapsedNanosSinceLastRequest(callbacks.dispatcher().timeSource()); +} + +} // namespace Server +} // namespace Nighthawk diff --git a/source/server/http_time_tracking_filter.h b/source/server/http_time_tracking_filter.h new file mode 100644 index 000000000..a466c5afe --- /dev/null +++ b/source/server/http_time_tracking_filter.h @@ -0,0 +1,82 @@ +#pragma once + +#include + +#include "envoy/common/time.h" +#include "envoy/server/filter_config.h" + +#include "nighthawk/common/stopwatch.h" + +#include "external/envoy/source/extensions/filters/http/common/pass_through_filter.h" + +#include "api/server/response_options.pb.h" + +namespace Nighthawk { +namespace Server { + +/** + * Filter configuration container class for the time tracking extension. + * Instances of this class will be shared accross instances of HttpTimeTrackingFilter. + */ +class HttpTimeTrackingFilterConfig { +public: + /** + * Constructs a new HttpTimeTrackingFilterConfig instance. + * + * @param proto_config The proto configuration of the filter. + */ + HttpTimeTrackingFilterConfig(nighthawk::server::ResponseOptions proto_config); + + /** + * @return const nighthawk::server::ResponseOptions& read-only reference to the proto config + * object. + */ + const nighthawk::server::ResponseOptions& server_config() { return server_config_; } + + /** + * Gets the number of elapsed nanoseconds since the last call (server wide). + * Safe to use concurrently. + * + * @param time_source Time source that will be used to obain an updated monotonic time sample. + * @return uint64_t 0 on the first call, else the number of elapsed nanoseconds since the last + * call. + */ + uint64_t getElapsedNanosSinceLastRequest(Envoy::TimeSource& time_source); + +private: + const nighthawk::server::ResponseOptions server_config_; + std::shared_ptr stopwatch_; +}; + +using HttpTimeTrackingFilterConfigSharedPtr = std::shared_ptr; + +/** + * Extension that tracks elapsed time between inbound requests. + */ +class HttpTimeTrackingFilter : public Envoy::Http::PassThroughFilter { +public: + /** + * Construct a new Http Time Tracking Filter object. + * + * @param config Configuration of the extension. + */ + HttpTimeTrackingFilter(HttpTimeTrackingFilterConfigSharedPtr config); + + // Http::StreamDecoderFilter + Envoy::Http::FilterHeadersStatus decodeHeaders(Envoy::Http::RequestHeaderMap& headers, + bool /*end_stream*/) override; + void setDecoderFilterCallbacks(Envoy::Http::StreamDecoderFilterCallbacks&) override; + + // Http::StreamEncoderFilter + Envoy::Http::FilterHeadersStatus encodeHeaders(Envoy::Http::ResponseHeaderMap&, bool) override; + +private: + const HttpTimeTrackingFilterConfigSharedPtr config_; + nighthawk::server::ResponseOptions base_config_; + bool json_merge_error_{false}; + std::string error_message_; + uint64_t last_request_delta_ns_; +}; + +} // namespace Server +} // namespace Nighthawk diff --git a/source/server/http_time_tracking_filter_config.cc b/source/server/http_time_tracking_filter_config.cc new file mode 100644 index 000000000..76adb0bb1 --- /dev/null +++ b/source/server/http_time_tracking_filter_config.cc @@ -0,0 +1,55 @@ +#include + +#include "envoy/registry/registry.h" + +#include "external/envoy/source/common/protobuf/message_validator_impl.h" + +#include "api/server/response_options.pb.h" +#include "api/server/response_options.pb.validate.h" + +#include "server/http_time_tracking_filter.h" + +namespace Nighthawk { +namespace Server { +namespace Configuration { + +class HttpTimeTrackingFilterConfig + : public Envoy::Server::Configuration::NamedHttpFilterConfigFactory { +public: + Envoy::Http::FilterFactoryCb + createFilterFactoryFromProto(const Envoy::Protobuf::Message& proto_config, const std::string&, + Envoy::Server::Configuration::FactoryContext& context) override { + Envoy::ProtobufMessage::ValidationVisitor& validation_visitor = + Envoy::ProtobufMessage::getStrictValidationVisitor(); + return createFilter( + Envoy::MessageUtil::downcastAndValidate( + proto_config, validation_visitor), + context); + } + + Envoy::ProtobufTypes::MessagePtr createEmptyConfigProto() override { + return Envoy::ProtobufTypes::MessagePtr{new nighthawk::server::ResponseOptions()}; + } + + std::string name() const override { return "time-tracking"; } + +private: + Envoy::Http::FilterFactoryCb createFilter(const nighthawk::server::ResponseOptions& proto_config, + Envoy::Server::Configuration::FactoryContext&) { + Nighthawk::Server::HttpTimeTrackingFilterConfigSharedPtr config = + std::make_shared( + Nighthawk::Server::HttpTimeTrackingFilterConfig(proto_config)); + + return [config](Envoy::Http::FilterChainFactoryCallbacks& callbacks) -> void { + auto* filter = new Nighthawk::Server::HttpTimeTrackingFilter(config); + callbacks.addStreamFilter(Envoy::Http::StreamFilterSharedPtr{filter}); + }; + } +}; + +static Envoy::Registry::RegisterFactory + register_; +} // namespace Configuration +} // namespace Server +} // namespace Nighthawk diff --git a/test/BUILD b/test/BUILD index 64a0c4fb4..f88f59e3a 100644 --- a/test/BUILD +++ b/test/BUILD @@ -337,3 +337,15 @@ envoy_cc_test( "@envoy//test/test_common:utility_lib", ], ) + +envoy_cc_test( + name = "stopwatch_test", + srcs = ["stopwatch_test.cc"], + repository = "@envoy", + deps = [ + "//source/common:thread_safe_monotonic_time_stopwatch_lib", + "//test/common:fake_time_source", + "@envoy//test/test_common:simulated_time_system_lib", + "@envoy//test/test_common:utility_lib", + ], +) diff --git a/test/benchmark_http_client_test.cc b/test/benchmark_http_client_test.cc index 9096d7d82..739012e5b 100644 --- a/test/benchmark_http_client_test.cc +++ b/test/benchmark_http_client_test.cc @@ -61,7 +61,8 @@ class BenchmarkClientHttpTest : public Test { std::make_unique(), std::make_unique(), std::make_unique(), std::make_unique(), std::make_unique(), std::make_unique(), - std::make_unique(), std::make_unique()) { + std::make_unique(), std::make_unique(), + std::make_unique()) { auto header_map_param = std::initializer_list>{ {":scheme", "http"}, {":method", "GET"}, {":path", "/"}, {":host", "localhost"}}; default_header_map_ = diff --git a/test/server/BUILD b/test/server/BUILD index 23723c3ac..0ea078851 100644 --- a/test/server/BUILD +++ b/test/server/BUILD @@ -30,3 +30,16 @@ envoy_cc_test( "@envoy//test/integration:http_integration_lib", ], ) + +envoy_cc_test( + name = "http_time_tracking_filter_integration_test", + srcs = ["http_time_tracking_filter_integration_test.cc"], + repository = "@envoy", + deps = [ + "//source/server:http_time_tracking_filter_config", + "@envoy//include/envoy/upstream:cluster_manager_interface_with_external_headers", + "@envoy//source/common/api:api_lib_with_external_headers", + "@envoy//test/integration:http_integration_lib", + "@envoy//test/test_common:simulated_time_system_lib", + ], +) diff --git a/test/server/http_time_tracking_filter_integration_test.cc b/test/server/http_time_tracking_filter_integration_test.cc new file mode 100644 index 000000000..55d08e9c9 --- /dev/null +++ b/test/server/http_time_tracking_filter_integration_test.cc @@ -0,0 +1,158 @@ +#include + +#include "envoy/upstream/cluster_manager.h" +#include "envoy/upstream/upstream.h" + +#include "external/envoy/test/common/upstream/utility.h" +#include "external/envoy/test/integration/http_integration.h" +#include "external/envoy/test/test_common/simulated_time_system.h" + +#include "api/server/response_options.pb.h" +#include "api/server/response_options.pb.validate.h" + +#include "server/configuration.h" +#include "server/http_time_tracking_filter.h" +#include "server/well_known_headers.h" + +#include "gtest/gtest.h" + +namespace Nighthawk { +namespace { + +using namespace std::chrono_literals; + +const std::string kLatencyResponseHeaderName = "x-prd"; +const std::string kDefaultProtoFragment = fmt::format( + "emit_previous_request_delta_in_response_header: \"{}\"", kLatencyResponseHeaderName); +const std::string kProtoConfigTemplate = R"EOF( +name: time-tracking +typed_config: + "@type": type.googleapis.com/nighthawk.server.ResponseOptions + {} +)EOF"; + +class HttpTimeTrackingIntegrationTest + : public Envoy::HttpIntegrationTest, + public testing::TestWithParam { +protected: + HttpTimeTrackingIntegrationTest() + : HttpIntegrationTest(Envoy::Http::CodecClient::Type::HTTP1, GetParam()), + request_headers_({{":method", "GET"}, {":path", "/"}, {":authority", "host"}}) {} + + // We don't override SetUp(): tests in this file will call setup() instead to avoid having to + // create a fixture per filter configuration. + void setup(const std::string& config) { + config_helper_.addFilter(config); + HttpIntegrationTest::initialize(); + } + + // Fetches a response with request-level configuration set in the request header. + Envoy::IntegrationStreamDecoderPtr getResponse(absl::string_view request_level_config, + bool setup_for_upstream_request = true) { + Envoy::Http::TestRequestHeaderMapImpl request_headers = request_headers_; + request_headers.setCopy(Nighthawk::Server::TestServer::HeaderNames::get().TestServerConfig, + request_level_config); + return getResponse(request_headers, setup_for_upstream_request); + } + + // Fetches a response with the default request headers, expecting the fake upstream to supply + // the response. + Envoy::IntegrationStreamDecoderPtr getResponse() { return getResponse(request_headers_); } + + // Fetches a response using the provided request headers. When setup_for_upstream_request + // is true, the expectation will be that an upstream request will be needed to provide a + // response. If it is set to false, the extension is expected to supply the response, and + // no upstream request ought to occur. + Envoy::IntegrationStreamDecoderPtr + getResponse(const Envoy::Http::TestRequestHeaderMapImpl& request_headers, + bool setup_for_upstream_request = true) { + cleanupUpstreamAndDownstream(); + codec_client_ = makeHttpConnection(lookupPort("http")); + Envoy::IntegrationStreamDecoderPtr response; + if (setup_for_upstream_request) { + response = sendRequestAndWaitForResponse(request_headers, 0, default_response_headers_, 0); + } else { + response = codec_client_->makeHeaderOnlyRequest(request_headers); + response->waitForEndStream(); + } + return response; + } + + const Envoy::Http::TestRequestHeaderMapImpl request_headers_; +}; + +INSTANTIATE_TEST_SUITE_P(IpVersions, HttpTimeTrackingIntegrationTest, + testing::ValuesIn(Envoy::TestEnvironment::getIpVersionsForTest())); + +// Verify expectations with static/file-based time-tracking configuration. +TEST_P(HttpTimeTrackingIntegrationTest, ReturnsPositiveLatencyForStaticConfiguration) { + setup(fmt::format(kProtoConfigTemplate, kDefaultProtoFragment)); + Envoy::IntegrationStreamDecoderPtr response = getResponse(); + int64_t latency; + const Envoy::Http::HeaderEntry* latency_header_1 = + response->headers().get(Envoy::Http::LowerCaseString(kLatencyResponseHeaderName)); + EXPECT_EQ(latency_header_1, nullptr); + response = getResponse(); + const Envoy::Http::HeaderEntry* latency_header_2 = + response->headers().get(Envoy::Http::LowerCaseString(kLatencyResponseHeaderName)); + ASSERT_NE(latency_header_2, nullptr); + EXPECT_TRUE(absl::SimpleAtoi(latency_header_2->value().getStringView(), &latency)); + EXPECT_GT(latency, 0); +} + +// Verify expectations with an empty time-tracking configuration. +TEST_P(HttpTimeTrackingIntegrationTest, ReturnsPositiveLatencyForPerRequestConfiguration) { + setup(fmt::format(kProtoConfigTemplate, "")); + // Don't send any config request header + getResponse(); + // Send a config request header with an empty / default config. Should be a no-op. + getResponse("{}"); + // Send a config request header, this should become effective. + Envoy::IntegrationStreamDecoderPtr response = + getResponse(fmt::format("{{{}}}", kDefaultProtoFragment)); + const Envoy::Http::HeaderEntry* latency_header = + response->headers().get(Envoy::Http::LowerCaseString(kLatencyResponseHeaderName)); + ASSERT_NE(latency_header, nullptr); + int64_t latency; + EXPECT_TRUE(absl::SimpleAtoi(latency_header->value().getStringView(), &latency)); + // TODO(oschaaf): figure out if we can use simtime here, and verify actual timing matches + // what we'd expect using that. + EXPECT_GT(latency, 0); +} + +TEST_P(HttpTimeTrackingIntegrationTest, BehavesWellWithBadPerRequestConfiguration) { + setup(fmt::format(kProtoConfigTemplate, "")); + // Send a malformed config request header. This ought to shortcut and directly reply, + // hence we don't expect an upstream request. + Envoy::IntegrationStreamDecoderPtr response = getResponse("bad_json", false); + EXPECT_EQ(Envoy::Http::Utility::getResponseStatus(response->headers()), 500); + EXPECT_EQ( + response->body(), + "time-tracking didn't understand the request: Error merging json config: Unable to parse " + "JSON as proto (INVALID_ARGUMENT:Unexpected token.\nbad_json\n^): bad_json"); + // Send an empty config header, which ought to trigger failure mode as well. + response = getResponse("", false); + EXPECT_EQ(Envoy::Http::Utility::getResponseStatus(response->headers()), 500); + EXPECT_EQ( + response->body(), + "time-tracking didn't understand the request: Error merging json config: Unable to " + "parse JSON as proto (INVALID_ARGUMENT:Unexpected end of string. Expected a value.\n\n^): "); +} + +class HttpTimeTrackingFilterConfigTest : public testing::Test, + public Envoy::Event::TestUsingSimulatedTime {}; + +TEST_F(HttpTimeTrackingFilterConfigTest, GetElapsedNanosSinceLastRequest) { + Envoy::Event::SimulatedTimeSystem& time_system = simTime(); + Server::HttpTimeTrackingFilterConfig config({}); + EXPECT_EQ(config.getElapsedNanosSinceLastRequest(time_system), 0); + time_system.setMonotonicTime(1ns); + EXPECT_EQ(config.getElapsedNanosSinceLastRequest(time_system), 1); + time_system.setMonotonicTime(1s + 1ns); + EXPECT_EQ(config.getElapsedNanosSinceLastRequest(time_system), 1e9); + time_system.setMonotonicTime(60s + 1s + 1ns); + EXPECT_EQ(config.getElapsedNanosSinceLastRequest(time_system), 60 * 1e9); +} + +} // namespace +} // namespace Nighthawk diff --git a/test/stopwatch_test.cc b/test/stopwatch_test.cc new file mode 100644 index 000000000..31883e1be --- /dev/null +++ b/test/stopwatch_test.cc @@ -0,0 +1,68 @@ +#include +#include +#include +#include + +#include "external/envoy/test/test_common/simulated_time_system.h" +#include "external/envoy/test/test_common/utility.h" + +#include "common/thread_safe_monotonic_time_stopwatch.h" + +#include "test/common/fake_time_source.h" + +#include "gtest/gtest.h" + +namespace Nighthawk { +namespace { + +using namespace std::chrono_literals; + +class SimTimeStopwatchTest : public testing::Test, public Envoy::Event::TestUsingSimulatedTime {}; + +TEST_F(SimTimeStopwatchTest, TestElapsedAndReset) { + ThreadSafeMontonicTimeStopwatch stopwatch; + Envoy::Event::SimulatedTimeSystem& time_system = simTime(); + time_system.setMonotonicTime(1ns); + // The first call should always return 0. + EXPECT_EQ(stopwatch.getElapsedNsAndReset(time_system), 0); + time_system.setMonotonicTime(2ns); + // Verify that moving the clock yields correct results. + EXPECT_EQ(stopwatch.getElapsedNsAndReset(time_system), 1); + time_system.setMonotonicTime(3ns); + EXPECT_EQ(stopwatch.getElapsedNsAndReset(time_system), 1); + time_system.setMonotonicTime(5ns); + EXPECT_EQ(stopwatch.getElapsedNsAndReset(time_system), 2); +} + +TEST(ThreadSafeStopwatchTest, ThreadedStopwatchSpamming) { + constexpr uint64_t kFakeTimeSourceDefaultTick = 1000000000; + constexpr uint32_t kNumThreads = 100; + ThreadSafeMontonicTimeStopwatch stopwatch; + FakeIncrementingMonotonicTimeSource time_system; + std::vector threads(kNumThreads); + std::promise signal_all_threads_running; + std::shared_future future(signal_all_threads_running.get_future()); + + // The first call should always return 0. + EXPECT_EQ(stopwatch.getElapsedNsAndReset(time_system), 0); + for (std::thread& thread : threads) { + thread = std::thread([&stopwatch, &time_system, kFakeTimeSourceDefaultTick, future] { + // We wait for all threads to be up and running here to maximize concurrency + // of the call below. + future.wait(); + // Subsequent calls should always return 1s. + EXPECT_EQ(stopwatch.getElapsedNsAndReset(time_system), kFakeTimeSourceDefaultTick); + }); + } + signal_all_threads_running.set_value(); + for (std::thread& thread : threads) { + thread.join(); + } + // Verify monotonic time has advanced right up to the point we expect + // it to, based on the number of threads that have excecuted. + EXPECT_EQ(time_system.monotonicTime().time_since_epoch().count(), + (kNumThreads * kFakeTimeSourceDefaultTick) + kFakeTimeSourceDefaultTick); +} + +} // namespace +} // namespace Nighthawk diff --git a/test/stream_decoder_test.cc b/test/stream_decoder_test.cc index ca6556906..bdd9a0a65 100644 --- a/test/stream_decoder_test.cc +++ b/test/stream_decoder_test.cc @@ -49,6 +49,7 @@ class StreamDecoderTest : public Test, public StreamDecoderCompletionCallback { StreamingStatistic latency_statistic_; StreamingStatistic response_header_size_statistic_; StreamingStatistic response_body_size_statistic_; + StreamingStatistic origin_latency_statistic_; HeaderMapPtr request_headers_; uint64_t stream_decoder_completion_callbacks_{0}; uint64_t pool_failures_{0}; @@ -64,7 +65,8 @@ TEST_F(StreamDecoderTest, HeaderOnlyTest) { auto decoder = new StreamDecoder( *dispatcher_, time_system_, *this, [&is_complete](bool, bool) { is_complete = true; }, connect_statistic_, latency_statistic_, response_header_size_statistic_, - response_body_size_statistic_, request_headers_, false, 0, random_generator_, http_tracer_); + response_body_size_statistic_, origin_latency_statistic_, request_headers_, false, 0, + random_generator_, http_tracer_); decoder->decodeHeaders(std::move(test_header_), true); EXPECT_TRUE(is_complete); EXPECT_EQ(1, stream_decoder_completion_callbacks_); @@ -76,7 +78,8 @@ TEST_F(StreamDecoderTest, HeaderWithBodyTest) { auto decoder = new StreamDecoder( *dispatcher_, time_system_, *this, [&is_complete](bool, bool) { is_complete = true; }, connect_statistic_, latency_statistic_, response_header_size_statistic_, - response_body_size_statistic_, request_headers_, false, 0, random_generator_, http_tracer_); + response_body_size_statistic_, origin_latency_statistic_, request_headers_, false, 0, + random_generator_, http_tracer_); decoder->decodeHeaders(std::move(test_header_), false); EXPECT_FALSE(is_complete); Envoy::Buffer::OwnedImpl buf(std::string(1, 'a')); @@ -92,7 +95,8 @@ TEST_F(StreamDecoderTest, TrailerTest) { auto decoder = new StreamDecoder( *dispatcher_, time_system_, *this, [&is_complete](bool, bool) { is_complete = true; }, connect_statistic_, latency_statistic_, response_header_size_statistic_, - response_body_size_statistic_, request_headers_, false, 0, random_generator_, http_tracer_); + response_body_size_statistic_, origin_latency_statistic_, request_headers_, false, 0, + random_generator_, http_tracer_); Envoy::Http::ResponseHeaderMapPtr headers{ new Envoy::Http::TestResponseHeaderMapImpl{{":status", "200"}}}; decoder->decodeHeaders(std::move(headers), false); @@ -105,8 +109,8 @@ TEST_F(StreamDecoderTest, TrailerTest) { TEST_F(StreamDecoderTest, LatencyIsNotMeasured) { auto decoder = new StreamDecoder( *dispatcher_, time_system_, *this, [](bool, bool) {}, connect_statistic_, latency_statistic_, - response_header_size_statistic_, response_body_size_statistic_, request_headers_, false, 0, - random_generator_, http_tracer_); + response_header_size_statistic_, response_body_size_statistic_, origin_latency_statistic_, + request_headers_, false, 0, random_generator_, http_tracer_); Envoy::Http::MockRequestEncoder stream_encoder; EXPECT_CALL(stream_encoder, getStream()); Envoy::Upstream::HostDescriptionConstSharedPtr ptr; @@ -141,8 +145,8 @@ TEST_F(StreamDecoderTest, LatencyIsMeasured) { {{":method", "GET"}, {":path", "/"}})); auto decoder = new StreamDecoder( *dispatcher_, time_system_, *this, [](bool, bool) {}, connect_statistic_, latency_statistic_, - response_header_size_statistic_, response_body_size_statistic_, request_header, true, 0, - random_generator_, http_tracer_); + response_header_size_statistic_, response_body_size_statistic_, origin_latency_statistic_, + request_header, true, 0, random_generator_, http_tracer_); Envoy::Http::MockRequestEncoder stream_encoder; EXPECT_CALL(stream_encoder, getStream()); @@ -164,7 +168,8 @@ TEST_F(StreamDecoderTest, StreamResetTest) { auto decoder = new StreamDecoder( *dispatcher_, time_system_, *this, [&is_complete](bool, bool) { is_complete = true; }, connect_statistic_, latency_statistic_, response_header_size_statistic_, - response_body_size_statistic_, request_headers_, false, 0, random_generator_, http_tracer_); + response_body_size_statistic_, origin_latency_statistic_, request_headers_, false, 0, + random_generator_, http_tracer_); decoder->decodeHeaders(std::move(test_header_), false); decoder->onResetStream(Envoy::Http::StreamResetReason::LocalReset, "fooreason"); EXPECT_TRUE(is_complete); // these do get reported. @@ -177,7 +182,8 @@ TEST_F(StreamDecoderTest, PoolFailureTest) { auto decoder = new StreamDecoder( *dispatcher_, time_system_, *this, [&is_complete](bool, bool) { is_complete = true; }, connect_statistic_, latency_statistic_, response_header_size_statistic_, - response_body_size_statistic_, request_headers_, false, 0, random_generator_, http_tracer_); + response_body_size_statistic_, origin_latency_statistic_, request_headers_, false, 0, + random_generator_, http_tracer_); Envoy::Upstream::HostDescriptionConstSharedPtr ptr; decoder->onPoolFailure(Envoy::Http::ConnectionPool::PoolFailureReason::Overflow, "fooreason", ptr); @@ -208,5 +214,36 @@ TEST_F(StreamDecoderTest, StreamResetReasonToResponseFlag) { Envoy::StreamInfo::ResponseFlag::UpstreamRemoteReset); } +// This test parameterization structure carries the response header name that ought to be treated +// as a latency input that should be tracked, as well as a boolean indicating if we ought to expect +// the latency delivered via that header to be added to the histogram. +using LatencyTrackingViaResponseHeaderTestParam = std::tuple; + +class LatencyTrackingViaResponseHeaderTest + : public StreamDecoderTest, + public WithParamInterface {}; + +INSTANTIATE_TEST_SUITE_P(ResponseHeaderLatencies, LatencyTrackingViaResponseHeaderTest, + ValuesIn({LatencyTrackingViaResponseHeaderTestParam{"0", true}, + LatencyTrackingViaResponseHeaderTestParam{"1", true}, + LatencyTrackingViaResponseHeaderTestParam{"-1", false}, + LatencyTrackingViaResponseHeaderTestParam{"1000", true}, + LatencyTrackingViaResponseHeaderTestParam{"invalid", false}, + LatencyTrackingViaResponseHeaderTestParam{"", false}})); + +// Tests that the StreamDecoder handles delivery of latencies by response header. +TEST_P(LatencyTrackingViaResponseHeaderTest, LatencyTrackingViaResponseHeader) { + auto decoder = new StreamDecoder( + *dispatcher_, time_system_, *this, [](bool, bool) {}, connect_statistic_, latency_statistic_, + response_header_size_statistic_, response_body_size_statistic_, origin_latency_statistic_, + request_headers_, false, 0, random_generator_, http_tracer_); + const LatencyTrackingViaResponseHeaderTestParam param = GetParam(); + Envoy::Http::ResponseHeaderMapPtr headers{new Envoy::Http::TestResponseHeaderMapImpl{ + {":status", "200"}, {"x-nighthawk-do-not-use-origin-timings", std::get<0>(param)}}}; + decoder->decodeHeaders(std::move(headers), true); + const uint64_t expected_count = std::get<1>(param) ? 1 : 0; + EXPECT_EQ(origin_latency_statistic_.count(), expected_count); +} + } // namespace Client } // namespace Nighthawk