walkero
/
nghttp2
1
0
Fork 0
Code Issues Pull Requests Projects Releases 1 Wiki Activity

Merge branch 'ericcarlschwartz-finer_stats'

This commit is contained in:
Tatsuhiro Tsujikawa 2015-05-03 16:47:52 +09:00
parent 7b3a33a313 b4e8bea4b5
commit fe6d065bb4
2 changed files with 187 additions and 34 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

195
src/h2load.cc
View File

@ -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), 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);
@ -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,44 @@ 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 (!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<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>(
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<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 +808,105 @@ 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.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<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.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<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.time_sd = std::chrono::microseconds(
static_cast<std::chrono::microseconds::rep>(sqrt(q / n)));
ts.request_time_mean = std::chrono::microseconds(request_sum / n);
ts.request_time_sd = std::chrono::microseconds(
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
@ -1442,12 +1555,30 @@ 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.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.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.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);

26
src/h2load.h
View File

@ -96,11 +96,23 @@ 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 +144,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 +189,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 +234,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();
};