On Mon, Sep 7, 2020 at 10:57 AM Numan Siddique <[email protected]> wrote:
> > > On Wed, Sep 2, 2020 at 4:57 AM Han Zhou <[email protected]> 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 <[email protected]> >> > > Acked-by: Numan Siddique <[email protected]> > > Thanks Numan. I applied this to master. > 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 >> [email protected] >> https://mail.openvswitch.org/mailman/listinfo/ovs-dev >> >> _______________________________________________ dev mailing list [email protected] https://mail.openvswitch.org/mailman/listinfo/ovs-dev
