[RFC] filter profiling

[Lennert Buytenhek]

Hi!

Attached is a crude hack to allow profiling filter processing.

When you're done implementing all of your filter logic and are
wondering exactly why it now takes bird so friggin' long to
propagate routes while sitting for several minutes at 100% CPU on the
anemic embedded CPUs you're trying to run it on, tools like 'perf'
aren't too useful, since they'll just tell you that all CPU time is
being spent in interpret() or related functions and won't tell you
which filter language statements are responsible for how much of the
CPU time.

The attached patch is a very rough way of attempting to enable you
to figure out what's eating your cycles.  The basic idea is that it
sets up a SIGUSR2 handler that will write to stderr the config file
name and line currently being processed, and the prefix being operated
on if there is one.  You can then send bird SIGUSR2 in a tight loop
whenever it seems to be spinning at 100% CPU and the resulting output
will give you a clue of what's going on.

This is a very dirty hack, and it does some things that probably
aren't entirely safe, like calling into snprintf from a signal
handler, and it shouldn't be merged in this form, but for our purposes,
it seems to be working well, and seems to be able to provide useful
insights into some of our self-inflicted filter performance problems.

Feedback appreciated!  (Better ideas also appreciated. :D)


Cheers,
Lennert


diff --git a/filter/f-util.c b/filter/f-util.c
index def2b248..452dbcb2 100644
--- a/filter/f-util.c
+++ b/filter/f-util.c
@@ -20,6 +20,7 @@ f_new_inst(void)
   ret->code = ret->aux = 0;
   ret->arg1 = ret->arg2 = ret->next = NULL;
   ret->lineno = ifs->lino;
+  ret->file_name = ifs->file_name;
   return ret;
 }
 
diff --git a/filter/filter.c b/filter/filter.c
index f18970e0..d58c6cb4 100644
--- a/filter/filter.c
+++ b/filter/filter.c
@@ -33,6 +33,10 @@
 
 #undef LOCAL_DEBUG
 
+#include <stdio.h>
+#include <signal.h>
+#include <unistd.h>
+
 #include "nest/bird.h"
 #include "lib/lists.h"
 #include "lib/resource.h"
@@ -551,7 +555,7 @@ val_format(struct f_val v, buffer *buf)
   }
 }
 
-static struct rte **f_rte;
+static struct rte ** volatile f_rte;
 static struct rta *f_old_rta;
 static struct ea_list **f_tmp_attrs;
 static struct linpool *f_pool;
@@ -630,8 +634,10 @@ static struct tbf rl_runtime_err = TBF_DEFAULT_LOG_LIMITS;
  * &f_val structures are copied around, so there are no problems with
  * memory managment.
  */
+static struct f_val interpret(struct f_inst *what);
+
 static struct f_val
-interpret(struct f_inst *what)
+__interpret(struct f_inst *what)
 {
   struct symbol *sym;
   struct f_val v1, v2, res, *vp;
@@ -1515,6 +1521,70 @@ interpret(struct f_inst *what)
   return res;
 }
 
+#define barrier() __asm__ __volatile__("": : :"memory")
+
+static char *file_name;
+static int lino;
+
+static struct f_val
+interpret(struct f_inst *what)
+{
+  struct f_val ret;
+
+  if (what != NULL) {
+    lino = what->lineno;
+    barrier();
+    file_name = what->file_name;
+  }
+
+  ret = __interpret(what);
+
+  if (what != NULL) {
+    file_name = NULL;
+    barrier();
+    lino = -1;
+  }
+
+  return ret;
+}
+
+static void handle_sigusr2(int sig UNUSED)
+{
+  char prefix[64];
+  char buf[1024];
+
+  if (file_name == NULL) {
+//    write(2, "not interpreting an f_inst right now\n", 37);
+    return;
+  }
+
+  prefix[0] = 0;
+#ifndef IPV6
+  if (f_rte != NULL) {
+    struct fib_node *n = &(*f_rte)->net->n;
+    ip_addr addr = n->prefix;
+
+    snprintf(prefix, sizeof(prefix), "%d.%d.%d.%d/%d",
+	     (addr >> 24) & 0xff, (addr >> 16) & 0xff,
+	     (addr >> 8) & 0xff, addr & 0xff, n->pxlen);
+  }
+#endif
+
+  snprintf(buf, sizeof(buf), "%s:%d %s\n", file_name, lino, prefix);
+
+  write(2, buf, strlen(buf));
+}
+
+void filter_profile_init(void)
+{
+  struct sigaction sa;
+
+  bzero(&sa, sizeof(sa));
+  sa.sa_handler = handle_sigusr2;
+  sa.sa_flags = SA_RESTART;
+  sigaction(SIGUSR2, &sa, NULL);
+}
+
 #undef ARG
 #define ARG(x,y) \
 	if (!i_same(f1->y, f2->y)) \
@@ -1720,6 +1790,7 @@ f_run(struct filter *filter, struct rte **rte, struct ea_list **tmp_attrs, struc
     rta_free(f_old_rta);
   }
 
+  f_rte = NULL;
 
   if (res.type != T_RETURN) {
     log_rl(&rl_runtime_err, L_ERR "Filter %s did not return accept nor reject. Make up your mind", filter->name);
@@ -1747,6 +1818,8 @@ f_eval_rte(struct f_inst *expr, struct rte **rte, struct linpool *tmp_pool)
   /* Note that in this function we assume that rte->attrs is private / uncached */
   struct f_val res = interpret(expr);
 
+  f_rte = NULL;
+
   /* Hack to include EAF_TEMP attributes to the main list */
   (*rte)->attrs->eattrs = ea_append(tmp_attrs, (*rte)->attrs->eattrs);
 
diff --git a/filter/filter.h b/filter/filter.h
index 049ceb76..4349fdb3 100644
--- a/filter/filter.h
+++ b/filter/filter.h
@@ -26,6 +26,7 @@ struct f_inst {		/* Instruction */
     int i;
     void *p;
   } a2;
+  char *file_name;
   int lineno;
 };
 
diff --git a/sysdep/unix/main.c b/sysdep/unix/main.c
index 8aa19fce..4ef84196 100644
--- a/sysdep/unix/main.c
+++ b/sysdep/unix/main.c
@@ -870,6 +870,7 @@ main(int argc, char **argv)
   write_pid_file();
 
   signal_init();
+  filter_profile_init();
 
   config_commit(conf, RECONFIG_HARD, 0);