From 4bba4bf66c08734f8fb181cf464b9889d4114cb9 Mon Sep 17 00:00:00 2001 From: es Date: Wed, 29 Apr 2015 15:29:37 -0700 Subject: [PATCH 1/2] 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 | 171 +++++++++++++++++++++++++++++++++++++++++--------- src/h2load.h | 26 +++++++- 2 files changed, 163 insertions(+), 34 deletions(-) diff --git a/src/h2load.cc b/src/h2load.cc index 5daff7b0..1dd3fd36 100644 --- a/src/h2load.cc +++ b/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> &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 (!req_stat.completed) { - continue; + if (type == STAT_REQUEST) { + for (const auto &req_stat : w->stats.req_stats) { + if (!req_stat.completed) { + continue; + } + auto t = std::chrono::duration_cast(req_stat.stream_close_time - req_stat.request_time); + if (lower <= t.count() && t.count() <= upper) { + ++m; + } } - auto t = std::chrono::duration_cast( - req_stat.stream_close_time - req_stat.request_time); - if (lower <= t.count() && t.count() <= upper) { - ++m; + } else { + const auto &stat = w->stats; + 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) + } + std::chrono::microseconds t; + if (type == STAT_CONNECT) { + t = std::chrono::duration_cast(stat.connect_times[i] - stat.start_times[i]); + } else if (type == STAT_FIRST_BYTE) { + t = std::chrono::duration_cast(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> &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.time_max = std::chrono::microseconds::min(); - ts.within_sd = 0.; + ts.request_time_min = std::chrono::microseconds::max(); + ts.request_time_max = std::chrono::microseconds::min(); + 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( + auto request_t = std::chrono::duration_cast( req_stat.stream_close_time - req_stat.request_time); - ts.time_min = std::min(ts.time_min, t); - ts.time_max = std::max(ts.time_max, t); - sum += t.count(); + ts.request_time_min = std::min(ts.request_time_min, request_t); + ts.request_time_max = std::max(ts.request_time_max, request_t); + request_sum += request_t.count(); - auto na = a + (t.count() - a) / n; - q = q + (t.count() - a) * (t.count() - na); - a = na; + auto request_na = request_a + (request_t.count() - request_a) / n; + request_q = request_q + (request_t.count() - request_a) * (request_t.count() - request_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( + 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( + 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.time_sd = std::chrono::microseconds( - static_cast(sqrt(q / n))); + ts.request_time_mean = std::chrono::microseconds(request_sum / n); + ts.request_time_sd = std::chrono::microseconds( + static_cast(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(sqrt(connect_q / m))); + + ts.ttfb_mean = std::chrono::microseconds(ttfb_sum / m); + ts.ttfb_sd = std::chrono::microseconds( + static_cast(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) << " " - << std::setw(10) << util::format_duration(time_stats.time_max) + << util::format_duration(time_stats.request_time_min) << " " + << std::setw(10) << util::format_duration(time_stats.request_time_max) << " " << std::setw(10) - << util::format_duration(time_stats.time_mean) << " " - << std::setw(10) << util::format_duration(time_stats.time_sd) - << std::setw(9) << util::dtos(time_stats.within_sd) << "%" + << util::format_duration(time_stats.request_time_mean) << " " + << std::setw(10) << util::format_duration(time_stats.request_time_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); diff --git a/src/h2load.h b/src/h2load.h index 6a837c1a..9df35f5e 100644 --- a/src/h2load.h +++ b/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 status; // The statistics per request std::vector req_stats; + // time connect starts + std::vector start_times; + // time to connect + std::vector connect_times; + // time to first byte + std::vector 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(); }; From b4e8bea4b5816b55770e8ac8b962ad12182db5f3 Mon Sep 17 00:00:00 2001 From: Tatsuhiro Tsujikawa Date: Sun, 3 May 2015 16:47:32 +0900 Subject: [PATCH 2/2] clang-format --- src/h2load.cc | 88 ++++++++++++++++++++++++++++++++------------------- src/h2load.h | 10 +++--- 2 files changed, 61 insertions(+), 37 deletions(-) diff --git a/src/h2load.cc b/src/h2load.cc index 9737ef77..75b3fa78 100644 --- a/src/h2load.cc +++ b/src/h2load.cc @@ -150,8 +150,8 @@ 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), first_byte_received(false), req_todo(req_todo), req_started(0), req_done(0), - fd(-1) { + 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); @@ -472,7 +472,7 @@ 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); @@ -523,11 +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; @@ -650,11 +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); - } + } } } @@ -759,7 +759,8 @@ void Worker::run() { namespace { double within_sd(const std::vector> &workers, const std::chrono::microseconds &mean, - const std::chrono::microseconds &sd, size_t n, TimeStatType type) { + 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; @@ -769,7 +770,8 @@ double within_sd(const std::vector> &workers, if (!req_stat.completed) { continue; } - auto t = std::chrono::duration_cast(req_stat.stream_close_time - req_stat.request_time); + auto t = std::chrono::duration_cast( + req_stat.stream_close_time - req_stat.request_time); if (lower <= t.count() && t.count() <= upper) { ++m; } @@ -777,14 +779,18 @@ double within_sd(const std::vector> &workers, } else { const auto &stat = w->stats; 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) + 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(stat.connect_times[i] - stat.start_times[i]); + t = std::chrono::duration_cast( + stat.connect_times[i] - stat.start_times[i]); } else if (type == STAT_FIRST_BYTE) { - t = std::chrono::duration_cast(stat.time_to_first_bytes[i] - stat.start_times[i]); + t = std::chrono::duration_cast( + stat.time_to_first_bytes[i] - stat.start_times[i]); } else { return -1; } @@ -839,28 +845,34 @@ process_time_stats(const std::vector> &workers) { request_sum += request_t.count(); auto request_na = request_a + (request_t.count() - request_a) / n; - request_q = request_q + (request_t.count() - request_a) * (request_t.count() - request_na); + request_q = + request_q + + (request_t.count() - request_a) * (request_t.count() - request_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) + 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( - stat.connect_times[i] - stat.start_times[i]); + 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( - stat.time_to_first_bytes[i] - stat.start_times[i]); + 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_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; @@ -869,8 +881,10 @@ process_time_stats(const std::vector> &workers) { } } if (n == 0) { - 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.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; } @@ -887,10 +901,12 @@ process_time_stats(const std::vector> &workers) { ts.ttfb_sd = std::chrono::microseconds( static_cast(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); + 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 @@ -1540,17 +1556,23 @@ traffic: )" << stats.bytes_total << " bytes total, " << stats.bytes_head min max mean sd +/- sd time for request: )" << std::setw(10) << util::format_duration(time_stats.request_time_min) << " " - << std::setw(10) << util::format_duration(time_stats.request_time_max) - << " " << std::setw(10) + << std::setw(10) + << util::format_duration(time_stats.request_time_max) << " " + << std::setw(10) << util::format_duration(time_stats.request_time_mean) << " " - << std::setw(10) << util::format_duration(time_stats.request_time_sd) - << std::setw(9) << util::dtos(time_stats.request_within_sd) << "%" << "\ntime for connect: " << std::setw(10) + << std::setw(10) + << util::format_duration(time_stats.request_time_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) + << 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) + << 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) diff --git a/src/h2load.h b/src/h2load.h index 9df35f5e..2f2f1e10 100644 --- a/src/h2load.h +++ b/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,13 @@ struct RequestStat { struct TimeStats { // time for request: max, min, mean and sd (standard deviation) - std::chrono::microseconds request_time_max, request_time_min, request_time_mean, request_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 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; + 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) @@ -142,7 +144,7 @@ struct Stats { std::array status; // The statistics per request std::vector req_stats; - // time connect starts + // time connect starts std::vector start_times; // time to connect std::vector connect_times;