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 <[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. >>>>> 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 <[email protected]>
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 _______________________________________________ dev mailing list [email protected] https://mail.openvswitch.org/mailman/listinfo/ovs-dev
