From 32009cb6eb8f53333e56c96050896a6645d68f50 Mon Sep 17 00:00:00 2001
From: Maria Matejka <mq@ucw.cz>
Date: Wed, 16 Aug 2023 15:05:36 +0200
Subject: [PATCH] Logging: Abolished stdio in favor of write() to make the
 logging faster.

---
 filter/data.c        |   2 +-
 filter/f-inst.c      |   9 ++-
 filter/filter.c      |  10 +--
 lib/birdlib.h        |  18 +++--
 lib/timer.c          |   5 +-
 nest/cmds.c          |   2 +-
 proto/bgp/bgp.c      |   2 +-
 sysdep/unix/config.Y |   9 +--
 sysdep/unix/io.c     |  40 ++++++----
 sysdep/unix/log.c    | 179 ++++++++++++++++++++++---------------------
 sysdep/unix/main.c   |  19 +++--
 sysdep/unix/unix.h   |  14 +++-
 12 files changed, 165 insertions(+), 144 deletions(-)

diff --git a/filter/data.c b/filter/data.c
index f104d2f8..ce8d7561 100644
--- a/filter/data.c
+++ b/filter/data.c
@@ -598,7 +598,7 @@ val_format(const struct f_val *v, buffer *buf)
 char *
 val_format_str(struct linpool *lp, const struct f_val *v) {
   buffer b;
-  LOG_BUFFER_INIT(b);
+  STACK_BUFFER_INIT(b, 1024);
   val_format(v, &b);
   return lp_strdup(lp, b.start);
 }
diff --git a/filter/f-inst.c b/filter/f-inst.c
index caffc2b8..4d0974e9 100644
--- a/filter/f-inst.c
+++ b/filter/f-inst.c
@@ -656,15 +656,20 @@
     VARARG;
 
     if (whati->varcount && !(fs->flags & FF_SILENT))
+    {
+      if (!fs->buf.class)
+	log_prepare(&fs->buf, *L_INFO);
+
       for (uint i=0; i<whati->varcount; i++)
-	val_format(&(vv(i)), &fs->buf);
+	val_format(&(vv(i)), &fs->buf.buf);
+    }
   }
 
   INST(FI_FLUSH, 0, 0) {
     NEVER_CONSTANT;
     if (!(fs->flags & FF_SILENT))
       /* After log_commit, the buffer is reset */
-      log_commit(*L_INFO, &fs->buf);
+      log_commit(&fs->buf);
   }
 
   INST(FI_DIE, 0, 0) {
diff --git a/filter/filter.c b/filter/filter.c
index 0aff4d30..931bc85e 100644
--- a/filter/filter.c
+++ b/filter/filter.c
@@ -77,7 +77,7 @@ struct filter_state {
   struct rte *rte;
 
   /* Buffer for log output */
-  struct buffer buf;
+  log_buffer buf;
 
   /* Filter execution flags */
   int flags;
@@ -219,8 +219,6 @@ f_run(const struct filter *filter, struct rte *rte, int flags)
 
   f_stack_init(filter_state);
 
-  LOG_BUFFER_INIT(filter_state.buf);
-
   /* Run the interpreter itself */
   enum filter_return fret = interpret(&filter_state, filter->root, NULL);
 
@@ -256,8 +254,6 @@ f_eval_rte(const struct f_line *expr, struct rte *rte)
 
   f_stack_init(filter_state);
 
-  LOG_BUFFER_INIT(filter_state.buf);
-
   ASSERT(!rta_is_cached(rte->attrs));
 
   return interpret(&filter_state, expr, NULL);
@@ -276,8 +272,6 @@ f_eval(const struct f_line *expr, struct f_val *pres)
 
   f_stack_init(filter_state);
 
-  LOG_BUFFER_INIT(filter_state.buf);
-
   enum filter_return fret = interpret(&filter_state, expr, pres);
   return fret;
 }
@@ -297,8 +291,6 @@ f_eval_int(const struct f_line *expr)
 
   struct f_val val;
 
-  LOG_BUFFER_INIT(filter_state.buf);
-
   if (interpret(&filter_state, expr, &val) > F_RETURN)
     cf_error("Runtime error while evaluating expression; see log for details");
 
diff --git a/lib/birdlib.h b/lib/birdlib.h
index 2eec5c0f..8146e63b 100644
--- a/lib/birdlib.h
+++ b/lib/birdlib.h
@@ -151,6 +151,16 @@ typedef struct buffer {
   byte *end;
 } buffer;
 
+#define LOG_BUFFER_SIZE 2560
+
+typedef struct log_buffer {
+  struct buffer buf;
+  byte *tm_pos;
+  byte *msg_pos;
+  int class;
+  char block[LOG_BUFFER_SIZE];
+} log_buffer;
+
 #define STACK_BUFFER_INIT(buf,size)		\
   do {						\
     buf.start = alloca(size);			\
@@ -158,13 +168,9 @@ typedef struct buffer {
     buf.end = buf.start + size;			\
   } while(0)
 
-#define LOG_BUFFER_INIT(buf)			\
-  STACK_BUFFER_INIT(buf, LOG_BUFFER_SIZE)
-
-#define LOG_BUFFER_SIZE 1024
-
 #define log log_msg
-void log_commit(int class, buffer *buf);
+void log_prepare(log_buffer *buf, int class);
+void log_commit(log_buffer *buf);
 void log_msg(const char *msg, ...);
 void log_rl(struct tbf *rl, const char *msg, ...);
 void die(const char *msg, ...) NORET;
diff --git a/lib/timer.c b/lib/timer.c
index 4e4aa55e..d64a3921 100644
--- a/lib/timer.c
+++ b/lib/timer.c
@@ -323,8 +323,5 @@ tm_format_real_time(char *x, size_t max, const char *fmt, btime t)
   if (!strfusec(tbuf, tbuf_size, fmt, t2))
     return 0;
 
-  if (!strftime(x, max, tbuf, &tm))
-    return 0;
-
-  return 1;
+  return strftime(x, max, tbuf, &tm);
 }
diff --git a/nest/cmds.c b/nest/cmds.c
index 6717be0c..4805b5a2 100644
--- a/nest/cmds.c
+++ b/nest/cmds.c
@@ -134,7 +134,7 @@ void
 cmd_eval(const struct f_line *expr)
 {
   buffer buf;
-  LOG_BUFFER_INIT(buf);
+  STACK_BUFFER_INIT(buf, CLI_MSG_SIZE);
 
   if (f_eval_buf(expr, &buf) > F_RETURN)
     {
diff --git a/proto/bgp/bgp.c b/proto/bgp/bgp.c
index c98f84ab..3a7ed6b7 100644
--- a/proto/bgp/bgp.c
+++ b/proto/bgp/bgp.c
@@ -2532,7 +2532,7 @@ static void
 bgp_show_afis(int code, char *s, u32 *afis, uint count)
 {
   buffer b;
-  LOG_BUFFER_INIT(b);
+  STACK_BUFFER_INIT(b, CLI_MSG_SIZE);
 
   buffer_puts(&b, s);
 
diff --git a/sysdep/unix/config.Y b/sysdep/unix/config.Y
index a50ec757..b1d60906 100644
--- a/sysdep/unix/config.Y
+++ b/sysdep/unix/config.Y
@@ -52,15 +52,14 @@ log_file:
    text log_limit {
      if (!parse_and_exit)
      {
-       this_log->rf = rf_open(new_config->pool, $1, "a");
+       this_log->rf = rf_open(new_config->pool, $1, RF_APPEND);
        if (!this_log->rf) cf_error("Unable to open log file '%s': %m", $1);
-       this_log->fh = rf_file(this_log->rf);
      }
      this_log->pos = -1;
      this_log->filename = $1;
    }
- | SYSLOG syslog_name { this_log->fh = NULL; new_config->syslog_name = $2; }
- | STDERR { this_log->fh = stderr; }
+ | SYSLOG syslog_name { this_log->rf = NULL; new_config->syslog_name = $2; }
+ | STDERR { this_log->rf = &rf_stderr; }
  ;
 
 log_mask:
@@ -93,7 +92,7 @@ mrtdump_base:
  | MRTDUMP text ';' {
      if (!parse_and_exit)
      {
-       struct rfile *f = rf_open(new_config->pool, $2, "a");
+       struct rfile *f = rf_open(new_config->pool, $2, RF_APPEND);
        if (!f) cf_error("Unable to open MRTDump file '%s': %m", $2);
        new_config->mrtdump_file = rf_fileno(f);
      }
diff --git a/sysdep/unix/io.c b/sysdep/unix/io.c
index b21df057..74f3fc71 100644
--- a/sysdep/unix/io.c
+++ b/sysdep/unix/io.c
@@ -64,7 +64,11 @@
 
 struct rfile {
   resource r;
-  FILE *f;
+  int fd;
+};
+
+struct rfile rf_stderr = {
+  .fd = 2,
 };
 
 static void
@@ -72,7 +76,7 @@ rf_free(resource *r)
 {
   struct rfile *a = (struct rfile *) r;
 
-  fclose(a->f);
+  close(a->fd);
 }
 
 static void
@@ -80,7 +84,7 @@ rf_dump(resource *r, unsigned indent UNUSED)
 {
   struct rfile *a = (struct rfile *) r;
 
-  debug("(FILE *%p)\n", a->f);
+  debug("(fd %d)\n", a->fd);
 }
 
 static struct resclass rf_class = {
@@ -93,28 +97,34 @@ static struct resclass rf_class = {
 };
 
 struct rfile *
-rf_open(pool *p, const char *name, const char *mode)
+rf_open(pool *p, const char *name, enum rf_mode mode)
 {
-  FILE *f = fopen(name, mode);
+  int omode = S_IRUSR | S_IWUSR | S_IRGRP | S_IWGRP | S_IROTH | S_IWOTH;
+  int flags;
 
-  if (!f)
-    return NULL;
+  switch (mode)
+  {
+    case RF_APPEND:
+      flags = O_WRONLY | O_CREAT | O_APPEND;
+      break;
+
+    default:
+      bug("rf_open() must have the mode set");
+  }
+
+  int fd = open(name, flags, omode);
+  if (fd < 0)
+    return NULL; /* The caller takes care of printing %m. */
 
   struct rfile *r = ralloc(p, &rf_class);
-  r->f = f;
+  r->fd = fd;
   return r;
 }
 
-void *
-rf_file(struct rfile *f)
-{
-  return f->f;
-}
-
 int
 rf_fileno(struct rfile *f)
 {
-  return fileno(f->f);
+  return f->fd;
 }
 
 
diff --git a/sysdep/unix/log.c b/sysdep/unix/log.c
index 5a1241dc..b5159914 100644
--- a/sysdep/unix/log.c
+++ b/sysdep/unix/log.c
@@ -32,8 +32,7 @@
 #include "lib/lists.h"
 #include "sysdep/unix/unix.h"
 
-static int dbg_fd = -1;
-static FILE *dbgf;
+static struct rfile *dbg_rf;
 static list *current_log_list;
 static char *current_syslog_name; /* NULL -> syslog closed */
 
@@ -46,6 +45,12 @@ static pthread_mutex_t log_mutex;
 static inline void log_lock(void) { pthread_mutex_lock(&log_mutex); }
 static inline void log_unlock(void) { pthread_mutex_unlock(&log_mutex); }
 
+/* Logging flags to validly prepare logging messages */
+#define LOGGING_TO_TERMINAL   0x1
+#define LOGGING_TO_FILE	      0x2
+
+static _Atomic uint logging_flags;
+
 #ifdef HAVE_SYSLOG_H
 #include <sys/syslog.h>
 
@@ -86,15 +91,16 @@ log_size(struct log_config *l)
 static void
 log_close(struct log_config *l)
 {
-  rfree(l->rf);
+  if (l->rf != &rf_stderr)
+    rfree(l->rf);
+
   l->rf = NULL;
-  l->fh = NULL;
 }
 
 static int
 log_open(struct log_config *l)
 {
-  l->rf = rf_open(config->pool, l->filename, "a");
+  l->rf = rf_open(config->pool, l->filename, RF_APPEND);
   if (!l->rf)
   {
     /* Well, we cannot do much in case of error as log is closed */
@@ -102,7 +108,6 @@ log_open(struct log_config *l)
     return -1;
   }
 
-  l->fh = rf_file(l->rf);
   l->pos = log_size(l);
 
   return 0;
@@ -125,6 +130,8 @@ log_rotate(struct log_config *l)
   return log_open(l);
 }
 
+#define LOG_MSG_OFFSET	(TM_DATETIME_BUFFER_SIZE + 64)
+
 /**
  * log_commit - commit a log message
  * @class: message class information (%L_DEBUG to %L_BUG, see |lib/birdlib.h|)
@@ -139,69 +146,83 @@ log_rotate(struct log_config *l)
  * in log(), so it should be written like *L_INFO.
  */
 void
-log_commit(int class, buffer *buf)
+log_commit(log_buffer *buf)
 {
   struct log_config *l;
 
-  if (buf->pos == buf->end)
-    strcpy(buf->end - 100, " ... <too long>");
+  if (buf->buf.pos == buf->buf.end)
+#define TOO_LONG " ... <too long>"
+    memcpy(buf->buf.end - sizeof TOO_LONG, TOO_LONG, sizeof TOO_LONG);
+#undef TOO_LONG
 
   log_lock();
   WALK_LIST(l, *current_log_list)
     {
-      if (!(l->mask & (1 << class)))
+      if (!(l->mask & (1 << buf->class)))
 	continue;
-      if (l->fh)
+      if (l->rf && buf->tm_pos)
 	{
-	  if (l->terminal_flag)
-	    fputs("bird: ", l->fh);
-	  else
-	    {
-	      byte tbuf[TM_DATETIME_BUFFER_SIZE];
-	      const char *fmt = config ? config->tf_log.fmt1 : "%F %T.%3f";
-	      if (!tm_format_real_time(tbuf, sizeof(tbuf), fmt, current_real_time()))
-		strcpy(tbuf, "<error>");
+	  *buf->buf.pos = '\n';
+	  byte *begin = l->terminal_flag ? buf->buf.start : buf->tm_pos;
+	  off_t msg_len = buf->buf.pos - begin + 1;
+	  if (l->limit && (l->pos + msg_len > l->limit) && (log_rotate(l) < 0))
+	    continue;
 
-	      if (l->limit)
-	      {
-		off_t msg_len = strlen(tbuf) + strlen(class_names[class]) +
-		  (buf->pos - buf->start) + 5;
-
-		if (l->pos < 0)
-		  l->pos = log_size(l);
-
-		if (l->pos + msg_len > l->limit)
-		  if (log_rotate(l) < 0)
-		    continue;
-
-		l->pos += msg_len;
-	      }
-
-	      fprintf(l->fh, "%s [%04x] <%s> ", tbuf, THIS_THREAD_ID, class_names[class]);
-	    }
-	  fputs(buf->start, l->fh);
-	  fputc('\n', l->fh);
-	  fflush(l->fh);
+	  l->pos += msg_len;
+	  while ((write(rf_fileno(l->rf), buf->tm_pos, msg_len) < 0) && (errno == EINTR))
+	    ;
 	}
 #ifdef HAVE_SYSLOG_H
       else
-	syslog(syslog_priorities[class], "%s", buf->start);
+      {
+	*buf->buf.pos = '\0';
+	syslog(syslog_priorities[buf->class], "%s", buf->msg_pos);
+      }
 #endif
     }
   log_unlock();
 
-  buf->pos = buf->start;
+  buf->msg_pos = buf->tm_pos = NULL;
 }
 
 int buffer_vprint(buffer *buf, const char *fmt, va_list args);
 
+void
+log_prepare(log_buffer *buf, int class)
+{
+  buf->buf.start = buf->buf.pos = buf->block;
+  buf->buf.end = buf->block + sizeof buf->block;
+
+  int lf = atomic_load_explicit(&logging_flags, memory_order_acquire);
+  if (lf & LOGGING_TO_TERMINAL)
+    buffer_puts(&buf->buf, "bird: ");
+
+  if (lf & LOGGING_TO_FILE)
+  {
+    const char *fmt = config ? config->tf_log.fmt1 : "%F %T.%3f";
+
+    buf->tm_pos = buf->buf.pos;
+    int t = tm_format_real_time(buf->buf.pos, buf->buf.end - buf->buf.pos, fmt, current_real_time());
+    if (t)
+      buf->buf.pos += t;
+    else
+      buffer_puts(&buf->buf, "<time format error>");
+
+    buffer_print(&buf->buf, " [%04x] <%s> ", THIS_THREAD_ID, class_names[class]);
+  }
+
+  buf->msg_pos = buf->buf.pos;
+  buf->class = class;
+}
+
 static void
 vlog(int class, const char *msg, va_list args)
 {
-  buffer buf;
-  LOG_BUFFER_INIT(buf);
-  buffer_vprint(&buf, msg, args);
-  log_commit(class, &buf);
+  static _Thread_local log_buffer buf;
+
+  log_prepare(&buf, class);
+  buffer_vprint(&buf.buf, msg, args);
+  log_commit(&buf);
 }
 
 
@@ -301,33 +322,13 @@ debug(const char *msg, ...)
   int max = MAX_DEBUG_BUFSIZE;
 
   va_start(args, msg);
-  if (dbgf)
+  if (dbg_rf)
     {
-#if 0
-      struct timespec dbg_time;
-      clock_gettime(CLOCK_MONOTONIC, &dbg_time);
-      uint nsec;
-      uint sec;
-
-      if (dbg_time.tv_nsec > dbg_time_start.tv_nsec)
-      {
-	nsec = dbg_time.tv_nsec - dbg_time_start.tv_nsec;
-	sec = dbg_time.tv_sec - dbg_time_start.tv_sec;
-      }
-      else
-      {
-	nsec = 1000000000 + dbg_time.tv_nsec - dbg_time_start.tv_nsec;
-	sec = dbg_time.tv_sec - dbg_time_start.tv_sec - 1;
-      }
-
-      int n = bsnprintf(pos, max, "%u.%09u: [%04x] ", sec, nsec, THIS_THREAD_ID);
-      pos += n;
-      max -= n;
-#endif
-      if (bvsnprintf(pos, max, msg, args) < 0)
+      int s = bvsnprintf(pos, max, msg, args);
+      if (s < 0)
 	bug("Extremely long debug output, split it.");
 
-      fputs(buf, dbgf);
+      write(rf_fileno(dbg_rf), buf, s);
     }
   va_end(args);
 }
@@ -343,8 +344,8 @@ debug(const char *msg, ...)
 void
 debug_safe(const char *msg)
 {
-  if (dbg_fd >= 0)
-    write(dbg_fd, msg, strlen(msg));
+  if (dbg_rf)
+    write(rf_fileno(dbg_rf), msg, strlen(msg));
 }
 
 static list *
@@ -355,7 +356,7 @@ default_log_list(int initial, const char **syslog_name)
   *syslog_name = NULL;
 
 #ifdef HAVE_SYSLOG_H
-  if (!dbgf)
+  if (!dbg_rf)
     {
       static struct log_config lc_syslog;
       lc_syslog = (struct log_config){
@@ -367,24 +368,24 @@ default_log_list(int initial, const char **syslog_name)
     }
 #endif
 
-  if (dbgf && (dbgf != stderr))
+  if (dbg_rf && (dbg_rf != &rf_stderr))
     {
       static struct log_config lc_debug;
       lc_debug = (struct log_config){
 	.mask = ~0,
-	.fh = dbgf
+	.rf = dbg_rf,
       };
 
       add_tail(&log_list, &lc_debug.n);
     }
 
-  if (initial || (dbgf == stderr))
+  if (initial || (dbg_rf == &rf_stderr))
     {
       static struct log_config lc_stderr;
       lc_stderr = (struct log_config){
 	.mask = ~0,
 	.terminal_flag = 1,
-	.fh = stderr
+	.rf = &rf_stderr,
       };
 
       add_tail(&log_list, &lc_stderr.n);
@@ -411,10 +412,19 @@ log_switch(int initial, list *logs, const char *new_syslog_name)
 	log_close(l);
 
   /* Reopen the logs, needed for 'configure undo' */
+  uint flags = 0;
   if (logs)
     WALK_LIST(l, *logs)
+    {
+      if (l->terminal_flag)
+	flags |= LOGGING_TO_TERMINAL;
       if (l->filename && !l->rf)
 	log_open(l);
+      if (l->rf)
+	flags |= LOGGING_TO_FILE;
+    }
+
+  atomic_store_explicit(&logging_flags, flags, memory_order_release);
 
   current_log_list = logs;
 
@@ -447,24 +457,17 @@ log_init_debug(char *f)
 {
   clock_gettime(CLOCK_MONOTONIC, &dbg_time_start);
 
-  dbg_fd = -1;
-  if (dbgf && dbgf != stderr)
-    fclose(dbgf);
+  if (dbg_rf && dbg_rf != &rf_stderr)
+    close(rf_fileno(dbg_rf));
 
   if (!f)
-    dbgf = NULL;
+    dbg_rf = NULL;
   else if (!*f)
-    dbgf = stderr;
-  else if (!(dbgf = fopen(f, "a")))
+    dbg_rf = &rf_stderr;
+  else if (!(dbg_rf = rf_open(&root_pool, f, RF_APPEND)))
   {
     /* Cannot use die() nor log() here, logging is not yet initialized */
     fprintf(stderr, "bird: Unable to open debug file %s: %s\n", f, strerror(errno));
     exit(1);
   }
-
-  if (dbgf)
-  {
-    setvbuf(dbgf, NULL, _IONBF, 0);
-    dbg_fd = fileno(dbgf);
-  }
 }
diff --git a/sysdep/unix/main.c b/sysdep/unix/main.c
index 738efe46..57a57e52 100644
--- a/sysdep/unix/main.c
+++ b/sysdep/unix/main.c
@@ -202,9 +202,10 @@ sysdep_preconfig(struct config *c)
 int
 sysdep_commit(struct config *new, struct config *old)
 {
-  log_switch(0, &new->logfiles, new->syslog_name);
-  bird_thread_commit(new, old);
+  if (!new->shutdown)
+    log_switch(0, &new->logfiles, new->syslog_name);
 
+  bird_thread_commit(new, old);
   return 0;
 }
 
@@ -893,14 +894,12 @@ main(int argc, char **argv)
     dmalloc_debug(0x2f03d00);
 #endif
 
-  times_update();
-  parse_args(argc, argv);
-  log_switch(1, NULL, NULL);
-
+  /* Prepare necessary infrastructure */
   the_bird_lock();
-
-  random_init();
+  times_update();
   resource_init();
+  random_init();
+
   birdloop_init();
   olock_init();
   rt_init();
@@ -909,6 +908,10 @@ main(int argc, char **argv)
 //  roa_init();
   config_init();
 
+  /* Arguments and logs */
+  parse_args(argc, argv);
+  log_switch(1, NULL, NULL);
+
   uid_t use_uid = get_uid(use_user);
   gid_t use_gid = get_gid(use_group);
 
diff --git a/sysdep/unix/unix.h b/sysdep/unix/unix.h
index 5262f3bb..66a3118a 100644
--- a/sysdep/unix/unix.h
+++ b/sysdep/unix/unix.h
@@ -114,9 +114,16 @@ void io_init(void);
 void io_loop(void);
 void io_log_dump(void);
 int sk_open_unix(struct birdsock *s, struct birdloop *, char *name);
-struct rfile *rf_open(struct pool *, const char *name, const char *mode);
-void *rf_file(struct rfile *f);
+
+enum rf_mode {
+  RF_APPEND,
+};
+
+struct rfile *rf_open(struct pool *, const char *name, enum rf_mode mode);
 int rf_fileno(struct rfile *f);
+
+extern struct rfile rf_stderr;
+
 void test_old_bird(char *path);
 
 /* krt.c bits */
@@ -131,8 +138,7 @@ void log_switch(int initial, list *l, const char *);
 struct log_config {
   node n;
   uint mask;				/* Classes to log */
-  void *fh;				/* FILE to log to, NULL=syslog */
-  struct rfile *rf;			/* Resource for log file */
+  struct rfile *rf;			/* Resource for log file; NULL=syslog */
   const char *filename;			/* Log filename */
   const char *backup;			/* Secondary filename (for log rotation) */
   off_t pos;				/* Position/size of current log */