On 6/20/22 18:46, Ilya Maximets wrote:
> On 11/16/21 15:34, Dumitru Ceara wrote:
>> 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.
>
> Hi, Dumitru. Thanks for the patch and sorry it took so long
> for me to review.
Hi Ilya!
No problem, thanks for taking a look!
>
> The change looks good to me in general. See some minor comments inline.
>
> Best regards, Ilya Maximets.
>
>>
>> V3:
>> - rebased
>> - addressed Mark Gray's comments
>> V2:
>> - rebased (fixed conflicts in NEWS).
>> ---
>> NEWS | 4 ++
>> ovsdb/ovsdb-server.1.in | 7 ++++
>> ovsdb/ovsdb-server.c | 86 +++++++++++++++++++++++++++++++++++++++++
>> ovsdb/row.c | 17 ++++++++
>> ovsdb/row.h | 1 +
>> ovsdb/table.c | 13 +++++++
>> ovsdb/table.h | 4 ++
>> ovsdb/transaction.c | 49 +++++++++++++++++++++++
>> 8 files changed, 181 insertions(+)
>>
>> diff --git a/NEWS b/NEWS
>> index 434ee570fb69..cc73f46f0135 100644
>> --- a/NEWS
>> +++ b/NEWS
>> @@ -16,6 +16,10 @@ Post-v2.16.0
>> - ovs-dpctl and 'ovs-appctl dpctl/':
>> * New commands 'cache-get-size' and 'cache-set-size' that allows to
>> get or configure linux kernel datapath cache sizes.
>> + - OVSDB:
>> + * 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.
>>
>>
>> v2.16.0 - 16 Aug 2021
>> 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 b34d97e29163..1a64363c7814 100644
>> --- a/ovsdb/ovsdb-server.c
>> +++ b/ovsdb/ovsdb-server.c
>> @@ -115,6 +115,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 *,
>> @@ -443,6 +445,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", NULL,
>> + 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,
>> @@ -1769,6 +1775,86 @@ 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 (!strcmp(command, "on")) {
>
> We're reporting these as "ON/OFF", but accepting "on/off".
> It's, probably, better to use strcasecmp here.
>
Sure, will do.
>> + log = true;
>> + } else if (!strcmp(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_log_ops(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_format(&s, "database table
>> logging\n");
>> + ds_put_format(&s, "-------- -----
>> -------\n");
>
> ds_put_cstr()
>
Ack.
>> +
>> + 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++) {
>> + ds_put_format(&s, " %-27s %s\n",
>> + tbl_nodes[j]->name,
>> + ovsdb_table_is_logging_ops(tbl_nodes[j]->data)
>> + ? "ON" : "OFF");
>> + }
>> + 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 e83c60a218f6..e88cd683f7e6 100644
>> --- a/ovsdb/row.c
>> +++ b/ovsdb/row.c
>> @@ -349,6 +349,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, ",");
>
> ds_put_char(out, ',');
>
Ack.
>> + }
>> + 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 455a3663fe89..bfc0976cb8e0 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_log_ops(struct ovsdb_table *table, bool enabled)
>
> Looks like a leftover from v1. Cna we rename this
> to, e.g., ovsdb_table_logging_enable() ?
>
Yep, sounds good.
>> +{
>> + table->log = enabled;
>> +}
>> +
>> +bool
>> +ovsdb_table_is_logging_ops(struct ovsdb_table *table)
>
> ovsdb_table_is_logging_enabled() ?
>
Here too.
>> +{
>> + return table->log;
>> +}
>> +
>> void
>> ovsdb_table_destroy(struct ovsdb_table *table)
>> {
>> diff --git a/ovsdb/table.h b/ovsdb/table.h
>> index ce69a5d130bf..d27a30f0070f 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_log_ops(struct ovsdb_table *, bool);
>> +bool ovsdb_table_is_logging_ops(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 88e05280025b..5c1c6045487b 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,47 @@ 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) {
>> + if (!vlog_should_drop(&this_module, VLL_INFO, &rl_row_log)) {
>> + 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_row_log)) {
>> + log_row = txn_row->new;
>> + op = "updated";
>> + }
>> + } else if (txn_row->old && !txn_row->new) {
>> + if (!vlog_should_drop(&this_module, VLL_INFO, &rl_row_log)) {
>> + log_row = txn_row->old;
>> + op = "deleted";
>> + }
>> + }
>> +
>> + if (op) {
>
> Can we get rid of vlog_should_drop() above and use:
>
> if (op && !VLOG_DROP_INFO(&rl_row_log)) {
>
> ?
>
Sure.
I'll be sending v4 shortly.
Thanks,
Dumitru
>> + 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 +542,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;
>
_______________________________________________
dev mailing list
[email protected]
https://mail.openvswitch.org/mailman/listinfo/ovs-dev
