From a90633904b804c80f4694db75124de132ca425c3 Mon Sep 17 00:00:00 2001 From: Harald Welte Date: Sat, 26 Sep 2020 21:45:16 +0200 Subject: logging: Change stderr + file target to use non-blocking write So far, we used blocking, buffered fwrite() to write to stderr and file targets. This causes problems if there are [slow] consumers causing delays, such as gnome-terminal (when the program is started interactively) or systemd/journald (where we observe 64..128ms blocks on stderr). This patch introduces stderr/file based logging via write_queue and osmo_select_main(), i.e. switch from glibc-buffered, blocking to internally buffered, non-blocking writes. Closes: OS#4311 Change-Id: Ia58fd78535c41b3da3aeb7733aadc785ace610da --- include/osmocom/core/logging.h | 4 + src/logging.c | 221 ++++++++++++++++++++++++++++++++++++++--- src/select.c | 4 + 3 files changed, 215 insertions(+), 14 deletions(-) diff --git a/include/osmocom/core/logging.h b/include/osmocom/core/logging.h index 36ce941c..6c1199ae 100644 --- a/include/osmocom/core/logging.h +++ b/include/osmocom/core/logging.h @@ -289,8 +289,11 @@ struct log_target { union { struct { + /* direct, blocking output via stdio */ FILE *out; const char *fname; + /* indirect output via write_queue and osmo_select_main() */ + struct osmo_wqueue *wqueue; } tgt_file; struct { @@ -393,6 +396,7 @@ struct log_target *log_target_create_gsmtap(const char *host, uint16_t port, bool ofd_wq_mode, bool add_sink); int log_target_file_reopen(struct log_target *tgt); +int log_target_file_switch_to_wqueue(struct log_target *tgt); int log_targets_reopen(void); void log_add_target(struct log_target *target); diff --git a/src/logging.c b/src/logging.c index e018916a..fed24801 100644 --- a/src/logging.c +++ b/src/logging.c @@ -35,6 +35,7 @@ #include #include #include +#include #ifdef HAVE_STRINGS_H #include @@ -46,6 +47,9 @@ #include #include +#include +#include +#include #include #include @@ -53,12 +57,17 @@ #include #include #include +#include +#include #include /* for LOGGING_STR. */ /* maximum length of the log string of a single log event (typically line), including NUL termination */ #define MAX_LOG_SIZE 4096 +/* maximum number of log statements we queue in file/stderr target write queue */ +#define LOG_WQUEUE_LEN 1024 + osmo_static_assert(_LOG_CTX_COUNT <= ARRAY_SIZE(((struct log_context*)NULL)->ctx), enum_logging_ctx_items_fit_in_struct_log_context); osmo_static_assert(_LOG_FLT_COUNT <= ARRAY_SIZE(((struct log_target*)NULL)->filter_data), @@ -834,12 +843,33 @@ void log_set_category_filter(struct log_target *target, int category, } #if (!EMBEDDED) -static void _file_output(struct log_target *target, unsigned int level, +static void _file_output_stream(struct log_target *target, unsigned int level, const char *log) { + OSMO_ASSERT(target->tgt_file.out); fprintf(target->tgt_file.out, "%s", log); fflush(target->tgt_file.out); } + +/* output via non-blocking write_queue, doing internal buffering */ +static void _file_output(struct log_target *target, unsigned int level, + const char *log) +{ + int len = strlen(log); + struct msgb *msg; + + OSMO_ASSERT(target->tgt_file.wqueue); + msg = msgb_alloc_c(target->tgt_file.wqueue, len, "log_file_msg"); + if (!msg) + return; + + /* we simply enqueue the log message to a write queue here, to avoid any blocking + * writes on the output file. The write queue will tell us once the file is writable + * and call _file_wq_write_cb() */ + memcpy(msg->data, log, len); + msgb_put(msg, len); + osmo_wqueue_enqueue_quiet(target->tgt_file.wqueue, msg); +} #endif /*! Create a new log target skeleton @@ -901,7 +931,7 @@ struct log_target *log_target_create_stderr(void) target->type = LOG_TGT_TYPE_STDERR; target->tgt_file.out = stderr; - target->output = _file_output; + target->output = _file_output_stream; return target; #else return NULL; @@ -909,11 +939,28 @@ struct log_target *log_target_create_stderr(void) } #if (!EMBEDDED) -/*! Create a new file-based log target +/* write-queue tells us we should write another msgb (log line) to the output fd */ +static int _file_wq_write_cb(struct osmo_fd *ofd, struct msgb *msg) +{ + int rc; + + rc = write(ofd->fd, msgb_data(msg), msgb_length(msg)); + if (rc < 0) + return rc; + if (rc != msgb_length(msg)) { + /* pull the number of bytes we have already written */ + msgb_pull(msg, rc); + /* ask write_queue to re-insert the msgb at the head of the queue */ + return -EAGAIN; + } + return 0; +} + +/*! Create a new file-based log target using buffered, blocking stream output * \param[in] fname File name of the new log file * \returns Log target in case of success, NULL otherwise */ -struct log_target *log_target_create_file(const char *fname) +struct log_target *log_target_create_file_stream(const char *fname) { struct log_target *target; @@ -927,9 +974,119 @@ struct log_target *log_target_create_file(const char *fname) log_target_destroy(target); return NULL; } + target->output = _file_output_stream; + target->tgt_file.fname = talloc_strdup(target, fname); + + return target; +} +/*! switch from blocking + buffered file output to non-blocking write-queue based output. + * \param[in] target log target which we should switch + * \return 0 on success; 1 if already switched before; negative on error */ +int log_target_file_switch_to_wqueue(struct log_target *target) +{ + struct osmo_wqueue *wq; + int rc; + + if (!target) + return -ENODEV; + + /* this only works for file/stderr targets */ + switch (target->type) { + case LOG_TGT_TYPE_FILE: + case LOG_TGT_TYPE_STDERR: + break; + default: + return -EINVAL; + } + + if (!target->tgt_file.out) { + /* target has already been switched over */ + return 1; + } + + /* we create a ~640kB sized talloc pool within the write-queue to ensure individual + * log lines (stored as msgbs) will not put result in malloc() calls, and also to + * reduce the OOM probability within logging, as the pool is already allocated */ + wq = talloc_pooled_object(target, struct osmo_wqueue, LOG_WQUEUE_LEN, + LOG_WQUEUE_LEN*(sizeof(struct msgb)+512)); + if (!wq) + return -ENOMEM; + osmo_wqueue_init(wq, LOG_WQUEUE_LEN); + + fflush(target->tgt_file.out); + if (target->type == LOG_TGT_TYPE_FILE) { + rc = open(target->tgt_file.fname, O_WRONLY|O_APPEND|O_NONBLOCK, 0660); + if (rc < 0) { + talloc_free(wq); + return -errno; + } + } else { + rc = STDERR_FILENO; + } + wq->bfd.fd = rc; + wq->bfd.when = OSMO_FD_WRITE; + wq->write_cb = _file_wq_write_cb; + + rc = osmo_fd_register(&wq->bfd); + if (rc < 0) { + talloc_free(wq); + return -EIO; + } + target->tgt_file.wqueue = wq; target->output = _file_output; + /* now that everything succeeded, we can finally close the old output stream */ + if (target->type == LOG_TGT_TYPE_FILE) + fclose(target->tgt_file.out); + target->tgt_file.out = NULL; + + return 0; +} + +/*! Create a new file-based log target using non-blocking write_queue + * \param[in] fname File name of the new log file + * \returns Log target in case of success, NULL otherwise + */ +struct log_target *log_target_create_file(const char *fname) +{ + struct log_target *target; + struct osmo_wqueue *wq; + int rc; + + target = log_target_create(); + if (!target) + return NULL; + + target->type = LOG_TGT_TYPE_FILE; + /* we create a ~640kB sized talloc pool within the write-queue to ensure individual + * log lines (stored as msgbs) will not put result in malloc() calls, and also to + * reduce the OOM probability within logging, as the pool is already allocated */ + wq = talloc_pooled_object(target, struct osmo_wqueue, LOG_WQUEUE_LEN, + LOG_WQUEUE_LEN*(sizeof(struct msgb)+512)); + if (!wq) { + log_target_destroy(target); + return NULL; + } + osmo_wqueue_init(wq, LOG_WQUEUE_LEN); + wq->bfd.fd = open(fname, O_WRONLY|O_APPEND|O_NONBLOCK, 0660); + if (wq->bfd.fd < 0) { + talloc_free(wq); + log_target_destroy(target); + return NULL; + } + wq->bfd.when = OSMO_FD_WRITE; + wq->write_cb = _file_wq_write_cb; + + rc = osmo_fd_register(&wq->bfd); + if (rc < 0) { + talloc_free(wq); + log_target_destroy(target); + return NULL; + } + + target->tgt_file.wqueue = wq; + target->output = _file_output; target->tgt_file.fname = talloc_strdup(target, fname); return target; @@ -969,17 +1126,33 @@ struct log_target *log_target_find(int type, const char *fname) * \param[in] target log target to unregister, close and delete */ void log_target_destroy(struct log_target *target) { - /* just in case, to make sure we don't have any references */ log_del_target(target); #if (!EMBEDDED) + struct osmo_wqueue *wq; switch (target->type) { case LOG_TGT_TYPE_FILE: - if (target->tgt_file.out == NULL) - break; - fclose(target->tgt_file.out); - target->tgt_file.out = NULL; + case LOG_TGT_TYPE_STDERR: + if (target->tgt_file.out) { + if (target->type == LOG_TGT_TYPE_FILE) + fclose(target->tgt_file.out); + target->tgt_file.out = NULL; + } + wq = target->tgt_file.wqueue; + if (wq) { + if (wq->bfd.fd >= 0) { + if (target->type == LOG_TGT_TYPE_FILE) + close(wq->bfd.fd); + wq->bfd.fd = -1; + } + osmo_fd_unregister(&wq->bfd); + osmo_wqueue_clear(wq); + talloc_free(wq); + target->tgt_file.wqueue = NULL; + } + talloc_free((void *)target->tgt_file.fname); + target->tgt_file.fname = NULL; break; #ifdef HAVE_SYSLOG_H case LOG_TGT_TYPE_SYSLOG: @@ -1000,13 +1173,33 @@ void log_target_destroy(struct log_target *target) * \returns 0 in case of success; negative otherwise */ int log_target_file_reopen(struct log_target *target) { - fclose(target->tgt_file.out); + struct osmo_wqueue *wq; + int rc; - target->tgt_file.out = fopen(target->tgt_file.fname, "a"); - if (!target->tgt_file.out) - return -errno; + OSMO_ASSERT(target->type == LOG_TGT_TYPE_FILE || target->type == LOG_TGT_TYPE_STDERR); + OSMO_ASSERT(target->tgt_file.out || target->tgt_file.wqueue); - /* we assume target->output already to be set */ + if (target->tgt_file.out) { + fclose(target->tgt_file.out); + target->tgt_file.out = fopen(target->tgt_file.fname, "a"); + if (!target->tgt_file.out) + return -errno; + } else { + wq = target->tgt_file.wqueue; + osmo_fd_unregister(&wq->bfd); + if (wq->bfd.fd >= 0) { + close(wq->bfd.fd); + wq->bfd.fd = -1; + } + + rc = open(target->tgt_file.fname, O_WRONLY|O_APPEND|O_NONBLOCK, 0660); + if (rc < 0) + return -errno; + wq->bfd.fd = rc; + rc = osmo_fd_register(&wq->bfd); + if (rc < 0) + return rc; + } return 0; } diff --git a/src/select.c b/src/select.c index 496beea9..17f409f6 100644 --- a/src/select.c +++ b/src/select.c @@ -38,6 +38,7 @@ #include #include #include +#include #include "../config.h" @@ -277,6 +278,9 @@ int osmo_select_main(int polling) osmo_panic("You cannot use the 'select' volatile " "context if you don't use osmo_select_main_ctx()!\n"); } + /* We now know this application is using osmo_select_main() and hence can switch the stderr + * log target from buffered, stream based I/O to non-blocking write-queue */ + log_target_file_switch_to_wqueue(osmo_stderr_target); #endif return rc; } -- cgit v1.2.3