From 11a6bf90b8ec4d04ac85b0246912f53c3a4c8af1 Mon Sep 17 00:00:00 2001 From: Harald Welte Date: Sun, 27 Sep 2020 17:15:10 +0200 Subject: logging: Avoid memcpy from stack to msgb in _file_output() For file and stderr output, the existing code always generates the log string on a stack buffer, and then (in case of non-blocking write via write_queue) copies it over to a msgb. Let's optimize this by turning _file_output() into a raw_output callback which first allocates the msgb and then format-prints directly to that msgb instaed of stack + memcpy. This has the disadvantage that we don't know how long the buffer has to be in order to print the entire string to it. As a result we always have to allocate a 4k-sized buffer (plus msgb overhead). The write_queue length for log file output has been decreased from 1024 entries to 156 entries in order to stay within the same memory requirements for each log target memory pool (about 648 kBytes). Change-Id: I0d10b0199576d2e7ff6421a6dba19ae5ffafd946 --- src/logging.c | 61 +++++++++++++++++++++++++++++++++++++++++------------------ 1 file changed, 43 insertions(+), 18 deletions(-) diff --git a/src/logging.c b/src/logging.c index fed24801..952869c3 100644 --- a/src/logging.c +++ b/src/logging.c @@ -66,7 +66,7 @@ #define MAX_LOG_SIZE 4096 /* maximum number of log statements we queue in file/stderr target write queue */ -#define LOG_WQUEUE_LEN 1024 +#define LOG_WQUEUE_LEN 156 osmo_static_assert(_LOG_CTX_COUNT <= ARRAY_SIZE(((struct log_context*)NULL)->ctx), enum_logging_ctx_items_fit_in_struct_log_context); @@ -398,12 +398,23 @@ static const char *const_basename(const char *path) return bn + 1; } -static void _output(struct log_target *target, unsigned int subsys, - unsigned int level, const char *file, int line, int cont, - const char *format, va_list ap) +/*! main output formatting function for log lines. + * \param[out] buf caller-allocated output buffer for the generated string + * \param[in] buf_len number of bytes availale in buf + * \param[in] target log target for which the string is to be formatted + * \param[in] subsys Log sub-system number + * \param[in] level Log level + * \param[in] file name of source code file generating the log + * \param[in] line line source code line number within 'file' generating the log + * \param[in] cont is this a continuation (true) or not (false) + * \param[in] format format string + * \param[in] ap variable argument list for format + * \returns number of bytes written to out */ +static int _output_buf(char *buf, int buf_len, struct log_target *target, unsigned int subsys, + unsigned int level, const char *file, int line, int cont, + const char *format, va_list ap) { - char buf[MAX_LOG_SIZE]; - int ret, len = 0, offset = 0, rem = sizeof(buf); + int ret, len = 0, offset = 0, rem = buf_len; const char *c_subsys = NULL; /* are we using color */ @@ -529,8 +540,21 @@ static void _output(struct log_target *target, unsigned int subsys, OSMO_SNPRINTF_RET(ret, rem, offset, len); } err: - buf[sizeof(buf)-1] = '\0'; - target->output(target, level, buf); + buf[buf_len-1] = '\0'; + return len; +} + +/* Format the log line for given target; use a stack buffer and call target->output */ +static void _output(struct log_target *target, unsigned int subsys, + unsigned int level, const char *file, int line, int cont, + const char *format, va_list ap) +{ + char buf[MAX_LOG_SIZE]; + int rc; + + rc = _output_buf(buf, sizeof(buf), target, subsys, level, file, line, cont, format, ap); + if (rc > 0) + target->output(target, level, buf); } /* Catch internal logging category indexes as well as out-of-bounds indexes. @@ -852,22 +876,22 @@ static void _file_output_stream(struct log_target *target, unsigned int level, } /* output via non-blocking write_queue, doing internal buffering */ -static void _file_output(struct log_target *target, unsigned int level, - const char *log) +static void _file_raw_output(struct log_target *target, int subsys, unsigned int level, const char *file, + int line, int cont, const char *format, va_list ap) { - int len = strlen(log); struct msgb *msg; + int rc; OSMO_ASSERT(target->tgt_file.wqueue); - msg = msgb_alloc_c(target->tgt_file.wqueue, len, "log_file_msg"); + msg = msgb_alloc_c(target->tgt_file.wqueue, MAX_LOG_SIZE, "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); + rc = _output_buf((char *)msgb_data(msg), msgb_tailroom(msg), target, subsys, level, file, line, cont, format, ap); + msgb_put(msg, rc); osmo_wqueue_enqueue_quiet(target->tgt_file.wqueue, msg); } #endif @@ -1009,7 +1033,7 @@ int log_target_file_switch_to_wqueue(struct log_target *target) * 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)); + LOG_WQUEUE_LEN*(sizeof(struct msgb)+MAX_LOG_SIZE)); if (!wq) return -ENOMEM; osmo_wqueue_init(wq, LOG_WQUEUE_LEN); @@ -1034,7 +1058,8 @@ int log_target_file_switch_to_wqueue(struct log_target *target) return -EIO; } target->tgt_file.wqueue = wq; - target->output = _file_output; + target->raw_output = _file_raw_output; + target->output = NULL; /* now that everything succeeded, we can finally close the old output stream */ if (target->type == LOG_TGT_TYPE_FILE) @@ -1063,7 +1088,7 @@ struct log_target *log_target_create_file(const char *fname) * 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)); + LOG_WQUEUE_LEN*(sizeof(struct msgb)+MAX_LOG_SIZE)); if (!wq) { log_target_destroy(target); return NULL; @@ -1086,7 +1111,7 @@ struct log_target *log_target_create_file(const char *fname) } target->tgt_file.wqueue = wq; - target->output = _file_output; + target->raw_output = _file_raw_output; target->tgt_file.fname = talloc_strdup(target, fname); return target; -- cgit v1.2.3