[ovs-dev] [PATCH v3] ovsdb-server: Log database transactions for user requested tables.

Mark Gray mrmarkgray at gmail.com
Tue Nov 16 20:06:18 UTC 2021


On Tue 16 Nov 2021, 14:34 Dumitru Ceara, <dceara at redhat.com> 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 <dceara at redhat.com>
>

Hi Dumitru,

Thanks for addressing my comments satisfactorily. This looks good to me. No
need to add my Ack.

Mark

---
> 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.
>
> 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")) {
> +        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");
> +
> +    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, ",");
> +    }
> +    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)
> +{
> +    table->log = enabled;
> +}
> +
> +bool
> +ovsdb_table_is_logging_ops(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..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) {
> +        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;
> --
> 2.27.0
>
>


More information about the dev mailing list