On 23/09/2021 11:20, Dumitru Ceara wrote:
> On 9/23/21 11:47 AM, Mark Gray wrote:
>> On 16/09/2021 16:37, 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 <[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.
>>>
>>> V2:
>>> - rebased (fixed conflicts in NEWS).
>>
>> Generally ok and I also did a quick test but I have a few comments on
>> the UI which wouldn't block an ACK and one small comment below in the code:
>
> Thanks for the review!
>
>>
>> * My personal preference would be that the syntax somewhat followed the
>> vlog/set one that seperates terms by ':'. Also a more memorable name.
>> For example tlog/set DB:TABLE:on or something like that but feel free to
>> choose to completely ignore me :) I just find it can sometimes be
>> difficult to remember syntax so I prefer some consistency.
>
> Makes sense, I'll try to come up with something more consistent.
>
>>
>> * One limititation is that I don't think we can add a log before a table
>> is created (i.e. to see the first entry). For example, let's say I want
>> to log the very first creation of a bridge using `ovs-vsctl add-br br0`.
>> Is there any way around it? I couldn't think of one.
>
> I'm not sure I follow this point. If you enable logging for the Bridge
> table before adding the first bridge you'll get the log, e.g., in an OVS
> sandbox:
>
> $ ovs-appctl -t $PWD/sandbox/ovsdb-server.*.ctl ovsdb-server/log-db-ops
> Open_vSwitch Bridge on
>
> $ ovs-vsctl show
> f43b960d-13f9-48d1-9898-703a3ac3f730
>
> $ ovs-vsctl add-br br9
>
> $ grep transaction sandbox/ovsdb-server.log
> 2021-09-23T09:57:53.426Z|00007|transaction|INFO|table:Bridge,op:inserted,name:br9,flood_vlans:[],auto_attach:[],ports:[388811ab-13a9-4b50-92c6-10c00a8b5e42],stp_enable:false,rstp_enable:false,_uuid:8a59955c-2a3c-41d3-9e93-66845e51878b,fail_mode:[],rstp_status:{},flow_tables:{},_version:1603df48-3730-4324-a71b-1c9f7eadb865,netflow:[],datapath_type:"",controller:[],other_config:{},external_ids:{},status:{},ipfix:[],datapath_id:[],mirrors:[],mcast_snooping_enable:false,datapath_version:"",sflow:[],protocols:[]
> [...]
I just tested again and it does work. I think I must have specified
"bridge" instead of "Bridge". Sorry for the confusion.
>>
>> * Could you make the table and database names case-insensitive. For
>> example, I can do `ovs-vsctl list open` even though the table name is
>> actually Open_vSwitch? However, with this I need to specify the actual
>> table name.
>>
>
> We can try but this would be a bit of an orthogonal change. For example
> "ovs-appctl -t .. ovsdb-server/remove-db DB" only accepts case sensitive
> database names (due to case sensitive shash operations). For using
> partial table names and/or, it would also be a more complex change.
> What you mentioned (ovs-vsctl) is actually implemented on the client
> side in db-ctl-base.c, get_table()/score_partial_match().
Ok, in that case, no need to update.
>
>> * There is no way to list the tables that are currently 'on'. Something
>> like vlog/list.
>
> Good idea, I'll add it!
Thanks
>
>>
>> * Would it be useful to be able to specify which level to log to?: e.g.
>>
>> tlog/set DB:TABLE:info
>>
>
> I'm not sure, maybe, although my initial goal was to make this usable at
> a reasonably high log level, e.g., INFO. I don't think there's a point
> to use an even higher level though (like WARN/ERR), though.
Ok
>
>> * Would it be useful to have a non-verbose mode that only states that an
>> insert/delete/update happened?
>>
>
> Would you log some row specific information then? E.g., _uuid.
Perhaps, I am just thinking that it will reduce the log size. Maybe it's
not useful.
>
>>> ---
>>> 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);
>>
>> Why do you have 3 different rate limiters?
>>
>
> Updates usually happen more often than inserts/deletes (e.g., with OVN
> logical ports). I thought it would be more useful if updates didn't
> consume tokens from the insert/delete logs. But thinking more about it,
> a rate of 30 logs per minute with a burst of 60 doesn't allow too many
> transactions to be logged often either. So, I guess, in a real use case
> the user would disable rate limiting for the "transaction" vlog module.
> We might as well move to a single rate limiter then.
>
> I'll change it in the next revision.
>
>>> +
>>> + 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_insert)) {
>>> + 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_update)) {
>>> + log_row = txn_row->new;
>>> + op = "updated";
>>> + }
>>> + } else if (txn_row->old && !txn_row->new) {
>>> + if (!vlog_should_drop(&this_module, VLL_INFO, &rl_delete)) {
>>> + 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)
>>> @@ -445,6 +495,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
