<p>laforge has uploaded this change for <strong>review</strong>.</p><p><a href="https://gerrit.osmocom.org/c/libosmocore/+/20317">View Change</a></p><pre style="font-family: monospace,monospace; white-space: pre-wrap;">logging: Attempt a synchronous, non-blocking write first (file, stderr)<br><br>In the old days, we performed synchronous, blocking writes to the log<br>file or stderr.  This was replaced by code that turned all log<br>file/stderr writes into non-blocking writes behind a write_queue.<br><br>This patch now introduces a further optimization: If we currently<br>don't have any log messages pending in the write queue, we are not<br>back-logged and assume we have a fair chance of writing the log message<br>right now, synchronously.  So we try that first, and only enqueue<br>the log message if the write fails (no bytes or insufficient number<br>of bytes written).<br><br>This way we should get the best of both worlds: No delay/re-ordering<br>(and lower select syscall load) for the "normal" case (benefits of<br>the old synchronous writes) while at the same time never risking to<br>block on log output.<br><br>Change-Id: I08469a7e4be9bc5bbd39140457bb582f4a0b1703<br>---<br>M src/logging.c<br>1 file changed, 30 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/17/20317/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 b538754..3d05bef 100644</span><br><span>--- a/src/logging.c</span><br><span>+++ b/src/logging.c</span><br><span>@@ -867,6 +867,24 @@</span><br><span> }</span><br><span> </span><br><span> #if (!EMBEDDED)</span><br><span style="color: hsl(120, 100%, 40%);">+/* write-queue tells us we should write another msgb (log line) to the output fd */</span><br><span style="color: hsl(120, 100%, 40%);">+static int _file_wq_write_cb(struct osmo_fd *ofd, struct msgb *msg)</span><br><span style="color: hsl(120, 100%, 40%);">+{</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 = write(ofd->fd, msgb_data(msg), msgb_length(msg));</span><br><span style="color: hsl(120, 100%, 40%);">+     if (rc < 0)</span><br><span style="color: hsl(120, 100%, 40%);">+                return rc;</span><br><span style="color: hsl(120, 100%, 40%);">+    if (rc != msgb_length(msg)) {</span><br><span style="color: hsl(120, 100%, 40%);">+         /* pull the number of bytes we have already written */</span><br><span style="color: hsl(120, 100%, 40%);">+                msgb_pull(msg, rc);</span><br><span style="color: hsl(120, 100%, 40%);">+           /* ask write_queue to re-insert the msgb at the head of the queue */</span><br><span style="color: hsl(120, 100%, 40%);">+          return -EAGAIN;</span><br><span style="color: hsl(120, 100%, 40%);">+       }</span><br><span style="color: hsl(120, 100%, 40%);">+     return 0;</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%);">+/* output via buffered, blocking stdio streams */</span><br><span> static void _file_output_stream(struct log_target *target, unsigned int level,</span><br><span>                   const char *log)</span><br><span> {</span><br><span>@@ -892,6 +910,18 @@</span><br><span>         * and call _file_wq_write_cb() */</span><br><span>   rc = _output_buf((char *)msgb_data(msg), msgb_tailroom(msg), target, subsys, level, file, line, cont, format, ap);</span><br><span>   msgb_put(msg, rc);</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+  /* attempt a synchronous, non-blocking write, if the write queue is empty */</span><br><span style="color: hsl(120, 100%, 40%);">+  if (target->tgt_file.wqueue->current_length == 0) {</span><br><span style="color: hsl(120, 100%, 40%);">+             rc = _file_wq_write_cb(&target->tgt_file.wqueue->bfd, msg);</span><br><span style="color: hsl(120, 100%, 40%);">+         if (rc == 0) {</span><br><span style="color: hsl(120, 100%, 40%);">+                        /* the write was complete, we can exit early */</span><br><span style="color: hsl(120, 100%, 40%);">+                       msgb_free(msg);</span><br><span style="color: hsl(120, 100%, 40%);">+                       return;</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%);">+     /* if we reach here, either we already had elements in the write_queue, or the synchronous write</span><br><span style="color: hsl(120, 100%, 40%);">+       * failed: enqueue the message to the write_queue (backlog) */</span><br><span>       osmo_wqueue_enqueue_quiet(target->tgt_file.wqueue, msg);</span><br><span> }</span><br><span> #endif</span><br><span>@@ -963,23 +993,6 @@</span><br><span> }</span><br><span> </span><br><span> #if (!EMBEDDED)</span><br><span style="color: hsl(0, 100%, 40%);">-/* write-queue tells us we should write another msgb (log line) to the output fd */</span><br><span style="color: hsl(0, 100%, 40%);">-static int _file_wq_write_cb(struct osmo_fd *ofd, struct msgb *msg)</span><br><span style="color: hsl(0, 100%, 40%);">-{</span><br><span style="color: hsl(0, 100%, 40%);">-    int rc;</span><br><span style="color: hsl(0, 100%, 40%);">-</span><br><span style="color: hsl(0, 100%, 40%);">- rc = write(ofd->fd, msgb_data(msg), msgb_length(msg));</span><br><span style="color: hsl(0, 100%, 40%);">-       if (rc < 0)</span><br><span style="color: hsl(0, 100%, 40%);">-          return rc;</span><br><span style="color: hsl(0, 100%, 40%);">-      if (rc != msgb_length(msg)) {</span><br><span style="color: hsl(0, 100%, 40%);">-           /* pull the number of bytes we have already written */</span><br><span style="color: hsl(0, 100%, 40%);">-          msgb_pull(msg, rc);</span><br><span style="color: hsl(0, 100%, 40%);">-             /* ask write_queue to re-insert the msgb at the head of the queue */</span><br><span style="color: hsl(0, 100%, 40%);">-            return -EAGAIN;</span><br><span style="color: hsl(0, 100%, 40%);">- }</span><br><span style="color: hsl(0, 100%, 40%);">-       return 0;</span><br><span style="color: hsl(0, 100%, 40%);">-}</span><br><span style="color: hsl(0, 100%, 40%);">-</span><br><span> /*! Create a new file-based log target using buffered, blocking stream output</span><br><span>  *  \param[in] fname File name of the new log file</span><br><span>  *  \returns Log target in case of success, NULL otherwise</span><br><span></span><br></pre><p>To view, visit <a href="https://gerrit.osmocom.org/c/libosmocore/+/20317">change 20317</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/+/20317"/><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: I08469a7e4be9bc5bbd39140457bb582f4a0b1703 </div>
<div style="display:none"> Gerrit-Change-Number: 20317 </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>