<p>laforge has uploaded this change for <strong>review</strong>.</p><p><a href="https://gerrit.osmocom.org/c/libosmocore/+/20305">View Change</a></p><pre style="font-family: monospace,monospace; white-space: pre-wrap;">logging: Avoid memcpy from stack to msgb in _file_output()<br><br>For file and stderr output, the existing code always generates<br>the log string on a stack buffer, and then (in case of non-blocking<br>write via write_queue) copies it over to a msgb.<br><br>Let's optimize this by turning _file_output() into a raw_output<br>callback which first allocates the msgb and then format-prints<br>directly to that msgb instaed of stack + memcpy.<br><br>This has the disadvantage that we don't know how long the buffer<br>has to be in order to print the entire string to it. As a result<br>we always have to allocate a 4k-sized buffer (plus msgb overhead).<br><br>The write_queue length for log file output has been decreased from<br>1024 entries to 156 entries in order to stay within the same<br>memory requirements for each log target memory pool (about 648 kBytes).<br><br>Change-Id: I0d10b0199576d2e7ff6421a6dba19ae5ffafd946<br>---<br>M src/logging.c<br>1 file changed, 41 insertions(+), 17 deletions(-)<br><br></pre><pre style="font-family: monospace,monospace; white-space: pre-wrap;">git pull ssh://gerrit.osmocom.org:29418/libosmocore refs/changes/05/20305/1</pre><pre style="font-family: monospace,monospace; white-space: pre-wrap;"><span>diff --git a/src/logging.c b/src/logging.c</span><br><span>index 4c0ea58..952c350 100644</span><br><span>--- a/src/logging.c</span><br><span>+++ b/src/logging.c</span><br><span>@@ -66,7 +66,7 @@</span><br><span> #define MAX_LOG_SIZE 4096</span><br><span> </span><br><span> /* maximum number of log statements we queue in file/stderr target write queue */</span><br><span style="color: hsl(0, 100%, 40%);">-#define LOG_WQUEUE_LEN 1024</span><br><span style="color: hsl(120, 100%, 40%);">+#define LOG_WQUEUE_LEN 156</span><br><span> </span><br><span> osmo_static_assert(_LOG_CTX_COUNT <= ARRAY_SIZE(((struct log_context*)NULL)->ctx),</span><br><span> enum_logging_ctx_items_fit_in_struct_log_context);</span><br><span>@@ -398,12 +398,23 @@</span><br><span> return bn + 1;</span><br><span> }</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">-static void _output(struct log_target *target, unsigned int subsys,</span><br><span style="color: hsl(0, 100%, 40%);">- unsigned int level, const char *file, int line, int cont,</span><br><span style="color: hsl(0, 100%, 40%);">- const char *format, va_list ap)</span><br><span style="color: hsl(120, 100%, 40%);">+/*! main output formatting function for log lines.</span><br><span style="color: hsl(120, 100%, 40%);">+ * \param[out] buf caller-allocated output buffer for the generated string</span><br><span style="color: hsl(120, 100%, 40%);">+ * \param[in] buf_len number of bytes availale in buf</span><br><span style="color: hsl(120, 100%, 40%);">+ * \param[in] target log target for which the string is to be formatted</span><br><span style="color: hsl(120, 100%, 40%);">+ * \param[in] subsys Log sub-system number</span><br><span style="color: hsl(120, 100%, 40%);">+ * \param[in] level Log level</span><br><span style="color: hsl(120, 100%, 40%);">+ * \param[in] file name of source code file generating the log</span><br><span style="color: hsl(120, 100%, 40%);">+ * \param[in] line line source code line number within 'file' generating the log</span><br><span style="color: hsl(120, 100%, 40%);">+ * \param[in] cont is this a continuation (true) or not (false)</span><br><span style="color: hsl(120, 100%, 40%);">+ * \param[in] format format string</span><br><span style="color: hsl(120, 100%, 40%);">+ * \param[in] ap variable argument list for format</span><br><span style="color: hsl(120, 100%, 40%);">+ * \returns number of bytes written to out */</span><br><span style="color: hsl(120, 100%, 40%);">+static int _output_buf(char *buf, int buf_len, struct log_target *target, unsigned int subsys,</span><br><span style="color: hsl(120, 100%, 40%);">+ unsigned int level, const char *file, int line, int cont,</span><br><span style="color: hsl(120, 100%, 40%);">+ const char *format, va_list ap)</span><br><span> {</span><br><span style="color: hsl(0, 100%, 40%);">- char buf[MAX_LOG_SIZE];</span><br><span style="color: hsl(0, 100%, 40%);">- int ret, len = 0, offset = 0, rem = sizeof(buf);</span><br><span style="color: hsl(120, 100%, 40%);">+ int ret, len = 0, offset = 0, rem = buf_len;</span><br><span> const char *c_subsys = NULL;</span><br><span> </span><br><span> /* are we using color */</span><br><span>@@ -529,8 +540,20 @@</span><br><span> OSMO_SNPRINTF_RET(ret, rem, offset, len);</span><br><span> }</span><br><span> err:</span><br><span style="color: hsl(0, 100%, 40%);">- buf[sizeof(buf)-1] = '\0';</span><br><span style="color: hsl(0, 100%, 40%);">- target->output(target, level, buf, len);</span><br><span style="color: hsl(120, 100%, 40%);">+ buf[buf_len-1] = '\0';</span><br><span style="color: hsl(120, 100%, 40%);">+ return len;</span><br><span style="color: hsl(120, 100%, 40%);">+}</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+/* Format the log line for given target; use a stack buffer and call target->output */</span><br><span style="color: hsl(120, 100%, 40%);">+static void _output(struct log_target *target, unsigned int subsys,</span><br><span style="color: hsl(120, 100%, 40%);">+ unsigned int level, const char *file, int line, int cont,</span><br><span style="color: hsl(120, 100%, 40%);">+ const char *format, va_list ap)</span><br><span style="color: hsl(120, 100%, 40%);">+{</span><br><span style="color: hsl(120, 100%, 40%);">+ char buf[MAX_LOG_SIZE];</span><br><span style="color: hsl(120, 100%, 40%);">+ int rc;</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+ rc = _output_buf(buf, sizeof(buf), target, subsys, level, file, line, cont, format, ap);</span><br><span style="color: hsl(120, 100%, 40%);">+ target->output(target, level, buf, rc);</span><br><span> }</span><br><span> </span><br><span> /* Catch internal logging category indexes as well as out-of-bounds indexes.</span><br><span>@@ -853,21 +876,21 @@</span><br><span> }</span><br><span> </span><br><span> /* output via non-blocking write_queue, doing internal buffering */</span><br><span style="color: hsl(0, 100%, 40%);">-static void _file_output(struct log_target *target, unsigned int level,</span><br><span style="color: hsl(0, 100%, 40%);">- const char *log, int len)</span><br><span style="color: hsl(120, 100%, 40%);">+static void _file_raw_output(struct log_target *target, int subsys, unsigned int level, const char *file,</span><br><span style="color: hsl(120, 100%, 40%);">+ int line, int cont, const char *format, va_list ap)</span><br><span> {</span><br><span> struct msgb *msg;</span><br><span> </span><br><span> OSMO_ASSERT(target->tgt_file.wqueue);</span><br><span style="color: hsl(0, 100%, 40%);">- msg = msgb_alloc_c(target->tgt_file.wqueue, len, "log_file_msg");</span><br><span style="color: hsl(120, 100%, 40%);">+ msg = msgb_alloc_c(target->tgt_file.wqueue, MAX_LOG_SIZE, "log_file_msg");</span><br><span> if (!msg)</span><br><span> return;</span><br><span> </span><br><span> /* we simply enqueue the log message to a write queue here, to avoid any blocking</span><br><span> * writes on the output file. The write queue will tell us once the file is writable</span><br><span> * and call _file_wq_write_cb() */</span><br><span style="color: hsl(0, 100%, 40%);">- memcpy(msg->data, log, len);</span><br><span style="color: hsl(0, 100%, 40%);">- msgb_put(msg, len);</span><br><span style="color: hsl(120, 100%, 40%);">+ rc = _output_buf((char *)msgb_data(msg), msgb_tailroom(msg), target, subsys, level, file, line, cont, format, ap);</span><br><span style="color: hsl(120, 100%, 40%);">+ msgb_put(msg, rc);</span><br><span> osmo_wqueue_enqueue_quiet(target->tgt_file.wqueue, msg);</span><br><span> }</span><br><span> #endif</span><br><span>@@ -1009,7 +1032,7 @@</span><br><span> * log lines (stored as msgbs) will not put result in malloc() calls, and also to</span><br><span> * reduce the OOM probability within logging, as the pool is already allocated */</span><br><span> wq = talloc_pooled_object(target, struct osmo_wqueue, LOG_WQUEUE_LEN,</span><br><span style="color: hsl(0, 100%, 40%);">- LOG_WQUEUE_LEN*(sizeof(struct msgb)+512));</span><br><span style="color: hsl(120, 100%, 40%);">+ LOG_WQUEUE_LEN*(sizeof(struct msgb)+MAX_LOG_SIZE));</span><br><span> if (!wq)</span><br><span> return -ENOMEM;</span><br><span> osmo_wqueue_init(wq, LOG_WQUEUE_LEN);</span><br><span>@@ -1034,7 +1057,8 @@</span><br><span> return -EIO;</span><br><span> }</span><br><span> target->tgt_file.wqueue = wq;</span><br><span style="color: hsl(0, 100%, 40%);">- target->output = _file_output;</span><br><span style="color: hsl(120, 100%, 40%);">+ target->raw_output = _file_raw_output;</span><br><span style="color: hsl(120, 100%, 40%);">+ target->output = NULL;</span><br><span> </span><br><span> /* now that everything succeeded, we can finally close the old output stream */</span><br><span> if (target->type == LOG_TGT_TYPE_FILE)</span><br><span>@@ -1063,7 +1087,7 @@</span><br><span> * log lines (stored as msgbs) will not put result in malloc() calls, and also to</span><br><span> * reduce the OOM probability within logging, as the pool is already allocated */</span><br><span> wq = talloc_pooled_object(target, struct osmo_wqueue, LOG_WQUEUE_LEN,</span><br><span style="color: hsl(0, 100%, 40%);">- LOG_WQUEUE_LEN*(sizeof(struct msgb)+512));</span><br><span style="color: hsl(120, 100%, 40%);">+ LOG_WQUEUE_LEN*(sizeof(struct msgb)+MAX_LOG_SIZE));</span><br><span> if (!wq) {</span><br><span> log_target_destroy(target);</span><br><span> return NULL;</span><br><span>@@ -1086,7 +1110,7 @@</span><br><span> }</span><br><span> </span><br><span> target->tgt_file.wqueue = wq;</span><br><span style="color: hsl(0, 100%, 40%);">- target->output = _file_output;</span><br><span style="color: hsl(120, 100%, 40%);">+ target->raw_output = _file_raw_output;</span><br><span> target->tgt_file.fname = talloc_strdup(target, fname);</span><br><span> </span><br><span> return target;</span><br><span></span><br></pre><p>To view, visit <a href="https://gerrit.osmocom.org/c/libosmocore/+/20305">change 20305</a>. To unsubscribe, or for help writing mail filters, visit <a href="https://gerrit.osmocom.org/settings">settings</a>.</p><div itemscope itemtype="http://schema.org/EmailMessage"><div itemscope itemprop="action" itemtype="http://schema.org/ViewAction"><link itemprop="url" href="https://gerrit.osmocom.org/c/libosmocore/+/20305"/><meta itemprop="name" content="View Change"/></div></div>
<div style="display:none"> Gerrit-Project: libosmocore </div>
<div style="display:none"> Gerrit-Branch: master </div>
<div style="display:none"> Gerrit-Change-Id: I0d10b0199576d2e7ff6421a6dba19ae5ffafd946 </div>
<div style="display:none"> Gerrit-Change-Number: 20305 </div>
<div style="display:none"> Gerrit-PatchSet: 1 </div>
<div style="display:none"> Gerrit-Owner: laforge <laforge@osmocom.org> </div>
<div style="display:none"> Gerrit-MessageType: newchange </div>