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

Dumitru Ceara dceara at redhat.com
Fri Jul 2 09:07:56 UTC 2021


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.

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;
             }
-- 
2.27.0



More information about the dev mailing list