On 02/07/2021 10:07, Dumitru Ceara wrote: > Time how long change/run handlers take and log this at debug level. > I-P engine debug logs are not so verbose so enabling them is quite > common when debugging scale/control plane latency related issues. > > One of the major missing pieces though was a log about how long each I-P > node change/run handler took to run. This commit adds it and also logs > a message when a node is recomputed because it misses an input change > handler.
I thought this (when a node is recomputed) was measured by the coverage counters? If not, should it be? > > Signed-off-by: Dumitru Ceara <[email protected]> > --- > lib/inc-proc-eng.c | 16 +++++++++++++++- > 1 file changed, 15 insertions(+), 1 deletion(-) > > diff --git a/lib/inc-proc-eng.c b/lib/inc-proc-eng.c > index c349efb22..bb96ef1a3 100644 > --- a/lib/inc-proc-eng.c > +++ b/lib/inc-proc-eng.c > @@ -27,6 +27,7 @@ > #include "openvswitch/hmap.h" > #include "openvswitch/vlog.h" > #include "inc-proc-eng.h" > +#include "timeval.h" > #include "unixctl.h" > > VLOG_DEFINE_THIS_MODULE(inc_proc_eng); > @@ -333,8 +334,10 @@ engine_recompute(struct engine_node *node, bool forced, > bool allowed) > } > > /* Run the node handler which might change state. */ > + long long int now = time_msec(); > node->run(node, node->data); > node->stats.recompute++; > + VLOG_DBG("node: %s, recompute took %lldms", node->name, time_msec() - > now); > } > > /* Return true if the node could be computed, false otherwise. */ > @@ -350,7 +353,12 @@ engine_compute(struct engine_node *node, bool > recompute_allowed) > /* If the input change can't be handled incrementally, run > * the node handler. > */ > - if (!node->inputs[i].change_handler(node, node->data)) { > + long long int now = time_msec(); > + bool handled = node->inputs[i].change_handler(node, node->data); > + VLOG_DBG("node: %s, handling change for input %s took %lldms", > + node->name, node->inputs[i].node->name, > + time_msec() - now); > + if (!handled) { > VLOG_DBG("node: %s, can't handle change for input %s, " > "fall back to recompute", > node->name, node->inputs[i].node->name); > @@ -369,8 +377,11 @@ engine_run_node(struct engine_node *node, bool > recompute_allowed) > { > if (!node->n_inputs) { > /* Run the node handler which might change state. */ > + long long int now = time_msec(); > node->run(node, node->data); > node->stats.recompute++; > + VLOG_DBG("node: %s, recompute took %lldms", node->name, > + time_msec() - now); > return; > } > > @@ -389,6 +400,9 @@ engine_run_node(struct engine_node *node, bool > recompute_allowed) > > /* Trigger a recompute if we don't have a change handler. */ > if (!node->inputs[i].change_handler) { > + VLOG_DBG("node %s, no handler for input %s, " > + "fall back to recompute", > + node->name, node->inputs[i].node->name); > engine_recompute(node, false, recompute_allowed); > return; > } > _______________________________________________ dev mailing list [email protected] https://mail.openvswitch.org/mailman/listinfo/ovs-dev
