This is merely a historical archive of years 2008-2021, before the migration to mailman3.
A maintained and still updated list archive can be found at https://lists.osmocom.org/hyperkitty/list/gerrit-log@lists.osmocom.org/.
laforge gerrit-no-reply at lists.osmocom.orglaforge has uploaded this change for review. ( https://gerrit.osmocom.org/c/libosmocore/+/20296 ) Change subject: logging: Change stderr + file target to use non-blocking write ...................................................................... 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 --- M include/osmocom/core/logging.h M src/logging.c M src/select.c 3 files changed, 208 insertions(+), 15 deletions(-) git pull ssh://gerrit.osmocom.org:29418/libosmocore refs/changes/96/20296/1 diff --git a/include/osmocom/core/logging.h b/include/osmocom/core/logging.h index 36ce941..6c1199a 100644 --- a/include/osmocom/core/logging.h +++ b/include/osmocom/core/logging.h @@ -289,8 +289,11 @@ 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 @@ 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 212b0b9..6bab54e 100644 --- a/src/logging.c +++ b/src/logging.c @@ -35,6 +35,7 @@ #include <stdlib.h> #include <stdio.h> #include <string.h> +#include <unistd.h> #ifdef HAVE_STRINGS_H #include <strings.h> @@ -46,6 +47,9 @@ #include <time.h> #include <sys/time.h> +#include <sys/types.h> +#include <sys/stat.h> +#include <fcntl.h> #include <errno.h> #include <pthread.h> @@ -53,9 +57,14 @@ #include <osmocom/core/utils.h> #include <osmocom/core/logging.h> #include <osmocom/core/timer.h> +#include <osmocom/core/select.h> +#include <osmocom/core/write_queue.h> #include <osmocom/vty/logging.h> /* for LOGGING_STR. */ +/* 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), @@ -831,11 +840,33 @@ } #if (!EMBEDDED) +/* output via buffered, blocking stdio streams */ +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) { - fprintf(target->tgt_file.out, "%s", log); - fflush(target->tgt_file.out); + unsigned 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 @@ -884,6 +915,83 @@ return 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)) + return -EIO; + return 0; +} + +/*! 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 the STDERR log target * \returns dynamically-allocated \ref log_target for STDERR */ struct log_target *log_target_create_stderr(void) @@ -898,7 +1006,7 @@ 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; @@ -906,11 +1014,11 @@ } #if (!EMBEDDED) -/*! Create a new file-based log target +/*! 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; @@ -924,9 +1032,55 @@ log_target_destroy(target); return NULL; } + target->output = _file_output_stream; + target->tgt_file.fname = talloc_strdup(target, fname); + return target; +} + +/*! 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; @@ -966,6 +1120,7 @@ * \param[in] target log target to unregister, close and delete */ void log_target_destroy(struct log_target *target) { + struct osmo_wqueue *wq; /* just in case, to make sure we don't have any references */ log_del_target(target); @@ -973,10 +1128,20 @@ #if (!EMBEDDED) 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; + if (target->tgt_file.out) { + fclose(target->tgt_file.out); + target->tgt_file.out = NULL; + } + wq = target->tgt_file.wqueue; + if (wq) { + close(wq->bfd.fd); + 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: @@ -997,13 +1162,33 @@ * \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 496beea..17f409f 100644 --- a/src/select.c +++ b/src/select.c @@ -38,6 +38,7 @@ #include <osmocom/core/logging.h> #include <osmocom/core/talloc.h> #include <osmocom/core/utils.h> +#include <osmocom/core/application.h> #include "../config.h" @@ -277,6 +278,9 @@ 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; } -- To view, visit https://gerrit.osmocom.org/c/libosmocore/+/20296 To unsubscribe, or for help writing mail filters, visit https://gerrit.osmocom.org/settings Gerrit-Project: libosmocore Gerrit-Branch: master Gerrit-Change-Id: Ia58fd78535c41b3da3aeb7733aadc785ace610da Gerrit-Change-Number: 20296 Gerrit-PatchSet: 1 Gerrit-Owner: laforge <laforge at osmocom.org> Gerrit-MessageType: newchange -------------- next part -------------- An HTML attachment was scrubbed... URL: <http://lists.osmocom.org/pipermail/gerrit-log/attachments/20200927/0d006fbf/attachment.htm>