[EXT] [PATCH v3 5/9] trace: fix dynamically enabling trace points

[David Marchand]

On Thu, Oct 13, 2022 at 4:53 PM Harman Kalra <hkalra at 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.


-- 
David Marchand