From d1b3a83f5982f4da69c31302450fd13e8e2a13cb Mon Sep 17 00:00:00 2001 From: dawg Date: Sun, 11 Nov 2018 21:33:50 +0300 Subject: [PATCH] h2load: add an option to write per-request logs --- src/h2load.cc | 44 +++++++++++++++++++++++++++++++++++++++++++- src/h2load.h | 9 +++++++++ 2 files changed, 52 insertions(+), 1 deletion(-) diff --git a/src/h2load.cc b/src/h2load.cc index 48a0e2ed..c1555cc6 100644 --- a/src/h2load.cc +++ b/src/h2load.cc @@ -748,6 +748,7 @@ void Client::on_header(int32_t stream_id, const uint8_t *name, size_t namelen, } } + stream.req_stat.status = status; if (status >= 200 && status < 300) { ++worker->stats.status[2]; stream.status_success = 1; @@ -775,6 +776,7 @@ void Client::on_status_code(int32_t stream_id, uint16_t status) { return; } + stream.req_stat.status = status; if (status >= 200 && status < 300) { ++worker->stats.status[2]; stream.status_success = 1; @@ -821,6 +823,21 @@ void Client::on_stream_close(int32_t stream_id, bool success, bool final) { } ++worker->stats.req_done; ++req_done; + + if (worker->log) { + auto start = std::chrono::duration_cast( + req_stat->request_wall_time.time_since_epoch()); + auto delta = std::chrono::duration_cast( + req_stat->stream_close_time - req_stat->request_time); + *worker->log << start.count() << '\t' << (success ? req_stat->status : -1) + << '\t' << delta.count() << '\n'; + // Flushing manually is important to ensure atomicity of lines, but + // doing it after each line (e.g. with std::endl) is noticeably slow. + if (++worker->log_pending == 16) { + worker->log->flush(); + worker->log_pending = 0; + } + } } worker->report_progress(); @@ -1177,6 +1194,7 @@ int Client::write_tls() { void Client::record_request_time(RequestStat *req_stat) { req_stat->request_time = std::chrono::steady_clock::now(); + req_stat->request_wall_time = std::chrono::system_clock::now(); } void Client::record_connect_start_time() { @@ -1246,7 +1264,8 @@ Worker::Worker(uint32_t id, SSL_CTX *ssl_ctx, size_t req_todo, size_t nclients, nreqs_rem(req_todo % nclients), rate(rate), max_samples(max_samples), - next_client_id(0) { + next_client_id(0), + log_pending(0) { if (!config->is_rate_mode() && !config->is_timing_based_mode()) { progress_interval = std::max(static_cast(1), req_todo / 10); } else { @@ -1281,6 +1300,11 @@ Worker::Worker(uint32_t id, SSL_CTX *ssl_ctx, size_t req_todo, size_t nclients, } else { current_phase = Phase::MAIN_DURATION; } + + if (!config->log_file.empty()) { + log = std::make_unique( + config->log_file, std::ios_base::out | std::ios_base::app); + } } Worker::~Worker() { @@ -1940,6 +1964,14 @@ Options: this option value and the value which server specified. Default: )" << util::utos_unit(config.encoder_header_table_size) << R"( + --log-file= + Write per-request information to a file as tab-separated + columns: start time as microseconds since epoch; HTTP + status code; microseconds until end of response. More + columns may be added later. Rows are ordered by end-of- + response time when using one worker thread, but may + appear slightly out of order with multiple threads due + to buffering. Status code is -1 for failed streams. -v, --verbose Output debug information. --version Display version information and exit. @@ -1996,6 +2028,7 @@ int main(int argc, char **argv) { {"header-table-size", required_argument, &flag, 7}, {"encoder-header-table-size", required_argument, &flag, 8}, {"warm-up-time", required_argument, &flag, 9}, + {"log-file", required_argument, &flag, 10}, {nullptr, 0, nullptr, 0}}; int option_index = 0; auto c = getopt_long(argc, argv, @@ -2219,6 +2252,15 @@ int main(int argc, char **argv) { exit(EXIT_FAILURE); } break; + case 10: + // --log-file + std::ofstream out(optarg, std::ios_base::out | std::ios_base::app); + if (!out.is_open()) { + std::cerr << "--log-file: cannot write to " << optarg << std::endl; + exit(EXIT_FAILURE); + } + config.log_file = optarg; + break; } break; default: diff --git a/src/h2load.h b/src/h2load.h index bde36e8d..63936dd4 100644 --- a/src/h2load.h +++ b/src/h2load.h @@ -71,6 +71,7 @@ struct Config { std::string host; std::string ifile; std::string ciphers; + std::string log_file; // length of upload data int64_t data_length; addrinfo *addrs; @@ -122,10 +123,14 @@ struct Config { struct RequestStat { // time point when request was sent std::chrono::steady_clock::time_point request_time; + // same, but in wall clock reference frame + std::chrono::system_clock::time_point request_wall_time; // time point when stream was closed std::chrono::steady_clock::time_point stream_close_time; // upload data length sent so far int64_t data_offset; + // HTTP status code + int status; // true if stream was successfully closed. This means stream was // not reset, but it does not mean HTTP level error (e.g., 404). bool completed; @@ -266,6 +271,10 @@ struct Worker { // specified ev_timer duration_watcher; ev_timer warmup_watcher; + // Stream to write per-request stats to. + std::unique_ptr log; + // Number of unflushed lines in the log. + uint32_t log_pending; Worker(uint32_t id, SSL_CTX *ssl_ctx, size_t nreq_todo, size_t nclients, size_t rate, size_t max_samples, Config *config);