Re: [dpdk-dev] [PATCH 2/8] trace: simplify trace point registration

[Olivier Matz <olivier.matz@6wind.com>]

Hi,

On Tue, May 05, 2020 at 04:16:02PM +0530, Jerin Jacob wrote:
> On Tue, May 5, 2020 at 3:56 PM Thomas Monjalon <thomas@monjalon.net> wrote:
> >
> > 05/05/2020 12:12, Jerin Jacob:
> > > On Tue, May 5, 2020 at 1:53 PM David Marchand <david.marchand@redhat.com> wrote:
> > > > On Tue, May 5, 2020 at 9:33 AM Jerin Jacob <jerinjacobk@gmail.com> wrote:
> > > > > > > What the proposed patch here.
> > > > > > > # Making N constructors from one
> > > > > > > # Grouping global variable and register function under a single Marco
> > > > > > > and making it as N constructors.
> > > > > > > Why can we do the same logic for rte_log?
> > > > > >
> > > > > > rte_log is simple, there is nothing to simplify.
> > > > >
> > > > > Why not make, rte_log_register() and the global variable under a macro?
> > > > > That's something done by the proposed patch.
> > > >
> > > > At the moment, there is not much that would go into such a macro, but
> > > > I had started to do some cleanups on logtype registration.
> > > > I did not finish because the question of the default log level is
> > > > still unclear (and I did not take the time).
> > > >
> > > > Having the logtype definition as part of the macro would be fine to me.
> > > > https://patchwork.dpdk.org/patch/57743/
> > >
> > > + Olivier (To get the feedback from rte_log PoV).
> > >
> > > The patchwork one is a bit different, IMO, Following is the mapping of
> > > this patch to rte_log one.
> > >
> > > Are we OK with the below semantics?
> > >
> > >
> > > diff --git a/drivers/common/octeontx2/otx2_common.c
> > > b/drivers/common/octeontx2/otx2_common.c
> > > index 1a257cf07..4d391a7e0 100644
> > > --- a/drivers/common/octeontx2/otx2_common.c
> > > +++ b/drivers/common/octeontx2/otx2_common.c
> > > @@ -169,89 +169,13 @@ int otx2_npa_lf_obj_ref(void)
> > >         return cnt ? 0 : -EINVAL;
> > >  }
> > > -/**
> > > - * @internal
> > > - */
> > > -int otx2_logtype_base;
> > > -/**
> > > - * @internal
> > > - */
> > > -int otx2_logtype_mbox;
> > > -/**
> > > - * @internal
> > > - */
> > > -int otx2_logtype_npa;
> > > -/**
> > > - * @internal
> > > - */
> > > -int otx2_logtype_nix;
> > > -/**
> > > - * @internal
> > > - */
> > > -int otx2_logtype_npc;
> > > -/**
> > > - * @internal
> > > - */
> > > -int otx2_logtype_tm;
> > > -/**
> > > - * @internal
> > > - */
> > > -int otx2_logtype_sso;
> > > -/**
> > > - * @internal
> > > - */
> > > -int otx2_logtype_tim;
> > > -/**
> > > - * @internal
> > > - */
> > > -int otx2_logtype_dpi;
> > > -/**
> > > - * @internal
> > > - */
> > > -int otx2_logtype_ep;
> > > -
> > > -RTE_INIT(otx2_log_init);
> > > -static void
> > > -otx2_log_init(void)
> > > -{
> > > -       otx2_logtype_base = rte_log_register("pmd.octeontx2.base");
> > > -       if (otx2_logtype_base >= 0)
> > > -               rte_log_set_level(otx2_logtype_base, RTE_LOG_NOTICE);
> > > -
> > > -       otx2_logtype_mbox = rte_log_register("pmd.octeontx2.mbox");
> > > -       if (otx2_logtype_mbox >= 0)
> > > -               rte_log_set_level(otx2_logtype_mbox, RTE_LOG_NOTICE);
> > > -
> > > -       otx2_logtype_npa = rte_log_register("pmd.mempool.octeontx2");
> > > -       if (otx2_logtype_npa >= 0)
> > > -               rte_log_set_level(otx2_logtype_npa, RTE_LOG_NOTICE);
> > > -
> > > -       otx2_logtype_nix = rte_log_register("pmd.net.octeontx2");
> > > -       if (otx2_logtype_nix >= 0)
> > > -               rte_log_set_level(otx2_logtype_nix, RTE_LOG_NOTICE);
> > > -
> > > -       otx2_logtype_npc = rte_log_register("pmd.net.octeontx2.flow");
> > > -       if (otx2_logtype_npc >= 0)
> > > -               rte_log_set_level(otx2_logtype_npc, RTE_LOG_NOTICE);
> > > -
> > > -       otx2_logtype_tm = rte_log_register("pmd.net.octeontx2.tm");
> > > -       if (otx2_logtype_tm >= 0)
> > > -               rte_log_set_level(otx2_logtype_tm, RTE_LOG_NOTICE);
> > > -
> > > -       otx2_logtype_sso = rte_log_register("pmd.event.octeontx2");
> > > -       if (otx2_logtype_sso >= 0)
> > > -               rte_log_set_level(otx2_logtype_sso, RTE_LOG_NOTICE);
> > > -
> > > -       otx2_logtype_tim = rte_log_register("pmd.event.octeontx2.timer");
> > > -       if (otx2_logtype_tim >= 0)
> > > -               rte_log_set_level(otx2_logtype_tim, RTE_LOG_NOTICE);
> > > -
> > > -       otx2_logtype_dpi = rte_log_register("pmd.raw.octeontx2.dpi");
> > > -       if (otx2_logtype_dpi >= 0)
> > > -               rte_log_set_level(otx2_logtype_dpi, RTE_LOG_NOTICE);
> > > -
> > > -       otx2_logtype_ep = rte_log_register("pmd.raw.octeontx2.ep");
> > > -       if (otx2_logtype_ep >= 0)
> > > -               rte_log_set_level(otx2_logtype_ep, RTE_LOG_NOTICE);
> > > -
> > > -}
> > > +RTE_LOG_REGISTER(otx2_logtype_base, pmd.octeontx2.base, NOTICE);
> > > +RTE_LOG_REGISTER(otx2_logtype_mbox, pmd.octeontx2.mbox, NOTICE);
> > > +RTE_LOG_REGISTER(otx2_logtype_npa, pmd.mempool.octeontx2, NOTICE);
> > > +RTE_LOG_REGISTER(otx2_logtype_nix, pmd.net.octeontx2, NOTICE);
> > > +RTE_LOG_REGISTER(otx2_logtype_npc, pmd.net.octeontx2.flow, NOTICE);
> > > +RTE_LOG_REGISTER(otx2_logtype_tm, pmd.net.octeontx2.tm, NOTICE);
> > > +RTE_LOG_REGISTER(otx2_logtype_sso, pmd.event.octeontx2, NOTICE);
> > > +RTE_LOG_REGISTER(otx2_logtype_tim, pmd.event.octeontx2.timer, NOTICE);
> > > +RTE_LOG_REGISTER(otx2_logtype_dpi, pmd.raw.octeontx2.dpi, NOTICE);
> > > +RTE_LOG_REGISTER(otx2_logtype_ep, pmd.raw.octeontx2.ep, NOTICE);
> > >
> > > diff --git a/lib/librte_eal/include/rte_log.h b/lib/librte_eal/include/rte_log.h
> > > index 1789ede56..22fc3802f 100644
> > > --- a/lib/librte_eal/include/rte_log.h
> > > +++ b/lib/librte_eal/include/rte_log.h
> > > @@ -376,6 +376,15 @@ int rte_vlog(uint32_t level, uint32_t logtype,
> > > const char *format, va_list ap)
> > >                  RTE_LOGTYPE_ ## t, # t ": " __VA_ARGS__) :     \
> > >          0)
> > >
> > > +#define RTE_LOG_REGISTER(type, name, level)                            \
> > > +int type;                                                              \
> > > +RTE_INIT(__##type)                                                     \
> > > +{                                                                      \
> > > +       type = rte_log_register(RTE_STR(name));                         \
> > > +       if (type >= 0)                                                  \
> > > +               rte_log_set_level(type, RTE_LOG_##level);               \
> > > +}
> > > +
> >
> >
> > Yes I agree, we could do that.
> > And now I better understand what you mean comparing rte_trace and rte_log.
> 
> OK.
> 
> Let Olivier share his view, I was/is under the impression that, The
> reason for not have this silly Marco to
> don't explode constructor usage in dpdk
> 
> If we are OK this scheme then lets first clean up rte_log registration.

Honnestly, I had no particular idea in mind about constructor number
when I added the rte_log_register() API. To me, it was quite simple:
just call a register function when you need a new log type. Now, as it's
mostly (always?) done at init time, I'm fine with the the principle of
having a macro to register new logs, given we also keep the previous
API.

To get back on the topic of the thread (RTE_TRACE), I think a simpler
API (one macro) is better. Since it's a new API, it makes sense to make
it as good as possible for the first version.

And by the way, thank you for this nice work.

Regards,
Olivier



> 
> 
> >
> >
> >
> > > > > > > > rte_trace requires 3 macros calls per trace type:
> > > > > > > > RTE_TRACE_POINT_REGISTER, RTE_TRACE_POINT_DEFINE, RTE_TRACE_POINT_ARGS
> > > > > > > > This patch is unifying the first 2 macro calls to make usage simpler,
> > > > > > > > and ease rte_trace adoption.
> > > > > > >
> > > > > > > RTE_TRACE_POINT_ARGS is NOP and for the syntax.
> > > > > > > It is similar to rte_log. rte_log don't have RTE_TRACE_POINT_REGISTER instead
> > > > > > > it is creating global variable  see, "int otx2_logtype_base;
> > > > > > >
> > > > > > > >
> > > > > > > > Note: the other usability weirdness is mandating declaring each trace
> > > > > > > > function with a magic double underscore prefix which appears nowhere else.
> > > > > > > >
> > > > > > > >
> > > > > > > > > Analyze the impact wrt boot time and cross-platform pov as the log
> > > > > > > > > has a lot of entries to test. If the usage makes sense then it should make sense
> > > > > > > > > for rte_log too. I would like to NOT have trace to be the first
> > > > > > > > > library to explode
> > > > > > > > > with the constructor scheme. I suggest removing this specific patch from RC2 and
> > > > > > > > > revisit later.
> > > > > > > >
> > > > > > > > You still did not give any argument against increasing the number
> > > > > > > > of constructors.
> > > > > > >
> > > > > > > If you are proposing the new scheme, you have to prove the overhead
> > > > > > > with a significant number of constructors
> > > > > > > and why it has differed from existing scheme of things. That's is the
> > > > > > > norm in opensource.
> > > > > >
> > > > > > I say there is no overhead.
> > > > >
> > > > > Please share the data.
> > > >
> > > > Measured time between first rte_trace_point_register and last one with
> > > > a simple patch:
> > >
> > > I will try to reproduce this, once we finalize on the above synergy
> > > with rte_log.
> > >
> > >
> > > >
> > > > diff --git a/lib/librte_eal/common/eal_common_trace.c
> > > > b/lib/librte_eal/common/eal_common_trace.c
> > > > index 875553d7e..95618314b 100644
> > > > --- a/lib/librte_eal/common/eal_common_trace.c
> > > > +++ b/lib/librte_eal/common/eal_common_trace.c
> > > > @@ -8,6 +8,7 @@
> > > >  #include <regex.h>
> > > >
> > > >  #include <rte_common.h>
> > > > +#include <rte_cycles.h>
> > > >  #include <rte_errno.h>
> > > >  #include <rte_lcore.h>
> > > >  #include <rte_per_lcore.h>
> > > > @@ -23,6 +24,9 @@ static RTE_DEFINE_PER_LCORE(int, ctf_count);
> > > >  static struct trace_point_head tp_list = STAILQ_HEAD_INITIALIZER(tp_list);
> > > >  static struct trace trace = { .args = STAILQ_HEAD_INITIALIZER(trace.args), };
> > > >
> > > > +uint64_t first_register;
> > > > +uint64_t last_register;
> > > > +
> > > >  struct trace *
> > > >  trace_obj_get(void)
> > > >  {
> > > > @@ -43,6 +47,8 @@ eal_trace_init(void)
> > > >         /* Trace memory should start with 8B aligned for natural alignment */
> > > >         RTE_BUILD_BUG_ON((offsetof(struct __rte_trace_header, mem) % 8) != 0);
> > > >
> > > > +       trace_err("delta=%"PRIu64, last_register - first_register);
> > > > +
> > > >         /* One of the trace point registration failed */
> > > >         if (trace.register_errno) {
> > > >                 rte_errno = trace.register_errno;
> > > > @@ -425,6 +431,9 @@ __rte_trace_point_register(rte_trace_point_t
> > > > *handle, const char *name,
> > > >                 goto fail;
> > > >         }
> > > >
> > > > +       if (first_register == 0)
> > > > +               first_register = rte_get_tsc_cycles();
> > > > +
> > > >         /* Check the size of the trace point object */
> > > >         RTE_PER_LCORE(trace_point_sz) = 0;
> > > >         RTE_PER_LCORE(ctf_count) = 0;
> > > > @@ -486,6 +495,8 @@ __rte_trace_point_register(rte_trace_point_t
> > > > *handle, const char *name,
> > > >         STAILQ_INSERT_TAIL(&tp_list, tp, next);
> > > >         __atomic_thread_fence(__ATOMIC_RELEASE);
> > > >
> > > > +       last_register = rte_get_tsc_cycles();
> > > > +
> > > >         /* All Good !!! */
> > > >         return 0;
> > > >  free:
> > > >
> > > >
> > > > I started testpmd 100 times for static and shared gcc builds
> > > > (test-meson-builds.sh) on a system with a 2.6GHz xeon.
> > > >
> > > > v20.05-rc1-13-g08dd97130 (before patch):
> > > > static: count=100, min=580812, max=1482326, avg=1764932
> > > > shared: count=100, min=554648, max=1344163, avg=1704638
> > > >
> > > > v20.05-rc1-14-g44250f392 (after patch):
> > > > static: count=100, min=668273, max=1530330, avg=1682548
> > > > shared: count=100, min=554634, max=1330264, avg=1672398
> >
> >
> >
> >