Add connection timing stats for http1/http2 connection pools.

source/common/http/http1/conn_pool.cc

@@ -155,6 +155,7 @@ void ConnPoolImpl::onConnectionEvent(ActiveClient& client, uint32_t events) {
       checkForDrained();
     }
   } else if (events & Network::ConnectionEvent::Connected) {
+    conn_connect_ms_->complete();
     processIdleClient(client);
   }
 
@@ -262,6 +263,8 @@ ConnPoolImpl::ActiveClient::ActiveClient(ConnPoolImpl& parent)
       connect_timer_(parent_.dispatcher_.createTimer([this]() -> void { onConnectTimeout(); })),
       remaining_requests_(parent_.host_->cluster().maxRequestsPerConnection()) {
 
+  parent_.conn_connect_ms_ =
+      parent_.host_->cluster().stats().upstream_cx_connect_ms_.allocateSpan();
   Upstream::Host::CreateConnectionData data = parent_.host_->createConnection(parent_.dispatcher_);
   real_host_description_ = data.host_description_;
   codec_client_ = parent_.createCodecClient(data);

source/common/http/http1/conn_pool.h

@@ -121,6 +121,7 @@ class ConnPoolImpl : Logger::Loggable<Logger::Id::pool>, public ConnectionPool::
   void onResponseComplete(ActiveClient& client);
   void processIdleClient(ActiveClient& client);
 
+  Stats::TimespanPtr conn_connect_ms_;
   Event::Dispatcher& dispatcher_;
   Upstream::ConstHostPtr host_;
   std::list<ActiveClientPtr> ready_clients_;

source/common/http/http2/conn_pool.cc

@@ -131,6 +131,10 @@ void ConnPoolImpl::onConnectionEvent(ActiveClient& client, uint32_t events) {
     }
   }
 
+  if (events & Network::ConnectionEvent::Connected) {
+    conn_connect_ms_->complete();
+  }
+
   if (client.connect_timer_) {
     client.connect_timer_->disableTimer();
     client.connect_timer_.reset();
@@ -206,6 +210,8 @@ ConnPoolImpl::ActiveClient::ActiveClient(ConnPoolImpl& parent)
     : parent_(parent),
       connect_timer_(parent_.dispatcher_.createTimer([this]() -> void { onConnectTimeout(); })) {
 
+  parent_.conn_connect_ms_ =
+      parent_.host_->cluster().stats().upstream_cx_connect_ms_.allocateSpan();
   Upstream::Host::CreateConnectionData data = parent_.host_->createConnection(parent_.dispatcher_);
   real_host_description_ = data.host_description_;
   client_ = parent_.createCodecClient(data);

source/common/http/http2/conn_pool.h

@@ -71,6 +71,7 @@ class ConnPoolImpl : Logger::Loggable<Logger::Id::pool>, public ConnectionPool::
   void onStreamDestroy(ActiveClient& client);
   void onStreamReset(ActiveClient& client, Http::StreamResetReason reason);
 
+  Stats::TimespanPtr conn_connect_ms_;
   Event::Dispatcher& dispatcher_;
   Upstream::ConstHostPtr host_;
   Stats::Store& stats_store_;

test/common/http/http1/conn_pool_test.cc

@@ -171,6 +171,24 @@ struct ActiveTestRequest {
   ConnPoolCallbacks callbacks_;
 };
 
+/**
+ * Test all timing stats are set.
+ */
+TEST_F(Http1ConnPoolImplTest, VerifyTimingStats) {
+  EXPECT_CALL(cluster_.stats_store_,
+              deliverTimingToSinks("cluster.fake_cluster.upstream_cx_connect_ms", _));
+  EXPECT_CALL(cluster_.stats_store_,
+              deliverTimingToSinks("cluster.fake_cluster.upstream_cx_length_ms", _));
+
+  ActiveTestRequest r1(*this, 0, ActiveTestRequest::Type::CreateConnection);
+  r1.startRequest();
+  r1.completeResponse(false);
+
+  EXPECT_CALL(conn_pool_, onClientDestroy());
+  conn_pool_.test_clients_[0].connection_->raiseEvents(Network::ConnectionEvent::RemoteClose);
+  dispatcher_.clearDeferredDeleteList();
+}
+
 /**
  * Tests a request that generates a new connection, completes, and then a second request that uses
  * the same connection.

test/common/http/http2/conn_pool_test.cc

@@ -110,6 +110,25 @@ class ActiveTestRequest {
   NiceMock<Http::MockStreamEncoder> inner_encoder_;
 };
 
+TEST_F(Http2ConnPoolImplTest, VerifyConectionTimingStats) {
+  expectClientCreate();
+  EXPECT_CALL(cluster_.stats_store_,
+              deliverTimingToSinks("cluster.fake_cluster.upstream_cx_connect_ms", _));
+  EXPECT_CALL(cluster_.stats_store_,
+              deliverTimingToSinks("cluster.fake_cluster.upstream_cx_length_ms", _));
+
+  ActiveTestRequest r1(*this, 0);
+  EXPECT_CALL(r1.inner_encoder_, encodeHeaders(_, true));
+  r1.callbacks_.outer_encoder_->encodeHeaders(HeaderMapImpl{}, true);
+  expectClientConnect(0);
+  EXPECT_CALL(r1.decoder_, decodeHeaders_(_, true));
+  r1.inner_decoder_->decodeHeaders(HeaderMapPtr{new HeaderMapImpl{}}, true);
+
+  test_clients_[0].connection_->raiseEvents(Network::ConnectionEvent::RemoteClose);
+  EXPECT_CALL(*this, onClientDestroy());
+  dispatcher_.clearDeferredDeleteList();
+}
+
 TEST_F(Http2ConnPoolImplTest, RequestAndResponse) {
   InSequence s;
 

test/mocks/stats/mocks.cc

@@ -13,4 +13,7 @@ MockTimespan::~MockTimespan() {}
 MockStore::MockStore() { ON_CALL(*this, counter(_)).WillByDefault(ReturnRef(counter_)); }
 MockStore::~MockStore() {}
 
+MockIsolatedStatsStore::MockIsolatedStatsStore() {}
+MockIsolatedStatsStore::~MockIsolatedStatsStore() {}
+
 } // Stats

test/mocks/stats/mocks.h

@@ -1,5 +1,9 @@
+#pragma once
+
 #include "envoy/stats/stats.h"
 
+#include "common/stats/stats_impl.h"
+
 namespace Stats {
 
 class MockCounter : public Counter {
@@ -42,4 +46,16 @@ class MockStore : public Store {
   testing::NiceMock<MockCounter> counter_;
 };
 
+/**
+ * With IsolatedStoreImpl it's hard to test timing stats.
+ * MockIsolatedStatsStore mocks only deliverTimingToSinks for better testing.
+ */
+class MockIsolatedStatsStore : public IsolatedStoreImpl {
+public:
+  MockIsolatedStatsStore();
+  ~MockIsolatedStatsStore();
+
+  MOCK_METHOD2(deliverTimingToSinks, void(const std::string&, std::chrono::milliseconds));
+};
+
 } // Stats

test/mocks/upstream/mocks.h

@@ -9,6 +9,7 @@
 
 #include "test/mocks/http/mocks.h"
 #include "test/mocks/runtime/mocks.h"
+#include "test/mocks/stats/mocks.h"
 
 using testing::NiceMock;
 
@@ -56,7 +57,7 @@ class MockCluster : public Cluster {
   const std::string alt_stat_name_{"fake_alt_cluster"};
   std::list<MemberUpdateCb> callbacks_;
   uint64_t max_requests_per_connection_{};
-  Stats::IsolatedStoreImpl stats_store_;
+  NiceMock<Stats::MockIsolatedStatsStore> stats_store_;
   const std::string stat_prefix_{"cluster.fake_cluster."};
   ClusterStats stats_;
   std::unique_ptr<Upstream::ResourceManager> resource_manager_;