[ovs-dev] [PATCH ovn] inc-proc-eng: Improve debug logging.

Mark Gray mark.d.gray at redhat.com
Fri Jul 2 15:51:41 UTC 2021


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 <dceara at redhat.com>
> ---
>  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;
>              }
> 



More information about the dev mailing list