Stop caching the timestamp in the server

Caching the timestamp makes the recv timestamps in the logs slightly
less useful, and the performance gains are questionable.

Change-Id: I71300325622ccc51bfef3cb548ce6e8a725b8429

diff --git a/src/logger/log_buffer.c b/src/logger/log_buffer.c
index 87e5af4..03b0021 100644 (file)
--- a/src/logger/log_buffer.c
+++ b/src/logger/log_buffer.c
@@ -46,7 +46,13 @@ static int service_writer_pipe(struct logger *server, struct writer *wr, struct
 
                        struct dlogutil_entry_with_msg lem;
                        parse_pipe_message(ple, &lem.header, ple->len);
-                       add_recv_timestamp(&lem.header, server->time);
+
+                       struct now_t now;
+                       r = get_now(&now);
+                       if (r < 0)
+                               return r;
+                       add_recv_timestamp(&lem.header, now);
+
                        fixup_pipe_msg(&lem, payload_size);
                        if (qos_is_enabled(&server->qos))
                                qos_add_log(&server->qos, &lem.header);
@@ -128,7 +134,12 @@ static int service_writer_stdout(struct logger *server, struct writer *wr, struc
                                .tid = wr->stdout_data->pid,
                        },
                };
-               add_recv_timestamp(&lem.header, server->time);
+
+               struct now_t now;
+               int r = get_now(&now);
+               if (r < 0)
+                       return r;
+               add_recv_timestamp(&lem.header, now);
 
                /* HACK: We copy recv to sent, because we assume that those timestamps are available
                 * and we do not want to special case them. TODO: Is there a better solution? */
@@ -154,7 +165,7 @@ static int service_writer_stdout(struct logger *server, struct writer *wr, struc
                if (qos_is_enabled(&server->qos))
                        qos_add_log(&server->qos, &lem.header);
 
-               int r = buffer_append(&lem.header, wr->buf_ptr);
+               r = buffer_append(&lem.header, wr->buf_ptr);
                if (r != 0)
                        return r;
 

diff --git a/src/logger/logger.c b/src/logger/logger.c
index 941b014..f7c9b34 100644 (file)
--- a/src/logger/logger.c
+++ b/src/logger/logger.c
@@ -65,15 +65,27 @@ static bool cond_reader_logger_free(void *ptr, void *user_data)
        return true;
 }
 
+// TODO: Consider inlining struct now_t everywhere
+int get_now(struct now_t *now)
+{
+       if (clock_gettime(CLOCK_MONOTONIC, &now->mono))
+               return -errno;
+       if (clock_gettime(CLOCK_REALTIME, &now->real))
+               return -errno;
+       return 0;
+}
+
 void qos_periodic_check(struct logger *server)
 {
        struct qos_module *const qos = &server->qos;
-       struct timespec const now = server->time.mono;
+       struct timespec ts_mono;
+       if (clock_gettime(CLOCK_MONOTONIC, &ts_mono))
+               return;
 
-       if (now.tv_sec < qos->cancel_limits_at.tv_sec)
+       if (ts_mono.tv_sec < qos->cancel_limits_at.tv_sec)
                return;
-       if (now.tv_sec == qos->cancel_limits_at.tv_sec
-       &&  now.tv_nsec < qos->cancel_limits_at.tv_nsec)
+       if (ts_mono.tv_sec == qos->cancel_limits_at.tv_sec
+       &&  ts_mono.tv_nsec < qos->cancel_limits_at.tv_nsec)
                return;
 
        if (metrics_get_total(qos->log_metrics) >= qos->threshold)
@@ -81,7 +93,7 @@ void qos_periodic_check(struct logger *server)
        else
                qos_relax_limits(qos);
 
-       qos_set_next_update_time(qos, now);
+       qos_set_next_update_time(qos, ts_mono);
        metrics_clear(qos->log_metrics);
 }
 
@@ -117,7 +129,11 @@ void check_if_fd_limit_reached(struct logger *server, int err)
                "DLOG",
                "\x1b[31m DLOG DAEMON FD LIMIT REACHED \x1b[0m" // make it stand out
        );
-       set_pipe_message_sent_timestamp((struct pipe_logger_entry *) &entry, &server->time.mono, &server->time.real);
+       struct now_t now;
+       int r = get_now(&now);
+       if (r < 0)
+               return;
+       set_pipe_message_sent_timestamp((struct pipe_logger_entry *) &entry, &now.mono, &now.real);
 
        if (buffer_append(&entry.header, buf))
                printf("ERROR: not enough memory either, please check platform settings as the daemon is seriously resource-starved!\n");
@@ -408,7 +424,13 @@ int service_writer_kmsg(struct logger *server, struct writer *wr, struct epoll_e
                        // don't signal an error: KMSG writer is too important to remove; besides, it would not get fixed that way.
                        return 0;
                }
-               add_recv_timestamp(&lem.header, server->time);
+
+               struct now_t now;
+               r = get_now(&now);
+               if (r < 0)
+                       return r;
+               add_recv_timestamp(&lem.header, now);
+
                r = buffer_append(&lem.header, wr->buf_ptr);
                if (r < 0)
                        return r;
@@ -434,8 +456,14 @@ static bool cond_service_reader_pipe(void *ptr, void *user_data)
        struct reader_pipe *reader = (struct reader_pipe *)ptr;
        struct logger *logger = (struct logger *)user_data;
 
-       int r = print_out_logs(reader, logger->time);
-
+       struct now_t now;
+       int r = get_now(&now);
+       if (r < 0) {
+               remove_reader_fd_entities(logger, &reader->common);
+               reader_pipe_free(reader);
+               return true;
+       }
+       r = print_out_logs(reader, now);
        if (r > 0) {
                remove_reader_fd_entities(logger, &reader->common);
                reader_pipe_free(reader);
@@ -462,7 +490,7 @@ static bool cond_service_reader_pipe(void *ptr, void *user_data)
                 * like we can do anything about it either */
        }
 
-       flush_logfile_timely(&reader->file, logger->time.mono, logger->buf_params.time);
+       flush_logfile_timely(&reader->file, now.mono, logger->buf_params.time);
 
        return false;
 }
@@ -474,7 +502,15 @@ static bool cond_service_reader_logger(void *ptr, void *user_data)
        struct reader_logger *reader = (struct reader_logger *)ptr;
        struct logger *logger = (struct logger *)user_data;
 
-       int r = service_reader_logger(reader, logger->time);
+       struct now_t now;
+       int r = get_now(&now);
+       if (r < 0) {
+               remove_reader_fd_entities(logger, &reader->common);
+               reader_logger_free(reader);
+               return true;
+       }
+
+       r = service_reader_logger(reader, now);
 
        if (r > 0) {
                remove_reader_fd_entities(logger, &reader->common);
@@ -502,7 +538,7 @@ static bool cond_service_reader_logger(void *ptr, void *user_data)
                 * like we can do anything about it either */
        }
 
-       reader_logger_flush(reader, logger->time.mono, logger->buf_params.time);
+       reader_logger_flush(reader, now.mono, logger->buf_params.time);
        return false;
 }
 
@@ -540,7 +576,12 @@ int service_writer_syslog(struct logger *server, struct writer *wr, struct epoll
                return 0;
        }
 
-       add_recv_timestamp(&lem.header, server->time);
+       struct now_t now;
+       r = get_now(&now);
+       if (r < 0)
+               return r;
+       add_recv_timestamp(&lem.header, now);
+
        return buffer_append(&lem.header, wr->buf_ptr);
 }
 
@@ -796,7 +837,7 @@ void dispatch_epoll_event(struct logger *server, struct epoll_event *event)
        entity->dispatch_event(server, event, entity->dispatch_data);
 }
 
-int handle_epoll_events_and_update_server_time(struct logger *server, struct epoll_metadata *metadata, int timeout)
+int handle_epoll_events(struct logger *server, struct epoll_metadata *metadata, int timeout)
 {
        ensure_epoll_size(&metadata->events, &metadata->events_size, metadata->cnt);
 
@@ -804,9 +845,6 @@ int handle_epoll_events_and_update_server_time(struct logger *server, struct epo
        if (nfds < 0)
                return errno == EINTR ? 0 : -errno;
 
-       clock_gettime(CLOCK_MONOTONIC, &server->time.mono);
-       clock_gettime(CLOCK_REALTIME, &server->time.real);
-
        for (int i = 0; i < nfds; i++)
                dispatch_epoll_event(server, metadata->events + i);
 
@@ -815,15 +853,20 @@ int handle_epoll_events_and_update_server_time(struct logger *server, struct epo
 
 int sleep_while_handling_socket(struct logger *server, struct epoll_metadata *metadata, int timeout)
 {
-       struct timespec start = server->time.mono;
+       struct timespec ts_start;
+       if (clock_gettime(CLOCK_MONOTONIC, &ts_start))
+               return -errno;
+       struct timespec ts_current;
 
        do {
-               int r = handle_epoll_events_and_update_server_time(server, metadata, timeout);
+               int r = handle_epoll_events(server, metadata, timeout);
                if (r < 0)
                        return r;
+               if (clock_gettime(CLOCK_MONOTONIC, &ts_current))
+                       return -errno;
        } while (
-               timeout > (server->time.mono.tv_sec  - start.tv_sec ) *  S_TO_MS
-                       + (server->time.mono.tv_nsec - start.tv_nsec) / MS_TO_NS
+               timeout > (ts_current.tv_sec  - ts_start.tv_sec ) *  S_TO_MS
+                       + (ts_current.tv_nsec - ts_start.tv_nsec) / MS_TO_NS
        );
 
        return 0;
@@ -857,9 +900,6 @@ int do_logger(struct logger *server)
 
        bool use_lazy_polling = true;
        while (g_logger_run) {
-               clock_gettime(CLOCK_MONOTONIC, &server->time.mono);
-               clock_gettime(CLOCK_REALTIME,  &server->time.real);
-
                if (server->lazy_polling_total >= 0) {
                        server->lazy_polling_total -= server->lazy_polling_sleep;
                        use_lazy_polling = (server->lazy_polling_total >= 0);
@@ -867,7 +907,7 @@ int do_logger(struct logger *server)
                if (use_lazy_polling)
                        sleep_while_handling_socket(server, &server->epoll_socket, server->lazy_polling_sleep);
 
-               int r = handle_epoll_events_and_update_server_time(server, &server->epoll_common, server->epolltime * !use_lazy_polling);
+               int r = handle_epoll_events(server, &server->epoll_common, server->epolltime * !use_lazy_polling);
                if (r < 0)
                        break;
 
@@ -1224,10 +1264,6 @@ static int finalize_init(struct logger_config_data *data, struct logger *server)
        if (r < 0)
                return r;
 
-       // used to populate the first readers
-       clock_gettime(CLOCK_MONOTONIC, &server->time.mono);
-       clock_gettime(CLOCK_REALTIME,  &server->time.real);
-
        //create files after resetting self privileges
        list_foreach(data->logfile_configs, server, parse_logfile_config);
 

diff --git a/src/logger/logger_internal.h b/src/logger/logger_internal.h
index 43db08c..28aa8d2 100644 (file)
--- a/src/logger/logger_internal.h
+++ b/src/logger/logger_internal.h
@@ -135,7 +135,6 @@ struct logger {
        struct log_buffer*    buffers[LOG_ID_MAX];
        struct buf_params     buf_params;
        int                   exiting;
-       struct now_t          time;
        struct qos_module     qos;
 };
 
@@ -166,6 +165,7 @@ void logger_add_writer(struct logger *l, struct writer *wr);
 int create_fifo_fds(struct logger *server, int pipe_fd[2], int flags, bool dump);
 int add_reader_pipe(struct logger *server, struct reader_pipe *reader);
 void flush_logfile_timely(struct log_file *file, struct timespec ts, int flush_time);
+int get_now(struct now_t *now);
 
 #ifdef __cplusplus
 }

diff --git a/src/logger/reader_logger.c b/src/logger/reader_logger.c
index 7c204ee..06dc88b 100644 (file)
--- a/src/logger/reader_logger.c
+++ b/src/logger/reader_logger.c
@@ -236,7 +236,15 @@ static void dispatch_event_reader_logger(struct logger *server, struct epoll_eve
                return;
        }
 
-       int r = service_reader_logger(rl, server->time);
+       struct now_t now;
+       int r = get_now(&now);
+       if (r < 0) {
+               remove_reader_fd_entities(server, &rl->common);
+               list_remove(&server->readers_logger, rl);
+               reader_logger_free(rl);
+       }
+
+       r = service_reader_logger(rl, now);
        if (r != 0) {
                /* TODO: There is no reason not to free the reader in full. However, when I do so, some tests start to
                 * fail without any reasonable reason. You are welcome to *try* to figure out why does this happen. */

diff --git a/src/logger/reader_pipe.c b/src/logger/reader_pipe.c
index 6e16516..d0fd091 100644 (file)
--- a/src/logger/reader_pipe.c
+++ b/src/logger/reader_pipe.c
@@ -36,7 +36,17 @@ static void dispatch_event_reader_pipe(struct logger *server, struct epoll_event
                return;
        }
 
-       int r = print_out_logs(rp, server->time);
+       struct now_t now;
+       int r = get_now(&now);
+       if (r < 0) {
+               remove_reader_fd_entities(server, &rp->common);
+               if (rp->buf_ptr)
+                       list_remove(&rp->buf_ptr->readers_pipe, rp);
+               reader_pipe_free(rp);
+               return;
+       }
+
+       r = print_out_logs(rp, now);
        if (r != 0) {
                /* TODO: There is no reason not to free the reader in full. However, when I do so, some tests start to
                 * fail without any reasonable reason. You are welcome to *try* to figure out why does this happen. */
@@ -72,7 +82,11 @@ int reader_pipe_init(struct reader_pipe **reader, log_id_t buf_id, struct logger
        assert(server);
        assert(filter);
 
-       __attribute__((cleanup(reader_pipe_cleanup))) struct reader_pipe *ret = reader_pipe_alloc(filter, file, server->time.mono, monitor, is_dumping);
+       struct timespec ts_mono;
+       if (clock_gettime(CLOCK_MONOTONIC, &ts_mono))
+               return -errno;
+
+       __attribute__((cleanup(reader_pipe_cleanup))) struct reader_pipe *ret = reader_pipe_alloc(filter, file, ts_mono, monitor, is_dumping);
        if (!ret)
                return -ENOMEM;
 
@@ -97,7 +111,11 @@ int reader_pipe_init_with_writer(struct reader_pipe **reader, struct writer *wri
        assert(server);
        assert(filter);
 
-       __attribute__((cleanup(reader_pipe_cleanup))) struct reader_pipe *ret = reader_pipe_alloc(filter, file, server->time.mono, monitor, is_dumping);
+       struct timespec ts_mono;
+       if (clock_gettime(CLOCK_MONOTONIC, &ts_mono))
+               return -errno;
+
+       __attribute__((cleanup(reader_pipe_cleanup))) struct reader_pipe *ret = reader_pipe_alloc(filter, file, ts_mono, monitor, is_dumping);
        if (!ret)
                return -ENOMEM;