[ovs-dev] [PATCH v2] ovsdb-server: Log database transactions for user requested tables.
Dumitru Ceara
dceara at redhat.com
Tue Nov 16 14:36:35 UTC 2021
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 at 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 at 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
More information about the dev
mailing list