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

[Thomas Monjalon <thomas@monjalon.net>]

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.



> > > > > > 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