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 <dce...@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 <msant...@redhat.com>

Regards,
Dumitru


_______________________________________________
dev mailing list
d...@openvswitch.org
https://mail.openvswitch.org/mailman/listinfo/ovs-dev

Reply via email to