From: Mateusz Majewski Date: Tue, 27 Apr 2021 08:06:28 +0000 (+0200) Subject: Stop caching the timestamp in the server X-Git-Tag: accepted/tizen/unified/20210505.141516~5 X-Git-Url: http://review.tizen.org/git/?a=commitdiff_plain;h=refs%2Fchanges%2F33%2F257533%2F4;p=platform%2Fcore%2Fsystem%2Fdlog.git 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 --- 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 --- 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 --- 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 --- 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 --- 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;