update h2load to give connect time and ttfb stats

finer statistics for h2load: update per comments from tatsuhiro-t

finer stats for h2load: fixed formatting

src/h2load.cc

@@ -150,7 +150,7 @@ void readcb(struct ev_loop *loop, ev_io *w, int revents) {
 
 Client::Client(Worker *worker, size_t req_todo)
     : worker(worker), ssl(nullptr), next_addr(config.addrs), reqidx(0),
-      state(CLIENT_IDLE), req_todo(req_todo), req_started(0), req_done(0),
+      state(CLIENT_IDLE), first_byte_received(false), req_todo(req_todo), req_started(0), req_done(0),
       fd(-1) {
   ev_io_init(&wev, writecb, 0, EV_WRITE);
   ev_io_init(&rev, readcb, 0, EV_READ);
@@ -165,6 +165,8 @@ int Client::do_read() { return readfn(*this); }
 int Client::do_write() { return writefn(*this); }
 
 int Client::connect() {
+  record_start_time(&worker->stats);
+
   while (next_addr) {
     auto addr = next_addr;
     next_addr = next_addr->ai_next;
@@ -469,6 +471,8 @@ int Client::connection_made() {
 
   session->on_connect();
 
+  record_connect_time(&worker->stats);
+  
   auto nreq =
       std::min(req_todo - req_started, (size_t)config.max_concurrent_streams);
 
@@ -519,6 +523,11 @@ int Client::read_clear() {
     if (on_read(buf, nread) != 0) {
       return -1;
     }
+   
+    if (!first_byte_received) {
+      first_byte_received = true;
+      record_time_to_first_byte(&worker->stats);
+    }     
   }
 
   return 0;
@@ -641,6 +650,11 @@ int Client::read_tls() {
     if (on_read(buf, rv) != 0) {
       return -1;
     }
+ 
+    if (!first_byte_received) {
+      first_byte_received = true;
+      record_time_to_first_byte(&worker->stats);
+    }    
   }
 }
 
@@ -691,6 +705,18 @@ void Client::record_request_time(RequestStat *req_stat) {
   req_stat->request_time = std::chrono::steady_clock::now();
 }
 
+void Client::record_start_time(Stats *stat) {
+  stat->start_times.push_back(std::chrono::steady_clock::now());
+}
+
+void Client::record_connect_time(Stats *stat) {
+  stat->connect_times.push_back(std::chrono::steady_clock::now());
+}
+
+void Client::record_time_to_first_byte(Stats *stat) {
+  stat->time_to_first_bytes.push_back(std::chrono::steady_clock::now());
+}
+
 void Client::signal_write() { ev_io_start(worker->loop, &wev); }
 
 Worker::Worker(uint32_t id, SSL_CTX *ssl_ctx, size_t req_todo, size_t nclients,
@@ -733,19 +759,38 @@ void Worker::run() {
 namespace {
 double within_sd(const std::vector<std::unique_ptr<Worker>> &workers,
                  const std::chrono::microseconds &mean,
-                 const std::chrono::microseconds &sd, size_t n) {
+                 const std::chrono::microseconds &sd, size_t n, TimeStatType type) {
   auto upper = mean.count() + sd.count();
   auto lower = mean.count() - sd.count();
   size_t m = 0;
   for (const auto &w : workers) {
-    for (const auto &req_stat : w->stats.req_stats) {
+    if (type == STAT_REQUEST) {
-      if (!req_stat.completed) {
+      for (const auto &req_stat : w->stats.req_stats) {
-        continue;
+        if (!req_stat.completed) {
+          continue;
+        }
+        auto t = std::chrono::duration_cast<std::chrono::microseconds>(req_stat.stream_close_time - req_stat.request_time);
+        if (lower <= t.count() && t.count() <= upper) {
+          ++m;
+        }
       }
-      auto t = std::chrono::duration_cast<std::chrono::microseconds>(
+    } else {
-          req_stat.stream_close_time - req_stat.request_time);
+      const auto &stat = w->stats;
-      if (lower <= t.count() && t.count() <= upper) {
+      for (unsigned int i = 0; i < stat.start_times.size(); i++) {
-        ++m;
+        if (i >= stat.connect_times.size() || i >= stat.time_to_first_bytes.size()) {
+          continue; //rule out cases where we started but didn't connect or get the first byte (errors)
+        }
+        std::chrono::microseconds t;
+        if (type == STAT_CONNECT) {
+          t = std::chrono::duration_cast<std::chrono::microseconds>(stat.connect_times[i] - stat.start_times[i]);
+        } else if (type == STAT_FIRST_BYTE) {
+          t = std::chrono::duration_cast<std::chrono::microseconds>(stat.time_to_first_bytes[i] - stat.start_times[i]);
+        } else {
+          return -1;
+        }
+        if (lower <= t.count() && t.count() <= upper) {
+          ++m;
+        }
       }
     }
   }
@@ -757,43 +802,95 @@ namespace {
 TimeStats
 process_time_stats(const std::vector<std::unique_ptr<Worker>> &workers) {
   auto ts = TimeStats();
-  int64_t sum = 0;
+  int64_t request_sum = 0;
+  int64_t connect_sum = 0;
+  int64_t ttfb_sum = 0;
+  size_t m = 0;
   size_t n = 0;
 
-  ts.time_min = std::chrono::microseconds::max();
+  ts.request_time_min = std::chrono::microseconds::max();
-  ts.time_max = std::chrono::microseconds::min();
+  ts.request_time_max = std::chrono::microseconds::min();
-  ts.within_sd = 0.;
+  ts.request_within_sd = 0.;
+
+  ts.connect_time_min = std::chrono::microseconds::max();
+  ts.connect_time_max = std::chrono::microseconds::min();
+  ts.connect_within_sd = 0.;
+
+  ts.ttfb_min = std::chrono::microseconds::max();
+  ts.ttfb_max = std::chrono::microseconds::min();
+  ts.ttfb_within_sd = 0.;
 
   // standard deviation calculated using Rapid calculation method:
   // http://en.wikipedia.org/wiki/Standard_deviation#Rapid_calculation_methods
-  double a = 0, q = 0;
+  double request_a = 0, request_q = 0;
+  double connect_a = 0, connect_q = 0;
+  double ttfb_a = 0, ttfb_q = 0;
   for (const auto &w : workers) {
+    const auto stat = w->stats;
     for (const auto &req_stat : w->stats.req_stats) {
       if (!req_stat.completed) {
         continue;
       }
       ++n;
-      auto t = std::chrono::duration_cast<std::chrono::microseconds>(
+      auto request_t = std::chrono::duration_cast<std::chrono::microseconds>(
           req_stat.stream_close_time - req_stat.request_time);
-      ts.time_min = std::min(ts.time_min, t);
+      ts.request_time_min = std::min(ts.request_time_min, request_t);
-      ts.time_max = std::max(ts.time_max, t);
+      ts.request_time_max = std::max(ts.request_time_max, request_t);
-      sum += t.count();
+      request_sum += request_t.count();
 
-      auto na = a + (t.count() - a) / n;
+      auto request_na = request_a + (request_t.count() - request_a) / n;
-      q = q + (t.count() - a) * (t.count() - na);
+      request_q = request_q + (request_t.count() - request_a) * (request_t.count() - request_na);
-      a = na;
+      request_a = request_na;
+    }
+    for (unsigned int i = 0; i < stat.start_times.size(); i++) {
+      if (i >= stat.connect_times.size() || i >= stat.time_to_first_bytes.size()) {
+        continue; //rule out cases where we started but didn't connect or get the first byte (errors)
+      }
+      ++m;
+      auto connect_t = std::chrono::duration_cast<std::chrono::microseconds>(
+        stat.connect_times[i] - stat.start_times[i]);
+      ts.connect_time_min = std::min(ts.connect_time_min, connect_t);
+      ts.connect_time_max = std::max(ts.connect_time_max, connect_t);
+      connect_sum += connect_t.count();
+
+      auto ttfb_t = std::chrono::duration_cast<std::chrono::microseconds>(
+        stat.time_to_first_bytes[i] - stat.start_times[i]);
+      ts.ttfb_min = std::min(ts.ttfb_min, ttfb_t);
+      ts.ttfb_max = std::max(ts.ttfb_max, ttfb_t);
+      ttfb_sum += ttfb_t.count();
+
+      auto connect_na = connect_a + (connect_t.count() - connect_a) / m;
+      connect_q = connect_q + (connect_t.count() - connect_a) * (connect_t.count() - connect_na);
+      connect_a = connect_na;
+
+      auto ttfb_na = ttfb_a + (ttfb_t.count() - ttfb_a) / m;
+      ttfb_q = ttfb_q + (ttfb_t.count() - ttfb_a) * (ttfb_t.count() - ttfb_na);
+      ttfb_a = ttfb_na;
     }
   }
   if (n == 0) {
-    ts.time_max = ts.time_min = std::chrono::microseconds::zero();
+    ts.request_time_max = ts.request_time_min = std::chrono::microseconds::zero();
+    ts.connect_time_max = ts.connect_time_min = std::chrono::microseconds::zero();
+    ts.ttfb_max = ts.ttfb_min = std::chrono::microseconds::zero();
     return ts;
   }
 
-  ts.time_mean = std::chrono::microseconds(sum / n);
+  ts.request_time_mean = std::chrono::microseconds(request_sum / n);
-  ts.time_sd = std::chrono::microseconds(
+  ts.request_time_sd = std::chrono::microseconds(
-      static_cast<std::chrono::microseconds::rep>(sqrt(q / n)));
+      static_cast<std::chrono::microseconds::rep>(sqrt(request_q / n)));
 
-  ts.within_sd = within_sd(workers, ts.time_mean, ts.time_sd, n);
+  ts.connect_time_mean = std::chrono::microseconds(connect_sum / m);
+  ts.connect_time_sd = std::chrono::microseconds(
+      static_cast<std::chrono::microseconds::rep>(sqrt(connect_q / m)));
+
+  ts.ttfb_mean = std::chrono::microseconds(ttfb_sum / m);
+  ts.ttfb_sd = std::chrono::microseconds(
+      static_cast<std::chrono::microseconds::rep>(sqrt(ttfb_q / m)));
+
+
+  ts.request_within_sd = within_sd(workers, ts.request_time_mean, ts.request_time_sd, n, STAT_REQUEST);
+  ts.connect_within_sd = within_sd(workers, ts.connect_time_mean, ts.connect_time_sd, m, STAT_CONNECT);
+  ts.ttfb_within_sd = within_sd(workers, ts.ttfb_mean, ts.ttfb_sd, m, STAT_FIRST_BYTE);
   return ts;
 }
 } // namespace
@@ -1440,12 +1537,24 @@ traffic: )" << stats.bytes_total << " bytes total, " << stats.bytes_head
             << " bytes headers, " << stats.bytes_body << R"( bytes data
                      min         max         mean         sd        +/- sd
 time for request: )" << std::setw(10)
-            << util::format_duration(time_stats.time_min) << "  "
+            << util::format_duration(time_stats.request_time_min) << "  "
-            << std::setw(10) << util::format_duration(time_stats.time_max)
+            << std::setw(10) << util::format_duration(time_stats.request_time_max)
             << "  " << std::setw(10)
-            << util::format_duration(time_stats.time_mean) << "  "
+            << util::format_duration(time_stats.request_time_mean) << "  "
-            << std::setw(10) << util::format_duration(time_stats.time_sd)
+            << std::setw(10) << util::format_duration(time_stats.request_time_sd)
-            << std::setw(9) << util::dtos(time_stats.within_sd) << "%"
+            << std::setw(9) << util::dtos(time_stats.request_within_sd) << "%" << "\ntime for connect: " << std::setw(10)
+            << util::format_duration(time_stats.connect_time_min) << "  "
+            << std::setw(10) << util::format_duration(time_stats.connect_time_max)
+            << "  " << std::setw(10)
+            << util::format_duration(time_stats.connect_time_mean) << "  "
+            << std::setw(10) << util::format_duration(time_stats.connect_time_sd)
+            << std::setw(9) << util::dtos(time_stats.connect_within_sd) << "%" << "\ntime to 1st byte: " << std::setw(10)
+            << util::format_duration(time_stats.ttfb_min) << "  "
+            << std::setw(10) << util::format_duration(time_stats.ttfb_max)
+            << "  " << std::setw(10)
+            << util::format_duration(time_stats.ttfb_mean) << "  "
+            << std::setw(10) << util::format_duration(time_stats.ttfb_sd)
+            << std::setw(9) << util::dtos(time_stats.ttfb_within_sd) << "%"
             << std::endl;
 
   SSL_CTX_free(ssl_ctx);

src/h2load.h

@@ -87,7 +87,7 @@ struct RequestStat {
   std::chrono::steady_clock::time_point request_time;
   // time point when stream was closed
   std::chrono::steady_clock::time_point stream_close_time;
-  // upload data length sent so far
+ // upload data length sent so far
   int64_t data_offset;
   // true if stream was successfully closed.  This means stream was
   // not reset, but it does not mean HTTP level error (e.g., 404).
@@ -96,11 +96,21 @@ struct RequestStat {
 
 struct TimeStats {
   // time for request: max, min, mean and sd (standard deviation)
-  std::chrono::microseconds time_max, time_min, time_mean, time_sd;
+  std::chrono::microseconds request_time_max, request_time_min, request_time_mean, request_time_sd;
   // percentage of number of requests inside mean -/+ sd
-  double within_sd;
+  double request_within_sd;
+  // time for connect: max, min, mean and sd (standard deviation)
+  std::chrono::microseconds connect_time_max, connect_time_min, connect_time_mean, connect_time_sd;
+  // percentage of number of connects inside mean -/+ sd
+  double connect_within_sd;
+  // time to first byte: max, min, mean and sd (standard deviation)
+  std::chrono::microseconds ttfb_max, ttfb_min, ttfb_mean, ttfb_sd;
+  // percentage of number of connects inside mean -/+ sd
+  double ttfb_within_sd;
 };
 
+enum TimeStatType { STAT_REQUEST, STAT_CONNECT, STAT_FIRST_BYTE };
+
 struct Stats {
   Stats(size_t req_todo);
   // The total number of requests
@@ -132,6 +142,12 @@ struct Stats {
   std::array<size_t, 6> status;
   // The statistics per request
   std::vector<RequestStat> req_stats;
+   // time connect starts
+  std::vector<std::chrono::steady_clock::time_point> start_times;
+  // time to connect
+  std::vector<std::chrono::steady_clock::time_point> connect_times;
+  // time to first byte
+  std::vector<std::chrono::steady_clock::time_point> time_to_first_bytes;
 };
 
 enum ClientState { CLIENT_IDLE, CLIENT_CONNECTED };
@@ -171,6 +187,7 @@ struct Client {
   addrinfo *next_addr;
   size_t reqidx;
   ClientState state;
+  bool first_byte_received;
   // The number of requests this client has to issue.
   size_t req_todo;
   // The number of requests this client has issued so far.
@@ -215,6 +232,9 @@ struct Client {
   void on_stream_close(int32_t stream_id, bool success, RequestStat *req_stat);
 
   void record_request_time(RequestStat *req_stat);
+  void record_start_time(Stats *stat);
+  void record_connect_time(Stats *stat);
+  void record_time_to_first_byte(Stats *stat);
 
   void signal_write();
 };