[ovs-dev] [PATCH] dpif/dpcls: limit count subtable search info logs

Thu Jul 1 12:12:18 UTC 2021

> -----Original Message-----
> From: Flavio Leitner <fbl at sysclose.org>
> Sent: Thursday, July 1, 2021 12:15 PM
> To: Van Haaren, Harry <harry.van.haaren at intel.com>
> Cc: Amber, Kumar <kumar.amber at intel.com>; dev at openvswitch.org;
> i.maximets at ovn.org
> Subject: Re: [ovs-dev] [PATCH] dpif/dpcls: limit count subtable search info logs
> 
> On Thu, Jul 01, 2021 at 10:55:55AM +0000, Van Haaren, Harry wrote:
> > > -----Original Message-----
> > > From: Amber, Kumar <kumar.amber at intel.com>
> > > Sent: Thursday, July 1, 2021 10:50 AM
> > > To: Van Haaren, Harry <harry.van.haaren at intel.com>
> > > Cc: dev at openvswitch.org; i.maximets at ovn.org; Flavio Leitner
> > > <fbl at sysclose.org>
> > > Subject: RE: [ovs-dev] [PATCH] dpif/dpcls: limit count subtable search info
> logs
> > >
> > > Hi Harry,
> > >
> > > Any Insights on the following 😊
> > >
> > > > -----Original Message-----
> > > > From: Flavio Leitner <fbl at sysclose.org>
> > > > Sent: Wednesday, June 30, 2021 12:28 AM
> > > > To: Amber, Kumar <kumar.amber at intel.com>
> > > > Cc: dev at openvswitch.org; i.maximets at ovn.org
> > > > Subject: Re: [ovs-dev] [PATCH] dpif/dpcls: limit count subtable search info
> logs
> > > >
> > > > On Tue, Jun 29, 2021 at 10:19:41PM +0530, Kumar Amber wrote:
> > > > > From: Harry van Haaren <harry.van.haaren at intel.com>
> > > > >
> > > > > This commit avoids many instances of "using subtable X for miniflow (x,y)"
> > > > > in the ovs-vswitchd log when using the DPCLS Autovalidator. This
> > > > > occurs when no specialized subtable is found, and the generic "_any"
> > > > > version of the avx512 subtable search implementation was used. This
> > > > > change logs the subtable usage once, avoiding duplicates.
> > > > >
> > > > > Signed-off-by: Harry van Haaren <harry.van.haaren at intel.com>
> > > > > ---
> > > > >  lib/dpif-netdev-lookup-avx512-gather.c | 2 +-
> > > > >  1 file changed, 1 insertion(+), 1 deletion(-)
> > > > >
> > > > > diff --git a/lib/dpif-netdev-lookup-avx512-gather.c
> > > > > b/lib/dpif-netdev-lookup-avx512-gather.c
> > > > > index bc359dc4a..f1b44deb3 100644
> > > > > --- a/lib/dpif-netdev-lookup-avx512-gather.c
> > > > > +++ b/lib/dpif-netdev-lookup-avx512-gather.c
> > > > > @@ -411,7 +411,7 @@ dpcls_subtable_avx512_gather_probe(uint32_t
> > > > u0_bits, uint32_t u1_bits)
> > > > >       */
> > > > >      if (!f && (u0_bits + u1_bits) < (NUM_U64_IN_ZMM_REG * 2)) {
> > > > >          f = dpcls_avx512_gather_mf_any;
> > > > > -        VLOG_INFO("Using avx512_gather_mf_any for subtable (%d,%d)\n",
> > > > > +        VLOG_INFO_ONCE("Using avx512_gather_mf_any for subtable
> > > > > + (%d,%d)\n",
> > > > >                    u0_bits, u1_bits);
> > > >
> > > > This will log only one time, but there are multiple subtables, so we won't
> see
> > > > other subtable changing. If the subtable information is not relevant, then it
> > > > shouldn't be in the msg.
> >
> > Note that this only logs the subtables that are not specialized.
> > Basically, this if this log is seen in the wild, it tell us OVS community that the
> > subtable fingerprint (u0_bits, u1_bits) combo should be specialized.
> 
> But then why you don't care about other fingerprints?

So we do care about other fingerprints. Ideally all non-specialized fingerprints
will get logged. It’s a question of verbosity of logging vs available info.

> > > > Also, the log only exists for *_mf_any, not for others specialized functions.
> >
> > Yes, intentionally. If the accelerated path is being chosen, why nag the user.
> 
> OK.
> 
> > If we're missing a specialized subtable, it would be good for OVS community to
> know,
> > so we log it, but only log it once. We could consider a rate-limited log instead of
> > a "ONCE".
> 
> This comes back to the point of showing or not the fingerprint.
> If it matters, then it seems a problem not printing others. If what
> matters is notifying the user that one or more subtables are not
> specialized, then a generic message without fingerprint is enough
> and cause less confusion.

If this VLOG ONCE log is hit, then a user could run commands to
identify what subtables they all have, and then we could identify which
ones aren't specialized yet... or we could just print them here :)

Side note, the "-m" flag to dump miniflow bits/fingerprint was added to
the dpctl/dump-flows command to identify these fingerprints:
ovs-appctl dpctl/dump-flows -m

> > Note that DPCLS Autovalidator calls probe() for each subtable-lookup, as it
> wants
> > to test all the different variants. ONCE avoids a lot of noise in this case, but I'm
> OK
> > with a _RL version too.
> 
> Sure, I understand the motivation and I agree we should improve that.
> 
> > > > Do we need that information in runtime? Unless I am missing other callers,
> > > > dpcls_subtable_get_best_impl() has a VLOG_DBG() logging all cases with
> the
> > > > same information.
> >
> > Yes, for debugging it is useful to see for any subtable, which is being selected.
> > The above prints are INFO level, so OVS community can see what subtables
> > could be specialized in future for better performance in those subtable
> lookups.
> >
> > So the one open is to use VLOG with ONCE (as this patch does) or with a
> RateLimit,
> > I'm OK with either approach.
> 
> Please help me understand how do you use that log message.

How we use the log messages?
In the case of the "_mf_any", we add code to specialize it.
More info is better, as each subtable fingerpint missed is not
improving performance.

In the case of an issue (not that I'm aware of any) in DPCLS, having
the vswitchd debug log what DPCLS impl is running seems useful for
a post-mortem if vswitch crashes?

Would we prefer to just print a message to the user?
"please run ovs-appctl dpctl/dump-flows -m, and mail results to ovs ML"?

Regards, -Harry