Use VLOG_INFO_RL in engine_recompute and engine_compute routines to log compute time over a given threshold (i.e. 500ms). Make timeout threshold configurable through ovs-appctl command:
$ovn-appctl -t ovn-controller inc-engine/compute-log-timeout 100 Reported-at: https://bugzilla.redhat.com/show_bug.cgi?id=1988555 Signed-off-by: Lorenzo Bianconi <[email protected]> --- Changes since v1: - add inc-engine/compute-log-timeout ovs-appctl command. --- lib/inc-proc-eng.c | 44 ++++++++++++++++++++++++++++++++++++++------ 1 file changed, 38 insertions(+), 6 deletions(-) diff --git a/lib/inc-proc-eng.c b/lib/inc-proc-eng.c index 2958a55e3..7b4391700 100644 --- a/lib/inc-proc-eng.c +++ b/lib/inc-proc-eng.c @@ -47,6 +47,8 @@ static const char *engine_node_state_name[EN_STATE_MAX] = { [EN_ABORTED] = "Aborted", }; +static long long engine_compute_log_timeout_msec = 500; + static void engine_recompute(struct engine_node *node, bool allowed, const char *reason_fmt, ...) OVS_PRINTF_FORMAT(3, 4); @@ -152,6 +154,20 @@ engine_trigger_recompute_cmd(struct unixctl_conn *conn, int argc OVS_UNUSED, unixctl_command_reply(conn, NULL); } +static void +engine_set_log_timeout_cmd(struct unixctl_conn *conn, int argc OVS_UNUSED, + const char *argv[], void *arg OVS_UNUSED) +{ + + unsigned int timeout; + if (!str_to_uint(argv[1], 10, &timeout)) { + unixctl_command_reply_error(conn, "unsigned integer required"); + return; + } + engine_compute_log_timeout_msec = timeout; + unixctl_command_reply(conn, NULL); +} + void engine_init(struct engine_node *node, struct engine_arg *arg) { @@ -172,6 +188,8 @@ engine_init(struct engine_node *node, struct engine_arg *arg) engine_clear_stats, NULL); unixctl_command_register("inc-engine/recompute", "", 0, 0, engine_trigger_recompute_cmd, NULL); + unixctl_command_register("inc-engine/compute-log-timeout", "", 1, 1, + engine_set_log_timeout_cmd, NULL); } void @@ -361,8 +379,15 @@ engine_recompute(struct engine_node *node, bool allowed, 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); + long long int delta_time = time_msec() - now; + if (delta_time > engine_compute_log_timeout_msec) { + static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(20, 10); + VLOG_INFO_RL(&rl, "node: %s, recompute (%s) took %lldms", node->name, + reason, delta_time); + } else { + VLOG_DBG("node: %s, recompute (%s) took %lldms", node->name, reason, + delta_time); + } done: free(reason); } @@ -379,10 +404,17 @@ engine_compute(struct engine_node *node, bool 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); + long long int delta_time = time_msec() - now; + if (delta_time > engine_compute_log_timeout_msec) { + static struct vlog_rate_limit rl = + VLOG_RATE_LIMIT_INIT(20, 10); + VLOG_INFO_RL(&rl, "node: %s, handler for input %s took %lldms", + node->name, node->inputs[i].node->name, + delta_time); + } else { + VLOG_DBG("node: %s, handler for input %s took %lldms", + node->name, node->inputs[i].node->name, delta_time); + } if (!handled) { engine_recompute(node, recompute_allowed, "failed handler for input %s", -- 2.34.1 _______________________________________________ dev mailing list [email protected] https://mail.openvswitch.org/mailman/listinfo/ovs-dev
