From patchwork Tue Sep 1 23:26:44 2020
Content-Type: text/plain; charset="utf-8"
MIME-Version: 1.0
Content-Transfer-Encoding: 7bit
X-Patchwork-Submitter: Han Zhou
X-Patchwork-Id: 1355456
Return-Path:
X-Original-To: incoming@patchwork.ozlabs.org
Delivered-To: patchwork-incoming@bilbo.ozlabs.org
Authentication-Results: ozlabs.org;
spf=pass (sender SPF authorized) smtp.mailfrom=openvswitch.org
(client-ip=140.211.166.136; helo=silver.osuosl.org;
envelope-from=ovs-dev-bounces@openvswitch.org; receiver=)
Authentication-Results: ozlabs.org;
dmarc=none (p=none dis=none) header.from=ovn.org
Received: from silver.osuosl.org (smtp3.osuosl.org [140.211.166.136])
(using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits))
(No client certificate requested)
by ozlabs.org (Postfix) with ESMTPS id 4Bh3Bg4YsXz9sRK
for ; Wed, 2 Sep 2020 09:27:23 +1000 (AEST)
Received: from localhost (localhost [127.0.0.1])
by silver.osuosl.org (Postfix) with ESMTP id 6C60C20762;
Tue, 1 Sep 2020 23:27:20 +0000 (UTC)
X-Virus-Scanned: amavisd-new at osuosl.org
Received: from silver.osuosl.org ([127.0.0.1])
by localhost (.osuosl.org [127.0.0.1]) (amavisd-new, port 10024)
with ESMTP id jnOKTyZC0dVA; Tue, 1 Sep 2020 23:27:10 +0000 (UTC)
Received: from lists.linuxfoundation.org (lf-lists.osuosl.org [140.211.9.56])
by silver.osuosl.org (Postfix) with ESMTP id 4DD5520532;
Tue, 1 Sep 2020 23:27:08 +0000 (UTC)
Received: from lf-lists.osuosl.org (localhost [127.0.0.1])
by lists.linuxfoundation.org (Postfix) with ESMTP id 0EF23C089E;
Tue, 1 Sep 2020 23:27:08 +0000 (UTC)
X-Original-To: dev@openvswitch.org
Delivered-To: ovs-dev@lists.linuxfoundation.org
Received: from fraxinus.osuosl.org (smtp4.osuosl.org [140.211.166.137])
by lists.linuxfoundation.org (Postfix) with ESMTP id AD4ACC0051
for ; Tue, 1 Sep 2020 23:27:05 +0000 (UTC)
Received: from localhost (localhost [127.0.0.1])
by fraxinus.osuosl.org (Postfix) with ESMTP id 9D1DE859D1
for ; Tue, 1 Sep 2020 23:27:05 +0000 (UTC)
X-Virus-Scanned: amavisd-new at osuosl.org
Received: from fraxinus.osuosl.org ([127.0.0.1])
by localhost (.osuosl.org [127.0.0.1]) (amavisd-new, port 10024)
with ESMTP id xKIqDHtQPCbG for ;
Tue, 1 Sep 2020 23:27:04 +0000 (UTC)
X-Greylist: domain auto-whitelisted by SQLgrey-1.7.6
Received: from relay3-d.mail.gandi.net (relay3-d.mail.gandi.net
[217.70.183.195])
by fraxinus.osuosl.org (Postfix) with ESMTPS id 355918589C
for ; Tue, 1 Sep 2020 23:27:04 +0000 (UTC)
X-Originating-IP: 216.113.160.71
Received: from localhost.localdomain.localdomain (unknown [216.113.160.71])
(Authenticated sender: hzhou@ovn.org)
by relay3-d.mail.gandi.net (Postfix) with ESMTPSA id ECBA760007;
Tue, 1 Sep 2020 23:27:01 +0000 (UTC)
From: Han Zhou
To: dev@openvswitch.org
Date: Tue, 1 Sep 2020 16:26:44 -0700
Message-Id: <1599002805-103574-3-git-send-email-hzhou@ovn.org>
X-Mailer: git-send-email 2.1.0
In-Reply-To: <1599002805-103574-1-git-send-email-hzhou@ovn.org>
References: <1599002805-103574-1-git-send-email-hzhou@ovn.org>
Cc: Han Zhou
Subject: [ovs-dev] [PATCH ovn 3/4] ovn-nbctl: Support option
--print-wait-time for latency measurement.
X-BeenThere: ovs-dev@openvswitch.org
X-Mailman-Version: 2.1.15
Precedence: list
List-Id:
List-Unsubscribe: ,
List-Archive:
List-Post:
List-Help:
List-Subscribe: ,
MIME-Version: 1.0
Errors-To: ovs-dev-bounces@openvswitch.org
Sender: "dev"
This patch adds option --print-wait-time, which can be used together
with --wait=sb/hv to print the time spent on respective processing.
For example:
$ ovn-nbctl --print-wait-time --wait=hv sync
Time spent on processing nb_cfg 392:
ovn-northd delay before processing: 1ms
ovn-northd completion: 32ms
ovn-controller(s) completion: 39ms
Without this, we had to use "time" command to measure the total time
spent by the ovn-nbctl command. However, it doesn't refect the actual
control plane latency, because the nb_cfg updates from all hypervisors
to SB DB contributes a significant part to the time spent on waiting
by the ovn-nbctl command. This doesn't reflect the real production
scenario. With this option (and the timestamp support from the previous
commit), we can measure the exact time when hypervisors completed
SB DB change handling and enforcing to OVS.
Signed-off-by: Han Zhou
Acked-by: Numan Siddique
---
tests/ovn.at | 3 +++
utilities/ovn-nbctl.8.xml | 17 +++++++++++++++++
utilities/ovn-nbctl.c | 38 +++++++++++++++++++++++++++++++++-----
3 files changed, 53 insertions(+), 5 deletions(-)
diff --git a/tests/ovn.at b/tests/ovn.at
index 55257c3..f238b66 100644
--- a/tests/ovn.at
+++ b/tests/ovn.at
@@ -21451,6 +21451,9 @@ hv3_ts=$(ovn-sbctl --bare --columns=nb_cfg_timestamp find chassis_private name=h
hv_cfg_ts=$(ovn-nbctl get nb_global . hv_cfg_timestamp)
AT_CHECK([test x$hv3_ts == x$hv_cfg_ts])
+AT_CHECK([test x$(ovn-nbctl --print-wait-time --wait=sb sync | grep ms | wc -l) == x2])
+AT_CHECK([test x$(ovn-nbctl --print-wait-time --wait=hv sync | grep ms | wc -l) == x3])
+
for i in $(seq 2 $n); do
OVN_CLEANUP_SBOX([hv$i])
done
diff --git a/utilities/ovn-nbctl.8.xml b/utilities/ovn-nbctl.8.xml
index 07447d2..fcc4312 100644
--- a/utilities/ovn-nbctl.8.xml
+++ b/utilities/ovn-nbctl.8.xml
@@ -1322,6 +1322,23 @@
+ --print-wait-time
+
+ When --wait
is specified, the option
+ --print-wait-time
can be used to print the time spent on
+ waiting, depending on the value specified in --wait
option.
+ If --wait=sb
is specified, it prints "ovn-northd delay
+ before processing", which is the time between the Northbound DB update by
+ the command and the moment when ovn-northd
starts
+ processing the update, and "ovn-northd completion", which is the time
+ between the Northbound DB update and the moment when
+ ovn-northd
completes the Southbound DB updating
+ successfully. If --wait=hv
is specified, in addition to the
+ above information, it also prints "ovn-controller(s) completion", which
+ is the time between the Northbound DB update and the moment when the
+ slowest hypervisor finishes processing the update.
+
+
--db
database
The OVSDB database remote to contact. If the OVN_NB_DB
diff --git a/utilities/ovn-nbctl.c b/utilities/ovn-nbctl.c
index d7bb4b4..57dfaa1 100644
--- a/utilities/ovn-nbctl.c
+++ b/utilities/ovn-nbctl.c
@@ -63,6 +63,8 @@ enum nbctl_wait_type {
};
static enum nbctl_wait_type wait_type = NBCTL_WAIT_NONE;
+static bool print_wait_time = false;
+
/* Should we wait (if specified by 'wait_type') even if the commands don't
* change the database at all? */
static bool force_wait = false;
@@ -302,14 +304,16 @@ main_loop(const char *args, struct ctl_command *commands, size_t n_commands,
#define MAIN_LOOP_OPTION_ENUMS \
OPT_NO_WAIT, \
OPT_WAIT, \
+ OPT_PRINT_WAIT_TIME, \
OPT_DRY_RUN, \
OPT_ONELINE
-#define MAIN_LOOP_LONG_OPTIONS \
- {"no-wait", no_argument, NULL, OPT_NO_WAIT}, \
- {"wait", required_argument, NULL, OPT_WAIT}, \
- {"dry-run", no_argument, NULL, OPT_DRY_RUN}, \
- {"oneline", no_argument, NULL, OPT_ONELINE}, \
+#define MAIN_LOOP_LONG_OPTIONS \
+ {"no-wait", no_argument, NULL, OPT_NO_WAIT}, \
+ {"wait", required_argument, NULL, OPT_WAIT}, \
+ {"print-wait-time", no_argument, NULL, OPT_PRINT_WAIT_TIME}, \
+ {"dry-run", no_argument, NULL, OPT_DRY_RUN}, \
+ {"oneline", no_argument, NULL, OPT_ONELINE}, \
{"timeout", required_argument, NULL, 't'}
enum {
@@ -358,6 +362,10 @@ handle_main_loop_option(int opt, const char *arg, bool *handled)
}
break;
+ case OPT_PRINT_WAIT_TIME:
+ print_wait_time = true;
+ break;
+
case OPT_DRY_RUN:
dry_run = true;
break;
@@ -777,6 +785,7 @@ Options:\n\
--no-shuffle-remotes do not shuffle the order of remotes\n\
--wait=sb wait for southbound database update\n\
--wait=hv wait for all chassis to catch up\n\
+ --print-wait-time print time spent on waiting\n\
-t, --timeout=SECS wait at most SECS seconds\n\
--dry-run do not commit changes to database\n\
--oneline print exactly one line of output per command\n",
@@ -5992,8 +6001,10 @@ run_prerequisites(struct ctl_command *commands, size_t n_commands,
ovsdb_idl_add_table(idl, &nbrec_table_nb_global);
if (wait_type == NBCTL_WAIT_SB) {
ovsdb_idl_add_column(idl, &nbrec_nb_global_col_sb_cfg);
+ ovsdb_idl_add_column(idl, &nbrec_nb_global_col_sb_cfg_timestamp);
} else if (wait_type == NBCTL_WAIT_HV) {
ovsdb_idl_add_column(idl, &nbrec_nb_global_col_hv_cfg);
+ ovsdb_idl_add_column(idl, &nbrec_nb_global_col_hv_cfg_timestamp);
}
for (struct ctl_command *c = commands; c < &commands[n_commands]; c++) {
@@ -6065,6 +6076,7 @@ do_nbctl(const char *args, struct ctl_command *commands, size_t n_commands,
struct shash_node *node;
int64_t next_cfg = 0;
char *error = NULL;
+ int64_t start_time = 0;
ovs_assert(retry);
@@ -6132,6 +6144,7 @@ do_nbctl(const char *args, struct ctl_command *commands, size_t n_commands,
}
}
+ start_time = time_wall_msec();
status = ovsdb_idl_txn_commit_block(txn);
if (wait_type != NBCTL_WAIT_NONE && status == TXN_SUCCESS) {
next_cfg = ovsdb_idl_txn_get_increment_new_value(txn);
@@ -6203,6 +6216,21 @@ do_nbctl(const char *args, struct ctl_command *commands, size_t n_commands,
? nb->sb_cfg
: nb->hv_cfg);
if (cur_cfg >= next_cfg) {
+ if (print_wait_time) {
+ printf("Time spent on processing nb_cfg %"PRId64":\n",
+ next_cfg);
+ printf("\tovn-northd delay before processing:"
+ "\t%"PRId64"ms\n",
+ nb->nb_cfg_timestamp - start_time);
+ printf("\tovn-northd completion:"
+ "\t\t\t%"PRId64"ms\n",
+ nb->sb_cfg_timestamp - start_time);
+ if (wait_type == NBCTL_WAIT_HV) {
+ printf("\tovn-controller(s) completion:"
+ "\t\t%"PRId64"ms\n",
+ nb->hv_cfg_timestamp - start_time);
+ }
+ }
goto done;
}
}