On 9/23/21 12:36 PM, Mark Gray wrote:
> 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.
>>
I went with "ovsdb-server/tlog-set DB:TABLE on|off" and
"ovsdb-server/tlog--list".
>>>
>>> * 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.
>
No worries.
>>>
>>> * 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.
>
Ack.
>>
>>> * There is no way to list the tables that are currently 'on'. Something
>>> like vlog/list.
>>
>> Good idea, I'll add it!
>
> Thanks
>
Done.
>>
>>>
>>> * 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
>
I left it fixed at level INFO for now.
>>
>>> * 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.
>
I decided not to implement this in the end. I'm not sure if the
flexibility would actually make debugging easier. In any case, we can
try to add it in the future if needed.
[...]
>>>>
>>>> +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.
>>
Done.
V3 posted:
https://patchwork.ozlabs.org/project/openvswitch/list/?series=272306&state=*
Regards,
Dumitru
_______________________________________________
dev mailing list
[email protected]
https://mail.openvswitch.org/mailman/listinfo/ovs-dev
