From b57530552825a13a3cd1924bda99e5e237c722a4 Mon Sep 17 00:00:00 2001 From: "Steinar H. Gunderson" Date: Wed, 22 Jul 2015 01:08:00 +0200 Subject: [PATCH] Change the connected time from time_t to timespec. The primary gain as the code stands is that we become immune to issues with the clock going backwards etc. in logs (since we can now use a monotonic timer). However, the motivating change is that we will soon be implementing request read timeouts. At that point, not only will the clock data be much more important to get right, but it will also be nice to have more fine-grained timestamps to be able to locate clients semi-uniquely in a sorted list. --- accesslog.cpp | 26 +++++++++++++++----------- client.cpp | 21 ++++++++++++++++++--- client.h | 6 ++++-- state.proto | 4 +++- stats.cpp | 13 +++++++++---- 5 files changed, 49 insertions(+), 21 deletions(-) diff --git a/accesslog.cpp b/accesslog.cpp index 9cd5be0..4414650 100644 --- a/accesslog.cpp +++ b/accesslog.cpp @@ -53,18 +53,22 @@ void AccessLogThread::do_work() if (logfp != NULL) { // Do the actual writes. - time_t now = time(NULL); - for (size_t i = 0; i < writes.size(); ++i) { - fprintf(logfp, "%llu %s %s %d %llu %llu %llu\n", - (long long unsigned)(writes[i].connect_time), - writes[i].remote_addr.c_str(), - writes[i].url.c_str(), - int(now - writes[i].connect_time), - (long long unsigned)(writes[i].bytes_sent), - (long long unsigned)(writes[i].bytes_lost), - (long long unsigned)(writes[i].num_loss_events)); + timespec now; + if (clock_gettime(CLOCK_MONOTONIC_COARSE, &now) == -1) { + log_perror("clock_gettime(CLOCK_MONOTONIC_COARSE)"); + } else { + for (size_t i = 0; i < writes.size(); ++i) { + fprintf(logfp, "%llu %s %s %d %llu %llu %llu\n", + (long long unsigned)(writes[i].connect_time.tv_sec), + writes[i].remote_addr.c_str(), + writes[i].url.c_str(), + int(now.tv_sec - writes[i].connect_time.tv_sec), // Rather coarse. + (long long unsigned)(writes[i].bytes_sent), + (long long unsigned)(writes[i].bytes_lost), + (long long unsigned)(writes[i].num_loss_events)); + } + fflush(logfp); } - fflush(logfp); } // Wait until we are being woken up, either to quit or because diff --git a/client.cpp b/client.cpp index b226d5e..e7a12f6 100644 --- a/client.cpp +++ b/client.cpp @@ -16,7 +16,6 @@ using namespace std; Client::Client(int sock) : sock(sock), - connect_time(time(NULL)), state(Client::READING_REQUEST), stream(NULL), header_or_error_bytes_sent(0), @@ -27,6 +26,11 @@ Client::Client(int sock) { request.reserve(1024); + if (clock_gettime(CLOCK_MONOTONIC_COARSE, &connect_time) == -1) { + log_perror("clock_gettime(CLOCK_MONOTONIC_COARSE)"); + return; + } + // Find the remote address, and convert it to ASCII. sockaddr_in6 addr; socklen_t addr_len = sizeof(addr); @@ -59,7 +63,6 @@ Client::Client(int sock) Client::Client(const ClientProto &serialized, Stream *stream) : sock(serialized.sock()), remote_addr(serialized.remote_addr()), - connect_time(serialized.connect_time()), state(State(serialized.state())), request(serialized.request()), url(serialized.url()), @@ -78,6 +81,17 @@ Client::Client(const ClientProto &serialized, Stream *stream) } } } + if (serialized.has_connect_time_old()) { + // Do a rough conversion from time() to monotonic time. + if (clock_gettime(CLOCK_MONOTONIC_COARSE, &connect_time) == -1) { + log_perror("clock_gettime(CLOCK_MONOTONIC_COARSE)"); + return; + } + connect_time.tv_sec += serialized.connect_time_old() - time(NULL); + } else { + connect_time.tv_sec = serialized.connect_time_sec(); + connect_time.tv_nsec = serialized.connect_time_nsec(); + } } ClientProto Client::serialize() const @@ -85,7 +99,8 @@ ClientProto Client::serialize() const ClientProto serialized; serialized.set_sock(sock); serialized.set_remote_addr(remote_addr); - serialized.set_connect_time(connect_time); + serialized.set_connect_time_sec(connect_time.tv_sec); + serialized.set_connect_time_nsec(connect_time.tv_nsec); serialized.set_state(state); serialized.set_request(request); serialized.set_url(url); diff --git a/client.h b/client.h index d23b860..4e80031 100644 --- a/client.h +++ b/client.h @@ -15,7 +15,7 @@ struct ClientStats { std::string url; int sock; std::string remote_addr; - time_t connect_time; + timespec connect_time; size_t bytes_sent; size_t bytes_lost; size_t num_loss_events; @@ -33,9 +33,11 @@ struct Client { // The file descriptor associated with this socket. int sock; + // When the client connected, in terms of CLOCK_MONOTONIC_COARSE. + timespec connect_time; + // Some information only used for logging. std::string remote_addr; - time_t connect_time; enum State { READING_REQUEST, SENDING_HEADER, SENDING_DATA, SENDING_ERROR, WAITING_FOR_KEYFRAME, PREBUFFERING }; State state; diff --git a/state.proto b/state.proto index e612831..30b63da 100644 --- a/state.proto +++ b/state.proto @@ -2,7 +2,9 @@ message ClientProto { optional int32 sock = 1; optional string remote_addr = 8; - optional int64 connect_time = 9; + optional int64 connect_time_old = 9; // Contains a time_t from time(). For versions prior to 1.1.3. + optional int64 connect_time_sec = 13; + optional int32 connect_time_nsec = 14; optional int32 state = 2; optional bytes request = 3; optional string url = 4; diff --git a/stats.cpp b/stats.cpp index 69bbd73..b0765ed 100644 --- a/stats.cpp +++ b/stats.cpp @@ -27,12 +27,18 @@ void StatsThread::do_work() { while (!should_stop()) { int fd; + char *filename; FILE *fp; - time_t now; + timespec now; vector client_stats; + if (clock_gettime(CLOCK_MONOTONIC_COARSE, &now) == -1) { + log_perror("clock_gettime(CLOCK_MONOTONIC_COARSE)"); + goto sleep; + } + // Open a new, temporary file. - char *filename = strdup((stats_file + ".new.XXXXXX").c_str()); + filename = strdup((stats_file + ".new.XXXXXX").c_str()); fd = mkostemp(filename, O_WRONLY); if (fd == -1) { log_perror(filename); @@ -51,7 +57,6 @@ void StatsThread::do_work() goto sleep; } - now = time(NULL); client_stats = servers->get_client_stats(); for (size_t i = 0; i < client_stats.size(); ++i) { fprintf(fp, "%s %d %d %s %d %llu %llu %llu\n", @@ -59,7 +64,7 @@ void StatsThread::do_work() client_stats[i].sock, 0, // Used to be fwmark. client_stats[i].url.c_str(), - int(now - client_stats[i].connect_time), + int(now.tv_sec - client_stats[i].connect_time.tv_sec), // Rather coarse. (long long unsigned)(client_stats[i].bytes_sent), (long long unsigned)(client_stats[i].bytes_lost), (long long unsigned)(client_stats[i].num_loss_events)); -- 2.39.2