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);