| Message ID | 20210916153753.20400-1-dceara@redhat.com |
|---|---|
| State | Changes Requested |
| Headers | show |
| Series | [ovs-dev,v2] ovsdb-server: Log database transactions for user requested tables. | expand |
| Context | Check | Description |
|---|---|---|
| ovsrobot/apply-robot | success | apply and check: success |
| ovsrobot/github-robot-_Build_and_Test | success | github build: passed |
On 9/16/21 11:37 AM, Dumitru Ceara wrote: > Add a new command, 'ovsdb-server/log-db-ops DB TABLE on|off', which > allows the user to enable/disable transaction logging for specific > databases and tables. > > By default, logging is disabled. Once enabled, logs are generated > with level INFO and are also rate limited. > > If used with care, this command can be useful in analyzing production > deployment performance issues, allowing the user to pin point > bottlenecks without the need to enable wider debug logs, e.g., jsonrpc. > > Signed-off-by: Dumitru Ceara <dceara@redhat.com> > --- > A sample use case is an ovn-kubernetes scaled deployment in which > we're interesting in reducing time to bring up PODs (represented by > OVN logical switch ports). In order to determine exactly where the > bottleneck is when provisioning PODs (CMS/ovn-nbctl/client > IDLs/ovsdb-server/ovn-controller/etc) we need timestamps of when > operations happen at various places in the stack. > > Without this patch the only option for tracking when transactions > happen in the Northbound database is to enable jsonrpc debug logs in > ovsdb-server. This generates a rather large amount of data. > > Instead, now, users would be able to just enable logging for the > Logical_Switch_Port table getting more relevant and precise > information. Very well written and explained Everything looks good to me. I just have one small question down below > > V2: > - rebased (fixed conflicts in NEWS). > --- > NEWS | 4 ++++ > ovsdb/ovsdb-server.c | 38 +++++++++++++++++++++++++++++++++ > ovsdb/row.c | 17 +++++++++++++++ > ovsdb/row.h | 1 + > ovsdb/table.c | 7 ++++++ > ovsdb/table.h | 3 +++ > ovsdb/transaction.c | 51 ++++++++++++++++++++++++++++++++++++++++++++ > 7 files changed, 121 insertions(+) > > diff --git a/NEWS b/NEWS > index 90f4b15902b8..d56329772276 100644 > --- a/NEWS > +++ b/NEWS > @@ -10,6 +10,10 @@ Post-v2.16.0 > limiting behavior. > * Add hardware offload support for matching IPv4/IPv6 frag types > (experimental). > + - OVSDB: > + * New unixctl command 'ovsdb-server/log-db-ops DB TABLE on|off". > + If turned on, ovsdb-server will log (at level INFO and rate limited) > + all operations that are committed to table TABLE in the DB database. > > > v2.16.0 - 16 Aug 2021 > diff --git a/ovsdb/ovsdb-server.c b/ovsdb/ovsdb-server.c > index 0b3d2bb71432..c48645f7e255 100644 > --- a/ovsdb/ovsdb-server.c > +++ b/ovsdb/ovsdb-server.c > @@ -115,6 +115,7 @@ static unixctl_cb_func ovsdb_server_list_remotes; > static unixctl_cb_func ovsdb_server_add_database; > static unixctl_cb_func ovsdb_server_remove_database; > static unixctl_cb_func ovsdb_server_list_databases; > +static unixctl_cb_func ovsdb_server_log_db_ops; > > static void read_db(struct server_config *, struct db *); > static struct ovsdb_error *open_db(struct server_config *, > @@ -443,6 +444,8 @@ main(int argc, char *argv[]) > ovsdb_server_remove_database, &server_config); > unixctl_command_register("ovsdb-server/list-dbs", "", 0, 0, > ovsdb_server_list_databases, &all_dbs); > + unixctl_command_register("ovsdb-server/log-db-ops", "DB TABLE on|off", > + 3, 3, ovsdb_server_log_db_ops, &all_dbs); > unixctl_command_register("ovsdb-server/perf-counters-show", "", 0, 0, > ovsdb_server_perf_counters_show, NULL); > unixctl_command_register("ovsdb-server/perf-counters-clear", "", 0, 0, > @@ -1769,6 +1772,41 @@ ovsdb_server_list_databases(struct unixctl_conn *conn, int argc OVS_UNUSED, > ds_destroy(&s); > } > > +static void > +ovsdb_server_log_db_ops(struct unixctl_conn *conn, int argc OVS_UNUSED, > + const char *argv[], void *all_dbs_) > +{ > + struct shash *all_dbs = all_dbs_; > + const char *db_name = argv[1]; > + const char *tbl_name = argv[2]; > + const char *command = argv[3]; > + bool log; > + > + if (!strcmp(command, "on")) { > + log = true; > + } else if (!strcmp(command, "off")) { > + log = false; > + } else { > + unixctl_command_reply_error(conn, "invalid argument"); > + return; > + } > + > + struct db *db = shash_find_data(all_dbs, db_name); > + if (!db) { > + unixctl_command_reply_error(conn, "no such database"); > + return; > + } > + > + struct ovsdb_table *table = ovsdb_get_table(db->db, tbl_name); > + if (!table) { > + unixctl_command_reply_error(conn, "no such table"); > + return; > + } > + > + ovsdb_table_log_ops(table, log); > + unixctl_command_reply(conn, NULL); > +} > + > static void > ovsdb_server_get_sync_status(struct unixctl_conn *conn, int argc OVS_UNUSED, > const char *argv[] OVS_UNUSED, void *config_) > diff --git a/ovsdb/row.c b/ovsdb/row.c > index 65a0546211c8..5e31716506bc 100644 > --- a/ovsdb/row.c > +++ b/ovsdb/row.c > @@ -278,6 +278,23 @@ ovsdb_row_to_json(const struct ovsdb_row *row, > } > return json; > } > + > +void > +ovsdb_row_to_string(const struct ovsdb_row *row, struct ds *out) > +{ > + struct shash_node *node; > + > + SHASH_FOR_EACH (node, &row->table->schema->columns) { > + const struct ovsdb_column *column = node->data; > + > + ds_put_format(out, "%s:", column->name); > + ovsdb_datum_to_string(&row->fields[column->index], &column->type, out); > + ds_put_cstr(out, ","); > + } > + if (shash_count(&row->table->schema->columns)) { > + ds_chomp(out, ','); > + } > +} > > void > ovsdb_row_set_init(struct ovsdb_row_set *set) > diff --git a/ovsdb/row.h b/ovsdb/row.h > index 394ac8eb49b6..f22a08ecd197 100644 > --- a/ovsdb/row.h > +++ b/ovsdb/row.h > @@ -95,6 +95,7 @@ struct ovsdb_error *ovsdb_row_from_json(struct ovsdb_row *, > OVS_WARN_UNUSED_RESULT; > struct json *ovsdb_row_to_json(const struct ovsdb_row *, > const struct ovsdb_column_set *include); > +void ovsdb_row_to_string(const struct ovsdb_row *, struct ds *); > > static inline const struct uuid * > ovsdb_row_get_uuid(const struct ovsdb_row *row) > diff --git a/ovsdb/table.c b/ovsdb/table.c > index 455a3663fe89..b7b41d139914 100644 > --- a/ovsdb/table.c > +++ b/ovsdb/table.c > @@ -301,10 +301,17 @@ ovsdb_table_create(struct ovsdb_table_schema *ts) > hmap_init(&table->indexes[i]); > } > hmap_init(&table->rows); > + table->log = false; > > return table; > } > > +void > +ovsdb_table_log_ops(struct ovsdb_table *table, bool enabled) > +{ > + table->log = enabled; > +} > + > void > ovsdb_table_destroy(struct ovsdb_table *table) > { > diff --git a/ovsdb/table.h b/ovsdb/table.h > index ce69a5d130bf..be88b7a59279 100644 > --- a/ovsdb/table.h > +++ b/ovsdb/table.h > @@ -63,10 +63,13 @@ struct ovsdb_table { > * ovsdb_row"s. Each of the hmap_nodes in indexes[i] are at index 'i' at > * the end of struct ovsdb_row, following the 'fields' member. */ > struct hmap *indexes; > + > + bool log; /* True if logging is enabled for this table. */ > }; > > struct ovsdb_table *ovsdb_table_create(struct ovsdb_table_schema *); > void ovsdb_table_destroy(struct ovsdb_table *); > +void ovsdb_table_log_ops(struct ovsdb_table *, bool); > > const struct ovsdb_row *ovsdb_table_get_row(const struct ovsdb_table *, > const struct uuid *); > diff --git a/ovsdb/transaction.c b/ovsdb/transaction.c > index 8ffefcf7c9d0..dc07e9c00a4b 100644 > --- a/ovsdb/transaction.c > +++ b/ovsdb/transaction.c > @@ -29,6 +29,7 @@ > #include "openvswitch/vlog.h" > #include "ovsdb-error.h" > #include "ovsdb.h" > +#include "ovs-thread.h" > #include "row.h" > #include "storage.h" > #include "table.h" > @@ -95,6 +96,7 @@ struct ovsdb_txn_row { > static struct ovsdb_error * OVS_WARN_UNUSED_RESULT > delete_garbage_row(struct ovsdb_txn *txn, struct ovsdb_txn_row *r); > static void ovsdb_txn_row_prefree(struct ovsdb_txn_row *); > +static void ovsdb_txn_row_log(const struct ovsdb_txn_row *); > static struct ovsdb_error * OVS_WARN_UNUSED_RESULT > for_each_txn_row(struct ovsdb_txn *txn, > struct ovsdb_error *(*)(struct ovsdb_txn *, > @@ -104,6 +106,11 @@ for_each_txn_row(struct ovsdb_txn *txn, > * processed. */ > static unsigned int serial; > > +/* Used by ovsdb_txn_row_log() to avoid reallocating dynamic strings > + * every time a row operation is logged. > + */ > +DEFINE_STATIC_PER_THREAD_DATA(struct ds, row_log_str, DS_EMPTY_INITIALIZER); > + > struct ovsdb_txn * > ovsdb_txn_create(struct ovsdb *db) > { > @@ -422,6 +429,49 @@ update_ref_counts(struct ovsdb_txn *txn) > return for_each_txn_row(txn, check_ref_count); > } > > +static void > +ovsdb_txn_row_log(const struct ovsdb_txn_row *txn_row) > +{ > + static struct vlog_rate_limit rl_insert = VLOG_RATE_LIMIT_INIT(30, 60); > + static struct vlog_rate_limit rl_update = VLOG_RATE_LIMIT_INIT(30, 60); > + static struct vlog_rate_limit rl_delete = VLOG_RATE_LIMIT_INIT(30, 60); > + > + if (!txn_row->table->log) { > + return; > + } Shouldn't this if-block be before the rate limitter initialization? > + > + size_t n_columns = shash_count(&txn_row->table->schema->columns); > + struct ovsdb_row *log_row; > + const char *op = NULL; > + > + if (!txn_row->old && txn_row->new) { > + if (!vlog_should_drop(&this_module, VLL_INFO, &rl_insert)) { > + log_row = txn_row->new; > + op = "inserted"; > + } > + } else if (txn_row->old && txn_row->new > + && !bitmap_is_all_zeros(txn_row->changed, n_columns)) { > + if (!vlog_should_drop(&this_module, VLL_INFO, &rl_update)) { > + log_row = txn_row->new; > + op = "updated"; > + } > + } else if (txn_row->old && !txn_row->new) { > + if (!vlog_should_drop(&this_module, VLL_INFO, &rl_delete)) { > + log_row = txn_row->old; > + op = "deleted"; > + } > + } > + > + if (op) { > + struct ds *ds = row_log_str_get(); > + ds_clear(ds); > + ds_put_format(ds, "table:%s,op:%s,", txn_row->table->schema->name, > + op); > + ovsdb_row_to_string(log_row, ds); > + VLOG_INFO("%s", ds_cstr(ds)); > + } > +} > + > static struct ovsdb_error * > ovsdb_txn_row_commit(struct ovsdb_txn *txn OVS_UNUSED, > struct ovsdb_txn_row *txn_row) > @@ -445,6 +495,7 @@ ovsdb_txn_row_commit(struct ovsdb_txn *txn OVS_UNUSED, > } > } > > + ovsdb_txn_row_log(txn_row); > ovsdb_txn_row_prefree(txn_row); > if (txn_row->new) { > txn_row->new->n_refs = txn_row->n_refs; >
On 9/21/21 6:12 PM, Michael Santana wrote: > > > On 9/16/21 11:37 AM, Dumitru Ceara wrote: >> Add a new command, 'ovsdb-server/log-db-ops DB TABLE on|off', which >> allows the user to enable/disable transaction logging for specific >> databases and tables. >> >> By default, logging is disabled. Once enabled, logs are generated >> with level INFO and are also rate limited. >> >> If used with care, this command can be useful in analyzing production >> deployment performance issues, allowing the user to pin point >> bottlenecks without the need to enable wider debug logs, e.g., jsonrpc. >> >> Signed-off-by: Dumitru Ceara <dceara@redhat.com> >> --- >> A sample use case is an ovn-kubernetes scaled deployment in which >> we're interesting in reducing time to bring up PODs (represented by >> OVN logical switch ports). In order to determine exactly where the >> bottleneck is when provisioning PODs (CMS/ovn-nbctl/client >> IDLs/ovsdb-server/ovn-controller/etc) we need timestamps of when >> operations happen at various places in the stack. >> >> Without this patch the only option for tracking when transactions >> happen in the Northbound database is to enable jsonrpc debug logs in >> ovsdb-server. This generates a rather large amount of data. >> >> Instead, now, users would be able to just enable logging for the >> Logical_Switch_Port table getting more relevant and precise >> information. > Very well written and explained > > Everything looks good to me. I just have one small question down below Thanks for reviewing this! >> >> V2: >> - rebased (fixed conflicts in NEWS). >> --- >> NEWS | 4 ++++ >> ovsdb/ovsdb-server.c | 38 +++++++++++++++++++++++++++++++++ >> ovsdb/row.c | 17 +++++++++++++++ >> ovsdb/row.h | 1 + >> ovsdb/table.c | 7 ++++++ >> ovsdb/table.h | 3 +++ >> ovsdb/transaction.c | 51 ++++++++++++++++++++++++++++++++++++++++++++ >> 7 files changed, 121 insertions(+) >> >> diff --git a/NEWS b/NEWS >> index 90f4b15902b8..d56329772276 100644 >> --- a/NEWS >> +++ b/NEWS >> @@ -10,6 +10,10 @@ Post-v2.16.0 >> limiting behavior. >> * Add hardware offload support for matching IPv4/IPv6 frag types >> (experimental). >> + - OVSDB: >> + * New unixctl command 'ovsdb-server/log-db-ops DB TABLE on|off". >> + If turned on, ovsdb-server will log (at level INFO and rate >> limited) >> + all operations that are committed to table TABLE in the DB >> database. >> v2.16.0 - 16 Aug 2021 >> diff --git a/ovsdb/ovsdb-server.c b/ovsdb/ovsdb-server.c >> index 0b3d2bb71432..c48645f7e255 100644 >> --- a/ovsdb/ovsdb-server.c >> +++ b/ovsdb/ovsdb-server.c >> @@ -115,6 +115,7 @@ static unixctl_cb_func ovsdb_server_list_remotes; >> static unixctl_cb_func ovsdb_server_add_database; >> static unixctl_cb_func ovsdb_server_remove_database; >> static unixctl_cb_func ovsdb_server_list_databases; >> +static unixctl_cb_func ovsdb_server_log_db_ops; >> static void read_db(struct server_config *, struct db *); >> static struct ovsdb_error *open_db(struct server_config *, >> @@ -443,6 +444,8 @@ main(int argc, char *argv[]) >> ovsdb_server_remove_database, >> &server_config); >> unixctl_command_register("ovsdb-server/list-dbs", "", 0, 0, >> ovsdb_server_list_databases, &all_dbs); >> + unixctl_command_register("ovsdb-server/log-db-ops", "DB TABLE >> on|off", >> + 3, 3, ovsdb_server_log_db_ops, &all_dbs); >> unixctl_command_register("ovsdb-server/perf-counters-show", "", >> 0, 0, >> ovsdb_server_perf_counters_show, NULL); >> unixctl_command_register("ovsdb-server/perf-counters-clear", "", >> 0, 0, >> @@ -1769,6 +1772,41 @@ ovsdb_server_list_databases(struct unixctl_conn >> *conn, int argc OVS_UNUSED, >> ds_destroy(&s); >> } >> +static void >> +ovsdb_server_log_db_ops(struct unixctl_conn *conn, int argc OVS_UNUSED, >> + const char *argv[], void *all_dbs_) >> +{ >> + struct shash *all_dbs = all_dbs_; >> + const char *db_name = argv[1]; >> + const char *tbl_name = argv[2]; >> + const char *command = argv[3]; >> + bool log; >> + >> + if (!strcmp(command, "on")) { >> + log = true; >> + } else if (!strcmp(command, "off")) { >> + log = false; >> + } else { >> + unixctl_command_reply_error(conn, "invalid argument"); >> + return; >> + } >> + >> + struct db *db = shash_find_data(all_dbs, db_name); >> + if (!db) { >> + unixctl_command_reply_error(conn, "no such database"); >> + return; >> + } >> + >> + struct ovsdb_table *table = ovsdb_get_table(db->db, tbl_name); >> + if (!table) { >> + unixctl_command_reply_error(conn, "no such table"); >> + return; >> + } >> + >> + ovsdb_table_log_ops(table, log); >> + unixctl_command_reply(conn, NULL); >> +} >> + >> static void >> ovsdb_server_get_sync_status(struct unixctl_conn *conn, int argc >> OVS_UNUSED, >> const char *argv[] OVS_UNUSED, void >> *config_) >> diff --git a/ovsdb/row.c b/ovsdb/row.c >> index 65a0546211c8..5e31716506bc 100644 >> --- a/ovsdb/row.c >> +++ b/ovsdb/row.c >> @@ -278,6 +278,23 @@ ovsdb_row_to_json(const struct ovsdb_row *row, >> } >> return json; >> } >> + >> +void >> +ovsdb_row_to_string(const struct ovsdb_row *row, struct ds *out) >> +{ >> + struct shash_node *node; >> + >> + SHASH_FOR_EACH (node, &row->table->schema->columns) { >> + const struct ovsdb_column *column = node->data; >> + >> + ds_put_format(out, "%s:", column->name); >> + ovsdb_datum_to_string(&row->fields[column->index], >> &column->type, out); >> + ds_put_cstr(out, ","); >> + } >> + if (shash_count(&row->table->schema->columns)) { >> + ds_chomp(out, ','); >> + } >> +} >> >> void >> ovsdb_row_set_init(struct ovsdb_row_set *set) >> diff --git a/ovsdb/row.h b/ovsdb/row.h >> index 394ac8eb49b6..f22a08ecd197 100644 >> --- a/ovsdb/row.h >> +++ b/ovsdb/row.h >> @@ -95,6 +95,7 @@ struct ovsdb_error *ovsdb_row_from_json(struct >> ovsdb_row *, >> OVS_WARN_UNUSED_RESULT; >> struct json *ovsdb_row_to_json(const struct ovsdb_row *, >> const struct ovsdb_column_set *include); >> +void ovsdb_row_to_string(const struct ovsdb_row *, struct ds *); >> static inline const struct uuid * >> ovsdb_row_get_uuid(const struct ovsdb_row *row) >> diff --git a/ovsdb/table.c b/ovsdb/table.c >> index 455a3663fe89..b7b41d139914 100644 >> --- a/ovsdb/table.c >> +++ b/ovsdb/table.c >> @@ -301,10 +301,17 @@ ovsdb_table_create(struct ovsdb_table_schema *ts) >> hmap_init(&table->indexes[i]); >> } >> hmap_init(&table->rows); >> + table->log = false; >> return table; >> } >> +void >> +ovsdb_table_log_ops(struct ovsdb_table *table, bool enabled) >> +{ >> + table->log = enabled; >> +} >> + >> void >> ovsdb_table_destroy(struct ovsdb_table *table) >> { >> diff --git a/ovsdb/table.h b/ovsdb/table.h >> index ce69a5d130bf..be88b7a59279 100644 >> --- a/ovsdb/table.h >> +++ b/ovsdb/table.h >> @@ -63,10 +63,13 @@ struct ovsdb_table { >> * ovsdb_row"s. Each of the hmap_nodes in indexes[i] are at >> index 'i' at >> * the end of struct ovsdb_row, following the 'fields' member. */ >> struct hmap *indexes; >> + >> + bool log; /* True if logging is enabled for this table. */ >> }; >> struct ovsdb_table *ovsdb_table_create(struct ovsdb_table_schema *); >> void ovsdb_table_destroy(struct ovsdb_table *); >> +void ovsdb_table_log_ops(struct ovsdb_table *, bool); >> const struct ovsdb_row *ovsdb_table_get_row(const struct >> ovsdb_table *, >> const struct uuid *); >> diff --git a/ovsdb/transaction.c b/ovsdb/transaction.c >> index 8ffefcf7c9d0..dc07e9c00a4b 100644 >> --- a/ovsdb/transaction.c >> +++ b/ovsdb/transaction.c >> @@ -29,6 +29,7 @@ >> #include "openvswitch/vlog.h" >> #include "ovsdb-error.h" >> #include "ovsdb.h" >> +#include "ovs-thread.h" >> #include "row.h" >> #include "storage.h" >> #include "table.h" >> @@ -95,6 +96,7 @@ struct ovsdb_txn_row { >> static struct ovsdb_error * OVS_WARN_UNUSED_RESULT >> delete_garbage_row(struct ovsdb_txn *txn, struct ovsdb_txn_row *r); >> static void ovsdb_txn_row_prefree(struct ovsdb_txn_row *); >> +static void ovsdb_txn_row_log(const struct ovsdb_txn_row *); >> static struct ovsdb_error * OVS_WARN_UNUSED_RESULT >> for_each_txn_row(struct ovsdb_txn *txn, >> struct ovsdb_error *(*)(struct ovsdb_txn *, >> @@ -104,6 +106,11 @@ for_each_txn_row(struct ovsdb_txn *txn, >> * processed. */ >> static unsigned int serial; >> +/* Used by ovsdb_txn_row_log() to avoid reallocating dynamic strings >> + * every time a row operation is logged. >> + */ >> +DEFINE_STATIC_PER_THREAD_DATA(struct ds, row_log_str, >> DS_EMPTY_INITIALIZER); >> + >> struct ovsdb_txn * >> ovsdb_txn_create(struct ovsdb *db) >> { >> @@ -422,6 +429,49 @@ update_ref_counts(struct ovsdb_txn *txn) >> return for_each_txn_row(txn, check_ref_count); >> } >> +static void >> +ovsdb_txn_row_log(const struct ovsdb_txn_row *txn_row) >> +{ >> + static struct vlog_rate_limit rl_insert = >> VLOG_RATE_LIMIT_INIT(30, 60); >> + static struct vlog_rate_limit rl_update = >> VLOG_RATE_LIMIT_INIT(30, 60); >> + static struct vlog_rate_limit rl_delete = >> VLOG_RATE_LIMIT_INIT(30, 60); >> + >> + if (!txn_row->table->log) { >> + return; >> + } > Shouldn't this if-block be before the rate limitter initialization? Well, I don't think it really matters because rl_insert/update/delete are static variables but if you think it's more readable I can send a v2 with the if-block moved up at the beginning of the function. Regards, Dumitru
On 9/22/21 3:24 AM, Dumitru Ceara wrote: > On 9/21/21 6:12 PM, Michael Santana wrote: >> >> >> On 9/16/21 11:37 AM, Dumitru Ceara wrote: >>> Add a new command, 'ovsdb-server/log-db-ops DB TABLE on|off', which >>> allows the user to enable/disable transaction logging for specific >>> databases and tables. >>> >>> By default, logging is disabled. Once enabled, logs are generated >>> with level INFO and are also rate limited. >>> >>> If used with care, this command can be useful in analyzing production >>> deployment performance issues, allowing the user to pin point >>> bottlenecks without the need to enable wider debug logs, e.g., jsonrpc. >>> >>> Signed-off-by: Dumitru Ceara <dceara@redhat.com> >>> --- >>> A sample use case is an ovn-kubernetes scaled deployment in which >>> we're interesting in reducing time to bring up PODs (represented by >>> OVN logical switch ports). In order to determine exactly where the >>> bottleneck is when provisioning PODs (CMS/ovn-nbctl/client >>> IDLs/ovsdb-server/ovn-controller/etc) we need timestamps of when >>> operations happen at various places in the stack. >>> >>> Without this patch the only option for tracking when transactions >>> happen in the Northbound database is to enable jsonrpc debug logs in >>> ovsdb-server. This generates a rather large amount of data. >>> >>> Instead, now, users would be able to just enable logging for the >>> Logical_Switch_Port table getting more relevant and precise >>> information. >> Very well written and explained >> >> Everything looks good to me. I just have one small question down below > > Thanks for reviewing this! > >>> >>> V2: >>> - rebased (fixed conflicts in NEWS). >>> --- >>> NEWS | 4 ++++ >>> ovsdb/ovsdb-server.c | 38 +++++++++++++++++++++++++++++++++ >>> ovsdb/row.c | 17 +++++++++++++++ >>> ovsdb/row.h | 1 + >>> ovsdb/table.c | 7 ++++++ >>> ovsdb/table.h | 3 +++ >>> ovsdb/transaction.c | 51 ++++++++++++++++++++++++++++++++++++++++++++ >>> 7 files changed, 121 insertions(+) >>> >>> diff --git a/NEWS b/NEWS >>> index 90f4b15902b8..d56329772276 100644 >>> --- a/NEWS >>> +++ b/NEWS >>> @@ -10,6 +10,10 @@ Post-v2.16.0 >>> limiting behavior. >>> * Add hardware offload support for matching IPv4/IPv6 frag types >>> (experimental). >>> + - OVSDB: >>> + * New unixctl command 'ovsdb-server/log-db-ops DB TABLE on|off". >>> + If turned on, ovsdb-server will log (at level INFO and rate >>> limited) >>> + all operations that are committed to table TABLE in the DB >>> database. >>> v2.16.0 - 16 Aug 2021 >>> diff --git a/ovsdb/ovsdb-server.c b/ovsdb/ovsdb-server.c >>> index 0b3d2bb71432..c48645f7e255 100644 >>> --- a/ovsdb/ovsdb-server.c >>> +++ b/ovsdb/ovsdb-server.c >>> @@ -115,6 +115,7 @@ static unixctl_cb_func ovsdb_server_list_remotes; >>> static unixctl_cb_func ovsdb_server_add_database; >>> static unixctl_cb_func ovsdb_server_remove_database; >>> static unixctl_cb_func ovsdb_server_list_databases; >>> +static unixctl_cb_func ovsdb_server_log_db_ops; >>> static void read_db(struct server_config *, struct db *); >>> static struct ovsdb_error *open_db(struct server_config *, >>> @@ -443,6 +444,8 @@ main(int argc, char *argv[]) >>> ovsdb_server_remove_database, >>> &server_config); >>> unixctl_command_register("ovsdb-server/list-dbs", "", 0, 0, >>> ovsdb_server_list_databases, &all_dbs); >>> + unixctl_command_register("ovsdb-server/log-db-ops", "DB TABLE >>> on|off", >>> + 3, 3, ovsdb_server_log_db_ops, &all_dbs); >>> unixctl_command_register("ovsdb-server/perf-counters-show", "", >>> 0, 0, >>> ovsdb_server_perf_counters_show, NULL); >>> unixctl_command_register("ovsdb-server/perf-counters-clear", "", >>> 0, 0, >>> @@ -1769,6 +1772,41 @@ ovsdb_server_list_databases(struct unixctl_conn >>> *conn, int argc OVS_UNUSED, >>> ds_destroy(&s); >>> } >>> +static void >>> +ovsdb_server_log_db_ops(struct unixctl_conn *conn, int argc OVS_UNUSED, >>> + const char *argv[], void *all_dbs_) >>> +{ >>> + struct shash *all_dbs = all_dbs_; >>> + const char *db_name = argv[1]; >>> + const char *tbl_name = argv[2]; >>> + const char *command = argv[3]; >>> + bool log; >>> + >>> + if (!strcmp(command, "on")) { >>> + log = true; >>> + } else if (!strcmp(command, "off")) { >>> + log = false; >>> + } else { >>> + unixctl_command_reply_error(conn, "invalid argument"); >>> + return; >>> + } >>> + >>> + struct db *db = shash_find_data(all_dbs, db_name); >>> + if (!db) { >>> + unixctl_command_reply_error(conn, "no such database"); >>> + return; >>> + } >>> + >>> + struct ovsdb_table *table = ovsdb_get_table(db->db, tbl_name); >>> + if (!table) { >>> + unixctl_command_reply_error(conn, "no such table"); >>> + return; >>> + } >>> + >>> + ovsdb_table_log_ops(table, log); >>> + unixctl_command_reply(conn, NULL); >>> +} >>> + >>> static void >>> ovsdb_server_get_sync_status(struct unixctl_conn *conn, int argc >>> OVS_UNUSED, >>> const char *argv[] OVS_UNUSED, void >>> *config_) >>> diff --git a/ovsdb/row.c b/ovsdb/row.c >>> index 65a0546211c8..5e31716506bc 100644 >>> --- a/ovsdb/row.c >>> +++ b/ovsdb/row.c >>> @@ -278,6 +278,23 @@ ovsdb_row_to_json(const struct ovsdb_row *row, >>> } >>> return json; >>> } >>> + >>> +void >>> +ovsdb_row_to_string(const struct ovsdb_row *row, struct ds *out) >>> +{ >>> + struct shash_node *node; >>> + >>> + SHASH_FOR_EACH (node, &row->table->schema->columns) { >>> + const struct ovsdb_column *column = node->data; >>> + >>> + ds_put_format(out, "%s:", column->name); >>> + ovsdb_datum_to_string(&row->fields[column->index], >>> &column->type, out); >>> + ds_put_cstr(out, ","); >>> + } >>> + if (shash_count(&row->table->schema->columns)) { >>> + ds_chomp(out, ','); >>> + } >>> +} >>> >>> void >>> ovsdb_row_set_init(struct ovsdb_row_set *set) >>> diff --git a/ovsdb/row.h b/ovsdb/row.h >>> index 394ac8eb49b6..f22a08ecd197 100644 >>> --- a/ovsdb/row.h >>> +++ b/ovsdb/row.h >>> @@ -95,6 +95,7 @@ struct ovsdb_error *ovsdb_row_from_json(struct >>> ovsdb_row *, >>> OVS_WARN_UNUSED_RESULT; >>> struct json *ovsdb_row_to_json(const struct ovsdb_row *, >>> const struct ovsdb_column_set *include); >>> +void ovsdb_row_to_string(const struct ovsdb_row *, struct ds *); >>> static inline const struct uuid * >>> ovsdb_row_get_uuid(const struct ovsdb_row *row) >>> diff --git a/ovsdb/table.c b/ovsdb/table.c >>> index 455a3663fe89..b7b41d139914 100644 >>> --- a/ovsdb/table.c >>> +++ b/ovsdb/table.c >>> @@ -301,10 +301,17 @@ ovsdb_table_create(struct ovsdb_table_schema *ts) >>> hmap_init(&table->indexes[i]); >>> } >>> hmap_init(&table->rows); >>> + table->log = false; >>> return table; >>> } >>> +void >>> +ovsdb_table_log_ops(struct ovsdb_table *table, bool enabled) >>> +{ >>> + table->log = enabled; >>> +} >>> + >>> void >>> ovsdb_table_destroy(struct ovsdb_table *table) >>> { >>> diff --git a/ovsdb/table.h b/ovsdb/table.h >>> index ce69a5d130bf..be88b7a59279 100644 >>> --- a/ovsdb/table.h >>> +++ b/ovsdb/table.h >>> @@ -63,10 +63,13 @@ struct ovsdb_table { >>> * ovsdb_row"s. Each of the hmap_nodes in indexes[i] are at >>> index 'i' at >>> * the end of struct ovsdb_row, following the 'fields' member. */ >>> struct hmap *indexes; >>> + >>> + bool log; /* True if logging is enabled for this table. */ >>> }; >>> struct ovsdb_table *ovsdb_table_create(struct ovsdb_table_schema *); >>> void ovsdb_table_destroy(struct ovsdb_table *); >>> +void ovsdb_table_log_ops(struct ovsdb_table *, bool); >>> const struct ovsdb_row *ovsdb_table_get_row(const struct >>> ovsdb_table *, >>> const struct uuid *); >>> diff --git a/ovsdb/transaction.c b/ovsdb/transaction.c >>> index 8ffefcf7c9d0..dc07e9c00a4b 100644 >>> --- a/ovsdb/transaction.c >>> +++ b/ovsdb/transaction.c >>> @@ -29,6 +29,7 @@ >>> #include "openvswitch/vlog.h" >>> #include "ovsdb-error.h" >>> #include "ovsdb.h" >>> +#include "ovs-thread.h" >>> #include "row.h" >>> #include "storage.h" >>> #include "table.h" >>> @@ -95,6 +96,7 @@ struct ovsdb_txn_row { >>> static struct ovsdb_error * OVS_WARN_UNUSED_RESULT >>> delete_garbage_row(struct ovsdb_txn *txn, struct ovsdb_txn_row *r); >>> static void ovsdb_txn_row_prefree(struct ovsdb_txn_row *); >>> +static void ovsdb_txn_row_log(const struct ovsdb_txn_row *); >>> static struct ovsdb_error * OVS_WARN_UNUSED_RESULT >>> for_each_txn_row(struct ovsdb_txn *txn, >>> struct ovsdb_error *(*)(struct ovsdb_txn *, >>> @@ -104,6 +106,11 @@ for_each_txn_row(struct ovsdb_txn *txn, >>> * processed. */ >>> static unsigned int serial; >>> +/* Used by ovsdb_txn_row_log() to avoid reallocating dynamic strings >>> + * every time a row operation is logged. >>> + */ >>> +DEFINE_STATIC_PER_THREAD_DATA(struct ds, row_log_str, >>> DS_EMPTY_INITIALIZER); >>> + >>> struct ovsdb_txn * >>> ovsdb_txn_create(struct ovsdb *db) >>> { >>> @@ -422,6 +429,49 @@ update_ref_counts(struct ovsdb_txn *txn) >>> return for_each_txn_row(txn, check_ref_count); >>> } >>> +static void >>> +ovsdb_txn_row_log(const struct ovsdb_txn_row *txn_row) >>> +{ >>> + static struct vlog_rate_limit rl_insert = >>> VLOG_RATE_LIMIT_INIT(30, 60); >>> + static struct vlog_rate_limit rl_update = >>> VLOG_RATE_LIMIT_INIT(30, 60); >>> + static struct vlog_rate_limit rl_delete = >>> VLOG_RATE_LIMIT_INIT(30, 60); >>> + >>> + if (!txn_row->table->log) { >>> + return; >>> + } >> Shouldn't this if-block be before the rate limitter initialization? > > Well, I don't think it really matters because rl_insert/update/delete > are static variables but if you think it's more readable I can send a v2 > with the if-block moved up at the beginning of the function. I missed it being static variables and the rate limiter functions being preprocessor functions. I was concern about hurting performance in the default case by making function calls that wouldn't be used and then immediately returning. Despite that I think we can still hurt performance (maybe insignificant amount?) by calling ovsdb_txn_row_log() every time from ovsdb_txn_row_commit() maybe checking if it's enabled before calling ovsdb_txn_row_log() prevent us from making unnecessary function calls in the default case where the log is disabled: if (txn_row->table->log) { ovsdb_txn_row_log(txn_row); } I dont how much of a difference it makes in terms of performance. If it's insignificant then just ignore this comment > > Regards, > Dumitru >
On 9/22/21 5:25 PM, Michael Santana wrote: > > > On 9/22/21 3:24 AM, Dumitru Ceara wrote: >> On 9/21/21 6:12 PM, Michael Santana wrote: >>> >>> >>> On 9/16/21 11:37 AM, Dumitru Ceara wrote: >>>> Add a new command, 'ovsdb-server/log-db-ops DB TABLE on|off', which >>>> allows the user to enable/disable transaction logging for specific >>>> databases and tables. >>>> >>>> By default, logging is disabled. Once enabled, logs are generated >>>> with level INFO and are also rate limited. >>>> >>>> If used with care, this command can be useful in analyzing production >>>> deployment performance issues, allowing the user to pin point >>>> bottlenecks without the need to enable wider debug logs, e.g., jsonrpc. >>>> >>>> Signed-off-by: Dumitru Ceara <dceara@redhat.com> >>>> --- >>>> A sample use case is an ovn-kubernetes scaled deployment in which >>>> we're interesting in reducing time to bring up PODs (represented by >>>> OVN logical switch ports). In order to determine exactly where the >>>> bottleneck is when provisioning PODs (CMS/ovn-nbctl/client >>>> IDLs/ovsdb-server/ovn-controller/etc) we need timestamps of when >>>> operations happen at various places in the stack. >>>> >>>> Without this patch the only option for tracking when transactions >>>> happen in the Northbound database is to enable jsonrpc debug logs in >>>> ovsdb-server. This generates a rather large amount of data. >>>> >>>> Instead, now, users would be able to just enable logging for the >>>> Logical_Switch_Port table getting more relevant and precise >>>> information. >>> Very well written and explained >>> >>> Everything looks good to me. I just have one small question down below >> >> Thanks for reviewing this! >> >>>> >>>> V2: >>>> - rebased (fixed conflicts in NEWS). >>>> --- >>>> NEWS | 4 ++++ >>>> ovsdb/ovsdb-server.c | 38 +++++++++++++++++++++++++++++++++ >>>> ovsdb/row.c | 17 +++++++++++++++ >>>> ovsdb/row.h | 1 + >>>> ovsdb/table.c | 7 ++++++ >>>> ovsdb/table.h | 3 +++ >>>> ovsdb/transaction.c | 51 >>>> ++++++++++++++++++++++++++++++++++++++++++++ >>>> 7 files changed, 121 insertions(+) >>>> >>>> diff --git a/NEWS b/NEWS >>>> index 90f4b15902b8..d56329772276 100644 >>>> --- a/NEWS >>>> +++ b/NEWS >>>> @@ -10,6 +10,10 @@ Post-v2.16.0 >>>> limiting behavior. >>>> * Add hardware offload support for matching IPv4/IPv6 frag >>>> types >>>> (experimental). >>>> + - OVSDB: >>>> + * New unixctl command 'ovsdb-server/log-db-ops DB TABLE on|off". >>>> + If turned on, ovsdb-server will log (at level INFO and rate >>>> limited) >>>> + all operations that are committed to table TABLE in the DB >>>> database. >>>> v2.16.0 - 16 Aug 2021 >>>> diff --git a/ovsdb/ovsdb-server.c b/ovsdb/ovsdb-server.c >>>> index 0b3d2bb71432..c48645f7e255 100644 >>>> --- a/ovsdb/ovsdb-server.c >>>> +++ b/ovsdb/ovsdb-server.c >>>> @@ -115,6 +115,7 @@ static unixctl_cb_func ovsdb_server_list_remotes; >>>> static unixctl_cb_func ovsdb_server_add_database; >>>> static unixctl_cb_func ovsdb_server_remove_database; >>>> static unixctl_cb_func ovsdb_server_list_databases; >>>> +static unixctl_cb_func ovsdb_server_log_db_ops; >>>> static void read_db(struct server_config *, struct db *); >>>> static struct ovsdb_error *open_db(struct server_config *, >>>> @@ -443,6 +444,8 @@ main(int argc, char *argv[]) >>>> ovsdb_server_remove_database, >>>> &server_config); >>>> unixctl_command_register("ovsdb-server/list-dbs", "", 0, 0, >>>> ovsdb_server_list_databases, &all_dbs); >>>> + unixctl_command_register("ovsdb-server/log-db-ops", "DB TABLE >>>> on|off", >>>> + 3, 3, ovsdb_server_log_db_ops, &all_dbs); >>>> unixctl_command_register("ovsdb-server/perf-counters-show", "", >>>> 0, 0, >>>> ovsdb_server_perf_counters_show, NULL); >>>> unixctl_command_register("ovsdb-server/perf-counters-clear", "", >>>> 0, 0, >>>> @@ -1769,6 +1772,41 @@ ovsdb_server_list_databases(struct unixctl_conn >>>> *conn, int argc OVS_UNUSED, >>>> ds_destroy(&s); >>>> } >>>> +static void >>>> +ovsdb_server_log_db_ops(struct unixctl_conn *conn, int argc >>>> OVS_UNUSED, >>>> + const char *argv[], void *all_dbs_) >>>> +{ >>>> + struct shash *all_dbs = all_dbs_; >>>> + const char *db_name = argv[1]; >>>> + const char *tbl_name = argv[2]; >>>> + const char *command = argv[3]; >>>> + bool log; >>>> + >>>> + if (!strcmp(command, "on")) { >>>> + log = true; >>>> + } else if (!strcmp(command, "off")) { >>>> + log = false; >>>> + } else { >>>> + unixctl_command_reply_error(conn, "invalid argument"); >>>> + return; >>>> + } >>>> + >>>> + struct db *db = shash_find_data(all_dbs, db_name); >>>> + if (!db) { >>>> + unixctl_command_reply_error(conn, "no such database"); >>>> + return; >>>> + } >>>> + >>>> + struct ovsdb_table *table = ovsdb_get_table(db->db, tbl_name); >>>> + if (!table) { >>>> + unixctl_command_reply_error(conn, "no such table"); >>>> + return; >>>> + } >>>> + >>>> + ovsdb_table_log_ops(table, log); >>>> + unixctl_command_reply(conn, NULL); >>>> +} >>>> + >>>> static void >>>> ovsdb_server_get_sync_status(struct unixctl_conn *conn, int argc >>>> OVS_UNUSED, >>>> const char *argv[] OVS_UNUSED, void >>>> *config_) >>>> diff --git a/ovsdb/row.c b/ovsdb/row.c >>>> index 65a0546211c8..5e31716506bc 100644 >>>> --- a/ovsdb/row.c >>>> +++ b/ovsdb/row.c >>>> @@ -278,6 +278,23 @@ ovsdb_row_to_json(const struct ovsdb_row *row, >>>> } >>>> return json; >>>> } >>>> + >>>> +void >>>> +ovsdb_row_to_string(const struct ovsdb_row *row, struct ds *out) >>>> +{ >>>> + struct shash_node *node; >>>> + >>>> + SHASH_FOR_EACH (node, &row->table->schema->columns) { >>>> + const struct ovsdb_column *column = node->data; >>>> + >>>> + ds_put_format(out, "%s:", column->name); >>>> + ovsdb_datum_to_string(&row->fields[column->index], >>>> &column->type, out); >>>> + ds_put_cstr(out, ","); >>>> + } >>>> + if (shash_count(&row->table->schema->columns)) { >>>> + ds_chomp(out, ','); >>>> + } >>>> +} >>>> >>>> void >>>> ovsdb_row_set_init(struct ovsdb_row_set *set) >>>> diff --git a/ovsdb/row.h b/ovsdb/row.h >>>> index 394ac8eb49b6..f22a08ecd197 100644 >>>> --- a/ovsdb/row.h >>>> +++ b/ovsdb/row.h >>>> @@ -95,6 +95,7 @@ struct ovsdb_error *ovsdb_row_from_json(struct >>>> ovsdb_row *, >>>> OVS_WARN_UNUSED_RESULT; >>>> struct json *ovsdb_row_to_json(const struct ovsdb_row *, >>>> const struct ovsdb_column_set >>>> *include); >>>> +void ovsdb_row_to_string(const struct ovsdb_row *, struct ds *); >>>> static inline const struct uuid * >>>> ovsdb_row_get_uuid(const struct ovsdb_row *row) >>>> diff --git a/ovsdb/table.c b/ovsdb/table.c >>>> index 455a3663fe89..b7b41d139914 100644 >>>> --- a/ovsdb/table.c >>>> +++ b/ovsdb/table.c >>>> @@ -301,10 +301,17 @@ ovsdb_table_create(struct ovsdb_table_schema *ts) >>>> hmap_init(&table->indexes[i]); >>>> } >>>> hmap_init(&table->rows); >>>> + table->log = false; >>>> return table; >>>> } >>>> +void >>>> +ovsdb_table_log_ops(struct ovsdb_table *table, bool enabled) >>>> +{ >>>> + table->log = enabled; >>>> +} >>>> + >>>> void >>>> ovsdb_table_destroy(struct ovsdb_table *table) >>>> { >>>> diff --git a/ovsdb/table.h b/ovsdb/table.h >>>> index ce69a5d130bf..be88b7a59279 100644 >>>> --- a/ovsdb/table.h >>>> +++ b/ovsdb/table.h >>>> @@ -63,10 +63,13 @@ struct ovsdb_table { >>>> * ovsdb_row"s. Each of the hmap_nodes in indexes[i] are at >>>> index 'i' at >>>> * the end of struct ovsdb_row, following the 'fields' >>>> member. */ >>>> struct hmap *indexes; >>>> + >>>> + bool log; /* True if logging is enabled for this table. */ >>>> }; >>>> struct ovsdb_table *ovsdb_table_create(struct >>>> ovsdb_table_schema *); >>>> void ovsdb_table_destroy(struct ovsdb_table *); >>>> +void ovsdb_table_log_ops(struct ovsdb_table *, bool); >>>> const struct ovsdb_row *ovsdb_table_get_row(const struct >>>> ovsdb_table *, >>>> const struct uuid *); >>>> diff --git a/ovsdb/transaction.c b/ovsdb/transaction.c >>>> index 8ffefcf7c9d0..dc07e9c00a4b 100644 >>>> --- a/ovsdb/transaction.c >>>> +++ b/ovsdb/transaction.c >>>> @@ -29,6 +29,7 @@ >>>> #include "openvswitch/vlog.h" >>>> #include "ovsdb-error.h" >>>> #include "ovsdb.h" >>>> +#include "ovs-thread.h" >>>> #include "row.h" >>>> #include "storage.h" >>>> #include "table.h" >>>> @@ -95,6 +96,7 @@ struct ovsdb_txn_row { >>>> static struct ovsdb_error * OVS_WARN_UNUSED_RESULT >>>> delete_garbage_row(struct ovsdb_txn *txn, struct ovsdb_txn_row *r); >>>> static void ovsdb_txn_row_prefree(struct ovsdb_txn_row *); >>>> +static void ovsdb_txn_row_log(const struct ovsdb_txn_row *); >>>> static struct ovsdb_error * OVS_WARN_UNUSED_RESULT >>>> for_each_txn_row(struct ovsdb_txn *txn, >>>> struct ovsdb_error *(*)(struct ovsdb_txn *, >>>> @@ -104,6 +106,11 @@ for_each_txn_row(struct ovsdb_txn *txn, >>>> * processed. */ >>>> static unsigned int serial; >>>> +/* Used by ovsdb_txn_row_log() to avoid reallocating dynamic >>>> strings >>>> + * every time a row operation is logged. >>>> + */ >>>> +DEFINE_STATIC_PER_THREAD_DATA(struct ds, row_log_str, >>>> DS_EMPTY_INITIALIZER); >>>> + >>>> struct ovsdb_txn * >>>> ovsdb_txn_create(struct ovsdb *db) >>>> { >>>> @@ -422,6 +429,49 @@ update_ref_counts(struct ovsdb_txn *txn) >>>> return for_each_txn_row(txn, check_ref_count); >>>> } >>>> +static void >>>> +ovsdb_txn_row_log(const struct ovsdb_txn_row *txn_row) >>>> +{ >>>> + static struct vlog_rate_limit rl_insert = >>>> VLOG_RATE_LIMIT_INIT(30, 60); >>>> + static struct vlog_rate_limit rl_update = >>>> VLOG_RATE_LIMIT_INIT(30, 60); >>>> + static struct vlog_rate_limit rl_delete = >>>> VLOG_RATE_LIMIT_INIT(30, 60); >>>> + >>>> + if (!txn_row->table->log) { >>>> + return; >>>> + } >>> Shouldn't this if-block be before the rate limitter initialization? >> >> Well, I don't think it really matters because rl_insert/update/delete >> are static variables but if you think it's more readable I can send a v2 >> with the if-block moved up at the beginning of the function. > I missed it being static variables and the rate limiter functions being > preprocessor functions. I was concern about hurting performance in the > default case by making function calls that wouldn't be used and then > immediately returning. > > Despite that I think we can still hurt performance (maybe insignificant > amount?) by calling ovsdb_txn_row_log() every time from > ovsdb_txn_row_commit() > > maybe checking if it's enabled before calling ovsdb_txn_row_log() > prevent us from making unnecessary function calls in the default case > where the log is disabled: > if (txn_row->table->log) { > ovsdb_txn_row_log(txn_row); > } ovsdb_txn_row_log() is static and will most likely be inlined by the compiler. So I don't think it matters either if we add the if before the call or not. > > I dont how much of a difference it makes in terms of performance. If > it's insignificant then just ignore this comment > Just to make sure, I checked, on my rhel machine with quite an old GCC version (gcc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-44)), when compiling with -O2: $ objdump -S ovsdb/ovsdb-server 0000000000417a30 <ovsdb_txn_row_commit>: { [...] if (!txn_row->table->log) { 417ac4: 48 8b 45 38 mov 0x38(%rbp),%rax 417ac8: 80 78 38 00 cmpb $0x0,0x38(%rax) 417acc: 0f 85 bf 00 00 00 jne 417b91 <ovsdb_txn_row_commit+0x161> 417ad2: 66 0f 1f 44 00 00 nopw 0x0(%rax,%rax,1) ovsdb_txn_row_prefree(txn_row); 417ad8: 48 89 ef mov %rbp,%rdi 417adb: e8 70 f7 ff ff callq 417250 <ovsdb_txn_row_prefree> So I guess it's OK as is. Regards, Dumitru
On 16/09/2021 16:37, Dumitru Ceara wrote: > Add a new command, 'ovsdb-server/log-db-ops DB TABLE on|off', which > allows the user to enable/disable transaction logging for specific > databases and tables. > > By default, logging is disabled. Once enabled, logs are generated > with level INFO and are also rate limited. > > If used with care, this command can be useful in analyzing production > deployment performance issues, allowing the user to pin point > bottlenecks without the need to enable wider debug logs, e.g., jsonrpc. > > Signed-off-by: Dumitru Ceara <dceara@redhat.com> > --- > A sample use case is an ovn-kubernetes scaled deployment in which > we're interesting in reducing time to bring up PODs (represented by > OVN logical switch ports). In order to determine exactly where the > bottleneck is when provisioning PODs (CMS/ovn-nbctl/client > IDLs/ovsdb-server/ovn-controller/etc) we need timestamps of when > operations happen at various places in the stack. > > Without this patch the only option for tracking when transactions > happen in the Northbound database is to enable jsonrpc debug logs in > ovsdb-server. This generates a rather large amount of data. > > Instead, now, users would be able to just enable logging for the > Logical_Switch_Port table getting more relevant and precise > information. > > V2: > - rebased (fixed conflicts in NEWS). Generally ok and I also did a quick test but I have a few comments on the UI which wouldn't block an ACK and one small comment below in the code: * My personal preference would be that the syntax somewhat followed the vlog/set one that seperates terms by ':'. Also a more memorable name. For example tlog/set DB:TABLE:on or something like that but feel free to choose to completely ignore me :) I just find it can sometimes be difficult to remember syntax so I prefer some consistency. * One limititation is that I don't think we can add a log before a table is created (i.e. to see the first entry). For example, let's say I want to log the very first creation of a bridge using `ovs-vsctl add-br br0`. Is there any way around it? I couldn't think of one. * Could you make the table and database names case-insensitive. For example, I can do `ovs-vsctl list open` even though the table name is actually Open_vSwitch? However, with this I need to specify the actual table name. * There is no way to list the tables that are currently 'on'. Something like vlog/list. * Would it be useful to be able to specify which level to log to?: e.g. tlog/set DB:TABLE:info * Would it be useful to have a non-verbose mode that only states that an insert/delete/update happened? > --- > NEWS | 4 ++++ > ovsdb/ovsdb-server.c | 38 +++++++++++++++++++++++++++++++++ > ovsdb/row.c | 17 +++++++++++++++ > ovsdb/row.h | 1 + > ovsdb/table.c | 7 ++++++ > ovsdb/table.h | 3 +++ > ovsdb/transaction.c | 51 ++++++++++++++++++++++++++++++++++++++++++++ > 7 files changed, 121 insertions(+) > > diff --git a/NEWS b/NEWS > index 90f4b15902b8..d56329772276 100644 > --- a/NEWS > +++ b/NEWS > @@ -10,6 +10,10 @@ Post-v2.16.0 > limiting behavior. > * Add hardware offload support for matching IPv4/IPv6 frag types > (experimental). > + - OVSDB: > + * New unixctl command 'ovsdb-server/log-db-ops DB TABLE on|off". > + If turned on, ovsdb-server will log (at level INFO and rate limited) > + all operations that are committed to table TABLE in the DB database. > > > v2.16.0 - 16 Aug 2021 > diff --git a/ovsdb/ovsdb-server.c b/ovsdb/ovsdb-server.c > index 0b3d2bb71432..c48645f7e255 100644 > --- a/ovsdb/ovsdb-server.c > +++ b/ovsdb/ovsdb-server.c > @@ -115,6 +115,7 @@ static unixctl_cb_func ovsdb_server_list_remotes; > static unixctl_cb_func ovsdb_server_add_database; > static unixctl_cb_func ovsdb_server_remove_database; > static unixctl_cb_func ovsdb_server_list_databases; > +static unixctl_cb_func ovsdb_server_log_db_ops; > > static void read_db(struct server_config *, struct db *); > static struct ovsdb_error *open_db(struct server_config *, > @@ -443,6 +444,8 @@ main(int argc, char *argv[]) > ovsdb_server_remove_database, &server_config); > unixctl_command_register("ovsdb-server/list-dbs", "", 0, 0, > ovsdb_server_list_databases, &all_dbs); > + unixctl_command_register("ovsdb-server/log-db-ops", "DB TABLE on|off", > + 3, 3, ovsdb_server_log_db_ops, &all_dbs); > unixctl_command_register("ovsdb-server/perf-counters-show", "", 0, 0, > ovsdb_server_perf_counters_show, NULL); > unixctl_command_register("ovsdb-server/perf-counters-clear", "", 0, 0, > @@ -1769,6 +1772,41 @@ ovsdb_server_list_databases(struct unixctl_conn *conn, int argc OVS_UNUSED, > ds_destroy(&s); > } > > +static void > +ovsdb_server_log_db_ops(struct unixctl_conn *conn, int argc OVS_UNUSED, > + const char *argv[], void *all_dbs_) > +{ > + struct shash *all_dbs = all_dbs_; > + const char *db_name = argv[1]; > + const char *tbl_name = argv[2]; > + const char *command = argv[3]; > + bool log; > + > + if (!strcmp(command, "on")) { > + log = true; > + } else if (!strcmp(command, "off")) { > + log = false; > + } else { > + unixctl_command_reply_error(conn, "invalid argument"); > + return; > + } > + > + struct db *db = shash_find_data(all_dbs, db_name); > + if (!db) { > + unixctl_command_reply_error(conn, "no such database"); > + return; > + } > + > + struct ovsdb_table *table = ovsdb_get_table(db->db, tbl_name); > + if (!table) { > + unixctl_command_reply_error(conn, "no such table"); > + return; > + } > + > + ovsdb_table_log_ops(table, log); > + unixctl_command_reply(conn, NULL); > +} > + > static void > ovsdb_server_get_sync_status(struct unixctl_conn *conn, int argc OVS_UNUSED, > const char *argv[] OVS_UNUSED, void *config_) > diff --git a/ovsdb/row.c b/ovsdb/row.c > index 65a0546211c8..5e31716506bc 100644 > --- a/ovsdb/row.c > +++ b/ovsdb/row.c > @@ -278,6 +278,23 @@ ovsdb_row_to_json(const struct ovsdb_row *row, > } > return json; > } > + > +void > +ovsdb_row_to_string(const struct ovsdb_row *row, struct ds *out) > +{ > + struct shash_node *node; > + > + SHASH_FOR_EACH (node, &row->table->schema->columns) { > + const struct ovsdb_column *column = node->data; > + > + ds_put_format(out, "%s:", column->name); > + ovsdb_datum_to_string(&row->fields[column->index], &column->type, out); > + ds_put_cstr(out, ","); > + } > + if (shash_count(&row->table->schema->columns)) { > + ds_chomp(out, ','); > + } > +} > > void > ovsdb_row_set_init(struct ovsdb_row_set *set) > diff --git a/ovsdb/row.h b/ovsdb/row.h > index 394ac8eb49b6..f22a08ecd197 100644 > --- a/ovsdb/row.h > +++ b/ovsdb/row.h > @@ -95,6 +95,7 @@ struct ovsdb_error *ovsdb_row_from_json(struct ovsdb_row *, > OVS_WARN_UNUSED_RESULT; > struct json *ovsdb_row_to_json(const struct ovsdb_row *, > const struct ovsdb_column_set *include); > +void ovsdb_row_to_string(const struct ovsdb_row *, struct ds *); > > static inline const struct uuid * > ovsdb_row_get_uuid(const struct ovsdb_row *row) > diff --git a/ovsdb/table.c b/ovsdb/table.c > index 455a3663fe89..b7b41d139914 100644 > --- a/ovsdb/table.c > +++ b/ovsdb/table.c > @@ -301,10 +301,17 @@ ovsdb_table_create(struct ovsdb_table_schema *ts) > hmap_init(&table->indexes[i]); > } > hmap_init(&table->rows); > + table->log = false; > > return table; > } > > +void > +ovsdb_table_log_ops(struct ovsdb_table *table, bool enabled) > +{ > + table->log = enabled; > +} > + > void > ovsdb_table_destroy(struct ovsdb_table *table) > { > diff --git a/ovsdb/table.h b/ovsdb/table.h > index ce69a5d130bf..be88b7a59279 100644 > --- a/ovsdb/table.h > +++ b/ovsdb/table.h > @@ -63,10 +63,13 @@ struct ovsdb_table { > * ovsdb_row"s. Each of the hmap_nodes in indexes[i] are at index 'i' at > * the end of struct ovsdb_row, following the 'fields' member. */ > struct hmap *indexes; > + > + bool log; /* True if logging is enabled for this table. */ > }; > > struct ovsdb_table *ovsdb_table_create(struct ovsdb_table_schema *); > void ovsdb_table_destroy(struct ovsdb_table *); > +void ovsdb_table_log_ops(struct ovsdb_table *, bool); > > const struct ovsdb_row *ovsdb_table_get_row(const struct ovsdb_table *, > const struct uuid *); > diff --git a/ovsdb/transaction.c b/ovsdb/transaction.c > index 8ffefcf7c9d0..dc07e9c00a4b 100644 > --- a/ovsdb/transaction.c > +++ b/ovsdb/transaction.c > @@ -29,6 +29,7 @@ > #include "openvswitch/vlog.h" > #include "ovsdb-error.h" > #include "ovsdb.h" > +#include "ovs-thread.h" > #include "row.h" > #include "storage.h" > #include "table.h" > @@ -95,6 +96,7 @@ struct ovsdb_txn_row { > static struct ovsdb_error * OVS_WARN_UNUSED_RESULT > delete_garbage_row(struct ovsdb_txn *txn, struct ovsdb_txn_row *r); > static void ovsdb_txn_row_prefree(struct ovsdb_txn_row *); > +static void ovsdb_txn_row_log(const struct ovsdb_txn_row *); > static struct ovsdb_error * OVS_WARN_UNUSED_RESULT > for_each_txn_row(struct ovsdb_txn *txn, > struct ovsdb_error *(*)(struct ovsdb_txn *, > @@ -104,6 +106,11 @@ for_each_txn_row(struct ovsdb_txn *txn, > * processed. */ > static unsigned int serial; > > +/* Used by ovsdb_txn_row_log() to avoid reallocating dynamic strings > + * every time a row operation is logged. > + */ > +DEFINE_STATIC_PER_THREAD_DATA(struct ds, row_log_str, DS_EMPTY_INITIALIZER); > + > struct ovsdb_txn * > ovsdb_txn_create(struct ovsdb *db) > { > @@ -422,6 +429,49 @@ update_ref_counts(struct ovsdb_txn *txn) > return for_each_txn_row(txn, check_ref_count); > } > > +static void > +ovsdb_txn_row_log(const struct ovsdb_txn_row *txn_row) > +{ > + static struct vlog_rate_limit rl_insert = VLOG_RATE_LIMIT_INIT(30, 60); > + static struct vlog_rate_limit rl_update = VLOG_RATE_LIMIT_INIT(30, 60); > + static struct vlog_rate_limit rl_delete = VLOG_RATE_LIMIT_INIT(30, 60); Why do you have 3 different rate limiters? > + > + if (!txn_row->table->log) { > + return; > + } > + > + size_t n_columns = shash_count(&txn_row->table->schema->columns); > + struct ovsdb_row *log_row; > + const char *op = NULL; > + > + if (!txn_row->old && txn_row->new) { > + if (!vlog_should_drop(&this_module, VLL_INFO, &rl_insert)) { > + log_row = txn_row->new; > + op = "inserted"; > + } > + } else if (txn_row->old && txn_row->new > + && !bitmap_is_all_zeros(txn_row->changed, n_columns)) { > + if (!vlog_should_drop(&this_module, VLL_INFO, &rl_update)) { > + log_row = txn_row->new; > + op = "updated"; > + } > + } else if (txn_row->old && !txn_row->new) { > + if (!vlog_should_drop(&this_module, VLL_INFO, &rl_delete)) { > + log_row = txn_row->old; > + op = "deleted"; > + } > + } > + > + if (op) { > + struct ds *ds = row_log_str_get(); > + ds_clear(ds); > + ds_put_format(ds, "table:%s,op:%s,", txn_row->table->schema->name, > + op); > + ovsdb_row_to_string(log_row, ds); > + VLOG_INFO("%s", ds_cstr(ds)); > + } > +} > + > static struct ovsdb_error * > ovsdb_txn_row_commit(struct ovsdb_txn *txn OVS_UNUSED, > struct ovsdb_txn_row *txn_row) > @@ -445,6 +495,7 @@ ovsdb_txn_row_commit(struct ovsdb_txn *txn OVS_UNUSED, > } > } > > + ovsdb_txn_row_log(txn_row); > ovsdb_txn_row_prefree(txn_row); > if (txn_row->new) { > txn_row->new->n_refs = txn_row->n_refs; >
On 23/09/2021 10:47, Mark Gray wrote: > On 16/09/2021 16:37, Dumitru Ceara wrote: >> Add a new command, 'ovsdb-server/log-db-ops DB TABLE on|off', which >> allows the user to enable/disable transaction logging for specific >> databases and tables. >> >> By default, logging is disabled. Once enabled, logs are generated >> with level INFO and are also rate limited. >> >> If used with care, this command can be useful in analyzing production >> deployment performance issues, allowing the user to pin point >> bottlenecks without the need to enable wider debug logs, e.g., jsonrpc. >> >> Signed-off-by: Dumitru Ceara <dceara@redhat.com> >> --- >> A sample use case is an ovn-kubernetes scaled deployment in which >> we're interesting in reducing time to bring up PODs (represented by >> OVN logical switch ports). In order to determine exactly where the >> bottleneck is when provisioning PODs (CMS/ovn-nbctl/client >> IDLs/ovsdb-server/ovn-controller/etc) we need timestamps of when >> operations happen at various places in the stack. >> >> Without this patch the only option for tracking when transactions >> happen in the Northbound database is to enable jsonrpc debug logs in >> ovsdb-server. This generates a rather large amount of data. >> >> Instead, now, users would be able to just enable logging for the >> Logical_Switch_Port table getting more relevant and precise >> information. >> >> V2: >> - rebased (fixed conflicts in NEWS). > Generally ok and I also did a quick test but I have a few comments on > the UI which wouldn't block an ACK and one small comment below in the code: > > * My personal preference would be that the syntax somewhat followed the > vlog/set one that seperates terms by ':'. Also a more memorable name. > For example tlog/set DB:TABLE:on or something like that but feel free to > choose to completely ignore me :) I just find it can sometimes be > difficult to remember syntax so I prefer some consistency. > > * One limititation is that I don't think we can add a log before a table > is created (i.e. to see the first entry). For example, let's say I want > to log the very first creation of a bridge using `ovs-vsctl add-br br0`. > Is there any way around it? I couldn't think of one. > > * Could you make the table and database names case-insensitive. For > example, I can do `ovs-vsctl list open` even though the table name is > actually Open_vSwitch? However, with this I need to specify the actual > table name. > > * There is no way to list the tables that are currently 'on'. Something > like vlog/list. > > * Would it be useful to be able to specify which level to log to?: e.g. > > tlog/set DB:TABLE:info > > * Would it be useful to have a non-verbose mode that only states that an > insert/delete/update happened? > Also, do we need to document this somewhere? I am not sure.
On 9/23/21 11:47 AM, Mark Gray wrote: > On 16/09/2021 16:37, Dumitru Ceara wrote: >> Add a new command, 'ovsdb-server/log-db-ops DB TABLE on|off', which >> allows the user to enable/disable transaction logging for specific >> databases and tables. >> >> By default, logging is disabled. Once enabled, logs are generated >> with level INFO and are also rate limited. >> >> If used with care, this command can be useful in analyzing production >> deployment performance issues, allowing the user to pin point >> bottlenecks without the need to enable wider debug logs, e.g., jsonrpc. >> >> Signed-off-by: Dumitru Ceara <dceara@redhat.com> >> --- >> A sample use case is an ovn-kubernetes scaled deployment in which >> we're interesting in reducing time to bring up PODs (represented by >> OVN logical switch ports). In order to determine exactly where the >> bottleneck is when provisioning PODs (CMS/ovn-nbctl/client >> IDLs/ovsdb-server/ovn-controller/etc) we need timestamps of when >> operations happen at various places in the stack. >> >> Without this patch the only option for tracking when transactions >> happen in the Northbound database is to enable jsonrpc debug logs in >> ovsdb-server. This generates a rather large amount of data. >> >> Instead, now, users would be able to just enable logging for the >> Logical_Switch_Port table getting more relevant and precise >> information. >> >> V2: >> - rebased (fixed conflicts in NEWS). > > Generally ok and I also did a quick test but I have a few comments on > the UI which wouldn't block an ACK and one small comment below in the code: Thanks for the review! > > * My personal preference would be that the syntax somewhat followed the > vlog/set one that seperates terms by ':'. Also a more memorable name. > For example tlog/set DB:TABLE:on or something like that but feel free to > choose to completely ignore me :) I just find it can sometimes be > difficult to remember syntax so I prefer some consistency. Makes sense, I'll try to come up with something more consistent. > > * One limititation is that I don't think we can add a log before a table > is created (i.e. to see the first entry). For example, let's say I want > to log the very first creation of a bridge using `ovs-vsctl add-br br0`. > Is there any way around it? I couldn't think of one. I'm not sure I follow this point. If you enable logging for the Bridge table before adding the first bridge you'll get the log, e.g., in an OVS sandbox: $ ovs-appctl -t $PWD/sandbox/ovsdb-server.*.ctl ovsdb-server/log-db-ops Open_vSwitch Bridge on $ ovs-vsctl show f43b960d-13f9-48d1-9898-703a3ac3f730 $ ovs-vsctl add-br br9 $ grep transaction sandbox/ovsdb-server.log 2021-09-23T09:57:53.426Z|00007|transaction|INFO|table:Bridge,op:inserted,name:br9,flood_vlans:[],auto_attach:[],ports:[388811ab-13a9-4b50-92c6-10c00a8b5e42],stp_enable:false,rstp_enable:false,_uuid:8a59955c-2a3c-41d3-9e93-66845e51878b,fail_mode:[],rstp_status:{},flow_tables:{},_version:1603df48-3730-4324-a71b-1c9f7eadb865,netflow:[],datapath_type:"",controller:[],other_config:{},external_ids:{},status:{},ipfix:[],datapath_id:[],mirrors:[],mcast_snooping_enable:false,datapath_version:"",sflow:[],protocols:[] [...] > > * Could you make the table and database names case-insensitive. For > example, I can do `ovs-vsctl list open` even though the table name is > actually Open_vSwitch? However, with this I need to specify the actual > table name. > We can try but this would be a bit of an orthogonal change. For example "ovs-appctl -t .. ovsdb-server/remove-db DB" only accepts case sensitive database names (due to case sensitive shash operations). For using partial table names and/or, it would also be a more complex change. What you mentioned (ovs-vsctl) is actually implemented on the client side in db-ctl-base.c, get_table()/score_partial_match(). > * There is no way to list the tables that are currently 'on'. Something > like vlog/list. Good idea, I'll add it! > > * Would it be useful to be able to specify which level to log to?: e.g. > > tlog/set DB:TABLE:info > I'm not sure, maybe, although my initial goal was to make this usable at a reasonably high log level, e.g., INFO. I don't think there's a point to use an even higher level though (like WARN/ERR), though. > * Would it be useful to have a non-verbose mode that only states that an > insert/delete/update happened? > Would you log some row specific information then? E.g., _uuid. >> --- >> NEWS | 4 ++++ >> ovsdb/ovsdb-server.c | 38 +++++++++++++++++++++++++++++++++ >> ovsdb/row.c | 17 +++++++++++++++ >> ovsdb/row.h | 1 + >> ovsdb/table.c | 7 ++++++ >> ovsdb/table.h | 3 +++ >> ovsdb/transaction.c | 51 ++++++++++++++++++++++++++++++++++++++++++++ >> 7 files changed, 121 insertions(+) >> >> diff --git a/NEWS b/NEWS >> index 90f4b15902b8..d56329772276 100644 >> --- a/NEWS >> +++ b/NEWS >> @@ -10,6 +10,10 @@ Post-v2.16.0 >> limiting behavior. >> * Add hardware offload support for matching IPv4/IPv6 frag types >> (experimental). >> + - OVSDB: >> + * New unixctl command 'ovsdb-server/log-db-ops DB TABLE on|off". >> + If turned on, ovsdb-server will log (at level INFO and rate limited) >> + all operations that are committed to table TABLE in the DB database. >> >> >> v2.16.0 - 16 Aug 2021 >> diff --git a/ovsdb/ovsdb-server.c b/ovsdb/ovsdb-server.c >> index 0b3d2bb71432..c48645f7e255 100644 >> --- a/ovsdb/ovsdb-server.c >> +++ b/ovsdb/ovsdb-server.c >> @@ -115,6 +115,7 @@ static unixctl_cb_func ovsdb_server_list_remotes; >> static unixctl_cb_func ovsdb_server_add_database; >> static unixctl_cb_func ovsdb_server_remove_database; >> static unixctl_cb_func ovsdb_server_list_databases; >> +static unixctl_cb_func ovsdb_server_log_db_ops; >> >> static void read_db(struct server_config *, struct db *); >> static struct ovsdb_error *open_db(struct server_config *, >> @@ -443,6 +444,8 @@ main(int argc, char *argv[]) >> ovsdb_server_remove_database, &server_config); >> unixctl_command_register("ovsdb-server/list-dbs", "", 0, 0, >> ovsdb_server_list_databases, &all_dbs); >> + unixctl_command_register("ovsdb-server/log-db-ops", "DB TABLE on|off", >> + 3, 3, ovsdb_server_log_db_ops, &all_dbs); >> unixctl_command_register("ovsdb-server/perf-counters-show", "", 0, 0, >> ovsdb_server_perf_counters_show, NULL); >> unixctl_command_register("ovsdb-server/perf-counters-clear", "", 0, 0, >> @@ -1769,6 +1772,41 @@ ovsdb_server_list_databases(struct unixctl_conn *conn, int argc OVS_UNUSED, >> ds_destroy(&s); >> } >> >> +static void >> +ovsdb_server_log_db_ops(struct unixctl_conn *conn, int argc OVS_UNUSED, >> + const char *argv[], void *all_dbs_) >> +{ >> + struct shash *all_dbs = all_dbs_; >> + const char *db_name = argv[1]; >> + const char *tbl_name = argv[2]; >> + const char *command = argv[3]; >> + bool log; >> + >> + if (!strcmp(command, "on")) { >> + log = true; >> + } else if (!strcmp(command, "off")) { >> + log = false; >> + } else { >> + unixctl_command_reply_error(conn, "invalid argument"); >> + return; >> + } >> + >> + struct db *db = shash_find_data(all_dbs, db_name); >> + if (!db) { >> + unixctl_command_reply_error(conn, "no such database"); >> + return; >> + } >> + >> + struct ovsdb_table *table = ovsdb_get_table(db->db, tbl_name); >> + if (!table) { >> + unixctl_command_reply_error(conn, "no such table"); >> + return; >> + } >> + >> + ovsdb_table_log_ops(table, log); >> + unixctl_command_reply(conn, NULL); >> +} >> + >> static void >> ovsdb_server_get_sync_status(struct unixctl_conn *conn, int argc OVS_UNUSED, >> const char *argv[] OVS_UNUSED, void *config_) >> diff --git a/ovsdb/row.c b/ovsdb/row.c >> index 65a0546211c8..5e31716506bc 100644 >> --- a/ovsdb/row.c >> +++ b/ovsdb/row.c >> @@ -278,6 +278,23 @@ ovsdb_row_to_json(const struct ovsdb_row *row, >> } >> return json; >> } >> + >> +void >> +ovsdb_row_to_string(const struct ovsdb_row *row, struct ds *out) >> +{ >> + struct shash_node *node; >> + >> + SHASH_FOR_EACH (node, &row->table->schema->columns) { >> + const struct ovsdb_column *column = node->data; >> + >> + ds_put_format(out, "%s:", column->name); >> + ovsdb_datum_to_string(&row->fields[column->index], &column->type, out); >> + ds_put_cstr(out, ","); >> + } >> + if (shash_count(&row->table->schema->columns)) { >> + ds_chomp(out, ','); >> + } >> +} >> >> void >> ovsdb_row_set_init(struct ovsdb_row_set *set) >> diff --git a/ovsdb/row.h b/ovsdb/row.h >> index 394ac8eb49b6..f22a08ecd197 100644 >> --- a/ovsdb/row.h >> +++ b/ovsdb/row.h >> @@ -95,6 +95,7 @@ struct ovsdb_error *ovsdb_row_from_json(struct ovsdb_row *, >> OVS_WARN_UNUSED_RESULT; >> struct json *ovsdb_row_to_json(const struct ovsdb_row *, >> const struct ovsdb_column_set *include); >> +void ovsdb_row_to_string(const struct ovsdb_row *, struct ds *); >> >> static inline const struct uuid * >> ovsdb_row_get_uuid(const struct ovsdb_row *row) >> diff --git a/ovsdb/table.c b/ovsdb/table.c >> index 455a3663fe89..b7b41d139914 100644 >> --- a/ovsdb/table.c >> +++ b/ovsdb/table.c >> @@ -301,10 +301,17 @@ ovsdb_table_create(struct ovsdb_table_schema *ts) >> hmap_init(&table->indexes[i]); >> } >> hmap_init(&table->rows); >> + table->log = false; >> >> return table; >> } >> >> +void >> +ovsdb_table_log_ops(struct ovsdb_table *table, bool enabled) >> +{ >> + table->log = enabled; >> +} >> + >> void >> ovsdb_table_destroy(struct ovsdb_table *table) >> { >> diff --git a/ovsdb/table.h b/ovsdb/table.h >> index ce69a5d130bf..be88b7a59279 100644 >> --- a/ovsdb/table.h >> +++ b/ovsdb/table.h >> @@ -63,10 +63,13 @@ struct ovsdb_table { >> * ovsdb_row"s. Each of the hmap_nodes in indexes[i] are at index 'i' at >> * the end of struct ovsdb_row, following the 'fields' member. */ >> struct hmap *indexes; >> + >> + bool log; /* True if logging is enabled for this table. */ >> }; >> >> struct ovsdb_table *ovsdb_table_create(struct ovsdb_table_schema *); >> void ovsdb_table_destroy(struct ovsdb_table *); >> +void ovsdb_table_log_ops(struct ovsdb_table *, bool); >> >> const struct ovsdb_row *ovsdb_table_get_row(const struct ovsdb_table *, >> const struct uuid *); >> diff --git a/ovsdb/transaction.c b/ovsdb/transaction.c >> index 8ffefcf7c9d0..dc07e9c00a4b 100644 >> --- a/ovsdb/transaction.c >> +++ b/ovsdb/transaction.c >> @@ -29,6 +29,7 @@ >> #include "openvswitch/vlog.h" >> #include "ovsdb-error.h" >> #include "ovsdb.h" >> +#include "ovs-thread.h" >> #include "row.h" >> #include "storage.h" >> #include "table.h" >> @@ -95,6 +96,7 @@ struct ovsdb_txn_row { >> static struct ovsdb_error * OVS_WARN_UNUSED_RESULT >> delete_garbage_row(struct ovsdb_txn *txn, struct ovsdb_txn_row *r); >> static void ovsdb_txn_row_prefree(struct ovsdb_txn_row *); >> +static void ovsdb_txn_row_log(const struct ovsdb_txn_row *); >> static struct ovsdb_error * OVS_WARN_UNUSED_RESULT >> for_each_txn_row(struct ovsdb_txn *txn, >> struct ovsdb_error *(*)(struct ovsdb_txn *, >> @@ -104,6 +106,11 @@ for_each_txn_row(struct ovsdb_txn *txn, >> * processed. */ >> static unsigned int serial; >> >> +/* Used by ovsdb_txn_row_log() to avoid reallocating dynamic strings >> + * every time a row operation is logged. >> + */ >> +DEFINE_STATIC_PER_THREAD_DATA(struct ds, row_log_str, DS_EMPTY_INITIALIZER); >> + >> struct ovsdb_txn * >> ovsdb_txn_create(struct ovsdb *db) >> { >> @@ -422,6 +429,49 @@ update_ref_counts(struct ovsdb_txn *txn) >> return for_each_txn_row(txn, check_ref_count); >> } >> >> +static void >> +ovsdb_txn_row_log(const struct ovsdb_txn_row *txn_row) >> +{ >> + static struct vlog_rate_limit rl_insert = VLOG_RATE_LIMIT_INIT(30, 60); >> + static struct vlog_rate_limit rl_update = VLOG_RATE_LIMIT_INIT(30, 60); >> + static struct vlog_rate_limit rl_delete = VLOG_RATE_LIMIT_INIT(30, 60); > > Why do you have 3 different rate limiters? > Updates usually happen more often than inserts/deletes (e.g., with OVN logical ports). I thought it would be more useful if updates didn't consume tokens from the insert/delete logs. But thinking more about it, a rate of 30 logs per minute with a burst of 60 doesn't allow too many transactions to be logged often either. So, I guess, in a real use case the user would disable rate limiting for the "transaction" vlog module. We might as well move to a single rate limiter then. I'll change it in the next revision. >> + >> + if (!txn_row->table->log) { >> + return; >> + } >> + >> + size_t n_columns = shash_count(&txn_row->table->schema->columns); >> + struct ovsdb_row *log_row; >> + const char *op = NULL; >> + >> + if (!txn_row->old && txn_row->new) { >> + if (!vlog_should_drop(&this_module, VLL_INFO, &rl_insert)) { >> + log_row = txn_row->new; >> + op = "inserted"; >> + } >> + } else if (txn_row->old && txn_row->new >> + && !bitmap_is_all_zeros(txn_row->changed, n_columns)) { >> + if (!vlog_should_drop(&this_module, VLL_INFO, &rl_update)) { >> + log_row = txn_row->new; >> + op = "updated"; >> + } >> + } else if (txn_row->old && !txn_row->new) { >> + if (!vlog_should_drop(&this_module, VLL_INFO, &rl_delete)) { >> + log_row = txn_row->old; >> + op = "deleted"; >> + } >> + } >> + >> + if (op) { >> + struct ds *ds = row_log_str_get(); >> + ds_clear(ds); >> + ds_put_format(ds, "table:%s,op:%s,", txn_row->table->schema->name, >> + op); >> + ovsdb_row_to_string(log_row, ds); >> + VLOG_INFO("%s", ds_cstr(ds)); >> + } >> +} >> + >> static struct ovsdb_error * >> ovsdb_txn_row_commit(struct ovsdb_txn *txn OVS_UNUSED, >> struct ovsdb_txn_row *txn_row) >> @@ -445,6 +495,7 @@ ovsdb_txn_row_commit(struct ovsdb_txn *txn OVS_UNUSED, >> } >> } >> >> + ovsdb_txn_row_log(txn_row); >> ovsdb_txn_row_prefree(txn_row); >> if (txn_row->new) { >> txn_row->new->n_refs = txn_row->n_refs; >> >
On 9/23/21 12:03 PM, Mark Gray wrote: > On 23/09/2021 10:47, Mark Gray wrote: >> On 16/09/2021 16:37, Dumitru Ceara wrote: >>> Add a new command, 'ovsdb-server/log-db-ops DB TABLE on|off', which >>> allows the user to enable/disable transaction logging for specific >>> databases and tables. >>> >>> By default, logging is disabled. Once enabled, logs are generated >>> with level INFO and are also rate limited. >>> >>> If used with care, this command can be useful in analyzing production >>> deployment performance issues, allowing the user to pin point >>> bottlenecks without the need to enable wider debug logs, e.g., jsonrpc. >>> >>> Signed-off-by: Dumitru Ceara <dceara@redhat.com> >>> --- >>> A sample use case is an ovn-kubernetes scaled deployment in which >>> we're interesting in reducing time to bring up PODs (represented by >>> OVN logical switch ports). In order to determine exactly where the >>> bottleneck is when provisioning PODs (CMS/ovn-nbctl/client >>> IDLs/ovsdb-server/ovn-controller/etc) we need timestamps of when >>> operations happen at various places in the stack. >>> >>> Without this patch the only option for tracking when transactions >>> happen in the Northbound database is to enable jsonrpc debug logs in >>> ovsdb-server. This generates a rather large amount of data. >>> >>> Instead, now, users would be able to just enable logging for the >>> Logical_Switch_Port table getting more relevant and precise >>> information. >>> >>> V2: >>> - rebased (fixed conflicts in NEWS). >> Generally ok and I also did a quick test but I have a few comments on >> the UI which wouldn't block an ACK and one small comment below in the code: >> >> * My personal preference would be that the syntax somewhat followed the >> vlog/set one that seperates terms by ':'. Also a more memorable name. >> For example tlog/set DB:TABLE:on or something like that but feel free to >> choose to completely ignore me :) I just find it can sometimes be >> difficult to remember syntax so I prefer some consistency. >> >> * One limititation is that I don't think we can add a log before a table >> is created (i.e. to see the first entry). For example, let's say I want >> to log the very first creation of a bridge using `ovs-vsctl add-br br0`. >> Is there any way around it? I couldn't think of one. >> >> * Could you make the table and database names case-insensitive. For >> example, I can do `ovs-vsctl list open` even though the table name is >> actually Open_vSwitch? However, with this I need to specify the actual >> table name. >> >> * There is no way to list the tables that are currently 'on'. Something >> like vlog/list. >> >> * Would it be useful to be able to specify which level to log to?: e.g. >> >> tlog/set DB:TABLE:info >> >> * Would it be useful to have a non-verbose mode that only states that an >> insert/delete/update happened? >> > > Also, do we need to document this somewhere? I am not sure. > I'm not sure where though.. I couldn't find documentation (apart from occasional mentions in the NEWS file) for the other "ovsdb-server/..." appctl commands.
On 23/09/2021 11:22, Dumitru Ceara wrote: > On 9/23/21 12:03 PM, Mark Gray wrote: >> On 23/09/2021 10:47, Mark Gray wrote: >>> On 16/09/2021 16:37, Dumitru Ceara wrote: >>>> Add a new command, 'ovsdb-server/log-db-ops DB TABLE on|off', which >>>> allows the user to enable/disable transaction logging for specific >>>> databases and tables. >>>> >>>> By default, logging is disabled. Once enabled, logs are generated >>>> with level INFO and are also rate limited. >>>> >>>> If used with care, this command can be useful in analyzing production >>>> deployment performance issues, allowing the user to pin point >>>> bottlenecks without the need to enable wider debug logs, e.g., jsonrpc. >>>> >>>> Signed-off-by: Dumitru Ceara <dceara@redhat.com> >>>> --- >>>> A sample use case is an ovn-kubernetes scaled deployment in which >>>> we're interesting in reducing time to bring up PODs (represented by >>>> OVN logical switch ports). In order to determine exactly where the >>>> bottleneck is when provisioning PODs (CMS/ovn-nbctl/client >>>> IDLs/ovsdb-server/ovn-controller/etc) we need timestamps of when >>>> operations happen at various places in the stack. >>>> >>>> Without this patch the only option for tracking when transactions >>>> happen in the Northbound database is to enable jsonrpc debug logs in >>>> ovsdb-server. This generates a rather large amount of data. >>>> >>>> Instead, now, users would be able to just enable logging for the >>>> Logical_Switch_Port table getting more relevant and precise >>>> information. >>>> >>>> V2: >>>> - rebased (fixed conflicts in NEWS). >>> Generally ok and I also did a quick test but I have a few comments on >>> the UI which wouldn't block an ACK and one small comment below in the code: >>> >>> * My personal preference would be that the syntax somewhat followed the >>> vlog/set one that seperates terms by ':'. Also a more memorable name. >>> For example tlog/set DB:TABLE:on or something like that but feel free to >>> choose to completely ignore me :) I just find it can sometimes be >>> difficult to remember syntax so I prefer some consistency. >>> >>> * One limititation is that I don't think we can add a log before a table >>> is created (i.e. to see the first entry). For example, let's say I want >>> to log the very first creation of a bridge using `ovs-vsctl add-br br0`. >>> Is there any way around it? I couldn't think of one. >>> >>> * Could you make the table and database names case-insensitive. For >>> example, I can do `ovs-vsctl list open` even though the table name is >>> actually Open_vSwitch? However, with this I need to specify the actual >>> table name. >>> >>> * There is no way to list the tables that are currently 'on'. Something >>> like vlog/list. >>> >>> * Would it be useful to be able to specify which level to log to?: e.g. >>> >>> tlog/set DB:TABLE:info >>> >>> * Would it be useful to have a non-verbose mode that only states that an >>> insert/delete/update happened? >>> >> >> Also, do we need to document this somewhere? I am not sure. >> > > I'm not sure where though.. I couldn't find documentation (apart from > occasional mentions in the NEWS file) for the other "ovsdb-server/..." > appctl commands. > Maybe /ovsdb/ovsdb-server.1 ?
On 23/09/2021 11:20, Dumitru Ceara wrote: > On 9/23/21 11:47 AM, Mark Gray wrote: >> On 16/09/2021 16:37, Dumitru Ceara wrote: >>> Add a new command, 'ovsdb-server/log-db-ops DB TABLE on|off', which >>> allows the user to enable/disable transaction logging for specific >>> databases and tables. >>> >>> By default, logging is disabled. Once enabled, logs are generated >>> with level INFO and are also rate limited. >>> >>> If used with care, this command can be useful in analyzing production >>> deployment performance issues, allowing the user to pin point >>> bottlenecks without the need to enable wider debug logs, e.g., jsonrpc. >>> >>> Signed-off-by: Dumitru Ceara <dceara@redhat.com> >>> --- >>> A sample use case is an ovn-kubernetes scaled deployment in which >>> we're interesting in reducing time to bring up PODs (represented by >>> OVN logical switch ports). In order to determine exactly where the >>> bottleneck is when provisioning PODs (CMS/ovn-nbctl/client >>> IDLs/ovsdb-server/ovn-controller/etc) we need timestamps of when >>> operations happen at various places in the stack. >>> >>> Without this patch the only option for tracking when transactions >>> happen in the Northbound database is to enable jsonrpc debug logs in >>> ovsdb-server. This generates a rather large amount of data. >>> >>> Instead, now, users would be able to just enable logging for the >>> Logical_Switch_Port table getting more relevant and precise >>> information. >>> >>> V2: >>> - rebased (fixed conflicts in NEWS). >> >> Generally ok and I also did a quick test but I have a few comments on >> the UI which wouldn't block an ACK and one small comment below in the code: > > Thanks for the review! > >> >> * My personal preference would be that the syntax somewhat followed the >> vlog/set one that seperates terms by ':'. Also a more memorable name. >> For example tlog/set DB:TABLE:on or something like that but feel free to >> choose to completely ignore me :) I just find it can sometimes be >> difficult to remember syntax so I prefer some consistency. > > Makes sense, I'll try to come up with something more consistent. > >> >> * One limititation is that I don't think we can add a log before a table >> is created (i.e. to see the first entry). For example, let's say I want >> to log the very first creation of a bridge using `ovs-vsctl add-br br0`. >> Is there any way around it? I couldn't think of one. > > I'm not sure I follow this point. If you enable logging for the Bridge > table before adding the first bridge you'll get the log, e.g., in an OVS > sandbox: > > $ ovs-appctl -t $PWD/sandbox/ovsdb-server.*.ctl ovsdb-server/log-db-ops > Open_vSwitch Bridge on > > $ ovs-vsctl show > f43b960d-13f9-48d1-9898-703a3ac3f730 > > $ ovs-vsctl add-br br9 > > $ grep transaction sandbox/ovsdb-server.log > 2021-09-23T09:57:53.426Z|00007|transaction|INFO|table:Bridge,op:inserted,name:br9,flood_vlans:[],auto_attach:[],ports:[388811ab-13a9-4b50-92c6-10c00a8b5e42],stp_enable:false,rstp_enable:false,_uuid:8a59955c-2a3c-41d3-9e93-66845e51878b,fail_mode:[],rstp_status:{},flow_tables:{},_version:1603df48-3730-4324-a71b-1c9f7eadb865,netflow:[],datapath_type:"",controller:[],other_config:{},external_ids:{},status:{},ipfix:[],datapath_id:[],mirrors:[],mcast_snooping_enable:false,datapath_version:"",sflow:[],protocols:[] > [...] I just tested again and it does work. I think I must have specified "bridge" instead of "Bridge". Sorry for the confusion. >> >> * Could you make the table and database names case-insensitive. For >> example, I can do `ovs-vsctl list open` even though the table name is >> actually Open_vSwitch? However, with this I need to specify the actual >> table name. >> > > We can try but this would be a bit of an orthogonal change. For example > "ovs-appctl -t .. ovsdb-server/remove-db DB" only accepts case sensitive > database names (due to case sensitive shash operations). For using > partial table names and/or, it would also be a more complex change. > What you mentioned (ovs-vsctl) is actually implemented on the client > side in db-ctl-base.c, get_table()/score_partial_match(). Ok, in that case, no need to update. > >> * There is no way to list the tables that are currently 'on'. Something >> like vlog/list. > > Good idea, I'll add it! Thanks > >> >> * Would it be useful to be able to specify which level to log to?: e.g. >> >> tlog/set DB:TABLE:info >> > > I'm not sure, maybe, although my initial goal was to make this usable at > a reasonably high log level, e.g., INFO. I don't think there's a point > to use an even higher level though (like WARN/ERR), though. Ok > >> * Would it be useful to have a non-verbose mode that only states that an >> insert/delete/update happened? >> > > Would you log some row specific information then? E.g., _uuid. Perhaps, I am just thinking that it will reduce the log size. Maybe it's not useful. > >>> --- >>> NEWS | 4 ++++ >>> ovsdb/ovsdb-server.c | 38 +++++++++++++++++++++++++++++++++ >>> ovsdb/row.c | 17 +++++++++++++++ >>> ovsdb/row.h | 1 + >>> ovsdb/table.c | 7 ++++++ >>> ovsdb/table.h | 3 +++ >>> ovsdb/transaction.c | 51 ++++++++++++++++++++++++++++++++++++++++++++ >>> 7 files changed, 121 insertions(+) >>> >>> diff --git a/NEWS b/NEWS >>> index 90f4b15902b8..d56329772276 100644 >>> --- a/NEWS >>> +++ b/NEWS >>> @@ -10,6 +10,10 @@ Post-v2.16.0 >>> limiting behavior. >>> * Add hardware offload support for matching IPv4/IPv6 frag types >>> (experimental). >>> + - OVSDB: >>> + * New unixctl command 'ovsdb-server/log-db-ops DB TABLE on|off". >>> + If turned on, ovsdb-server will log (at level INFO and rate limited) >>> + all operations that are committed to table TABLE in the DB database. >>> >>> >>> v2.16.0 - 16 Aug 2021 >>> diff --git a/ovsdb/ovsdb-server.c b/ovsdb/ovsdb-server.c >>> index 0b3d2bb71432..c48645f7e255 100644 >>> --- a/ovsdb/ovsdb-server.c >>> +++ b/ovsdb/ovsdb-server.c >>> @@ -115,6 +115,7 @@ static unixctl_cb_func ovsdb_server_list_remotes; >>> static unixctl_cb_func ovsdb_server_add_database; >>> static unixctl_cb_func ovsdb_server_remove_database; >>> static unixctl_cb_func ovsdb_server_list_databases; >>> +static unixctl_cb_func ovsdb_server_log_db_ops; >>> >>> static void read_db(struct server_config *, struct db *); >>> static struct ovsdb_error *open_db(struct server_config *, >>> @@ -443,6 +444,8 @@ main(int argc, char *argv[]) >>> ovsdb_server_remove_database, &server_config); >>> unixctl_command_register("ovsdb-server/list-dbs", "", 0, 0, >>> ovsdb_server_list_databases, &all_dbs); >>> + unixctl_command_register("ovsdb-server/log-db-ops", "DB TABLE on|off", >>> + 3, 3, ovsdb_server_log_db_ops, &all_dbs); >>> unixctl_command_register("ovsdb-server/perf-counters-show", "", 0, 0, >>> ovsdb_server_perf_counters_show, NULL); >>> unixctl_command_register("ovsdb-server/perf-counters-clear", "", 0, 0, >>> @@ -1769,6 +1772,41 @@ ovsdb_server_list_databases(struct unixctl_conn *conn, int argc OVS_UNUSED, >>> ds_destroy(&s); >>> } >>> >>> +static void >>> +ovsdb_server_log_db_ops(struct unixctl_conn *conn, int argc OVS_UNUSED, >>> + const char *argv[], void *all_dbs_) >>> +{ >>> + struct shash *all_dbs = all_dbs_; >>> + const char *db_name = argv[1]; >>> + const char *tbl_name = argv[2]; >>> + const char *command = argv[3]; >>> + bool log; >>> + >>> + if (!strcmp(command, "on")) { >>> + log = true; >>> + } else if (!strcmp(command, "off")) { >>> + log = false; >>> + } else { >>> + unixctl_command_reply_error(conn, "invalid argument"); >>> + return; >>> + } >>> + >>> + struct db *db = shash_find_data(all_dbs, db_name); >>> + if (!db) { >>> + unixctl_command_reply_error(conn, "no such database"); >>> + return; >>> + } >>> + >>> + struct ovsdb_table *table = ovsdb_get_table(db->db, tbl_name); >>> + if (!table) { >>> + unixctl_command_reply_error(conn, "no such table"); >>> + return; >>> + } >>> + >>> + ovsdb_table_log_ops(table, log); >>> + unixctl_command_reply(conn, NULL); >>> +} >>> + >>> static void >>> ovsdb_server_get_sync_status(struct unixctl_conn *conn, int argc OVS_UNUSED, >>> const char *argv[] OVS_UNUSED, void *config_) >>> diff --git a/ovsdb/row.c b/ovsdb/row.c >>> index 65a0546211c8..5e31716506bc 100644 >>> --- a/ovsdb/row.c >>> +++ b/ovsdb/row.c >>> @@ -278,6 +278,23 @@ ovsdb_row_to_json(const struct ovsdb_row *row, >>> } >>> return json; >>> } >>> + >>> +void >>> +ovsdb_row_to_string(const struct ovsdb_row *row, struct ds *out) >>> +{ >>> + struct shash_node *node; >>> + >>> + SHASH_FOR_EACH (node, &row->table->schema->columns) { >>> + const struct ovsdb_column *column = node->data; >>> + >>> + ds_put_format(out, "%s:", column->name); >>> + ovsdb_datum_to_string(&row->fields[column->index], &column->type, out); >>> + ds_put_cstr(out, ","); >>> + } >>> + if (shash_count(&row->table->schema->columns)) { >>> + ds_chomp(out, ','); >>> + } >>> +} >>> >>> void >>> ovsdb_row_set_init(struct ovsdb_row_set *set) >>> diff --git a/ovsdb/row.h b/ovsdb/row.h >>> index 394ac8eb49b6..f22a08ecd197 100644 >>> --- a/ovsdb/row.h >>> +++ b/ovsdb/row.h >>> @@ -95,6 +95,7 @@ struct ovsdb_error *ovsdb_row_from_json(struct ovsdb_row *, >>> OVS_WARN_UNUSED_RESULT; >>> struct json *ovsdb_row_to_json(const struct ovsdb_row *, >>> const struct ovsdb_column_set *include); >>> +void ovsdb_row_to_string(const struct ovsdb_row *, struct ds *); >>> >>> static inline const struct uuid * >>> ovsdb_row_get_uuid(const struct ovsdb_row *row) >>> diff --git a/ovsdb/table.c b/ovsdb/table.c >>> index 455a3663fe89..b7b41d139914 100644 >>> --- a/ovsdb/table.c >>> +++ b/ovsdb/table.c >>> @@ -301,10 +301,17 @@ ovsdb_table_create(struct ovsdb_table_schema *ts) >>> hmap_init(&table->indexes[i]); >>> } >>> hmap_init(&table->rows); >>> + table->log = false; >>> >>> return table; >>> } >>> >>> +void >>> +ovsdb_table_log_ops(struct ovsdb_table *table, bool enabled) >>> +{ >>> + table->log = enabled; >>> +} >>> + >>> void >>> ovsdb_table_destroy(struct ovsdb_table *table) >>> { >>> diff --git a/ovsdb/table.h b/ovsdb/table.h >>> index ce69a5d130bf..be88b7a59279 100644 >>> --- a/ovsdb/table.h >>> +++ b/ovsdb/table.h >>> @@ -63,10 +63,13 @@ struct ovsdb_table { >>> * ovsdb_row"s. Each of the hmap_nodes in indexes[i] are at index 'i' at >>> * the end of struct ovsdb_row, following the 'fields' member. */ >>> struct hmap *indexes; >>> + >>> + bool log; /* True if logging is enabled for this table. */ >>> }; >>> >>> struct ovsdb_table *ovsdb_table_create(struct ovsdb_table_schema *); >>> void ovsdb_table_destroy(struct ovsdb_table *); >>> +void ovsdb_table_log_ops(struct ovsdb_table *, bool); >>> >>> const struct ovsdb_row *ovsdb_table_get_row(const struct ovsdb_table *, >>> const struct uuid *); >>> diff --git a/ovsdb/transaction.c b/ovsdb/transaction.c >>> index 8ffefcf7c9d0..dc07e9c00a4b 100644 >>> --- a/ovsdb/transaction.c >>> +++ b/ovsdb/transaction.c >>> @@ -29,6 +29,7 @@ >>> #include "openvswitch/vlog.h" >>> #include "ovsdb-error.h" >>> #include "ovsdb.h" >>> +#include "ovs-thread.h" >>> #include "row.h" >>> #include "storage.h" >>> #include "table.h" >>> @@ -95,6 +96,7 @@ struct ovsdb_txn_row { >>> static struct ovsdb_error * OVS_WARN_UNUSED_RESULT >>> delete_garbage_row(struct ovsdb_txn *txn, struct ovsdb_txn_row *r); >>> static void ovsdb_txn_row_prefree(struct ovsdb_txn_row *); >>> +static void ovsdb_txn_row_log(const struct ovsdb_txn_row *); >>> static struct ovsdb_error * OVS_WARN_UNUSED_RESULT >>> for_each_txn_row(struct ovsdb_txn *txn, >>> struct ovsdb_error *(*)(struct ovsdb_txn *, >>> @@ -104,6 +106,11 @@ for_each_txn_row(struct ovsdb_txn *txn, >>> * processed. */ >>> static unsigned int serial; >>> >>> +/* Used by ovsdb_txn_row_log() to avoid reallocating dynamic strings >>> + * every time a row operation is logged. >>> + */ >>> +DEFINE_STATIC_PER_THREAD_DATA(struct ds, row_log_str, DS_EMPTY_INITIALIZER); >>> + >>> struct ovsdb_txn * >>> ovsdb_txn_create(struct ovsdb *db) >>> { >>> @@ -422,6 +429,49 @@ update_ref_counts(struct ovsdb_txn *txn) >>> return for_each_txn_row(txn, check_ref_count); >>> } >>> >>> +static void >>> +ovsdb_txn_row_log(const struct ovsdb_txn_row *txn_row) >>> +{ >>> + static struct vlog_rate_limit rl_insert = VLOG_RATE_LIMIT_INIT(30, 60); >>> + static struct vlog_rate_limit rl_update = VLOG_RATE_LIMIT_INIT(30, 60); >>> + static struct vlog_rate_limit rl_delete = VLOG_RATE_LIMIT_INIT(30, 60); >> >> Why do you have 3 different rate limiters? >> > > Updates usually happen more often than inserts/deletes (e.g., with OVN > logical ports). I thought it would be more useful if updates didn't > consume tokens from the insert/delete logs. But thinking more about it, > a rate of 30 logs per minute with a burst of 60 doesn't allow too many > transactions to be logged often either. So, I guess, in a real use case > the user would disable rate limiting for the "transaction" vlog module. > We might as well move to a single rate limiter then. > > I'll change it in the next revision. > >>> + >>> + if (!txn_row->table->log) { >>> + return; >>> + } >>> + >>> + size_t n_columns = shash_count(&txn_row->table->schema->columns); >>> + struct ovsdb_row *log_row; >>> + const char *op = NULL; >>> + >>> + if (!txn_row->old && txn_row->new) { >>> + if (!vlog_should_drop(&this_module, VLL_INFO, &rl_insert)) { >>> + log_row = txn_row->new; >>> + op = "inserted"; >>> + } >>> + } else if (txn_row->old && txn_row->new >>> + && !bitmap_is_all_zeros(txn_row->changed, n_columns)) { >>> + if (!vlog_should_drop(&this_module, VLL_INFO, &rl_update)) { >>> + log_row = txn_row->new; >>> + op = "updated"; >>> + } >>> + } else if (txn_row->old && !txn_row->new) { >>> + if (!vlog_should_drop(&this_module, VLL_INFO, &rl_delete)) { >>> + log_row = txn_row->old; >>> + op = "deleted"; >>> + } >>> + } >>> + >>> + if (op) { >>> + struct ds *ds = row_log_str_get(); >>> + ds_clear(ds); >>> + ds_put_format(ds, "table:%s,op:%s,", txn_row->table->schema->name, >>> + op); >>> + ovsdb_row_to_string(log_row, ds); >>> + VLOG_INFO("%s", ds_cstr(ds)); >>> + } >>> +} >>> + >>> static struct ovsdb_error * >>> ovsdb_txn_row_commit(struct ovsdb_txn *txn OVS_UNUSED, >>> struct ovsdb_txn_row *txn_row) >>> @@ -445,6 +495,7 @@ ovsdb_txn_row_commit(struct ovsdb_txn *txn OVS_UNUSED, >>> } >>> } >>> >>> + ovsdb_txn_row_log(txn_row); >>> ovsdb_txn_row_prefree(txn_row); >>> if (txn_row->new) { >>> txn_row->new->n_refs = txn_row->n_refs; >>> >> >
On 9/23/21 12:33 PM, Mark Gray wrote: > On 23/09/2021 11:22, Dumitru Ceara wrote: >> On 9/23/21 12:03 PM, Mark Gray wrote: >>> On 23/09/2021 10:47, Mark Gray wrote: >>>> On 16/09/2021 16:37, Dumitru Ceara wrote: >>>>> Add a new command, 'ovsdb-server/log-db-ops DB TABLE on|off', which >>>>> allows the user to enable/disable transaction logging for specific >>>>> databases and tables. >>>>> >>>>> By default, logging is disabled. Once enabled, logs are generated >>>>> with level INFO and are also rate limited. >>>>> >>>>> If used with care, this command can be useful in analyzing production >>>>> deployment performance issues, allowing the user to pin point >>>>> bottlenecks without the need to enable wider debug logs, e.g., jsonrpc. >>>>> >>>>> Signed-off-by: Dumitru Ceara <dceara@redhat.com> >>>>> --- >>>>> A sample use case is an ovn-kubernetes scaled deployment in which >>>>> we're interesting in reducing time to bring up PODs (represented by >>>>> OVN logical switch ports). In order to determine exactly where the >>>>> bottleneck is when provisioning PODs (CMS/ovn-nbctl/client >>>>> IDLs/ovsdb-server/ovn-controller/etc) we need timestamps of when >>>>> operations happen at various places in the stack. >>>>> >>>>> Without this patch the only option for tracking when transactions >>>>> happen in the Northbound database is to enable jsonrpc debug logs in >>>>> ovsdb-server. This generates a rather large amount of data. >>>>> >>>>> Instead, now, users would be able to just enable logging for the >>>>> Logical_Switch_Port table getting more relevant and precise >>>>> information. >>>>> >>>>> V2: >>>>> - rebased (fixed conflicts in NEWS). >>>> Generally ok and I also did a quick test but I have a few comments on >>>> the UI which wouldn't block an ACK and one small comment below in the code: >>>> >>>> * My personal preference would be that the syntax somewhat followed the >>>> vlog/set one that seperates terms by ':'. Also a more memorable name. >>>> For example tlog/set DB:TABLE:on or something like that but feel free to >>>> choose to completely ignore me :) I just find it can sometimes be >>>> difficult to remember syntax so I prefer some consistency. >>>> >>>> * One limititation is that I don't think we can add a log before a table >>>> is created (i.e. to see the first entry). For example, let's say I want >>>> to log the very first creation of a bridge using `ovs-vsctl add-br br0`. >>>> Is there any way around it? I couldn't think of one. >>>> >>>> * Could you make the table and database names case-insensitive. For >>>> example, I can do `ovs-vsctl list open` even though the table name is >>>> actually Open_vSwitch? However, with this I need to specify the actual >>>> table name. >>>> >>>> * There is no way to list the tables that are currently 'on'. Something >>>> like vlog/list. >>>> >>>> * Would it be useful to be able to specify which level to log to?: e.g. >>>> >>>> tlog/set DB:TABLE:info >>>> >>>> * Would it be useful to have a non-verbose mode that only states that an >>>> insert/delete/update happened? >>>> >>> >>> Also, do we need to document this somewhere? I am not sure. >>> >> >> I'm not sure where though.. I couldn't find documentation (apart from >> occasional mentions in the NEWS file) for the other "ovsdb-server/..." >> appctl commands. >> > > Maybe /ovsdb/ovsdb-server.1 ? > Ah, right, my way of grepping for it was wrong! Thanks for pointing it out, I'll add documentation in the next revision.
On 9/22/21 12:29 PM, Dumitru Ceara wrote: > On 9/22/21 5:25 PM, Michael Santana wrote: >> >> >> On 9/22/21 3:24 AM, Dumitru Ceara wrote: >>> On 9/21/21 6:12 PM, Michael Santana wrote: >>>> >>>> >>>> On 9/16/21 11:37 AM, Dumitru Ceara wrote: >>>>> Add a new command, 'ovsdb-server/log-db-ops DB TABLE on|off', which >>>>> allows the user to enable/disable transaction logging for specific >>>>> databases and tables. >>>>> >>>>> By default, logging is disabled. Once enabled, logs are generated >>>>> with level INFO and are also rate limited. >>>>> >>>>> If used with care, this command can be useful in analyzing production >>>>> deployment performance issues, allowing the user to pin point >>>>> bottlenecks without the need to enable wider debug logs, e.g., jsonrpc. >>>>> >>>>> Signed-off-by: Dumitru Ceara <dceara@redhat.com> >>>>> --- >>>>> A sample use case is an ovn-kubernetes scaled deployment in which >>>>> we're interesting in reducing time to bring up PODs (represented by >>>>> OVN logical switch ports). In order to determine exactly where the >>>>> bottleneck is when provisioning PODs (CMS/ovn-nbctl/client >>>>> IDLs/ovsdb-server/ovn-controller/etc) we need timestamps of when >>>>> operations happen at various places in the stack. >>>>> >>>>> Without this patch the only option for tracking when transactions >>>>> happen in the Northbound database is to enable jsonrpc debug logs in >>>>> ovsdb-server. This generates a rather large amount of data. >>>>> >>>>> Instead, now, users would be able to just enable logging for the >>>>> Logical_Switch_Port table getting more relevant and precise >>>>> information. >>>> Very well written and explained >>>> >>>> Everything looks good to me. I just have one small question down below >>> >>> Thanks for reviewing this! >>> >>>>> >>>>> V2: >>>>> - rebased (fixed conflicts in NEWS). >>>>> --- >>>>> NEWS | 4 ++++ >>>>> ovsdb/ovsdb-server.c | 38 +++++++++++++++++++++++++++++++++ >>>>> ovsdb/row.c | 17 +++++++++++++++ >>>>> ovsdb/row.h | 1 + >>>>> ovsdb/table.c | 7 ++++++ >>>>> ovsdb/table.h | 3 +++ >>>>> ovsdb/transaction.c | 51 >>>>> ++++++++++++++++++++++++++++++++++++++++++++ >>>>> 7 files changed, 121 insertions(+) >>>>> >>>>> diff --git a/NEWS b/NEWS >>>>> index 90f4b15902b8..d56329772276 100644 >>>>> --- a/NEWS >>>>> +++ b/NEWS >>>>> @@ -10,6 +10,10 @@ Post-v2.16.0 >>>>> limiting behavior. >>>>> * Add hardware offload support for matching IPv4/IPv6 frag >>>>> types >>>>> (experimental). >>>>> + - OVSDB: >>>>> + * New unixctl command 'ovsdb-server/log-db-ops DB TABLE on|off". >>>>> + If turned on, ovsdb-server will log (at level INFO and rate >>>>> limited) >>>>> + all operations that are committed to table TABLE in the DB >>>>> database. >>>>> v2.16.0 - 16 Aug 2021 >>>>> diff --git a/ovsdb/ovsdb-server.c b/ovsdb/ovsdb-server.c >>>>> index 0b3d2bb71432..c48645f7e255 100644 >>>>> --- a/ovsdb/ovsdb-server.c >>>>> +++ b/ovsdb/ovsdb-server.c >>>>> @@ -115,6 +115,7 @@ static unixctl_cb_func ovsdb_server_list_remotes; >>>>> static unixctl_cb_func ovsdb_server_add_database; >>>>> static unixctl_cb_func ovsdb_server_remove_database; >>>>> static unixctl_cb_func ovsdb_server_list_databases; >>>>> +static unixctl_cb_func ovsdb_server_log_db_ops; >>>>> static void read_db(struct server_config *, struct db *); >>>>> static struct ovsdb_error *open_db(struct server_config *, >>>>> @@ -443,6 +444,8 @@ main(int argc, char *argv[]) >>>>> ovsdb_server_remove_database, >>>>> &server_config); >>>>> unixctl_command_register("ovsdb-server/list-dbs", "", 0, 0, >>>>> ovsdb_server_list_databases, &all_dbs); >>>>> + unixctl_command_register("ovsdb-server/log-db-ops", "DB TABLE >>>>> on|off", >>>>> + 3, 3, ovsdb_server_log_db_ops, &all_dbs); >>>>> unixctl_command_register("ovsdb-server/perf-counters-show", "", >>>>> 0, 0, >>>>> ovsdb_server_perf_counters_show, NULL); >>>>> unixctl_command_register("ovsdb-server/perf-counters-clear", "", >>>>> 0, 0, >>>>> @@ -1769,6 +1772,41 @@ ovsdb_server_list_databases(struct unixctl_conn >>>>> *conn, int argc OVS_UNUSED, >>>>> ds_destroy(&s); >>>>> } >>>>> +static void >>>>> +ovsdb_server_log_db_ops(struct unixctl_conn *conn, int argc >>>>> OVS_UNUSED, >>>>> + const char *argv[], void *all_dbs_) >>>>> +{ >>>>> + struct shash *all_dbs = all_dbs_; >>>>> + const char *db_name = argv[1]; >>>>> + const char *tbl_name = argv[2]; >>>>> + const char *command = argv[3]; >>>>> + bool log; >>>>> + >>>>> + if (!strcmp(command, "on")) { >>>>> + log = true; >>>>> + } else if (!strcmp(command, "off")) { >>>>> + log = false; >>>>> + } else { >>>>> + unixctl_command_reply_error(conn, "invalid argument"); >>>>> + return; >>>>> + } >>>>> + >>>>> + struct db *db = shash_find_data(all_dbs, db_name); >>>>> + if (!db) { >>>>> + unixctl_command_reply_error(conn, "no such database"); >>>>> + return; >>>>> + } >>>>> + >>>>> + struct ovsdb_table *table = ovsdb_get_table(db->db, tbl_name); >>>>> + if (!table) { >>>>> + unixctl_command_reply_error(conn, "no such table"); >>>>> + return; >>>>> + } >>>>> + >>>>> + ovsdb_table_log_ops(table, log); >>>>> + unixctl_command_reply(conn, NULL); >>>>> +} >>>>> + >>>>> static void >>>>> ovsdb_server_get_sync_status(struct unixctl_conn *conn, int argc >>>>> OVS_UNUSED, >>>>> const char *argv[] OVS_UNUSED, void >>>>> *config_) >>>>> diff --git a/ovsdb/row.c b/ovsdb/row.c >>>>> index 65a0546211c8..5e31716506bc 100644 >>>>> --- a/ovsdb/row.c >>>>> +++ b/ovsdb/row.c >>>>> @@ -278,6 +278,23 @@ ovsdb_row_to_json(const struct ovsdb_row *row, >>>>> } >>>>> return json; >>>>> } >>>>> + >>>>> +void >>>>> +ovsdb_row_to_string(const struct ovsdb_row *row, struct ds *out) >>>>> +{ >>>>> + struct shash_node *node; >>>>> + >>>>> + SHASH_FOR_EACH (node, &row->table->schema->columns) { >>>>> + const struct ovsdb_column *column = node->data; >>>>> + >>>>> + ds_put_format(out, "%s:", column->name); >>>>> + ovsdb_datum_to_string(&row->fields[column->index], >>>>> &column->type, out); >>>>> + ds_put_cstr(out, ","); >>>>> + } >>>>> + if (shash_count(&row->table->schema->columns)) { >>>>> + ds_chomp(out, ','); >>>>> + } >>>>> +} >>>>> >>>>> void >>>>> ovsdb_row_set_init(struct ovsdb_row_set *set) >>>>> diff --git a/ovsdb/row.h b/ovsdb/row.h >>>>> index 394ac8eb49b6..f22a08ecd197 100644 >>>>> --- a/ovsdb/row.h >>>>> +++ b/ovsdb/row.h >>>>> @@ -95,6 +95,7 @@ struct ovsdb_error *ovsdb_row_from_json(struct >>>>> ovsdb_row *, >>>>> OVS_WARN_UNUSED_RESULT; >>>>> struct json *ovsdb_row_to_json(const struct ovsdb_row *, >>>>> const struct ovsdb_column_set >>>>> *include); >>>>> +void ovsdb_row_to_string(const struct ovsdb_row *, struct ds *); >>>>> static inline const struct uuid * >>>>> ovsdb_row_get_uuid(const struct ovsdb_row *row) >>>>> diff --git a/ovsdb/table.c b/ovsdb/table.c >>>>> index 455a3663fe89..b7b41d139914 100644 >>>>> --- a/ovsdb/table.c >>>>> +++ b/ovsdb/table.c >>>>> @@ -301,10 +301,17 @@ ovsdb_table_create(struct ovsdb_table_schema *ts) >>>>> hmap_init(&table->indexes[i]); >>>>> } >>>>> hmap_init(&table->rows); >>>>> + table->log = false; >>>>> return table; >>>>> } >>>>> +void >>>>> +ovsdb_table_log_ops(struct ovsdb_table *table, bool enabled) >>>>> +{ >>>>> + table->log = enabled; >>>>> +} >>>>> + >>>>> void >>>>> ovsdb_table_destroy(struct ovsdb_table *table) >>>>> { >>>>> diff --git a/ovsdb/table.h b/ovsdb/table.h >>>>> index ce69a5d130bf..be88b7a59279 100644 >>>>> --- a/ovsdb/table.h >>>>> +++ b/ovsdb/table.h >>>>> @@ -63,10 +63,13 @@ struct ovsdb_table { >>>>> * ovsdb_row"s. Each of the hmap_nodes in indexes[i] are at >>>>> index 'i' at >>>>> * the end of struct ovsdb_row, following the 'fields' >>>>> member. */ >>>>> struct hmap *indexes; >>>>> + >>>>> + bool log; /* True if logging is enabled for this table. */ >>>>> }; >>>>> struct ovsdb_table *ovsdb_table_create(struct >>>>> ovsdb_table_schema *); >>>>> void ovsdb_table_destroy(struct ovsdb_table *); >>>>> +void ovsdb_table_log_ops(struct ovsdb_table *, bool); >>>>> const struct ovsdb_row *ovsdb_table_get_row(const struct >>>>> ovsdb_table *, >>>>> const struct uuid *); >>>>> diff --git a/ovsdb/transaction.c b/ovsdb/transaction.c >>>>> index 8ffefcf7c9d0..dc07e9c00a4b 100644 >>>>> --- a/ovsdb/transaction.c >>>>> +++ b/ovsdb/transaction.c >>>>> @@ -29,6 +29,7 @@ >>>>> #include "openvswitch/vlog.h" >>>>> #include "ovsdb-error.h" >>>>> #include "ovsdb.h" >>>>> +#include "ovs-thread.h" >>>>> #include "row.h" >>>>> #include "storage.h" >>>>> #include "table.h" >>>>> @@ -95,6 +96,7 @@ struct ovsdb_txn_row { >>>>> static struct ovsdb_error * OVS_WARN_UNUSED_RESULT >>>>> delete_garbage_row(struct ovsdb_txn *txn, struct ovsdb_txn_row *r); >>>>> static void ovsdb_txn_row_prefree(struct ovsdb_txn_row *); >>>>> +static void ovsdb_txn_row_log(const struct ovsdb_txn_row *); >>>>> static struct ovsdb_error * OVS_WARN_UNUSED_RESULT >>>>> for_each_txn_row(struct ovsdb_txn *txn, >>>>> struct ovsdb_error *(*)(struct ovsdb_txn *, >>>>> @@ -104,6 +106,11 @@ for_each_txn_row(struct ovsdb_txn *txn, >>>>> * processed. */ >>>>> static unsigned int serial; >>>>> +/* Used by ovsdb_txn_row_log() to avoid reallocating dynamic >>>>> strings >>>>> + * every time a row operation is logged. >>>>> + */ >>>>> +DEFINE_STATIC_PER_THREAD_DATA(struct ds, row_log_str, >>>>> DS_EMPTY_INITIALIZER); >>>>> + >>>>> struct ovsdb_txn * >>>>> ovsdb_txn_create(struct ovsdb *db) >>>>> { >>>>> @@ -422,6 +429,49 @@ update_ref_counts(struct ovsdb_txn *txn) >>>>> return for_each_txn_row(txn, check_ref_count); >>>>> } >>>>> +static void >>>>> +ovsdb_txn_row_log(const struct ovsdb_txn_row *txn_row) >>>>> +{ >>>>> + static struct vlog_rate_limit rl_insert = >>>>> VLOG_RATE_LIMIT_INIT(30, 60); >>>>> + static struct vlog_rate_limit rl_update = >>>>> VLOG_RATE_LIMIT_INIT(30, 60); >>>>> + static struct vlog_rate_limit rl_delete = >>>>> VLOG_RATE_LIMIT_INIT(30, 60); >>>>> + >>>>> + if (!txn_row->table->log) { >>>>> + return; >>>>> + } >>>> Shouldn't this if-block be before the rate limitter initialization? >>> >>> Well, I don't think it really matters because rl_insert/update/delete >>> are static variables but if you think it's more readable I can send a v2 >>> with the if-block moved up at the beginning of the function. >> I missed it being static variables and the rate limiter functions being >> preprocessor functions. I was concern about hurting performance in the >> default case by making function calls that wouldn't be used and then >> immediately returning. >> >> Despite that I think we can still hurt performance (maybe insignificant >> amount?) by calling ovsdb_txn_row_log() every time from >> ovsdb_txn_row_commit() >> >> maybe checking if it's enabled before calling ovsdb_txn_row_log() >> prevent us from making unnecessary function calls in the default case >> where the log is disabled: >> if (txn_row->table->log) { >> ovsdb_txn_row_log(txn_row); >> } > > ovsdb_txn_row_log() is static and will most likely be inlined by the > compiler. So I don't think it matters either if we add the if before > the call or not. > >> >> I dont how much of a difference it makes in terms of performance. If >> it's insignificant then just ignore this comment >> > > Just to make sure, I checked, on my rhel machine with quite an old GCC > version (gcc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-44)), when compiling > with -O2: > > $ objdump -S ovsdb/ovsdb-server > > 0000000000417a30 <ovsdb_txn_row_commit>: > { > [...] > if (!txn_row->table->log) { > 417ac4: 48 8b 45 38 mov 0x38(%rbp),%rax > 417ac8: 80 78 38 00 cmpb $0x0,0x38(%rax) > 417acc: 0f 85 bf 00 00 00 jne 417b91 > <ovsdb_txn_row_commit+0x161> > 417ad2: 66 0f 1f 44 00 00 nopw 0x0(%rax,%rax,1) > ovsdb_txn_row_prefree(txn_row); > 417ad8: 48 89 ef mov %rbp,%rdi > 417adb: e8 70 f7 ff ff callq 417250 > <ovsdb_txn_row_prefree> > > So I guess it's OK as is. Agreed Reviewed-by: Michael Santana <msantana@redhat.com> > > Regards, > Dumitru >
On 9/23/21 12:36 PM, Mark Gray wrote: > On 23/09/2021 11:20, Dumitru Ceara wrote: >> On 9/23/21 11:47 AM, Mark Gray wrote: >>> On 16/09/2021 16:37, Dumitru Ceara wrote: >>>> Add a new command, 'ovsdb-server/log-db-ops DB TABLE on|off', which >>>> allows the user to enable/disable transaction logging for specific >>>> databases and tables. >>>> >>>> By default, logging is disabled. Once enabled, logs are generated >>>> with level INFO and are also rate limited. >>>> >>>> If used with care, this command can be useful in analyzing production >>>> deployment performance issues, allowing the user to pin point >>>> bottlenecks without the need to enable wider debug logs, e.g., jsonrpc. >>>> >>>> Signed-off-by: Dumitru Ceara <dceara@redhat.com> >>>> --- >>>> A sample use case is an ovn-kubernetes scaled deployment in which >>>> we're interesting in reducing time to bring up PODs (represented by >>>> OVN logical switch ports). In order to determine exactly where the >>>> bottleneck is when provisioning PODs (CMS/ovn-nbctl/client >>>> IDLs/ovsdb-server/ovn-controller/etc) we need timestamps of when >>>> operations happen at various places in the stack. >>>> >>>> Without this patch the only option for tracking when transactions >>>> happen in the Northbound database is to enable jsonrpc debug logs in >>>> ovsdb-server. This generates a rather large amount of data. >>>> >>>> Instead, now, users would be able to just enable logging for the >>>> Logical_Switch_Port table getting more relevant and precise >>>> information. >>>> >>>> V2: >>>> - rebased (fixed conflicts in NEWS). >>> >>> Generally ok and I also did a quick test but I have a few comments on >>> the UI which wouldn't block an ACK and one small comment below in the code: >> >> Thanks for the review! >> >>> >>> * My personal preference would be that the syntax somewhat followed the >>> vlog/set one that seperates terms by ':'. Also a more memorable name. >>> For example tlog/set DB:TABLE:on or something like that but feel free to >>> choose to completely ignore me :) I just find it can sometimes be >>> difficult to remember syntax so I prefer some consistency. >> >> Makes sense, I'll try to come up with something more consistent. >> I went with "ovsdb-server/tlog-set DB:TABLE on|off" and "ovsdb-server/tlog--list". >>> >>> * One limititation is that I don't think we can add a log before a table >>> is created (i.e. to see the first entry). For example, let's say I want >>> to log the very first creation of a bridge using `ovs-vsctl add-br br0`. >>> Is there any way around it? I couldn't think of one. >> >> I'm not sure I follow this point. If you enable logging for the Bridge >> table before adding the first bridge you'll get the log, e.g., in an OVS >> sandbox: >> >> $ ovs-appctl -t $PWD/sandbox/ovsdb-server.*.ctl ovsdb-server/log-db-ops >> Open_vSwitch Bridge on >> >> $ ovs-vsctl show >> f43b960d-13f9-48d1-9898-703a3ac3f730 >> >> $ ovs-vsctl add-br br9 >> >> $ grep transaction sandbox/ovsdb-server.log >> 2021-09-23T09:57:53.426Z|00007|transaction|INFO|table:Bridge,op:inserted,name:br9,flood_vlans:[],auto_attach:[],ports:[388811ab-13a9-4b50-92c6-10c00a8b5e42],stp_enable:false,rstp_enable:false,_uuid:8a59955c-2a3c-41d3-9e93-66845e51878b,fail_mode:[],rstp_status:{},flow_tables:{},_version:1603df48-3730-4324-a71b-1c9f7eadb865,netflow:[],datapath_type:"",controller:[],other_config:{},external_ids:{},status:{},ipfix:[],datapath_id:[],mirrors:[],mcast_snooping_enable:false,datapath_version:"",sflow:[],protocols:[] >> [...] > > I just tested again and it does work. I think I must have specified > "bridge" instead of "Bridge". Sorry for the confusion. > No worries. >>> >>> * Could you make the table and database names case-insensitive. For >>> example, I can do `ovs-vsctl list open` even though the table name is >>> actually Open_vSwitch? However, with this I need to specify the actual >>> table name. >>> >> >> We can try but this would be a bit of an orthogonal change. For example >> "ovs-appctl -t .. ovsdb-server/remove-db DB" only accepts case sensitive >> database names (due to case sensitive shash operations). For using >> partial table names and/or, it would also be a more complex change. >> What you mentioned (ovs-vsctl) is actually implemented on the client >> side in db-ctl-base.c, get_table()/score_partial_match(). > > Ok, in that case, no need to update. > Ack. >> >>> * There is no way to list the tables that are currently 'on'. Something >>> like vlog/list. >> >> Good idea, I'll add it! > > Thanks > Done. >> >>> >>> * Would it be useful to be able to specify which level to log to?: e.g. >>> >>> tlog/set DB:TABLE:info >>> >> >> I'm not sure, maybe, although my initial goal was to make this usable at >> a reasonably high log level, e.g., INFO. I don't think there's a point >> to use an even higher level though (like WARN/ERR), though. > > Ok > I left it fixed at level INFO for now. >> >>> * Would it be useful to have a non-verbose mode that only states that an >>> insert/delete/update happened? >>> >> >> Would you log some row specific information then? E.g., _uuid. > > Perhaps, I am just thinking that it will reduce the log size. Maybe it's > not useful. > I decided not to implement this in the end. I'm not sure if the flexibility would actually make debugging easier. In any case, we can try to add it in the future if needed. [...] >>>> >>>> +static void >>>> +ovsdb_txn_row_log(const struct ovsdb_txn_row *txn_row) >>>> +{ >>>> + static struct vlog_rate_limit rl_insert = VLOG_RATE_LIMIT_INIT(30, 60); >>>> + static struct vlog_rate_limit rl_update = VLOG_RATE_LIMIT_INIT(30, 60); >>>> + static struct vlog_rate_limit rl_delete = VLOG_RATE_LIMIT_INIT(30, 60); >>> >>> Why do you have 3 different rate limiters? >>> >> >> Updates usually happen more often than inserts/deletes (e.g., with OVN >> logical ports). I thought it would be more useful if updates didn't >> consume tokens from the insert/delete logs. But thinking more about it, >> a rate of 30 logs per minute with a burst of 60 doesn't allow too many >> transactions to be logged often either. So, I guess, in a real use case >> the user would disable rate limiting for the "transaction" vlog module. >> We might as well move to a single rate limiter then. >> >> I'll change it in the next revision. >> Done. V3 posted: https://patchwork.ozlabs.org/project/openvswitch/list/?series=272306&state=* Regards, Dumitru
On 9/23/21 7:03 PM, Michael Santana wrote: > > > On 9/22/21 12:29 PM, Dumitru Ceara wrote: >> On 9/22/21 5:25 PM, Michael Santana wrote: >>> >>> >>> On 9/22/21 3:24 AM, Dumitru Ceara wrote: >>>> On 9/21/21 6:12 PM, Michael Santana wrote: >>>>> >>>>> >>>>> On 9/16/21 11:37 AM, Dumitru Ceara wrote: >>>>>> Add a new command, 'ovsdb-server/log-db-ops DB TABLE on|off', which >>>>>> allows the user to enable/disable transaction logging for specific >>>>>> databases and tables. >>>>>> >>>>>> By default, logging is disabled. Once enabled, logs are generated >>>>>> with level INFO and are also rate limited. >>>>>> >>>>>> If used with care, this command can be useful in analyzing production >>>>>> deployment performance issues, allowing the user to pin point >>>>>> bottlenecks without the need to enable wider debug logs, e.g., >>>>>> jsonrpc. >>>>>> >>>>>> Signed-off-by: Dumitru Ceara <dceara@redhat.com> >>>>>> --- >>>>>> A sample use case is an ovn-kubernetes scaled deployment in which >>>>>> we're interesting in reducing time to bring up PODs (represented by >>>>>> OVN logical switch ports). In order to determine exactly where the >>>>>> bottleneck is when provisioning PODs (CMS/ovn-nbctl/client >>>>>> IDLs/ovsdb-server/ovn-controller/etc) we need timestamps of when >>>>>> operations happen at various places in the stack. >>>>>> >>>>>> Without this patch the only option for tracking when transactions >>>>>> happen in the Northbound database is to enable jsonrpc debug logs in >>>>>> ovsdb-server. This generates a rather large amount of data. >>>>>> >>>>>> Instead, now, users would be able to just enable logging for the >>>>>> Logical_Switch_Port table getting more relevant and precise >>>>>> information. >>>>> Very well written and explained >>>>> >>>>> Everything looks good to me. I just have one small question down below >>>> >>>> Thanks for reviewing this! >>>> >>>>>> >>>>>> V2: >>>>>> - rebased (fixed conflicts in NEWS). >>>>>> --- >>>>>> NEWS | 4 ++++ >>>>>> ovsdb/ovsdb-server.c | 38 +++++++++++++++++++++++++++++++++ >>>>>> ovsdb/row.c | 17 +++++++++++++++ >>>>>> ovsdb/row.h | 1 + >>>>>> ovsdb/table.c | 7 ++++++ >>>>>> ovsdb/table.h | 3 +++ >>>>>> ovsdb/transaction.c | 51 >>>>>> ++++++++++++++++++++++++++++++++++++++++++++ >>>>>> 7 files changed, 121 insertions(+) >>>>>> >>>>>> diff --git a/NEWS b/NEWS >>>>>> index 90f4b15902b8..d56329772276 100644 >>>>>> --- a/NEWS >>>>>> +++ b/NEWS >>>>>> @@ -10,6 +10,10 @@ Post-v2.16.0 >>>>>> limiting behavior. >>>>>> * Add hardware offload support for matching IPv4/IPv6 frag >>>>>> types >>>>>> (experimental). >>>>>> + - OVSDB: >>>>>> + * New unixctl command 'ovsdb-server/log-db-ops DB TABLE >>>>>> on|off". >>>>>> + If turned on, ovsdb-server will log (at level INFO and rate >>>>>> limited) >>>>>> + all operations that are committed to table TABLE in the DB >>>>>> database. >>>>>> v2.16.0 - 16 Aug 2021 >>>>>> diff --git a/ovsdb/ovsdb-server.c b/ovsdb/ovsdb-server.c >>>>>> index 0b3d2bb71432..c48645f7e255 100644 >>>>>> --- a/ovsdb/ovsdb-server.c >>>>>> +++ b/ovsdb/ovsdb-server.c >>>>>> @@ -115,6 +115,7 @@ static unixctl_cb_func ovsdb_server_list_remotes; >>>>>> static unixctl_cb_func ovsdb_server_add_database; >>>>>> static unixctl_cb_func ovsdb_server_remove_database; >>>>>> static unixctl_cb_func ovsdb_server_list_databases; >>>>>> +static unixctl_cb_func ovsdb_server_log_db_ops; >>>>>> static void read_db(struct server_config *, struct db *); >>>>>> static struct ovsdb_error *open_db(struct server_config *, >>>>>> @@ -443,6 +444,8 @@ main(int argc, char *argv[]) >>>>>> ovsdb_server_remove_database, >>>>>> &server_config); >>>>>> unixctl_command_register("ovsdb-server/list-dbs", "", 0, 0, >>>>>> ovsdb_server_list_databases, >>>>>> &all_dbs); >>>>>> + unixctl_command_register("ovsdb-server/log-db-ops", "DB TABLE >>>>>> on|off", >>>>>> + 3, 3, ovsdb_server_log_db_ops, >>>>>> &all_dbs); >>>>>> >>>>>> unixctl_command_register("ovsdb-server/perf-counters-show", "", >>>>>> 0, 0, >>>>>> ovsdb_server_perf_counters_show, >>>>>> NULL); >>>>>> >>>>>> unixctl_command_register("ovsdb-server/perf-counters-clear", "", >>>>>> 0, 0, >>>>>> @@ -1769,6 +1772,41 @@ ovsdb_server_list_databases(struct >>>>>> unixctl_conn >>>>>> *conn, int argc OVS_UNUSED, >>>>>> ds_destroy(&s); >>>>>> } >>>>>> +static void >>>>>> +ovsdb_server_log_db_ops(struct unixctl_conn *conn, int argc >>>>>> OVS_UNUSED, >>>>>> + const char *argv[], void *all_dbs_) >>>>>> +{ >>>>>> + struct shash *all_dbs = all_dbs_; >>>>>> + const char *db_name = argv[1]; >>>>>> + const char *tbl_name = argv[2]; >>>>>> + const char *command = argv[3]; >>>>>> + bool log; >>>>>> + >>>>>> + if (!strcmp(command, "on")) { >>>>>> + log = true; >>>>>> + } else if (!strcmp(command, "off")) { >>>>>> + log = false; >>>>>> + } else { >>>>>> + unixctl_command_reply_error(conn, "invalid argument"); >>>>>> + return; >>>>>> + } >>>>>> + >>>>>> + struct db *db = shash_find_data(all_dbs, db_name); >>>>>> + if (!db) { >>>>>> + unixctl_command_reply_error(conn, "no such database"); >>>>>> + return; >>>>>> + } >>>>>> + >>>>>> + struct ovsdb_table *table = ovsdb_get_table(db->db, tbl_name); >>>>>> + if (!table) { >>>>>> + unixctl_command_reply_error(conn, "no such table"); >>>>>> + return; >>>>>> + } >>>>>> + >>>>>> + ovsdb_table_log_ops(table, log); >>>>>> + unixctl_command_reply(conn, NULL); >>>>>> +} >>>>>> + >>>>>> static void >>>>>> ovsdb_server_get_sync_status(struct unixctl_conn *conn, int argc >>>>>> OVS_UNUSED, >>>>>> const char *argv[] OVS_UNUSED, void >>>>>> *config_) >>>>>> diff --git a/ovsdb/row.c b/ovsdb/row.c >>>>>> index 65a0546211c8..5e31716506bc 100644 >>>>>> --- a/ovsdb/row.c >>>>>> +++ b/ovsdb/row.c >>>>>> @@ -278,6 +278,23 @@ ovsdb_row_to_json(const struct ovsdb_row *row, >>>>>> } >>>>>> return json; >>>>>> } >>>>>> + >>>>>> +void >>>>>> +ovsdb_row_to_string(const struct ovsdb_row *row, struct ds *out) >>>>>> +{ >>>>>> + struct shash_node *node; >>>>>> + >>>>>> + SHASH_FOR_EACH (node, &row->table->schema->columns) { >>>>>> + const struct ovsdb_column *column = node->data; >>>>>> + >>>>>> + ds_put_format(out, "%s:", column->name); >>>>>> + ovsdb_datum_to_string(&row->fields[column->index], >>>>>> &column->type, out); >>>>>> + ds_put_cstr(out, ","); >>>>>> + } >>>>>> + if (shash_count(&row->table->schema->columns)) { >>>>>> + ds_chomp(out, ','); >>>>>> + } >>>>>> +} >>>>>> >>>>>> void >>>>>> ovsdb_row_set_init(struct ovsdb_row_set *set) >>>>>> diff --git a/ovsdb/row.h b/ovsdb/row.h >>>>>> index 394ac8eb49b6..f22a08ecd197 100644 >>>>>> --- a/ovsdb/row.h >>>>>> +++ b/ovsdb/row.h >>>>>> @@ -95,6 +95,7 @@ struct ovsdb_error *ovsdb_row_from_json(struct >>>>>> ovsdb_row *, >>>>>> OVS_WARN_UNUSED_RESULT; >>>>>> struct json *ovsdb_row_to_json(const struct ovsdb_row *, >>>>>> const struct ovsdb_column_set >>>>>> *include); >>>>>> +void ovsdb_row_to_string(const struct ovsdb_row *, struct ds *); >>>>>> static inline const struct uuid * >>>>>> ovsdb_row_get_uuid(const struct ovsdb_row *row) >>>>>> diff --git a/ovsdb/table.c b/ovsdb/table.c >>>>>> index 455a3663fe89..b7b41d139914 100644 >>>>>> --- a/ovsdb/table.c >>>>>> +++ b/ovsdb/table.c >>>>>> @@ -301,10 +301,17 @@ ovsdb_table_create(struct ovsdb_table_schema >>>>>> *ts) >>>>>> hmap_init(&table->indexes[i]); >>>>>> } >>>>>> hmap_init(&table->rows); >>>>>> + table->log = false; >>>>>> return table; >>>>>> } >>>>>> +void >>>>>> +ovsdb_table_log_ops(struct ovsdb_table *table, bool enabled) >>>>>> +{ >>>>>> + table->log = enabled; >>>>>> +} >>>>>> + >>>>>> void >>>>>> ovsdb_table_destroy(struct ovsdb_table *table) >>>>>> { >>>>>> diff --git a/ovsdb/table.h b/ovsdb/table.h >>>>>> index ce69a5d130bf..be88b7a59279 100644 >>>>>> --- a/ovsdb/table.h >>>>>> +++ b/ovsdb/table.h >>>>>> @@ -63,10 +63,13 @@ struct ovsdb_table { >>>>>> * ovsdb_row"s. Each of the hmap_nodes in indexes[i] are at >>>>>> index 'i' at >>>>>> * the end of struct ovsdb_row, following the 'fields' >>>>>> member. */ >>>>>> struct hmap *indexes; >>>>>> + >>>>>> + bool log; /* True if logging is enabled for this table. */ >>>>>> }; >>>>>> struct ovsdb_table *ovsdb_table_create(struct >>>>>> ovsdb_table_schema *); >>>>>> void ovsdb_table_destroy(struct ovsdb_table *); >>>>>> +void ovsdb_table_log_ops(struct ovsdb_table *, bool); >>>>>> const struct ovsdb_row *ovsdb_table_get_row(const struct >>>>>> ovsdb_table *, >>>>>> const struct uuid *); >>>>>> diff --git a/ovsdb/transaction.c b/ovsdb/transaction.c >>>>>> index 8ffefcf7c9d0..dc07e9c00a4b 100644 >>>>>> --- a/ovsdb/transaction.c >>>>>> +++ b/ovsdb/transaction.c >>>>>> @@ -29,6 +29,7 @@ >>>>>> #include "openvswitch/vlog.h" >>>>>> #include "ovsdb-error.h" >>>>>> #include "ovsdb.h" >>>>>> +#include "ovs-thread.h" >>>>>> #include "row.h" >>>>>> #include "storage.h" >>>>>> #include "table.h" >>>>>> @@ -95,6 +96,7 @@ struct ovsdb_txn_row { >>>>>> static struct ovsdb_error * OVS_WARN_UNUSED_RESULT >>>>>> delete_garbage_row(struct ovsdb_txn *txn, struct ovsdb_txn_row >>>>>> *r); >>>>>> static void ovsdb_txn_row_prefree(struct ovsdb_txn_row *); >>>>>> +static void ovsdb_txn_row_log(const struct ovsdb_txn_row *); >>>>>> static struct ovsdb_error * OVS_WARN_UNUSED_RESULT >>>>>> for_each_txn_row(struct ovsdb_txn *txn, >>>>>> struct ovsdb_error *(*)(struct ovsdb_txn *, >>>>>> @@ -104,6 +106,11 @@ for_each_txn_row(struct ovsdb_txn *txn, >>>>>> * processed. */ >>>>>> static unsigned int serial; >>>>>> +/* Used by ovsdb_txn_row_log() to avoid reallocating dynamic >>>>>> strings >>>>>> + * every time a row operation is logged. >>>>>> + */ >>>>>> +DEFINE_STATIC_PER_THREAD_DATA(struct ds, row_log_str, >>>>>> DS_EMPTY_INITIALIZER); >>>>>> + >>>>>> struct ovsdb_txn * >>>>>> ovsdb_txn_create(struct ovsdb *db) >>>>>> { >>>>>> @@ -422,6 +429,49 @@ update_ref_counts(struct ovsdb_txn *txn) >>>>>> return for_each_txn_row(txn, check_ref_count); >>>>>> } >>>>>> +static void >>>>>> +ovsdb_txn_row_log(const struct ovsdb_txn_row *txn_row) >>>>>> +{ >>>>>> + static struct vlog_rate_limit rl_insert = >>>>>> VLOG_RATE_LIMIT_INIT(30, 60); >>>>>> + static struct vlog_rate_limit rl_update = >>>>>> VLOG_RATE_LIMIT_INIT(30, 60); >>>>>> + static struct vlog_rate_limit rl_delete = >>>>>> VLOG_RATE_LIMIT_INIT(30, 60); >>>>>> + >>>>>> + if (!txn_row->table->log) { >>>>>> + return; >>>>>> + } >>>>> Shouldn't this if-block be before the rate limitter initialization? >>>> >>>> Well, I don't think it really matters because rl_insert/update/delete >>>> are static variables but if you think it's more readable I can send >>>> a v2 >>>> with the if-block moved up at the beginning of the function. >>> I missed it being static variables and the rate limiter functions being >>> preprocessor functions. I was concern about hurting performance in the >>> default case by making function calls that wouldn't be used and then >>> immediately returning. >>> >>> Despite that I think we can still hurt performance (maybe insignificant >>> amount?) by calling ovsdb_txn_row_log() every time from >>> ovsdb_txn_row_commit() >>> >>> maybe checking if it's enabled before calling ovsdb_txn_row_log() >>> prevent us from making unnecessary function calls in the default case >>> where the log is disabled: >>> if (txn_row->table->log) { >>> ovsdb_txn_row_log(txn_row); >>> } >> >> ovsdb_txn_row_log() is static and will most likely be inlined by the >> compiler. So I don't think it matters either if we add the if before >> the call or not. >> >>> >>> I dont how much of a difference it makes in terms of performance. If >>> it's insignificant then just ignore this comment >>> >> >> Just to make sure, I checked, on my rhel machine with quite an old GCC >> version (gcc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-44)), when compiling >> with -O2: >> >> $ objdump -S ovsdb/ovsdb-server >> >> 0000000000417a30 <ovsdb_txn_row_commit>: >> { >> [...] >> if (!txn_row->table->log) { >> 417ac4: 48 8b 45 38 mov 0x38(%rbp),%rax >> 417ac8: 80 78 38 00 cmpb $0x0,0x38(%rax) >> 417acc: 0f 85 bf 00 00 00 jne 417b91 >> <ovsdb_txn_row_commit+0x161> >> 417ad2: 66 0f 1f 44 00 00 nopw 0x0(%rax,%rax,1) >> ovsdb_txn_row_prefree(txn_row); >> 417ad8: 48 89 ef mov %rbp,%rdi >> 417adb: e8 70 f7 ff ff callq 417250 >> <ovsdb_txn_row_prefree> >> >> So I guess it's OK as is. > Agreed > > Reviewed-by: Michael Santana <msantana@redhat.com> Thanks for the review! However, since I made quite a few changes in v3 I decided to not add your "Reviewed-by". It would be great if you could have a look at the new revision: https://patchwork.ozlabs.org/project/openvswitch/list/?series=272306&state=* Thanks, Dumitru
diff --git a/NEWS b/NEWS index 90f4b15902b8..d56329772276 100644 --- a/NEWS +++ b/NEWS @@ -10,6 +10,10 @@ Post-v2.16.0 limiting behavior. * Add hardware offload support for matching IPv4/IPv6 frag types (experimental). + - OVSDB: + * New unixctl command 'ovsdb-server/log-db-ops DB TABLE on|off". + If turned on, ovsdb-server will log (at level INFO and rate limited) + all operations that are committed to table TABLE in the DB database. v2.16.0 - 16 Aug 2021 diff --git a/ovsdb/ovsdb-server.c b/ovsdb/ovsdb-server.c index 0b3d2bb71432..c48645f7e255 100644 --- a/ovsdb/ovsdb-server.c +++ b/ovsdb/ovsdb-server.c @@ -115,6 +115,7 @@ static unixctl_cb_func ovsdb_server_list_remotes; static unixctl_cb_func ovsdb_server_add_database; static unixctl_cb_func ovsdb_server_remove_database; static unixctl_cb_func ovsdb_server_list_databases; +static unixctl_cb_func ovsdb_server_log_db_ops; static void read_db(struct server_config *, struct db *); static struct ovsdb_error *open_db(struct server_config *, @@ -443,6 +444,8 @@ main(int argc, char *argv[]) ovsdb_server_remove_database, &server_config); unixctl_command_register("ovsdb-server/list-dbs", "", 0, 0, ovsdb_server_list_databases, &all_dbs); + unixctl_command_register("ovsdb-server/log-db-ops", "DB TABLE on|off", + 3, 3, ovsdb_server_log_db_ops, &all_dbs); unixctl_command_register("ovsdb-server/perf-counters-show", "", 0, 0, ovsdb_server_perf_counters_show, NULL); unixctl_command_register("ovsdb-server/perf-counters-clear", "", 0, 0, @@ -1769,6 +1772,41 @@ ovsdb_server_list_databases(struct unixctl_conn *conn, int argc OVS_UNUSED, ds_destroy(&s); } +static void +ovsdb_server_log_db_ops(struct unixctl_conn *conn, int argc OVS_UNUSED, + const char *argv[], void *all_dbs_) +{ + struct shash *all_dbs = all_dbs_; + const char *db_name = argv[1]; + const char *tbl_name = argv[2]; + const char *command = argv[3]; + bool log; + + if (!strcmp(command, "on")) { + log = true; + } else if (!strcmp(command, "off")) { + log = false; + } else { + unixctl_command_reply_error(conn, "invalid argument"); + return; + } + + struct db *db = shash_find_data(all_dbs, db_name); + if (!db) { + unixctl_command_reply_error(conn, "no such database"); + return; + } + + struct ovsdb_table *table = ovsdb_get_table(db->db, tbl_name); + if (!table) { + unixctl_command_reply_error(conn, "no such table"); + return; + } + + ovsdb_table_log_ops(table, log); + unixctl_command_reply(conn, NULL); +} + static void ovsdb_server_get_sync_status(struct unixctl_conn *conn, int argc OVS_UNUSED, const char *argv[] OVS_UNUSED, void *config_) diff --git a/ovsdb/row.c b/ovsdb/row.c index 65a0546211c8..5e31716506bc 100644 --- a/ovsdb/row.c +++ b/ovsdb/row.c @@ -278,6 +278,23 @@ ovsdb_row_to_json(const struct ovsdb_row *row, } return json; } + +void +ovsdb_row_to_string(const struct ovsdb_row *row, struct ds *out) +{ + struct shash_node *node; + + SHASH_FOR_EACH (node, &row->table->schema->columns) { + const struct ovsdb_column *column = node->data; + + ds_put_format(out, "%s:", column->name); + ovsdb_datum_to_string(&row->fields[column->index], &column->type, out); + ds_put_cstr(out, ","); + } + if (shash_count(&row->table->schema->columns)) { + ds_chomp(out, ','); + } +} void ovsdb_row_set_init(struct ovsdb_row_set *set) diff --git a/ovsdb/row.h b/ovsdb/row.h index 394ac8eb49b6..f22a08ecd197 100644 --- a/ovsdb/row.h +++ b/ovsdb/row.h @@ -95,6 +95,7 @@ struct ovsdb_error *ovsdb_row_from_json(struct ovsdb_row *, OVS_WARN_UNUSED_RESULT; struct json *ovsdb_row_to_json(const struct ovsdb_row *, const struct ovsdb_column_set *include); +void ovsdb_row_to_string(const struct ovsdb_row *, struct ds *); static inline const struct uuid * ovsdb_row_get_uuid(const struct ovsdb_row *row) diff --git a/ovsdb/table.c b/ovsdb/table.c index 455a3663fe89..b7b41d139914 100644 --- a/ovsdb/table.c +++ b/ovsdb/table.c @@ -301,10 +301,17 @@ ovsdb_table_create(struct ovsdb_table_schema *ts) hmap_init(&table->indexes[i]); } hmap_init(&table->rows); + table->log = false; return table; } +void +ovsdb_table_log_ops(struct ovsdb_table *table, bool enabled) +{ + table->log = enabled; +} + void ovsdb_table_destroy(struct ovsdb_table *table) { diff --git a/ovsdb/table.h b/ovsdb/table.h index ce69a5d130bf..be88b7a59279 100644 --- a/ovsdb/table.h +++ b/ovsdb/table.h @@ -63,10 +63,13 @@ struct ovsdb_table { * ovsdb_row"s. Each of the hmap_nodes in indexes[i] are at index 'i' at * the end of struct ovsdb_row, following the 'fields' member. */ struct hmap *indexes; + + bool log; /* True if logging is enabled for this table. */ }; struct ovsdb_table *ovsdb_table_create(struct ovsdb_table_schema *); void ovsdb_table_destroy(struct ovsdb_table *); +void ovsdb_table_log_ops(struct ovsdb_table *, bool); const struct ovsdb_row *ovsdb_table_get_row(const struct ovsdb_table *, const struct uuid *); diff --git a/ovsdb/transaction.c b/ovsdb/transaction.c index 8ffefcf7c9d0..dc07e9c00a4b 100644 --- a/ovsdb/transaction.c +++ b/ovsdb/transaction.c @@ -29,6 +29,7 @@ #include "openvswitch/vlog.h" #include "ovsdb-error.h" #include "ovsdb.h" +#include "ovs-thread.h" #include "row.h" #include "storage.h" #include "table.h" @@ -95,6 +96,7 @@ struct ovsdb_txn_row { static struct ovsdb_error * OVS_WARN_UNUSED_RESULT delete_garbage_row(struct ovsdb_txn *txn, struct ovsdb_txn_row *r); static void ovsdb_txn_row_prefree(struct ovsdb_txn_row *); +static void ovsdb_txn_row_log(const struct ovsdb_txn_row *); static struct ovsdb_error * OVS_WARN_UNUSED_RESULT for_each_txn_row(struct ovsdb_txn *txn, struct ovsdb_error *(*)(struct ovsdb_txn *, @@ -104,6 +106,11 @@ for_each_txn_row(struct ovsdb_txn *txn, * processed. */ static unsigned int serial; +/* Used by ovsdb_txn_row_log() to avoid reallocating dynamic strings + * every time a row operation is logged. + */ +DEFINE_STATIC_PER_THREAD_DATA(struct ds, row_log_str, DS_EMPTY_INITIALIZER); + struct ovsdb_txn * ovsdb_txn_create(struct ovsdb *db) { @@ -422,6 +429,49 @@ update_ref_counts(struct ovsdb_txn *txn) return for_each_txn_row(txn, check_ref_count); } +static void +ovsdb_txn_row_log(const struct ovsdb_txn_row *txn_row) +{ + static struct vlog_rate_limit rl_insert = VLOG_RATE_LIMIT_INIT(30, 60); + static struct vlog_rate_limit rl_update = VLOG_RATE_LIMIT_INIT(30, 60); + static struct vlog_rate_limit rl_delete = VLOG_RATE_LIMIT_INIT(30, 60); + + if (!txn_row->table->log) { + return; + } + + size_t n_columns = shash_count(&txn_row->table->schema->columns); + struct ovsdb_row *log_row; + const char *op = NULL; + + if (!txn_row->old && txn_row->new) { + if (!vlog_should_drop(&this_module, VLL_INFO, &rl_insert)) { + log_row = txn_row->new; + op = "inserted"; + } + } else if (txn_row->old && txn_row->new + && !bitmap_is_all_zeros(txn_row->changed, n_columns)) { + if (!vlog_should_drop(&this_module, VLL_INFO, &rl_update)) { + log_row = txn_row->new; + op = "updated"; + } + } else if (txn_row->old && !txn_row->new) { + if (!vlog_should_drop(&this_module, VLL_INFO, &rl_delete)) { + log_row = txn_row->old; + op = "deleted"; + } + } + + if (op) { + struct ds *ds = row_log_str_get(); + ds_clear(ds); + ds_put_format(ds, "table:%s,op:%s,", txn_row->table->schema->name, + op); + ovsdb_row_to_string(log_row, ds); + VLOG_INFO("%s", ds_cstr(ds)); + } +} + static struct ovsdb_error * ovsdb_txn_row_commit(struct ovsdb_txn *txn OVS_UNUSED, struct ovsdb_txn_row *txn_row) @@ -445,6 +495,7 @@ ovsdb_txn_row_commit(struct ovsdb_txn *txn OVS_UNUSED, } } + ovsdb_txn_row_log(txn_row); ovsdb_txn_row_prefree(txn_row); if (txn_row->new) { txn_row->new->n_refs = txn_row->n_refs;
Add a new command, 'ovsdb-server/log-db-ops DB TABLE on|off', which allows the user to enable/disable transaction logging for specific databases and tables. By default, logging is disabled. Once enabled, logs are generated with level INFO and are also rate limited. If used with care, this command can be useful in analyzing production deployment performance issues, allowing the user to pin point bottlenecks without the need to enable wider debug logs, e.g., jsonrpc. Signed-off-by: Dumitru Ceara <dceara@redhat.com> --- A sample use case is an ovn-kubernetes scaled deployment in which we're interesting in reducing time to bring up PODs (represented by OVN logical switch ports). In order to determine exactly where the bottleneck is when provisioning PODs (CMS/ovn-nbctl/client IDLs/ovsdb-server/ovn-controller/etc) we need timestamps of when operations happen at various places in the stack. Without this patch the only option for tracking when transactions happen in the Northbound database is to enable jsonrpc debug logs in ovsdb-server. This generates a rather large amount of data. Instead, now, users would be able to just enable logging for the Logical_Switch_Port table getting more relevant and precise information. V2: - rebased (fixed conflicts in NEWS). --- NEWS | 4 ++++ ovsdb/ovsdb-server.c | 38 +++++++++++++++++++++++++++++++++ ovsdb/row.c | 17 +++++++++++++++ ovsdb/row.h | 1 + ovsdb/table.c | 7 ++++++ ovsdb/table.h | 3 +++ ovsdb/transaction.c | 51 ++++++++++++++++++++++++++++++++++++++++++++ 7 files changed, 121 insertions(+)