Merge commit 'a4451535' into thread-next

6 files changed, 282 insertions, 69 deletions

diff --git a/sysdep/unix/Makefile b/sysdep/unix/Makefile
index 51ab98a9..a01e8f46 100644
--- a/sysdep/unix/Makefile
+++ b/sysdep/unix/Makefile
@@ -1,4 +1,4 @@
-src := alloc.c io.c krt.c log.c main.c random.c
+src := alloc.c io.c krt.c log.c main.c random.c coroutine.c
 obj := $(src-o-files)
 $(all-daemon)
 $(cf-local)
diff --git a/sysdep/unix/coroutine.c b/sysdep/unix/coroutine.c
new file mode 100644
index 00000000..2eba142c
--- /dev/null
+++ b/sysdep/unix/coroutine.c
@@ -0,0 +1,179 @@
+/*
+ *	BIRD Coroutines
+ *
+ *	(c) 2017 Martin Mares <mj@ucw.cz>
+ *	(c) 2020 Maria Matejka <mq@jmq.cz>
+ *
+ *	Can be freely distributed and used under the terms of the GNU GPL.
+ */
+
+#ifndef _GNU_SOURCE
+#define _GNU_SOURCE
+#endif
+
+#undef LOCAL_DEBUG
+
+#undef DEBUG_LOCKING
+
+#include "lib/birdlib.h"
+#include "lib/locking.h"
+#include "lib/coro.h"
+#include "lib/resource.h"
+#include "lib/timer.h"
+
+/* Using a rather big stack for coroutines to allow for stack-local allocations.
+ * In real world, the kernel doesn't alloc this memory until it is used.
+ * */
+#define CORO_STACK_SIZE	1048576
+
+/*
+ *	Implementation of coroutines based on POSIX threads
+ */
+
+#include <errno.h>
+#include <fcntl.h>
+#include <poll.h>
+#include <pthread.h>
+#include <semaphore.h>
+#include <stdatomic.h>
+#include <stdlib.h>
+#include <string.h>
+#include <unistd.h>
+
+/*
+ *	Locking subsystem
+ */
+
+_Thread_local struct lock_order locking_stack = {};
+_Thread_local struct domain_generic **last_locked = NULL;
+
+#define ASSERT_NO_LOCK	ASSERT_DIE(last_locked == NULL)
+
+struct domain_generic {
+  pthread_mutex_t mutex;
+  uint order;
+  struct domain_generic **prev;
+  struct lock_order *locked_by;
+  const char *name;
+};
+
+#define DOMAIN_INIT(_name, _order) { .mutex = PTHREAD_MUTEX_INITIALIZER, .name = _name, .order = _order }
+
+static struct domain_generic the_bird_domain_gen = DOMAIN_INIT("The BIRD", OFFSETOF(struct lock_order, the_bird));
+
+DOMAIN(the_bird) the_bird_domain = { .the_bird = &the_bird_domain_gen };
+
+struct domain_generic *
+domain_new(const char *name, uint order)
+{
+  ASSERT_DIE(order < sizeof(struct lock_order));
+  struct domain_generic *dg = xmalloc(sizeof(struct domain_generic));
+  *dg = (struct domain_generic) DOMAIN_INIT(name, order);
+  return dg;
+}
+
+void
+domain_free(struct domain_generic *dg)
+{
+  pthread_mutex_destroy(&dg->mutex);
+  xfree(dg);
+}
+
+void do_lock(struct domain_generic *dg, struct domain_generic **lsp)
+{
+  if ((char *) lsp - (char *) &locking_stack != dg->order)
+    bug("Trying to lock on bad position: order=%u, lsp=%p, base=%p", dg->order, lsp, &locking_stack);
+
+  if (lsp <= last_locked)
+    bug("Trying to lock in a bad order");
+  if (*lsp)
+    bug("Inconsistent locking stack state on lock");
+
+  pthread_mutex_lock(&dg->mutex);
+
+  if (dg->prev || dg->locked_by)
+    bug("Previous unlock not finished correctly");
+  dg->prev = last_locked;
+  *lsp = dg;
+  last_locked = lsp;
+  dg->locked_by = &locking_stack;
+}
+
+void do_unlock(struct domain_generic *dg, struct domain_generic **lsp)
+{
+  if ((char *) lsp - (char *) &locking_stack != dg->order)
+    bug("Trying to unlock on bad position: order=%u, lsp=%p, base=%p", dg->order, lsp, &locking_stack);
+
+  if (dg->locked_by != &locking_stack)
+    bug("Inconsistent domain state on unlock");
+  if ((last_locked != lsp) || (*lsp != dg))
+    bug("Inconsistent locking stack state on unlock");
+  dg->locked_by = NULL;
+  last_locked = dg->prev;
+  *lsp = NULL;
+  dg->prev = NULL;
+  pthread_mutex_unlock(&dg->mutex);
+}
+
+/* Coroutines */
+struct coroutine {
+  resource r;
+  pthread_t id;
+  pthread_attr_t attr;
+  void (*entry)(void *);
+  void *data;
+};
+
+static _Thread_local _Bool coro_cleaned_up = 0;
+
+static void coro_free(resource *r)
+{
+  struct coroutine *c = (void *) r;
+  ASSERT_DIE(pthread_equal(pthread_self(), c->id));
+  pthread_attr_destroy(&c->attr);
+  coro_cleaned_up = 1;
+}
+
+static struct resclass coro_class = {
+  .name = "Coroutine",
+  .size = sizeof(struct coroutine),
+  .free = coro_free,
+};
+
+static void *coro_entry(void *p)
+{
+  struct coroutine *c = p;
+  ASSERT_DIE(c->entry);
+
+  c->entry(c->data);
+  ASSERT_DIE(coro_cleaned_up);
+
+  return NULL;
+}
+
+struct coroutine *coro_run(pool *p, void (*entry)(void *), void *data)
+{
+  ASSERT_DIE(entry);
+  ASSERT_DIE(p);
+
+  struct coroutine *c = ralloc(p, &coro_class);
+
+  c->entry = entry;
+  c->data = data;
+
+  int e = 0;
+
+  if (e = pthread_attr_init(&c->attr))
+    die("pthread_attr_init() failed: %M", e);
+
+  if (e = pthread_attr_setstacksize(&c->attr, CORO_STACK_SIZE))
+    die("pthread_attr_setstacksize(%u) failed: %M", CORO_STACK_SIZE, e);
+
+  if (e = pthread_attr_setdetachstate(&c->attr, PTHREAD_CREATE_DETACHED))
+    die("pthread_attr_setdetachstate(PTHREAD_CREATE_DETACHED) failed: %M", e);
+
+  if (e = pthread_create(&c->id, &c->attr, coro_entry, c))
+    die("pthread_create() failed: %M", e);
+
+  return c;
+}
diff --git a/sysdep/unix/io.c b/sysdep/unix/io.c
index 810e782d..a3f1491a 100644
--- a/sysdep/unix/io.c
+++ b/sysdep/unix/io.c
@@ -36,6 +36,7 @@
 #include "lib/resource.h"
 #include "lib/socket.h"
 #include "lib/event.h"
+#include "lib/locking.h"
 #include "lib/timer.h"
 #include "lib/string.h"
 #include "nest/iface.h"
@@ -122,55 +123,50 @@ rf_fileno(struct rfile *f)
 
 btime boot_time;
 
+
 void
-times_init(struct timeloop *loop)
+times_update(void)
 {
   struct timespec ts;
   int rv;
 
+  btime old_time = current_time();
+  btime old_real_time = current_real_time();
+
   rv = clock_gettime(CLOCK_MONOTONIC, &ts);
   if (rv < 0)
     die("Monotonic clock is missing");
 
   if ((ts.tv_sec < 0) || (((u64) ts.tv_sec) > ((u64) 1 << 40)))
     log(L_WARN "Monotonic clock is crazy");
-
-  loop->last_time = ts.tv_sec S + ts.tv_nsec NS;
-  loop->real_time = 0;
-}
-
-void
-times_update(struct timeloop *loop)
-{
-  struct timespec ts;
-  int rv;
-
-  rv = clock_gettime(CLOCK_MONOTONIC, &ts);
-  if (rv < 0)
-    die("clock_gettime: %m");
-
+  
   btime new_time = ts.tv_sec S + ts.tv_nsec NS;
 
-  if (new_time < loop->last_time)
+  if (new_time < old_time)
     log(L_ERR "Monotonic clock is broken");
 
-  loop->last_time = new_time;
-  loop->real_time = 0;
-}
-
-void
-times_update_real_time(struct timeloop *loop)
-{
-  struct timespec ts;
-  int rv;
-
   rv = clock_gettime(CLOCK_REALTIME, &ts);
   if (rv < 0)
     die("clock_gettime: %m");
 
-  loop->real_time = ts.tv_sec S + ts.tv_nsec NS;
-}
+  btime new_real_time = ts.tv_sec S + ts.tv_nsec NS;
+
+  if (!atomic_compare_exchange_strong_explicit(
+      &last_time,
+      &old_time,
+      new_time,
+      memory_order_acq_rel,
+      memory_order_relaxed))
+    DBG("Time update collision: last_time");
 
+  if (!atomic_compare_exchange_strong_explicit(
+      &real_time,
+      &old_real_time,
+      new_real_time,
+      memory_order_acq_rel,
+      memory_order_relaxed))
+    DBG("Time update collision: real_time");
+}
 
 /**
  * DOC: Sockets
@@ -2037,30 +2033,17 @@ struct event_log_entry
 static struct event_log_entry event_log[EVENT_LOG_LENGTH];
 static struct event_log_entry *event_open;
 static int event_log_pos, event_log_num, watchdog_active;
-static btime last_time;
+static btime last_io_time;
 static btime loop_time;
 
 static void
 io_update_time(void)
 {
-  struct timespec ts;
-  int rv;
-
-  /*
-   * This is third time-tracking procedure (after update_times() above and
-   * times_update() in BFD), dedicated to internal event log and latency
-   * tracking. Hopefully, we consolidate these sometimes.
-   */
-
-  rv = clock_gettime(CLOCK_MONOTONIC, &ts);
-  if (rv < 0)
-    die("clock_gettime: %m");
-
-  last_time = ts.tv_sec S + ts.tv_nsec NS;
+  last_io_time = current_time();
 
   if (event_open)
   {
-    event_open->duration = last_time - event_open->timestamp;
+    event_open->duration = last_io_time - event_open->timestamp;
 
     if (event_open->duration > config->latency_limit)
       log(L_WARN "Event 0x%p 0x%p took %u.%03u ms",
@@ -2089,7 +2072,7 @@ io_log_event(void *hook, void *data)
 
   en->hook = hook;
   en->data = data;
-  en->timestamp = last_time;
+  en->timestamp = last_io_time;
   en->duration = 0;
 
   event_log_num++;
@@ -2117,14 +2100,14 @@ io_log_dump(void)
     struct event_log_entry *en = event_log + (event_log_pos + i) % EVENT_LOG_LENGTH;
     if (en->hook)
       log(L_DEBUG "  Event 0x%p 0x%p at %8d for %d ms", en->hook, en->data,
-	  (int) ((last_time - en->timestamp) TO_MS), (int) (en->duration TO_MS));
+	  (int) ((last_io_time - en->timestamp) TO_MS), (int) (en->duration TO_MS));
   }
 }
 
 void
 watchdog_sigalrm(int sig UNUSED)
 {
-  /* Update last_time and duration, but skip latency check */
+  /* Update last_io_time and duration, but skip latency check */
   config->latency_limit = 0xffffffff;
   io_update_time();
 
@@ -2137,7 +2120,7 @@ watchdog_start1(void)
 {
   io_update_time();
 
-  loop_time = last_time;
+  loop_time = last_io_time;
 }
 
 static inline void
@@ -2145,7 +2128,7 @@ watchdog_start(void)
 {
   io_update_time();
 
-  loop_time = last_time;
+  loop_time = last_io_time;
   event_log_num = 0;
 
   if (config->watchdog_timeout)
@@ -2166,7 +2149,7 @@ watchdog_stop(void)
     watchdog_active = 0;
   }
 
-  btime duration = last_time - loop_time;
+  btime duration = last_io_time - loop_time;
   if (duration > config->watchdog_warning)
     log(L_WARN "I/O loop cycle took %u.%03u ms for %d events",
 	(uint) (duration TO_MS), (uint) (duration % 1000), event_log_num);
@@ -2196,6 +2179,15 @@ static int short_loops = 0;
 #define SHORT_LOOP_MAX 10
 #define WORK_EVENTS_MAX 10
 
+static int poll_reload_pipe[2];
+
+void
+io_loop_reload(void)
+{
+  char b;
+  write(poll_reload_pipe[1], &b, 1);
+}
+
 void
 io_loop(void)
 {
@@ -2207,10 +2199,13 @@ io_loop(void)
   int fdmax = 256;
   struct pollfd *pfd = xmalloc(fdmax * sizeof(struct pollfd));
 
+  if (pipe(poll_reload_pipe) < 0)
+    die("pipe(poll_reload_pipe) failed: %m");
+
   watchdog_start1();
   for(;;)
     {
-      times_update(&main_timeloop);
+      times_update();
       events = ev_run_list(&global_event_list);
       events = ev_run_list_limited(&global_work_list, WORK_EVENTS_MAX) || events;
       timers_fire(&main_timeloop);
@@ -2220,12 +2215,17 @@ io_loop(void)
       poll_tout = (events ? 0 : 3000); /* Time in milliseconds */
       if (t = timers_first(&main_timeloop))
       {
-	times_update(&main_timeloop);
+	times_update();
 	timeout = (tm_remains(t) TO_MS) + 1;
 	poll_tout = MIN(poll_tout, timeout);
       }
 
-      nfds = 0;
+      /* A hack to reload main io_loop() when something has changed asynchronously. */
+      pfd[0].fd = poll_reload_pipe[0];
+      pfd[0].events = POLLIN;
+
+      nfds = 1;
+
       WALK_LIST(n, sock_list)
 	{
 	  pfd[nfds] = (struct pollfd) { .fd = -1 }; /* everything other set to 0 by this */
@@ -2284,7 +2284,9 @@ io_loop(void)
 
       /* And finally enter poll() to find active sockets */
       watchdog_stop();
+      the_bird_unlock();
       pout = poll(pfd, nfds, poll_tout);
+      the_bird_lock();
       watchdog_start();
 
       if (pout < 0)
@@ -2295,7 +2297,15 @@ io_loop(void)
 	}
       if (pout)
 	{
-	  times_update(&main_timeloop);
+	  if (pfd[0].revents & POLLIN)
+	  {
+	    /* IO loop reload requested */
+	    char b;
+	    read(poll_reload_pipe[0], &b, 1);
+	    continue;
+	  }
+
+	  times_update();
 
 	  /* guaranteed to be non-empty */
 	  current_sock = SKIP_BACK(sock, n, HEAD(sock_list));
diff --git a/sysdep/unix/log.c b/sysdep/unix/log.c
index 4e9df069..f48588b6 100644
--- a/sysdep/unix/log.c
+++ b/sysdep/unix/log.c
@@ -15,6 +15,7 @@
  * user's manual.
  */
 
+#include <stdatomic.h>
 #include <stdio.h>
 #include <stdlib.h>
 #include <stdarg.h>
@@ -35,8 +36,10 @@ static FILE *dbgf;
 static list *current_log_list;
 static char *current_syslog_name; /* NULL -> syslog closed */
 
+static _Atomic uint max_coro_id = ATOMIC_VAR_INIT(1);
+static _Thread_local uint this_coro_id;
 
-#ifdef USE_PTHREADS
+#define THIS_CORO_ID  (this_coro_id ?: (this_coro_id = atomic_fetch_add_explicit(&max_coro_id, 1, memory_order_acq_rel)))
 
 #include <pthread.h>
 
@@ -48,15 +51,6 @@ static pthread_t main_thread;
 void main_thread_init(void) { main_thread = pthread_self(); }
 static int main_thread_self(void) { return pthread_equal(pthread_self(), main_thread); }
 
-#else
-
-static inline void log_lock(void) {  }
-static inline void log_unlock(void) {  }
-void main_thread_init(void) { }
-static int main_thread_self(void) { return 1; }
-
-#endif
-
 
 #ifdef HAVE_SYSLOG_H
 #include <sys/syslog.h>
@@ -189,7 +183,7 @@ log_commit(int class, buffer *buf)
 		l->pos += msg_len;
 	      }
 
-	      fprintf(l->fh, "%s <%s> ", tbuf, class_names[class]);
+	      fprintf(l->fh, "%s [%04x] <%s> ", tbuf, THIS_CORO_ID, class_names[class]);
 	    }
 	  fputs(buf->start, l->fh);
 	  fputc('\n', l->fh);
@@ -299,6 +293,8 @@ die(const char *msg, ...)
   exit(1);
 }
 
+static struct timespec dbg_time_start;
+
 /**
  * debug - write to debug output
  * @msg: a printf-like message
@@ -311,12 +307,33 @@ debug(const char *msg, ...)
 {
 #define MAX_DEBUG_BUFSIZE 16384
   va_list args;
-  char buf[MAX_DEBUG_BUFSIZE];
+  char buf[MAX_DEBUG_BUFSIZE], *pos = buf;
+  int max = MAX_DEBUG_BUFSIZE;
 
   va_start(args, msg);
   if (dbgf)
     {
-      if (bvsnprintf(buf, MAX_DEBUG_BUFSIZE, msg, args) < 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_CORO_ID);
+      pos += n;
+      max -= n;
+
+      if (bvsnprintf(pos, max, msg, args) < 0)
 	bug("Extremely long debug output, split it.");
 
       fputs(buf, dbgf);
@@ -422,6 +439,8 @@ done:
 void
 log_init_debug(char *f)
 {
+  clock_gettime(CLOCK_MONOTONIC, &dbg_time_start);
+
   if (dbgf && dbgf != stderr)
     fclose(dbgf);
   if (!f)
diff --git a/sysdep/unix/main.c b/sysdep/unix/main.c
index 07d6c691..8bc07d94 100644
--- a/sysdep/unix/main.c
+++ b/sysdep/unix/main.c
@@ -28,6 +28,7 @@
 #include "lib/resource.h"
 #include "lib/socket.h"
 #include "lib/event.h"
+#include "lib/locking.h"
 #include "lib/timer.h"
 #include "lib/string.h"
 #include "nest/rt.h"
@@ -873,6 +874,7 @@ main(int argc, char **argv)
     dmalloc_debug(0x2f03d00);
 #endif
 
+  times_update();
   parse_args(argc, argv);
   log_switch(1, NULL, NULL);
 
@@ -927,6 +929,8 @@ main(int argc, char **argv)
       dup2(0, 2);
     }
 
+  the_bird_lock();
+
   main_thread_init();
 
   write_pid_file();
diff --git a/sysdep/unix/unix.h b/sysdep/unix/unix.h
index ad85d1ea..313c97c3 100644
--- a/sysdep/unix/unix.h
+++ b/sysdep/unix/unix.h
@@ -106,6 +106,7 @@ extern volatile sig_atomic_t async_shutdown_flag;
 
 void io_init(void);
 void io_loop(void);
+void io_loop_reload(void);
 void io_log_dump(void);
 int sk_open_unix(struct birdsock *s, char *name);
 struct rfile *rf_open(struct pool *, const char *name, const char *mode);