On 7/2/21 5:51 PM, Mark Gray wrote: > 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?
It is counted by coverage counters but if we enable inc_proc_eng DBG logs we log all other cases, except for this one. It might be just my workflow that's not ideal, but I find it easier to enable the inc_proc_eng DBG logs and check them rather than looking at the coverage counters. > >> >> 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
