Add a new command, 'ovsdb-server/tlog-set 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. A command to inspect the logging state is also added: 'ovsdb-server/tlog-list'. Signed-off-by: Dumitru Ceara <[email protected]> --- 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. V4: - Fixed usage string of ovsdb-server/tlog-list (it was hiding the command). - addressed Ilya's comments: - case insensitive on/off check - ds_put_cstr()/_char() where applicable - renamed some of the functions - simplified log rate limit check V3: - rebased - addressed Mark Gray's comments V2: - rebased (fixed conflicts in NEWS). --- NEWS | 3 ++ ovsdb/ovsdb-server.1.in | 7 ++++ ovsdb/ovsdb-server.c | 87 +++++++++++++++++++++++++++++++++++++++++ ovsdb/row.c | 17 ++++++++ ovsdb/row.h | 1 + ovsdb/table.c | 13 ++++++ ovsdb/table.h | 4 ++ ovsdb/transaction.c | 43 ++++++++++++++++++++ 8 files changed, 175 insertions(+) diff --git a/NEWS b/NEWS index 9fe3f44f431a..d7724a4573f6 100644 --- a/NEWS +++ b/NEWS @@ -14,6 +14,9 @@ Post-v2.17.0 - OVSDB: * 'relay' service model now supports transaction history, i.e. honors the 'last-txn-id' field in 'monitor_cond_since' requests from clients. + * New unixctl command 'ovsdb-server/tlog-set 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. - OVSDB-IDL: * New monitor mode flag, OVSDB_IDL_WRITE_CHANGED_ONLY, allowing applications to relax atomicity requirements when dealing with diff --git a/ovsdb/ovsdb-server.1.in b/ovsdb/ovsdb-server.1.in index dac0f02cb987..da7a6fd5d542 100644 --- a/ovsdb/ovsdb-server.1.in +++ b/ovsdb/ovsdb-server.1.in @@ -273,6 +273,13 @@ again (with \fBovsdb\-server/add\-db\fR). Outputs a list of the currently configured databases added either through the command line or through the \fBovsdb\-server/add\-db\fR command. . +.IP "\fBovsdb\-server/tlog\-set \fIdatabase\fR:\fItable\fR \fIon\fR|\fIoff\fR" +Enables or disables logging of all operations executed on the specified +database and table. Logs are generated at INFO level and are rate limtied. +. +.IP "\fBovsdb\-server/tlog\-list" +Displays the logging state for all currently configured databases and tables. +. .SS "Active-Backup Commands" .PP These commands query and update the role of \fBovsdb\-server\fR within diff --git a/ovsdb/ovsdb-server.c b/ovsdb/ovsdb-server.c index 8fa9379030c2..5549b4e3a6c7 100644 --- a/ovsdb/ovsdb-server.c +++ b/ovsdb/ovsdb-server.c @@ -116,6 +116,8 @@ 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_tlog_set; +static unixctl_cb_func ovsdb_server_tlog_list; static void read_db(struct server_config *, struct db *); static struct ovsdb_error *open_db(struct server_config *, @@ -444,6 +446,10 @@ 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/tlog-set", "DB:TABLE on|off", + 2, 2, ovsdb_server_tlog_set, &all_dbs); + unixctl_command_register("ovsdb-server/tlog-list", "", + 0, 0, ovsdb_server_tlog_list, &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, @@ -1774,6 +1780,87 @@ ovsdb_server_list_databases(struct unixctl_conn *conn, int argc OVS_UNUSED, ds_destroy(&s); } +static void +ovsdb_server_tlog_set(struct unixctl_conn *conn, int argc OVS_UNUSED, + const char *argv[], void *all_dbs_) +{ + struct shash *all_dbs = all_dbs_; + const char *name_ = argv[1]; + const char *command = argv[2]; + bool log; + + if (!strcasecmp(command, "on")) { + log = true; + } else if (!strcasecmp(command, "off")) { + log = false; + } else { + unixctl_command_reply_error(conn, "invalid command argument"); + return; + } + + char *name = xstrdup(name_); + char *save_ptr = NULL; + + const char *db_name = strtok_r(name, ":", &save_ptr); /* "DB" */ + const char *tbl_name = strtok_r(NULL, ":", &save_ptr); /* "TABLE" */ + if (!db_name || !tbl_name || strtok_r(NULL, ":", &save_ptr)) { + unixctl_command_reply_error(conn, "invalid DB:TABLE argument"); + goto out; + } + + struct db *db = shash_find_data(all_dbs, db_name); + if (!db) { + unixctl_command_reply_error(conn, "no such database"); + goto out; + } + + struct ovsdb_table *table = ovsdb_get_table(db->db, tbl_name); + if (!table) { + unixctl_command_reply_error(conn, "no such table"); + goto out; + } + + ovsdb_table_logging_enable(table, log); + unixctl_command_reply(conn, NULL); +out: + free(name); +} + +static void +ovsdb_server_tlog_list(struct unixctl_conn *conn, int argc OVS_UNUSED, + const char *argv[] OVS_UNUSED, void *all_dbs_) +{ + const struct shash_node **db_nodes; + struct ds s = DS_EMPTY_INITIALIZER; + struct shash *all_dbs = all_dbs_; + + ds_put_cstr(&s, "database table logging\n"); + ds_put_cstr(&s, "-------- ----- -------\n"); + + db_nodes = shash_sort(all_dbs); + for (size_t i = 0; i < shash_count(all_dbs); i++) { + const struct shash_node *db_node = db_nodes[i]; + struct db *db = db_node->data; + if (db->db) { + const struct shash_node **tbl_nodes = shash_sort(&db->db->tables); + + ds_put_format(&s, "%-16s \n", db_node->name); + for (size_t j = 0; j < shash_count(&db->db->tables); j++) { + const char *logging_enabled = + ovsdb_table_is_logging_enabled(tbl_nodes[j]->data) + ? "ON" : "OFF"; + ds_put_format(&s, " %-27s %s\n", + tbl_nodes[j]->name, logging_enabled); + } + free(tbl_nodes); + } + } + free(db_nodes); + + unixctl_command_reply(conn, ds_cstr(&s)); + ds_destroy(&s); +} + 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 40f53b0a5dfc..f93fe2306620 100644 --- a/ovsdb/row.c +++ b/ovsdb/row.c @@ -343,6 +343,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_char(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 fe04555d0c2d..4d3c17afca66 100644 --- a/ovsdb/row.h +++ b/ovsdb/row.h @@ -117,6 +117,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 2184701ec1dc..66071ce2f883 100644 --- a/ovsdb/table.c +++ b/ovsdb/table.c @@ -301,10 +301,23 @@ 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_logging_enable(struct ovsdb_table *table, bool enabled) +{ + table->log = enabled; +} + +bool +ovsdb_table_is_logging_enabled(struct ovsdb_table *table) +{ + return table->log; +} + void ovsdb_table_destroy(struct ovsdb_table *table) { diff --git a/ovsdb/table.h b/ovsdb/table.h index ce69a5d130bf..614c4ed826aa 100644 --- a/ovsdb/table.h +++ b/ovsdb/table.h @@ -63,10 +63,14 @@ 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_logging_enable(struct ovsdb_table *, bool); +bool ovsdb_table_is_logging_enabled(struct ovsdb_table *table); 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 437a7549475d..ab7bb0eb168a 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" @@ -102,6 +103,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 *, @@ -111,6 +113,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) { @@ -471,6 +478,41 @@ 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_row_log = 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) { + log_row = txn_row->new; + op = "inserted"; + } else if (txn_row->old && txn_row->new + && !bitmap_is_all_zeros(txn_row->changed, n_columns)) { + log_row = txn_row->new; + op = "updated"; + } else if (txn_row->old && !txn_row->new) { + log_row = txn_row->old; + op = "deleted"; + } + + if (op && !VLOG_DROP_INFO(&rl_row_log)) { + 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) @@ -494,6 +536,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; -- 2.31.1 _______________________________________________ dev mailing list [email protected] https://mail.openvswitch.org/mailman/listinfo/ovs-dev
