From 6beaf4d9f325fa1766a046b0cf2cd69bf1fca3e0 Mon Sep 17 00:00:00 2001 From: Tatsuhiro Tsujikawa Date: Tue, 1 Dec 2015 23:49:28 +0900 Subject: [PATCH] h2load: Add req/s min, max, mean and sd for clients --- doc/h2load.h2r | 15 +++++++++ src/h2load.cc | 88 ++++++++++++++++++++++++++++++++++-------------- src/h2load.h | 30 ++++++++++++----- src/util.cc | 14 ++++++++ src/util.h | 3 ++ src/util_test.cc | 9 +++++ 6 files changed, 125 insertions(+), 34 deletions(-) diff --git a/doc/h2load.h2r b/doc/h2load.h2r index 60826931..e022aa8d 100644 --- a/doc/h2load.h2r +++ b/doc/h2load.h2r @@ -86,6 +86,21 @@ time for 1st byte (of (decrypted in case of TLS) application data) deviation range (mean +/- sd) against total number of successful connections. +req/s (client) + min + The minimum request per second among all clients. + max + The maximum request per second among all clients. + mean + The mean request per second among all clients. + sd + The standard deviation of request per second among all clients. + server. + +/- sd + The fraction of the number of connections within standard + deviation range (mean +/- sd) against total number of successful + connections. + FLOW CONTROL ------------ diff --git a/src/h2load.cc b/src/h2load.cc index dcd4e4e6..3f642eb6 100644 --- a/src/h2load.cc +++ b/src/h2load.cc @@ -309,6 +309,7 @@ int Client::make_socket(addrinfo *addr) { int Client::connect() { int rv; + record_client_start_time(); clear_connect_times(); record_connect_start_time(); @@ -391,6 +392,8 @@ void Client::fail() { } void Client::disconnect() { + record_client_end_time(); + ev_timer_stop(worker->loop, &conn_inactivity_watcher); ev_timer_stop(worker->loop, &conn_active_watcher); ev_timer_stop(worker->loop, &request_timeout_watcher); @@ -610,6 +613,8 @@ void Client::on_stream_close(int32_t stream_id, bool success, if (success) { req_stat->completed = true; ++worker->stats.req_success; + auto &cstat = worker->stats.client_stats[id]; + ++cstat.req_success; } ++worker->stats.req_done; ++req_done; @@ -1006,6 +1011,26 @@ void Client::clear_connect_times() { cstat.ttfb = std::chrono::steady_clock::time_point(); } +void Client::record_client_start_time() { + auto &cstat = worker->stats.client_stats[id]; + + // Record start time only once at the very first connection is going + // to be made. + if (recorded(cstat.client_start_time)) { + return; + } + + cstat.client_start_time = std::chrono::steady_clock::now(); +} + +void Client::record_client_end_time() { + auto &cstat = worker->stats.client_stats[id]; + + // Unlike client_start_time, we overwrite client_end_time. This + // handles multiple connect/disconnect for HTTP/1.1 benchmark. + cstat.client_end_time = std::chrono::steady_clock::now(); +} + void Client::signal_write() { ev_io_start(worker->loop, &wev); } void Client::try_new_connection() { new_connection_requested = true; } @@ -1065,9 +1090,7 @@ void Worker::run() { namespace { // Returns percentage of number of samples within mean +/- sd. -template -double within_sd(const std::vector &samples, const Duration &mean, - const Duration &sd) { +double within_sd(const std::vector &samples, double mean, double sd) { if (samples.size() == 0) { return 0.0; } @@ -1075,7 +1098,7 @@ double within_sd(const std::vector &samples, const Duration &mean, auto upper = mean + sd; auto m = std::count_if( std::begin(samples), std::end(samples), - [&lower, &upper](const Duration &t) { return lower <= t && t <= upper; }); + [&lower, &upper](double t) { return lower <= t && t <= upper; }); return (m / static_cast(samples.size())) * 100; } } // namespace @@ -1083,32 +1106,31 @@ double within_sd(const std::vector &samples, const Duration &mean, namespace { // Computes statistics using |samples|. The min, max, mean, sd, and // percentage of number of samples within mean +/- sd are computed. -template -TimeStat compute_time_stat(const std::vector &samples) { +SDStat compute_time_stat(const std::vector &samples) { if (samples.empty()) { - return {Duration::zero(), Duration::zero(), Duration::zero(), - Duration::zero(), 0.0}; + return {0.0, 0.0, 0.0, 0.0, 0.0}; } // standard deviation calculated using Rapid calculation method: // http://en.wikipedia.org/wiki/Standard_deviation#Rapid_calculation_methods double a = 0, q = 0; size_t n = 0; - int64_t sum = 0; - auto res = TimeStat{Duration::max(), Duration::min()}; + double sum = 0; + auto res = SDStat{std::numeric_limits::max(), + std::numeric_limits::min()}; for (const auto &t : samples) { ++n; res.min = std::min(res.min, t); res.max = std::max(res.max, t); - sum += t.count(); + sum += t; - auto na = a + (t.count() - a) / n; - q += (t.count() - a) * (t.count() - na); + auto na = a + (t - a) / n; + q += (t - a) * (t - na); a = na; } assert(n > 0); - res.mean = Duration(sum / n); - res.sd = Duration(static_cast(sqrt(q / n))); + res.mean = sum / n; + res.sd = sqrt(q / n); res.within_sd = within_sd(samples, res.mean, res.sd); return res; @@ -1116,19 +1138,20 @@ TimeStat compute_time_stat(const std::vector &samples) { } // namespace namespace { -TimeStats +SDStats process_time_stats(const std::vector> &workers) { size_t nrequest_times = 0; for (const auto &w : workers) { nrequest_times += w->stats.req_stats.size(); } - std::vector request_times; + std::vector request_times; request_times.reserve(nrequest_times); - std::vector connect_times, ttfb_times; + std::vector connect_times, ttfb_times, rps_values; connect_times.reserve(config.nclients); ttfb_times.reserve(config.nclients); + rps_values.reserve(config.nclients); for (const auto &w : workers) { for (const auto &req_stat : w->stats.req_stats) { @@ -1136,13 +1159,22 @@ process_time_stats(const std::vector> &workers) { continue; } request_times.push_back( - std::chrono::duration_cast( - req_stat.stream_close_time - req_stat.request_time)); + std::chrono::duration_cast>( + req_stat.stream_close_time - req_stat.request_time).count()); } const auto &stat = w->stats; for (const auto &cstat : stat.client_stats) { + if (recorded(cstat.client_start_time) && + recorded(cstat.client_end_time)) { + auto t = std::chrono::duration_cast>( + cstat.client_end_time - cstat.client_start_time).count(); + if (t > 1e-9) { + rps_values.push_back(cstat.req_success / t); + } + } + // We will get connect event before FFTB. if (!recorded(cstat.connect_start_time) || !recorded(cstat.connect_time)) { @@ -1150,21 +1182,21 @@ process_time_stats(const std::vector> &workers) { } connect_times.push_back( - std::chrono::duration_cast( - cstat.connect_time - cstat.connect_start_time)); + std::chrono::duration_cast>( + cstat.connect_time - cstat.connect_start_time).count()); if (!recorded(cstat.ttfb)) { continue; } ttfb_times.push_back( - std::chrono::duration_cast( - cstat.ttfb - cstat.connect_start_time)); + std::chrono::duration_cast>( + cstat.ttfb - cstat.connect_start_time).count()); } } return {compute_time_stat(request_times), compute_time_stat(connect_times), - compute_time_stat(ttfb_times)}; + compute_time_stat(ttfb_times), compute_time_stat(rps_values)}; } } // namespace @@ -2220,7 +2252,11 @@ time for request: )" << std::setw(10) << util::format_duration(ts.request.min) << util::format_duration(ts.ttfb.max) << " " << std::setw(10) << util::format_duration(ts.ttfb.mean) << " " << std::setw(10) << util::format_duration(ts.ttfb.sd) << std::setw(9) - << util::dtos(ts.ttfb.within_sd) << "%" << std::endl; + << util::dtos(ts.ttfb.within_sd) << "%" + << "\nreq/s (client) : " << std::setw(10) << ts.rps.min << " " + << std::setw(10) << ts.rps.max << " " << std::setw(10) + << ts.rps.mean << " " << std::setw(10) << ts.rps.sd << std::setw(9) + << util::dtos(ts.rps.within_sd) << "%" << std::endl; SSL_CTX_free(ssl_ctx); diff --git a/src/h2load.h b/src/h2load.h index 3b7c16cb..a7e07ea4 100644 --- a/src/h2load.h +++ b/src/h2load.h @@ -125,6 +125,18 @@ struct RequestStat { }; struct ClientStat { + // time client started (i.e., first connect starts) + std::chrono::steady_clock::time_point client_start_time; + // time client end (i.e., client somehow processed all requests it + // is responsible for, and disconnected) + std::chrono::steady_clock::time_point client_end_time; + // The number of requests completed successfull, but not necessarily + // means successful HTTP status code. + size_t req_success; + + // The following 3 numbers are overwritten each time when connection + // is made. + // time connect starts std::chrono::steady_clock::time_point connect_start_time; // time to connect @@ -133,24 +145,24 @@ struct ClientStat { std::chrono::steady_clock::time_point ttfb; }; -template struct TimeStat { +struct SDStat { // min, max, mean and sd (standard deviation) - Duration min, max, mean, sd; + double min, max, mean, sd; // percentage of samples inside mean -/+ sd double within_sd; }; -struct TimeStats { +struct SDStats { // time for request - TimeStat request; + SDStat request; // time for connect - TimeStat connect; + SDStat connect; // time to first byte (TTFB) - TimeStat ttfb; + SDStat ttfb; + // request per second for each client + SDStat rps; }; -enum TimeStatType { STAT_REQUEST, STAT_CONNECT, STAT_FIRST_BYTE }; - struct Stats { Stats(size_t req_todo, size_t nclients); // The total number of requests @@ -314,6 +326,8 @@ struct Client { void record_connect_time(); void record_ttfb(); void clear_connect_times(); + void record_client_start_time(); + void record_client_end_time(); void signal_write(); }; diff --git a/src/util.cc b/src/util.cc index 40066588..a2d649ef 100644 --- a/src/util.cc +++ b/src/util.cc @@ -1092,6 +1092,20 @@ std::string format_duration(const std::chrono::microseconds &u) { return dtos(static_cast(t) / d) + unit; } +std::string format_duration(double t) { + const char *unit = "us"; + if (t >= 1.) { + unit = "s"; + } else if (t >= 0.001) { + t *= 1000.; + unit = "ms"; + } else { + t *= 1000000.; + return utos(static_cast(t)) + unit; + } + return dtos(t) + unit; +} + std::string dtos(double n) { auto f = utos(static_cast(round(100. * n)) % 100); return utos(static_cast(n)) + "." + (f.size() == 1 ? "0" : "") + f; diff --git a/src/util.h b/src/util.h index 9319e7cd..8efd7407 100644 --- a/src/util.h +++ b/src/util.h @@ -585,6 +585,9 @@ std::string duration_str(double t); // fractional digits follow. std::string format_duration(const std::chrono::microseconds &u); +// Just like above, but this takes |t| as seconds. +std::string format_duration(double t); + // Creates "host:port" string using given |host| and |port|. If // |host| is numeric IPv6 address (e.g., ::1), it is enclosed by "[" // and "]". If |port| is 80 or 443, port part is omitted. diff --git a/src/util_test.cc b/src/util_test.cc index adc079f6..9732ff15 100644 --- a/src/util_test.cc +++ b/src/util_test.cc @@ -341,6 +341,15 @@ void test_util_format_duration(void) { util::format_duration(std::chrono::microseconds(1000000))); CU_ASSERT("1.05s" == util::format_duration(std::chrono::microseconds(1050000))); + + CU_ASSERT("0us" == util::format_duration(0.)); + CU_ASSERT("999us" == util::format_duration(0.000999)); + CU_ASSERT("1.00ms" == util::format_duration(0.001)); + CU_ASSERT("1.09ms" == util::format_duration(0.00109)); + CU_ASSERT("1.01ms" == util::format_duration(0.001009)); + CU_ASSERT("999.99ms" == util::format_duration(0.99999)); + CU_ASSERT("1.00s" == util::format_duration(1.)); + CU_ASSERT("1.05s" == util::format_duration(1.05)); } void test_util_starts_with(void) {