Finalize emission and tracking of latencies in response headers

BUILD

@@ -32,6 +32,7 @@ envoy_cc_binary(
     deps = [
         "//source/server:http_dynamic_delay_filter_config",
         "//source/server:http_test_server_filter_config",
+        "//source/server:http_time_tracking_filter_config",
         "@envoy//source/exe:envoy_main_entry_lib",
     ],
 )

README.md

@@ -43,8 +43,9 @@ bazel build -c opt //:nighthawk
 ```
 USAGE:
 
-bazel-bin/nighthawk_client  [--stats-flush-interval <uint32_t>]
-[--stats-sinks <string>] ...
+bazel-bin/nighthawk_client  [--response-header-with-latency-input
+<string>] [--stats-flush-interval
+<uint32_t>] [--stats-sinks <string>] ...
 [--no-duration] [--simple-warmup]
 [--request-source <uri format>] [--label
 <string>] ... [--multi-target-use-https]
@@ -80,6 +81,12 @@ format>
 
 Where:
 
+--response-header-with-latency-input <string>
+Set an optional response header name, whose values will be tracked in
+a latency histogram if set. Can be used in tandem with the test server
+"emit_previous_request_delta_in_response_header" option to get a sense
+of elapsed time between request arrivals. Default: ""
+
 --stats-flush-interval <uint32_t>
 Time interval (in seconds) between flushes to configured stats sinks.
 Default: 5.

api/client/options.proto

@@ -202,4 +202,9 @@ message CommandLineOptions {
   // specified the default is 5 seconds. Time interval must be at least 1s and at most 300s.
   google.protobuf.UInt32Value stats_flush_interval = 35
       [(validate.rules).uint32 = {gte: 1, lte: 300}];
+  // Set an optional response header name, whose values will be tracked in a latency histogram if
+  // set. Can be used in tandem with the test server's
+  // "emit_previous_request_delta_in_response_header" option to get a sense of elapsed time between
+  // request arrivals.
+  google.protobuf.StringValue response_header_with_latency_input = 36;
 }

include/nighthawk/client/options.h

@@ -71,6 +71,7 @@ class Options {
   virtual bool noDuration() const PURE;
   virtual std::vector<envoy::config::metrics::v3::StatsSink> statsSinks() const PURE;
   virtual uint32_t statsFlushInterval() const PURE;
+  virtual std::string responseHeaderWithLatencyInput() const PURE;
 
   /**
    * Converts an Options instance to an equivalent CommandLineOptions instance in terms of option

source/client/benchmark_client_impl.cc

@@ -83,13 +83,15 @@ BenchmarkClientHttpImpl::BenchmarkClientHttpImpl(
     BenchmarkClientStatistic& statistic, bool use_h2,
     Envoy::Upstream::ClusterManagerPtr& cluster_manager,
     Envoy::Tracing::HttpTracerSharedPtr& http_tracer, absl::string_view cluster_name,
-    RequestGenerator request_generator, const bool provide_resource_backpressure)
+    RequestGenerator request_generator, const bool provide_resource_backpressure,
+    absl::string_view response_header_with_latency_input)
     : api_(api), dispatcher_(dispatcher), scope_(scope.createScope("benchmark.")),
       statistic_(std::move(statistic)), use_h2_(use_h2),
       benchmark_client_counters_({ALL_BENCHMARK_CLIENT_COUNTERS(POOL_COUNTER(*scope_))}),
       cluster_manager_(cluster_manager), http_tracer_(http_tracer),
       cluster_name_(std::string(cluster_name)), request_generator_(std::move(request_generator)),
-      provide_resource_backpressure_(provide_resource_backpressure) {
+      provide_resource_backpressure_(provide_resource_backpressure),
+      response_header_with_latency_input_(response_header_with_latency_input) {
   statistic_.connect_statistic->setId("benchmark_http_client.queue_to_connect");
   statistic_.response_statistic->setId("benchmark_http_client.request_to_response");
   statistic_.response_header_size_statistic->setId("benchmark_http_client.response_header_size");
@@ -166,7 +168,7 @@ bool BenchmarkClientHttpImpl::tryStartRequest(CompletionCallback caller_completi
       *statistic_.connect_statistic, *statistic_.response_statistic,
       *statistic_.response_header_size_statistic, *statistic_.response_body_size_statistic,
       *statistic_.origin_latency_statistic, request->header(), shouldMeasureLatencies(),
-      content_length, generator_, http_tracer_);
+      content_length, generator_, http_tracer_, response_header_with_latency_input_);
   requests_initiated_++;
   pool_ptr->newStream(*stream_decoder, *stream_decoder);
   return true;

source/client/benchmark_client_impl.h

@@ -106,7 +106,8 @@ class BenchmarkClientHttpImpl : public BenchmarkClient,
                           bool use_h2, Envoy::Upstream::ClusterManagerPtr& cluster_manager,
                           Envoy::Tracing::HttpTracerSharedPtr& http_tracer,
                           absl::string_view cluster_name, RequestGenerator request_generator,
-                          const bool provide_resource_backpressure);
+                          const bool provide_resource_backpressure,
+                          absl::string_view response_header_with_latency_input);
   void setConnectionLimit(uint32_t connection_limit) { connection_limit_ = connection_limit; }
   void setMaxPendingRequests(uint32_t max_pending_requests) {
     max_pending_requests_ = max_pending_requests;
@@ -162,6 +163,7 @@ class BenchmarkClientHttpImpl : public BenchmarkClient,
   std::string cluster_name_;
   const RequestGenerator request_generator_;
   const bool provide_resource_backpressure_;
+  const std::string response_header_with_latency_input_;
 };
 
 } // namespace Client

source/client/factories_impl.cc

@@ -51,7 +51,7 @@ BenchmarkClientPtr BenchmarkClientFactoryImpl::create(
                                      std::make_unique<SinkableHdrStatistic>(scope, worker_id));
   auto benchmark_client = std::make_unique<BenchmarkClientHttpImpl>(
       api, dispatcher, scope, statistic, options_.h2(), cluster_manager, http_tracer, cluster_name,
-      request_generator.get(), !options_.openLoop());
+      request_generator.get(), !options_.openLoop(), options_.responseHeaderWithLatencyInput());
   auto request_options = options_.toCommandLineOptions()->request_options();
   benchmark_client->setConnectionLimit(options_.connections());
   benchmark_client->setMaxPendingRequests(options_.maxPendingRequests());

source/client/options_impl.cc

@@ -294,6 +294,14 @@ OptionsImpl::OptionsImpl(int argc, const char* const* argv) {
                   stats_flush_interval_),
       false, 5, "uint32_t", cmd);
 
+  TCLAP::ValueArg<std::string> response_header_with_latency_input(
+      "", "response-header-with-latency-input",
+      "Set an optional response header name, whose values will be tracked in a latency histogram "
+      "if set. Can be used in tandem with the test server "
+      "\"emit_previous_request_delta_in_response_header\" option to get a sense of elapsed time "
+      "between request arrivals. Default: \"\"",
+      false, "", "string", cmd);
+
   Utility::parseCommand(cmd, argc, argv);
 
   // --duration and --no-duration are mutually exclusive
@@ -425,6 +433,7 @@ OptionsImpl::OptionsImpl(int argc, const char* const* argv) {
     }
   }
   TCLAP_SET_IF_SPECIFIED(stats_flush_interval, stats_flush_interval_);
+  TCLAP_SET_IF_SPECIFIED(response_header_with_latency_input, response_header_with_latency_input_);
 
   // CLI-specific tests.
   // TODO(oschaaf): as per mergconflicts's remark, it would be nice to aggregate
@@ -610,6 +619,9 @@ OptionsImpl::OptionsImpl(const nighthawk::client::CommandLineOptions& options) {
     no_duration_ = PROTOBUF_GET_WRAPPED_OR_DEFAULT(options, no_duration, no_duration_);
   }
   std::copy(options.labels().begin(), options.labels().end(), std::back_inserter(labels_));
+  response_header_with_latency_input_ = PROTOBUF_GET_WRAPPED_OR_DEFAULT(
+      options, response_header_with_latency_input, response_header_with_latency_input_);
+
   validate();
 }
 
@@ -781,6 +793,8 @@ CommandLineOptionsPtr OptionsImpl::toCommandLineOptionsInternal() const {
     *command_line_options->add_stats_sinks() = stats_sink;
   }
   command_line_options->mutable_stats_flush_interval()->set_value(stats_flush_interval_);
+  command_line_options->mutable_response_header_with_latency_input()->set_value(
+      response_header_with_latency_input_);
   return command_line_options;
 }
 

source/client/options_impl.h

@@ -85,6 +85,9 @@ class OptionsImpl : public Options, public Envoy::Logger::Loggable<Envoy::Logger
     return stats_sinks_;
   }
   uint32_t statsFlushInterval() const override { return stats_flush_interval_; }
+  std::string responseHeaderWithLatencyInput() const override {
+    return response_header_with_latency_input_;
+  };
 
 private:
   void parsePredicates(const TCLAP::MultiArg<std::string>& arg,
@@ -138,6 +141,7 @@ class OptionsImpl : public Options, public Envoy::Logger::Loggable<Envoy::Logger
   bool no_duration_{false};
   std::vector<envoy::config::metrics::v3::StatsSink> stats_sinks_;
   uint32_t stats_flush_interval_{5};
+  std::string response_header_with_latency_input_;
 };
 
 } // namespace Client

source/client/stream_decoder.cc

@@ -19,17 +19,19 @@ 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<uint32_t>(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 (!response_header_with_latency_input_.empty()) {
+    const auto timing_header_name =
+        Envoy::Http::LowerCaseString(response_header_with_latency_input_);
+    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);
+      }
     }
   }
 

source/client/stream_decoder.h

@@ -46,7 +46,8 @@ class StreamDecoder : public Envoy::Http::ResponseDecoder,
                 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)
+                Envoy::Tracing::HttpTracerSharedPtr& http_tracer,
+                std::string response_header_with_latency_input)
       : dispatcher_(dispatcher), time_source_(time_source),
         decoder_completion_callback_(decoder_completion_callback),
         caller_completion_callback_(std::move(caller_completion_callback)),
@@ -57,7 +58,8 @@ class StreamDecoder : public Envoy::Http::ResponseDecoder,
         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_),
-        random_generator_(random_generator), http_tracer_(http_tracer) {
+        random_generator_(random_generator), http_tracer_(http_tracer),
+        response_header_with_latency_input_(std::move(response_header_with_latency_input)) {
     if (measure_latencies_ && http_tracer_ != nullptr) {
       setupForTracing();
     }
@@ -119,6 +121,7 @@ class StreamDecoder : public Envoy::Http::ResponseDecoder,
   Envoy::Tracing::HttpTracerSharedPtr& http_tracer_;
   Envoy::Tracing::SpanPtr active_span_;
   Envoy::StreamInfo::UpstreamTiming upstream_timing_;
+  const std::string response_header_with_latency_input_;
 };
 
 } // namespace Client

source/server/http_time_tracking_filter.h

@@ -45,7 +45,7 @@ class HttpTimeTrackingFilterConfig {
 
 private:
   const nighthawk::server::ResponseOptions server_config_;
-  std::shared_ptr<Stopwatch> stopwatch_;
+  std::unique_ptr<Stopwatch> stopwatch_;
 };
 
 using HttpTimeTrackingFilterConfigSharedPtr = std::shared_ptr<HttpTimeTrackingFilterConfig>;

test/benchmark_http_client_test.cc

@@ -179,7 +179,7 @@ class BenchmarkClientHttpTest : public Test {
   void setupBenchmarkClient(const RequestGenerator& request_generator) {
     client_ = std::make_unique<Client::BenchmarkClientHttpImpl>(
         *api_, *dispatcher_, store_, statistic_, false, cluster_manager_, http_tracer_, "benchmark",
-        request_generator, true);
+        request_generator, true, "");
   }
 
   uint64_t getCounter(absl::string_view name) {

test/factories_test.cc

@@ -41,6 +41,7 @@ TEST_F(FactoriesTest, CreateBenchmarkClient) {
   EXPECT_CALL(options_, maxActiveRequests()).Times(1);
   EXPECT_CALL(options_, maxRequestsPerConnection()).Times(1);
   EXPECT_CALL(options_, openLoop()).Times(1);
+  EXPECT_CALL(options_, responseHeaderWithLatencyInput()).Times(1);
   auto cmd = std::make_unique<nighthawk::client::CommandLineOptions>();
   EXPECT_CALL(options_, toCommandLineOptions()).Times(1).WillOnce(Return(ByMove(std::move(cmd))));
   StaticRequestSourceImpl request_generator(

test/integration/BUILD

@@ -14,6 +14,7 @@ py_library(
     data = [
         "configurations/nighthawk_http_origin.yaml",
         "configurations/nighthawk_https_origin.yaml",
+        "configurations/nighthawk_track_timings.yaml",
         "configurations/sni_origin.yaml",
         "//:nighthawk_client",
         "//:nighthawk_output_transform",

test/integration/configurations/nighthawk_track_timings.yaml

@@ -0,0 +1,34 @@
+admin:
+  access_log_path: $tmpdir/nighthawk-test-server-admin-access.log
+  profile_path: $tmpdir/nighthawk-test-server.prof
+  address:
+    socket_address: { address: $server_ip, port_value: 0 }
+static_resources:
+  listeners:
+  - address:
+      socket_address:
+        address: $server_ip
+        port_value: 0
+    filter_chains:
+    - filters:
+      - name: envoy.http_connection_manager
+        config:
+          generate_request_id: false
+          codec_type: auto
+          stat_prefix: ingress_http
+          route_config:
+            name: local_route
+            virtual_hosts:
+            - name: service
+              domains:
+              - "*"
+          http_filters:
+          - name: time-tracking
+            config:
+              emit_previous_request_delta_in_response_header: x-origin-request-receipt-delta
+          - name: test-server
+            config:
+              response_body_size: 10
+          - name: envoy.router
+            config:
+              dynamic_stats: false

test/integration/test_integration_basics.py

@@ -700,6 +700,24 @@ def test_cancellation_with_infinite_duration(http_test_server_fixture):
   asserts.assertCounterGreaterEqual(counters, "benchmark.http_2xx", 1)
 
 
+@pytest.mark.parametrize('server_config',
+                         ["nighthawk/test/integration/configurations/nighthawk_track_timings.yaml"])
+def test_http_h1_response_header_latency_tracking(http_test_server_fixture):
+  """Test emission and tracking of response header latencies.
+
+  Run the CLI configured to track latencies delivered by response header from the test-server
+  which is set up emit those. Ensure the expected histogram is observed.
+  """
+  parsed_json, _ = http_test_server_fixture.runNighthawkClient([
+      http_test_server_fixture.getTestServerRootUri(), "--connections", "1", "--rps", "100",
+      "--duration", "100", "--termination-predicate", "benchmark.http_2xx:99",
+      "--response-header-with-latency-input", "x-origin-request-receipt-delta"
+  ])
+  global_histograms = http_test_server_fixture.getNighthawkGlobalHistogramsbyIdFromJson(parsed_json)
+  asserts.assertEqual(
+      int(global_histograms["benchmark_http_client.origin_latency_statistic"]["count"]), 99)
+
+
 def _run_client_with_args(args):
   return utility.run_binary_with_args("nighthawk_client", args)
 

test/mocks/client/mock_options.h

@@ -54,6 +54,7 @@ class MockOptions : public Options {
   MOCK_CONST_METHOD0(noDuration, bool());
   MOCK_CONST_METHOD0(statsSinks, std::vector<envoy::config::metrics::v3::StatsSink>());
   MOCK_CONST_METHOD0(statsFlushInterval, uint32_t());
+  MOCK_CONST_METHOD0(responseHeaderWithLatencyInput, std::string());
 };
 
 } // namespace Client

test/options_test.cc

@@ -117,7 +117,8 @@ TEST_F(OptionsImplTest, AlmostAll) {
       "--failure-predicate f2:2 --jitter-uniform .00001s "
       "--experimental-h2-use-multiple-connections "
       "--experimental-h1-connection-reuse-strategy lru --label label1 --label label2 {} "
-      "--simple-warmup --stats-sinks {} --stats-sinks {} --stats-flush-interval 10",
+      "--simple-warmup --stats-sinks {} --stats-sinks {} --stats-flush-interval 10 "
+      "--response-header-with-latency-input zz",
       client_name_,
       "{name:\"envoy.transport_sockets.tls\","
       "typed_config:{\"@type\":\"type.googleapis.com/envoy.api.v2.auth.UpstreamTlsContext\","
@@ -189,6 +190,7 @@ TEST_F(OptionsImplTest, AlmostAll) {
             "}\n"
             "183412668: \"envoy.config.metrics.v2.StatsSink\"\n",
             options->statsSinks()[1].DebugString());
+  EXPECT_EQ("zz", options->responseHeaderWithLatencyInput());
 
   // Check that our conversion to CommandLineOptionsPtr makes sense.
   CommandLineOptionsPtr cmd = options->toCommandLineOptions();
@@ -246,6 +248,8 @@ TEST_F(OptionsImplTest, AlmostAll) {
   ASSERT_EQ(cmd->stats_sinks_size(), options->statsSinks().size());
   EXPECT_TRUE(util(cmd->stats_sinks(0), options->statsSinks()[0]));
   EXPECT_TRUE(util(cmd->stats_sinks(1), options->statsSinks()[1]));
+  EXPECT_EQ(cmd->response_header_with_latency_input().value(),
+            options->responseHeaderWithLatencyInput());
 
   OptionsImpl options_from_proto(*cmd);
   std::string s1 = Envoy::MessageUtil::getYamlStringFromMessage(