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

[Jerin Jacob <jerinjacobk@gmail.com>]

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);               \
+}
+
 #ifdef __cplusplus
 }
 #endif




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