[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