[ovs-dev] [PATCH ovn] inc-proc-eng: Improve debug logging.

Dumitru Ceara dceara at redhat.com
Fri Jul 2 11:36:20 UTC 2021


On 7/2/21 1:32 PM, Mark Gray wrote:
> On 02/07/2021 10:07, Dumitru Ceara wrote:
>> Time how long change/run handlers take and log this at debug level.
>> I-P engine debug logs are not so verbose so enabling them is quite
>> common when debugging scale/control plane latency related issues.
>>
>> One of the major missing pieces though was a log about how long each I-P
>> node change/run handler took to run.  This commit adds it and also logs
>> a message when a node is recomputed because it misses an input change
>> handler.
>>
>> Signed-off-by: Dumitru Ceara <dceara at redhat.com>
>> ---
>>  lib/inc-proc-eng.c | 16 +++++++++++++++-
>>  1 file changed, 15 insertions(+), 1 deletion(-)
>>
>> diff --git a/lib/inc-proc-eng.c b/lib/inc-proc-eng.c
>> index c349efb22..bb96ef1a3 100644
>> --- a/lib/inc-proc-eng.c
>> +++ b/lib/inc-proc-eng.c
>> @@ -27,6 +27,7 @@
>>  #include "openvswitch/hmap.h"
>>  #include "openvswitch/vlog.h"
>>  #include "inc-proc-eng.h"
>> +#include "timeval.h"
>>  #include "unixctl.h"
>>  
>>  VLOG_DEFINE_THIS_MODULE(inc_proc_eng);
>> @@ -333,8 +334,10 @@ engine_recompute(struct engine_node *node, bool forced, bool allowed)
>>      }
>>  
>>      /* Run the node handler which might change state. */
>> +    long long int now = time_msec();
>>      node->run(node, node->data);
>>      node->stats.recompute++;
>> +    VLOG_DBG("node: %s, recompute took %lldms", node->name, time_msec() - now);
>>  }
>>  
>>  /* Return true if the node could be computed, false otherwise. */
>> @@ -350,7 +353,12 @@ engine_compute(struct engine_node *node, bool recompute_allowed)
>>              /* If the input change can't be handled incrementally, run
>>               * the node handler.
>>               */
>> -            if (!node->inputs[i].change_handler(node, node->data)) {
>> +            long long int now = time_msec();
>> +            bool handled = node->inputs[i].change_handler(node, node->data);
>> +            VLOG_DBG("node: %s, handling change for input %s took %lldms",
>> +                     node->name, node->inputs[i].node->name,
>> +                     time_msec() - now);
> 
> Why not add a stopwatch?
> 

Because I keep forgetting they exist. :)

I'll switch to stopwatches in v2, thanks for the review!



More information about the dev mailing list