[ovs-dev] [PATCH ovn v2] inc-proc-eng: Improve debug logging.
Dumitru Ceara
dceara at redhat.com
Tue Jul 6 13:45:59 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
the reason why engine_recompute() has been called for a given node:
missing change handler, failed handler, or forced recompute).
Signed-off-by: Dumitru Ceara <dceara at redhat.com>
---
v2:
- Addressed Han's comments:
- added reason to engine_recompute()
- removed noisy/not so relevant logs.
Note: Mark Gray had acked v1 but since there are quite a bit of changes
in v2 I'll not add his ack.
---
lib/inc-proc-eng.c | 52 +++++++++++++++++++++++++++++++++-------------
1 file changed, 37 insertions(+), 15 deletions(-)
diff --git a/lib/inc-proc-eng.c b/lib/inc-proc-eng.c
index c349efb22..49a1fe2f2 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);
@@ -45,6 +46,10 @@ static const char *engine_node_state_name[EN_STATE_MAX] = {
[EN_ABORTED] = "Aborted",
};
+static void
+engine_recompute(struct engine_node *node, bool allowed,
+ const char *reason_fmt, ...) OVS_PRINTF_FORMAT(3, 4);
+
void
engine_set_force_recompute(bool val)
{
@@ -315,15 +320,23 @@ engine_init_run(void)
* mark the node as "aborted".
*/
static void
-engine_recompute(struct engine_node *node, bool forced, bool allowed)
+engine_recompute(struct engine_node *node, bool allowed,
+ const char *reason_fmt, ...)
{
- VLOG_DBG("node: %s, recompute (%s)", node->name,
- forced ? "forced" : "triggered");
+ char *reason = NULL;
+
+ if (VLOG_IS_DBG_ENABLED()) {
+ va_list reason_args;
+
+ va_start(reason_args, reason_fmt);
+ reason = xvasprintf(reason_fmt, reason_args);
+ va_end(reason_args);
+ }
if (!allowed) {
- VLOG_DBG("node: %s, recompute aborted", node->name);
+ VLOG_DBG("node: %s, recompute (%s) aborted", node->name, reason);
engine_set_node_state(node, EN_ABORTED);
- return;
+ goto done;
}
/* Clear tracked data before calling run() so that partially tracked data
@@ -333,8 +346,13 @@ 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 (%s) took %lldms", node->name, reason,
+ time_msec() - now);
+done:
+ free(reason);
}
/* Return true if the node could be computed, false otherwise. */
@@ -344,17 +362,19 @@ engine_compute(struct engine_node *node, bool recompute_allowed)
for (size_t i = 0; i < node->n_inputs; i++) {
/* If the input node data changed call its change handler. */
if (node->inputs[i].node->state == EN_UPDATED) {
- VLOG_DBG("node: %s, handle change for input %s",
- node->name, node->inputs[i].node->name);
-
/* If the input change can't be handled incrementally, run
* the node handler.
*/
- if (!node->inputs[i].change_handler(node, node->data)) {
- VLOG_DBG("node: %s, can't handle change for input %s, "
- "fall back to recompute",
- node->name, node->inputs[i].node->name);
- engine_recompute(node, false, recompute_allowed);
+ long long int now = time_msec();
+ bool handled = node->inputs[i].change_handler(node, node->data);
+
+ VLOG_DBG("node: %s, handler for input %s took %lldms",
+ node->name, node->inputs[i].node->name,
+ time_msec() - now);
+ if (!handled) {
+ engine_recompute(node, recompute_allowed,
+ "failed handler for input %s",
+ node->inputs[i].node->name);
return (node->state != EN_ABORTED);
}
}
@@ -375,7 +395,7 @@ engine_run_node(struct engine_node *node, bool recompute_allowed)
}
if (engine_force_recompute) {
- engine_recompute(node, true, recompute_allowed);
+ engine_recompute(node, recompute_allowed, "forced");
return;
}
@@ -389,7 +409,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) {
- engine_recompute(node, false, recompute_allowed);
+ engine_recompute(node, recompute_allowed,
+ "missing handler for input %s",
+ node->inputs[i].node->name);
return;
}
}
--
2.27.0
More information about the dev
mailing list