[v3,5/9] trace: fix dynamically enabling trace points
Checks
Commit Message
Enabling trace points at runtime was not working if no trace point had
been enabled first at rte_eal_init() time. The reason was that
trace.args reflected the arguments passed to --trace= EAL option.
To fix this:
- the trace subsystem initialisation is updated: trace directory
creation is deferred to when traces are dumped (to avoid creating
directories that may not be used),
- per lcore memory allocation still relies on rte_trace_is_enabled() but
this helper now tracks if any trace point is enabled. The
documentation is updated accordingly,
- cleanup helpers must always be called in rte_eal_cleanup() since some
trace points might have been enabled and disabled in the lifetime of
the DPDK application,
With this fix, we can update the unit test and check that a trace point
callback is invoked when expected.
Note:
- the 'trace' global variable might be shadowed with the argument
passed to the functions dealing with trace point handles.
'tp' has been used for referring to trace_point object.
Prefer 't' for referring to handles,
Fixes: 84c4fae4628f ("trace: implement operation APIs")
Cc: stable@dpdk.org
Signed-off-by: David Marchand <david.marchand@redhat.com>
Acked-by: Sunil Kumar Kori <skori@marvell.com>
---
Changes since v1:
- restored level to INFO for trace directory log message,
- moved trace_mkdir() to rte_trace_save,
---
app/test/test_trace.c | 20 ++++++++++
app/test/test_trace.h | 2 +
doc/guides/prog_guide/trace_lib.rst | 14 +++++--
lib/eal/common/eal_common_trace.c | 53 ++++++++++---------------
lib/eal/common/eal_common_trace_utils.c | 11 ++++-
lib/eal/common/eal_trace.h | 3 +-
6 files changed, 65 insertions(+), 38 deletions(-)
Comments
> -int
> +static int
> trace_mkdir(void)
> {
> struct trace *trace = trace_obj_get();
> char session[TRACE_DIR_STR_LEN];
> + static bool already_done;
> char *dir_path;
> int rc;
>
> + if (already_done)
> + return 0;
> +
Hi David
I was trying out "trace: take live traces via telemetry" patch
I came across following scenario
- Started testpmd with trace=.*
- Executed /trace/save from telemetry script, trace file saved successfully
- Later after stopping application, rte_eal_cleanup() did not save the trace.
With this we lost traces after /trace/save executed
This happened because "already_done" was set after rte_trace_save() called via telemetry.
Later rte_eal_cleanup returned from this point without saving later traces.
What is the purpose of already_done flag?
Thanks
Harman
> if (!trace->dir_offset) {
> dir_path = calloc(1, sizeof(trace->dir));
> if (dir_path == NULL) {
> @@ -365,6 +369,7 @@ trace_mkdir(void)
> }
>
> RTE_LOG(INFO, EAL, "Trace dir: %s\n", trace->dir);
> + already_done = true;
On Thu, Oct 13, 2022 at 4:53 PM Harman Kalra <hkalra@marvell.com> wrote:
>
>
> > -int
> > +static int
> > trace_mkdir(void)
> > {
> > struct trace *trace = trace_obj_get();
> > char session[TRACE_DIR_STR_LEN];
> > + static bool already_done;
> > char *dir_path;
> > int rc;
> >
> > + if (already_done)
> > + return 0;
> > +
> Hi David
>
> I was trying out "trace: take live traces via telemetry" patch
> I came across following scenario
> - Started testpmd with trace=.*
> - Executed /trace/save from telemetry script, trace file saved successfully
> - Later after stopping application, rte_eal_cleanup() did not save the trace.
>
> With this we lost traces after /trace/save executed
Sorry, I must be missing something.
What patches did you apply and how are you testing?
With the whole traces fixes series applied first, then the new "trace:
take live traces via telemetry" patch applied, I can't reproduce your
issue.
Here is what I did:
$ ./build/app/dpdk-testpmd -c 3 --no-huge -m 40 -a 0:0.0 -d
build-gcc/drivers --vdev net_null1 --vdev net_null2 --trace=.* --
--no-mlockall --total-num-mbufs=2048 -ia
--> /trace/save
{"/trace/save": {"Status": "OK", "Path":
"/home/dmarchan/dpdk-traces/rte-2022-10-13-PM-05-44-56"}}
At this point, the trace file contains events until:
...
[17:44:50.738892453] (+0.000000154) lib.eal.mem.malloc: { cpu_id =
0x0, name = "dpdk-testpmd" }, { type = "", size = 0x0, align = 0x0,
socket = 0, ptr = 0x0 }
[17:44:50.738892470] (+0.000000017) lib.eal.mem.zmalloc: { cpu_id =
0x0, name = "dpdk-testpmd" }, { type = "", size = 0x0, align = 0x0,
socket = 0, ptr = 0x0 }
[17:44:50.738894858] (+0.000002388) lib.eal.mem.malloc: { cpu_id =
0x0, name = "dpdk-testpmd" }, { type = "", size = 0x0, align = 0x0,
socket = 0, ptr = 0x0 }
[17:44:50.738894881] (+0.000000023) lib.eal.mem.zmalloc: { cpu_id =
0x0, name = "dpdk-testpmd" }, { type = "", size = 0x0, align = 0x0,
socket = 0, ptr = 0x0 }
[17:44:50.738894899] (+0.000000018) lib.ethdev.rxq.setup: { cpu_id =
0x0, name = "dpdk-testpmd" }, { port_id = 0x1, rx_queue_id = 0x0,
nb_rx_desc = 0x200, mp = 0x101A9E540, rx_conf_rx_thresh_pthresh = 0x0,
rx_conf_rx_thresh_hthresh = 0x0, rx_conf_rx_thresh_wthresh = 0x0,
rx_conf_rx_drop_en = 0x0, rx_conf_rx_deferred_start = 0x0,
rx_conf_offloads = 0x0, rc = 0 }
[17:44:50.738895490] (+0.000000591) lib.ethdev.start: { cpu_id = 0x0,
name = "dpdk-testpmd" }, { port_id = 0x1 }
[17:44:50.738908652] (+0.000013162) lib.eal.memzone.lookup: { cpu_id =
0x0, name = "dpdk-testpmd" }, { name = "RTE_METRICS", memzone = 0x0 }
[17:44:50.738912231] (+0.000003579) lib.eal.memzone.reserve: { cpu_id
= 0x0, name = "dpdk-testpmd" }, { name = "RTE_METRICS", len = 0x15010,
socket_id = 0, flags = 0x0, align = 0x40, bound = 0x0, mz =
0x100007168 }
[17:44:50.779538885] (+0.040626654) lib.eal.thread.remote.launch: {
cpu_id = 0x0, name = "dpdk-testpmd" }, { f = 0x458130, arg =
0x101C20780, worker_id = 0x1, rc = 0 }
Then, I stop testpmd, and look again at the same trace file:
...
[17:44:50.779538885] (+0.040626654) lib.eal.thread.remote.launch: {
cpu_id = 0x0, name = "dpdk-testpmd" }, { f = 0x458130, arg =
0x101C20780, worker_id = 0x1, rc = 0 }
[17:45:12.630581221] (+21.851042336) lib.ethdev.stop: { cpu_id = 0x0,
name = "dpdk-testpmd" }, { port_id = 0x0, ret = 0 }
[17:45:12.630590961] (+0.000009740) lib.ethdev.stop: { cpu_id = 0x0,
name = "dpdk-testpmd" }, { port_id = 0x1, ret = 0 }
[17:45:12.630601415] (+0.000010454) lib.ethdev.close: { cpu_id = 0x0,
name = "dpdk-testpmd" }, { port_id = 0x0 }
[17:45:12.630606931] (+0.000005516) lib.eal.mem.free: { cpu_id = 0x0,
name = "dpdk-testpmd" }, { ptr = 0x10126D700 }
[17:45:12.630618608] (+0.000011677) lib.eal.mem.free: { cpu_id = 0x0,
name = "dpdk-testpmd" }, { ptr = 0x10126B680 }
[17:45:12.630621015] (+0.000002407) lib.eal.mem.free: { cpu_id = 0x0,
name = "dpdk-testpmd" }, { ptr = 0x0 }
[17:45:12.630621038] (+0.000000023) lib.eal.mem.free: { cpu_id = 0x0,
name = "dpdk-testpmd" }, { ptr = 0x0 }
[17:45:12.630621062] (+0.000000024) lib.eal.mem.free: { cpu_id = 0x0,
name = "dpdk-testpmd" }, { ptr = 0x102643B40 }
[17:45:12.630668837] (+0.000047775) lib.ethdev.close: { cpu_id = 0x0,
name = "dpdk-testpmd" }, { port_id = 0x1 }
[17:45:12.630671206] (+0.000002369) lib.eal.mem.free: { cpu_id = 0x0,
name = "dpdk-testpmd" }, { ptr = 0x101269480 }
[17:45:12.630673731] (+0.000002525) lib.eal.mem.free: { cpu_id = 0x0,
name = "dpdk-testpmd" }, { ptr = 0x101267400 }
[17:45:12.630675638] (+0.000001907) lib.eal.mem.free: { cpu_id = 0x0,
name = "dpdk-testpmd" }, { ptr = 0x0 }
[17:45:12.630675662] (+0.000000024) lib.eal.mem.free: { cpu_id = 0x0,
name = "dpdk-testpmd" }, { ptr = 0x0 }
[17:45:12.630675685] (+0.000000023) lib.eal.mem.free: { cpu_id = 0x0,
name = "dpdk-testpmd" }, { ptr = 0x10262F940 }
[17:45:12.630712155] (+0.000036470) lib.eal.mem.free: { cpu_id = 0x0,
name = "dpdk-testpmd" }, { ptr = 0x101C206C0 }
[17:45:12.630712692] (+0.000000537) lib.mempool.free: { cpu_id = 0x0,
name = "dpdk-testpmd" }, { mempool = 0x101A9E540, mempool_name =
"mb_pool_0" }
[17:45:12.630893367] (+0.000180675) lib.eal.mem.free: { cpu_id = 0x0,
name = "dpdk-testpmd" }, { ptr = 0x101295F80 }
[17:45:12.631196732] (+0.000303365) lib.eal.memzone.free: { cpu_id =
0x0, name = "dpdk-testpmd" }, { name = "MP_mb_pool_0_0", addr =
0x101295F80, rc = 0 }
[17:45:12.631197557] (+0.000000825) lib.eal.mem.free: { cpu_id = 0x0,
name = "dpdk-testpmd" }, { ptr = 0x101295EC0 }
[17:45:12.631198085] (+0.000000528) lib.mempool.ops.free: { cpu_id =
0x0, name = "dpdk-testpmd" }, { mempool = 0x101A9E540, mempool_name =
"mb_pool_0" }
[17:45:12.631201058] (+0.000002973) lib.eal.mem.free: { cpu_id = 0x0,
name = "dpdk-testpmd" }, { ptr = 0x101A96280 }
[17:45:12.631202316] (+0.000001258) lib.eal.memzone.free: { cpu_id =
0x0, name = "dpdk-testpmd" }, { name = "RG_MP_mb_pool_0", addr =
0x101A96280, rc = 0 }
[17:45:12.631203186] (+0.000000870) lib.eal.mem.free: { cpu_id = 0x0,
name = "dpdk-testpmd" }, { ptr = 0x101A9E480 }
[17:45:12.631203338] (+0.000000152) lib.eal.mem.free: { cpu_id = 0x0,
name = "dpdk-testpmd" }, { ptr = 0x101A9E540 }
[17:45:12.631263318] (+0.000059980) lib.eal.memzone.free: { cpu_id =
0x0, name = "dpdk-testpmd" }, { name = "MP_mb_pool_0", addr =
0x101A9E540, rc = 0 }
[17:45:12.631525049] (+0.000261731) lib.eal.mem.free: { cpu_id = 0x0,
name = "dpdk-testpmd" }, { ptr = 0x1026ABE80 }
[17:45:12.631525323] (+0.000000274) lib.eal.mem.free: { cpu_id = 0x0,
name = "dpdk-testpmd" }, { ptr = 0x102687E00 }
>
> This happened because "already_done" was set after rte_trace_save() called via telemetry.
> Later rte_eal_cleanup returned from this point without saving later traces.
>
> What is the purpose of already_done flag?
already_done is used to create the trace directory once, and log a
message with this directory path once.
> -----Original Message-----
> From: David Marchand <david.marchand@redhat.com>
> Sent: Thursday, October 13, 2022 9:22 PM
> To: Harman Kalra <hkalra@marvell.com>
> Cc: dev@dpdk.org; Jerin Jacob Kollanukkaran <jerinj@marvell.com>; Sunil
> Kumar Kori <skori@marvell.com>; stable@dpdk.org
> Subject: Re: [EXT] [PATCH v3 5/9] trace: fix dynamically enabling trace points
>
> On Thu, Oct 13, 2022 at 4:53 PM Harman Kalra <hkalra@marvell.com> wrote:
> >
> >
> > > -int
> > > +static int
> > > trace_mkdir(void)
> > > {
> > > struct trace *trace = trace_obj_get();
> > > char session[TRACE_DIR_STR_LEN];
> > > + static bool already_done;
> > > char *dir_path;
> > > int rc;
> > >
> > > + if (already_done)
> > > + return 0;
> > > +
> > Hi David
> >
> > I was trying out "trace: take live traces via telemetry" patch I came
> > across following scenario
> > - Started testpmd with trace=.*
> > - Executed /trace/save from telemetry script, trace file saved
> > successfully
> > - Later after stopping application, rte_eal_cleanup() did not save the trace.
> >
> > With this we lost traces after /trace/save executed
>
> Sorry, I must be missing something.
> What patches did you apply and how are you testing?
I applied the whole trace fixes series and then tested live traces
>
> With the whole traces fixes series applied first, then the new "trace:
> take live traces via telemetry" patch applied, I can't reproduce your issue.
>
>
Yes, you replicated the same scenario what I tried.
Sorry, I realized that actually it's not an issue, traces generated after /trace/save are getting
appended but in the same file (timestamped on /trace/save) on rte_eal_cleanup().
I assumed that trace dir generated with a timestamp will include all the trace points emitted
before that timestamp. But in the above scenario same trace dir includes trace points emitted
after this timestamp. I think this is bit confusing. Shall we add a logic where if already_done is
set, rename the original trace dir to latest timestamp?
Thanks
Harman
>
> >
> > This happened because "already_done" was set after rte_trace_save()
> called via telemetry.
> > Later rte_eal_cleanup returned from this point without saving later traces.
> >
> > What is the purpose of already_done flag?
>
> already_done is used to create the trace directory once, and log a message
> with this directory path once.
>
>
> --
> David Marchand
On Thu, Oct 13, 2022 at 7:07 PM Harman Kalra <hkalra@marvell.com> wrote:
> >
> > With the whole traces fixes series applied first, then the new "trace:
> > take live traces via telemetry" patch applied, I can't reproduce your issue.
> >
> >
>
> Yes, you replicated the same scenario what I tried.
> Sorry, I realized that actually it's not an issue, traces generated after /trace/save are getting
> appended but in the same file (timestamped on /trace/save) on rte_eal_cleanup().
>
> I assumed that trace dir generated with a timestamp will include all the trace points emitted
> before that timestamp. But in the above scenario same trace dir includes trace points emitted
> after this timestamp. I think this is bit confusing. Shall we add a logic where if already_done is
> set, rename the original trace dir to latest timestamp?
Afaiu, the behavior before this series was the same.
An application calling rte_trace_save() would always save to a single directory.
One thing that changed though is that the directory is timestamped
with the time of the first call to rte_trace_save.
Before the seriesn the timestamp was based on the time when the trace
subsystem was initialised.
We can go with what you describe (which makes sense to me).
But I'd like to get a ack from traces maintainers before looking into it.
On Fri, Oct 14, 2022 at 12:41 AM David Marchand
<david.marchand@redhat.com> wrote:
>
> On Thu, Oct 13, 2022 at 7:07 PM Harman Kalra <hkalra@marvell.com> wrote:
> > >
> > > With the whole traces fixes series applied first, then the new "trace:
> > > take live traces via telemetry" patch applied, I can't reproduce your issue.
> > >
> > >
> >
> > Yes, you replicated the same scenario what I tried.
> > Sorry, I realized that actually it's not an issue, traces generated after /trace/save are getting
> > appended but in the same file (timestamped on /trace/save) on rte_eal_cleanup().
> >
> > I assumed that trace dir generated with a timestamp will include all the trace points emitted
> > before that timestamp. But in the above scenario same trace dir includes trace points emitted
> > after this timestamp. I think this is bit confusing. Shall we add a logic where if already_done is
> > set, rename the original trace dir to latest timestamp?
>
> Afaiu, the behavior before this series was the same.
> An application calling rte_trace_save() would always save to a single directory.
> One thing that changed though is that the directory is timestamped
> with the time of the first call to rte_trace_save.
> Before the seriesn the timestamp was based on the time when the trace
> subsystem was initialised.
>
>
> We can go with what you describe (which makes sense to me).
> But I'd like to get a ack from traces maintainers before looking into it.
IMO, We can remove "already_done" logic, whenever, rte_trace_save()
called, it creates
the directory of that timestamp and copies the trace buffers. Since we
have "overwrite" and "discard"
modes, it is better to not add "already_done" dogic in rte_trace_save().
>
>
> --
> David Marchand
>
On Fri, Oct 14, 2022 at 6:27 AM Jerin Jacob <jerinjacobk@gmail.com> wrote:
>
> On Fri, Oct 14, 2022 at 12:41 AM David Marchand
> <david.marchand@redhat.com> wrote:
> >
> > On Thu, Oct 13, 2022 at 7:07 PM Harman Kalra <hkalra@marvell.com> wrote:
> > > >
> > > > With the whole traces fixes series applied first, then the new "trace:
> > > > take live traces via telemetry" patch applied, I can't reproduce your issue.
> > > >
> > > >
> > >
> > > Yes, you replicated the same scenario what I tried.
> > > Sorry, I realized that actually it's not an issue, traces generated after /trace/save are getting
> > > appended but in the same file (timestamped on /trace/save) on rte_eal_cleanup().
> > >
> > > I assumed that trace dir generated with a timestamp will include all the trace points emitted
> > > before that timestamp. But in the above scenario same trace dir includes trace points emitted
> > > after this timestamp. I think this is bit confusing. Shall we add a logic where if already_done is
> > > set, rename the original trace dir to latest timestamp?
> >
> > Afaiu, the behavior before this series was the same.
> > An application calling rte_trace_save() would always save to a single directory.
> > One thing that changed though is that the directory is timestamped
> > with the time of the first call to rte_trace_save.
> > Before the seriesn the timestamp was based on the time when the trace
> > subsystem was initialised.
> >
> >
> > We can go with what you describe (which makes sense to me).
> > But I'd like to get a ack from traces maintainers before looking into it.
>
> IMO, We can remove "already_done" logic, whenever, rte_trace_save()
> called, it creates
> the directory of that timestamp and copies the trace buffers. Since we
> have "overwrite" and "discard"
> modes, it is better to not add "already_done" dogic in rte_trace_save().
Well, it's a bit more difficult than just removing already_done.
Before my changes, the timestamp was decided and the directory created
once and for all at init.
On the other hand, every trace_mkdir() call resulted in a
trace_dir_update() call.
--> /trace/save
{"/trace/save": {"Status": "OK", "Path":
"/home/dmarchan/dpdk-traces/rte-2022-10-14-AM-08-39-37"}}
--> /trace/save
{"/trace/save": {"Status": "OK", "Path":
"/home/dmarchan/dpdk-traces/rte-2022-10-14-AM-08-39-37rte-2022-10-14-AM-08-39-38"}}
I prototyped a change (which deserves a separate patch).
Testing it, there is still one corner case when calling
rte_trace_save() twice in the same minute:
--> /trace/save
{"/trace/save": {"Status": "OK", "Path":
"/home/dmarchan/dpdk-traces/rte-2022-10-14-AM-10-11-19"}}
--> /trace/save
{"/trace/save": {"Status": "KO", "Path":
"/home/dmarchan/dpdk-traces/rte-2022-10-14-AM-10-11-19"}}
EAL: Trace dir: /home/dmarchan/dpdk-traces/rte-2022-10-14-AM-10-11-19
EAL: trace_mkdir():321 mkdir
/home/dmarchan/dpdk-traces/rte-2022-10-14-AM-10-11-19 failed [File
exists]
What do you suggest for this?
On Fri, Oct 14, 2022 at 1:49 PM David Marchand
<david.marchand@redhat.com> wrote:
>
> On Fri, Oct 14, 2022 at 6:27 AM Jerin Jacob <jerinjacobk@gmail.com> wrote:
> >
> > On Fri, Oct 14, 2022 at 12:41 AM David Marchand
> > <david.marchand@redhat.com> wrote:
> > >
> > > On Thu, Oct 13, 2022 at 7:07 PM Harman Kalra <hkalra@marvell.com> wrote:
> > > > >
> > > > > With the whole traces fixes series applied first, then the new "trace:
> > > > > take live traces via telemetry" patch applied, I can't reproduce your issue.
> > > > >
> > > > >
> > > >
> > > > Yes, you replicated the same scenario what I tried.
> > > > Sorry, I realized that actually it's not an issue, traces generated after /trace/save are getting
> > > > appended but in the same file (timestamped on /trace/save) on rte_eal_cleanup().
> > > >
> > > > I assumed that trace dir generated with a timestamp will include all the trace points emitted
> > > > before that timestamp. But in the above scenario same trace dir includes trace points emitted
> > > > after this timestamp. I think this is bit confusing. Shall we add a logic where if already_done is
> > > > set, rename the original trace dir to latest timestamp?
> > >
> > > Afaiu, the behavior before this series was the same.
> > > An application calling rte_trace_save() would always save to a single directory.
> > > One thing that changed though is that the directory is timestamped
> > > with the time of the first call to rte_trace_save.
> > > Before the seriesn the timestamp was based on the time when the trace
> > > subsystem was initialised.
> > >
> > >
> > > We can go with what you describe (which makes sense to me).
> > > But I'd like to get a ack from traces maintainers before looking into it.
> >
> > IMO, We can remove "already_done" logic, whenever, rte_trace_save()
> > called, it creates
> > the directory of that timestamp and copies the trace buffers. Since we
> > have "overwrite" and "discard"
> > modes, it is better to not add "already_done" dogic in rte_trace_save().
>
> Well, it's a bit more difficult than just removing already_done.
>
> Before my changes, the timestamp was decided and the directory created
> once and for all at init.
> On the other hand, every trace_mkdir() call resulted in a
> trace_dir_update() call.
> --> /trace/save
> {"/trace/save": {"Status": "OK", "Path":
> "/home/dmarchan/dpdk-traces/rte-2022-10-14-AM-08-39-37"}}
> --> /trace/save
> {"/trace/save": {"Status": "OK", "Path":
> "/home/dmarchan/dpdk-traces/rte-2022-10-14-AM-08-39-37rte-2022-10-14-AM-08-39-38"}}
>
> I prototyped a change (which deserves a separate patch).
> Testing it, there is still one corner case when calling
> rte_trace_save() twice in the same minute:
> --> /trace/save
> {"/trace/save": {"Status": "OK", "Path":
> "/home/dmarchan/dpdk-traces/rte-2022-10-14-AM-10-11-19"}}
> --> /trace/save
> {"/trace/save": {"Status": "KO", "Path":
> "/home/dmarchan/dpdk-traces/rte-2022-10-14-AM-10-11-19"}}
>
> EAL: Trace dir: /home/dmarchan/dpdk-traces/rte-2022-10-14-AM-10-11-19
> EAL: trace_mkdir():321 mkdir
> /home/dmarchan/dpdk-traces/rte-2022-10-14-AM-10-11-19 failed [File
> exists]
>
> What do you suggest for this?
Top of the tree has "seconds" in trace director creation[1]. That will
make it unique in all practical cases.
To make future proof:
We could do either of
1)Even with the second, if a directory exists and wait for 1sec and do
from trace_session_name_generate()
2)Add 2 or 3 digits in the name. Have a counter to make it unique if
the directory exists.
[1]
rc = strftime(trace_dir + rc, TRACE_DIR_STR_LEN - rc,
"%Y-%m-%d-%p-%I-%M-%S", tm_result);
>
>
> --
> David Marchand
>
@@ -9,6 +9,8 @@
#include "test.h"
#include "test_trace.h"
+int app_dpdk_test_tp_count;
+
#ifdef RTE_EXEC_ENV_WINDOWS
static int
@@ -95,8 +97,15 @@ test_trace_point_regex(void)
static int32_t
test_trace_point_disable_enable(void)
{
+ int expected;
int rc;
+ /* At tp registration, the associated counter increases once. */
+ expected = 1;
+ TEST_ASSERT_EQUAL(app_dpdk_test_tp_count, expected,
+ "Expecting %d, but got %d for app_dpdk_test_tp_count",
+ expected, app_dpdk_test_tp_count);
+
rc = rte_trace_point_disable(&__app_dpdk_test_tp);
if (rc < 0)
goto failed;
@@ -104,6 +113,12 @@ test_trace_point_disable_enable(void)
if (rte_trace_point_is_enabled(&__app_dpdk_test_tp))
goto failed;
+ /* No emission expected */
+ app_dpdk_test_tp("app.dpdk.test.tp");
+ TEST_ASSERT_EQUAL(app_dpdk_test_tp_count, expected,
+ "Expecting %d, but got %d for app_dpdk_test_tp_count",
+ expected, app_dpdk_test_tp_count);
+
rc = rte_trace_point_enable(&__app_dpdk_test_tp);
if (rc < 0)
goto failed;
@@ -113,6 +128,11 @@ test_trace_point_disable_enable(void)
/* Emit the trace */
app_dpdk_test_tp("app.dpdk.test.tp");
+ expected++;
+ TEST_ASSERT_EQUAL(app_dpdk_test_tp_count, expected,
+ "Expecting %d, but got %d for app_dpdk_test_tp_count",
+ expected, app_dpdk_test_tp_count);
+
return TEST_SUCCESS;
failed:
@@ -3,10 +3,12 @@
*/
#include <rte_trace_point.h>
+extern int app_dpdk_test_tp_count;
RTE_TRACE_POINT(
app_dpdk_test_tp,
RTE_TRACE_POINT_ARGS(const char *str),
rte_trace_point_emit_string(str);
+ app_dpdk_test_tp_count++;
)
RTE_TRACE_POINT_FP(
@@ -271,10 +271,16 @@ Trace memory
The trace memory will be allocated through an internal function
``__rte_trace_mem_per_thread_alloc()``. The trace memory will be allocated
per thread to enable lock less trace-emit function.
-The memory for the trace memory for DPDK lcores will be allocated on
-``rte_eal_init()`` if the trace is enabled through a EAL option.
-For non DPDK threads, on the first trace emission, the memory will be
-allocated.
+
+For non lcore threads, the trace memory is allocated on the first trace
+emission.
+
+For lcore threads, if trace points are enabled through a EAL option, the trace
+memory is allocated when the threads are known of DPDK
+(``rte_eal_init`` for EAL lcores, ``rte_thread_register`` for non-EAL lcores).
+Otherwise, when trace points are enabled later in the life of the application,
+the behavior is the same as non lcore threads and the trace memory is allocated
+on the first trace emission.
Trace memory layout
~~~~~~~~~~~~~~~~~~~
@@ -48,12 +48,6 @@ eal_trace_init(void)
goto fail;
}
- if (!STAILQ_EMPTY(&trace.args))
- trace.status = true;
-
- if (!rte_trace_is_enabled())
- return 0;
-
rte_spinlock_init(&trace.lock);
/* Is duplicate trace name registered */
@@ -72,13 +66,9 @@ eal_trace_init(void)
if (trace_metadata_create() < 0)
goto fail;
- /* Create trace directory */
- if (trace_mkdir())
- goto free_meta;
-
/* Save current epoch timestamp for future use */
if (trace_epoch_time_save() < 0)
- goto fail;
+ goto free_meta;
/* Apply global configurations */
STAILQ_FOREACH(arg, &trace.args, next)
@@ -98,8 +88,6 @@ eal_trace_init(void)
void
eal_trace_fini(void)
{
- if (!rte_trace_is_enabled())
- return;
trace_mem_free();
trace_metadata_destroy();
eal_trace_args_free();
@@ -108,17 +96,17 @@ eal_trace_fini(void)
bool
rte_trace_is_enabled(void)
{
- return trace.status;
+ return __atomic_load_n(&trace.status, __ATOMIC_ACQUIRE) != 0;
}
static void
-trace_mode_set(rte_trace_point_t *trace, enum rte_trace_mode mode)
+trace_mode_set(rte_trace_point_t *t, enum rte_trace_mode mode)
{
if (mode == RTE_TRACE_MODE_OVERWRITE)
- __atomic_and_fetch(trace, ~__RTE_TRACE_FIELD_ENABLE_DISCARD,
+ __atomic_and_fetch(t, ~__RTE_TRACE_FIELD_ENABLE_DISCARD,
__ATOMIC_RELEASE);
else
- __atomic_or_fetch(trace, __RTE_TRACE_FIELD_ENABLE_DISCARD,
+ __atomic_or_fetch(t, __RTE_TRACE_FIELD_ENABLE_DISCARD,
__ATOMIC_RELEASE);
}
@@ -146,36 +134,42 @@ trace_point_is_invalid(rte_trace_point_t *t)
}
bool
-rte_trace_point_is_enabled(rte_trace_point_t *trace)
+rte_trace_point_is_enabled(rte_trace_point_t *t)
{
uint64_t val;
- if (trace_point_is_invalid(trace))
+ if (trace_point_is_invalid(t))
return false;
- val = __atomic_load_n(trace, __ATOMIC_ACQUIRE);
+ val = __atomic_load_n(t, __ATOMIC_ACQUIRE);
return (val & __RTE_TRACE_FIELD_ENABLE_MASK) != 0;
}
int
-rte_trace_point_enable(rte_trace_point_t *trace)
+rte_trace_point_enable(rte_trace_point_t *t)
{
- if (trace_point_is_invalid(trace))
+ uint64_t prev;
+
+ if (trace_point_is_invalid(t))
return -ERANGE;
- __atomic_or_fetch(trace, __RTE_TRACE_FIELD_ENABLE_MASK,
- __ATOMIC_RELEASE);
+ prev = __atomic_fetch_or(t, __RTE_TRACE_FIELD_ENABLE_MASK, __ATOMIC_RELEASE);
+ if ((prev & __RTE_TRACE_FIELD_ENABLE_MASK) == 0)
+ __atomic_add_fetch(&trace.status, 1, __ATOMIC_RELEASE);
return 0;
}
int
-rte_trace_point_disable(rte_trace_point_t *trace)
+rte_trace_point_disable(rte_trace_point_t *t)
{
- if (trace_point_is_invalid(trace))
+ uint64_t prev;
+
+ if (trace_point_is_invalid(t))
return -ERANGE;
- __atomic_and_fetch(trace, ~__RTE_TRACE_FIELD_ENABLE_MASK,
- __ATOMIC_RELEASE);
+ prev = __atomic_fetch_and(t, ~__RTE_TRACE_FIELD_ENABLE_MASK, __ATOMIC_RELEASE);
+ if ((prev & __RTE_TRACE_FIELD_ENABLE_MASK) != 0)
+ __atomic_sub_fetch(&trace.status, 1, __ATOMIC_RELEASE);
return 0;
}
@@ -417,9 +411,6 @@ trace_mem_free(void)
struct trace *trace = trace_obj_get();
uint32_t count;
- if (!rte_trace_is_enabled())
- return;
-
rte_spinlock_lock(&trace->lock);
for (count = 0; count < trace->nb_trace_mem_list; count++) {
trace_mem_per_thread_free_unlocked(&trace->lcore_meta[count]);
@@ -314,14 +314,18 @@ trace_dir_default_path_get(char *dir_path)
return 0;
}
-int
+static int
trace_mkdir(void)
{
struct trace *trace = trace_obj_get();
char session[TRACE_DIR_STR_LEN];
+ static bool already_done;
char *dir_path;
int rc;
+ if (already_done)
+ return 0;
+
if (!trace->dir_offset) {
dir_path = calloc(1, sizeof(trace->dir));
if (dir_path == NULL) {
@@ -365,6 +369,7 @@ trace_mkdir(void)
}
RTE_LOG(INFO, EAL, "Trace dir: %s\n", trace->dir);
+ already_done = true;
return 0;
}
@@ -434,6 +439,10 @@ rte_trace_save(void)
if (trace->nb_trace_mem_list == 0)
return rc;
+ rc = trace_mkdir();
+ if (rc < 0)
+ return rc;
+
rc = trace_meta_save(trace);
if (rc)
return rc;
@@ -54,7 +54,7 @@ struct trace {
char dir[PATH_MAX];
int dir_offset;
int register_errno;
- bool status;
+ uint32_t status;
enum rte_trace_mode mode;
rte_uuid_t uuid;
uint32_t buff_len;
@@ -104,7 +104,6 @@ void trace_uuid_generate(void);
int trace_metadata_create(void);
void trace_metadata_destroy(void);
char *trace_metadata_fixup_field(const char *field);
-int trace_mkdir(void);
int trace_epoch_time_save(void);
void trace_mem_free(void);
void trace_mem_per_thread_free(void);