Merge branch 'pyos-master'

This commit is contained in:
Tatsuhiro Tsujikawa 2018-11-23 12:11:21 +09:00
commit de4fe72861
2 changed files with 52 additions and 1 deletions

View File

@ -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) { if (status >= 200 && status < 300) {
++worker->stats.status[2]; ++worker->stats.status[2];
stream.status_success = 1; stream.status_success = 1;
@ -775,6 +776,7 @@ void Client::on_status_code(int32_t stream_id, uint16_t status) {
return; return;
} }
stream.req_stat.status = status;
if (status >= 200 && status < 300) { if (status >= 200 && status < 300) {
++worker->stats.status[2]; ++worker->stats.status[2];
stream.status_success = 1; 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; ++worker->stats.req_done;
++req_done; ++req_done;
if (worker->log) {
auto start = std::chrono::duration_cast<std::chrono::microseconds>(
req_stat->request_wall_time.time_since_epoch());
auto delta = std::chrono::duration_cast<std::chrono::microseconds>(
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(); worker->report_progress();
@ -1177,6 +1194,7 @@ int Client::write_tls() {
void Client::record_request_time(RequestStat *req_stat) { void Client::record_request_time(RequestStat *req_stat) {
req_stat->request_time = std::chrono::steady_clock::now(); 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() { 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), nreqs_rem(req_todo % nclients),
rate(rate), rate(rate),
max_samples(max_samples), 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()) { if (!config->is_rate_mode() && !config->is_timing_based_mode()) {
progress_interval = std::max(static_cast<size_t>(1), req_todo / 10); progress_interval = std::max(static_cast<size_t>(1), req_todo / 10);
} else { } else {
@ -1281,6 +1300,11 @@ Worker::Worker(uint32_t id, SSL_CTX *ssl_ctx, size_t req_todo, size_t nclients,
} else { } else {
current_phase = Phase::MAIN_DURATION; current_phase = Phase::MAIN_DURATION;
} }
if (!config->log_file.empty()) {
log = std::make_unique<std::ofstream>(
config->log_file, std::ios_base::out | std::ios_base::app);
}
} }
Worker::~Worker() { Worker::~Worker() {
@ -1940,6 +1964,14 @@ Options:
this option value and the value which server specified. this option value and the value which server specified.
Default: )" Default: )"
<< util::utos_unit(config.encoder_header_table_size) << R"( << util::utos_unit(config.encoder_header_table_size) << R"(
--log-file=<PATH>
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 -v, --verbose
Output debug information. Output debug information.
--version Display version information and exit. --version Display version information and exit.
@ -1996,6 +2028,7 @@ int main(int argc, char **argv) {
{"header-table-size", required_argument, &flag, 7}, {"header-table-size", required_argument, &flag, 7},
{"encoder-header-table-size", required_argument, &flag, 8}, {"encoder-header-table-size", required_argument, &flag, 8},
{"warm-up-time", required_argument, &flag, 9}, {"warm-up-time", required_argument, &flag, 9},
{"log-file", required_argument, &flag, 10},
{nullptr, 0, nullptr, 0}}; {nullptr, 0, nullptr, 0}};
int option_index = 0; int option_index = 0;
auto c = getopt_long(argc, argv, auto c = getopt_long(argc, argv,
@ -2219,6 +2252,15 @@ int main(int argc, char **argv) {
exit(EXIT_FAILURE); exit(EXIT_FAILURE);
} }
break; 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; break;
default: default:

View File

@ -71,6 +71,7 @@ struct Config {
std::string host; std::string host;
std::string ifile; std::string ifile;
std::string ciphers; std::string ciphers;
std::string log_file;
// length of upload data // length of upload data
int64_t data_length; int64_t data_length;
addrinfo *addrs; addrinfo *addrs;
@ -122,10 +123,14 @@ struct Config {
struct RequestStat { struct RequestStat {
// time point when request was sent // time point when request was sent
std::chrono::steady_clock::time_point request_time; 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 // time point when stream was closed
std::chrono::steady_clock::time_point stream_close_time; 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; int64_t data_offset;
// HTTP status code
int status;
// true if stream was successfully closed. This means stream was // true if stream was successfully closed. This means stream was
// not reset, but it does not mean HTTP level error (e.g., 404). // not reset, but it does not mean HTTP level error (e.g., 404).
bool completed; bool completed;
@ -266,6 +271,10 @@ struct Worker {
// specified // specified
ev_timer duration_watcher; ev_timer duration_watcher;
ev_timer warmup_watcher; ev_timer warmup_watcher;
// Stream to write per-request stats to.
std::unique_ptr<std::ostream> 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, Worker(uint32_t id, SSL_CTX *ssl_ctx, size_t nreq_todo, size_t nclients,
size_t rate, size_t max_samples, Config *config); size_t rate, size_t max_samples, Config *config);