[ovs-dev] [PATCH ovn 3/4] ovn-nbctl: Support option --print-wait-time for latency measurement.
Numan Siddique
numans at ovn.org
Mon Sep 7 17:57:11 UTC 2020
On Wed, Sep 2, 2020 at 4:57 AM Han Zhou <hzhou at ovn.org> wrote:
> 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 <hzhou at ovn.org>
>
Acked-by: Numan Siddique <numans at ovn.org>
Thanks
Numan
> ---
> 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 @@
> </p>
> </dd>
>
> + <dt><code>--print-wait-time</code></dt>
> + <dd>
> + When <code>--wait</code> is specified, the option
> + <code>--print-wait-time</code> can be used to print the time spent
> on
> + waiting, depending on the value specified in <code> --wait</code>
> option.
> + If <code>--wait=sb</code> 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 <code> ovn-northd</code> starts
> + processing the update, and "ovn-northd completion", which is the
> time
> + between the Northbound DB update and the moment when
> + <code>ovn-northd</code> completes the Southbound DB updating
> + successfully. If <code>--wait=hv</code> 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.
> + </dd>
> +
> <dt><code>--db</code> <var>database</var></dt>
> <dd>
> The OVSDB database remote to contact. If the <env>OVN_NB_DB</env>
> 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;
> }
> }
> --
> 2.1.0
>
> _______________________________________________
> dev mailing list
> dev at openvswitch.org
> https://mail.openvswitch.org/mailman/listinfo/ovs-dev
>
>
More information about the dev
mailing list