2021-05-28 17:14:44

by Leo Yan

[permalink] [raw]
Subject: [PATCH v1 1/3] coresight: etm-perf: Correct buffer syncing for snapshot

The perf tool records the Arm CoreSight trace data with snapshot mode
with the option '-S', when receiving USR2 signal, it is observed the
captured trace data size is very varied: from several MBs to ~20MBs.
This can be reproduced with the command:

perf record -e cs_etm// -S \
-- dd if=/dev/zero of=/dev/null > /dev/null 2>&1 &
PERFPID=$!
sleep 1
kill -USR2 $PERFPID

It's different for only specifying option '-S' than options '-a -S'. If
without option '-a', perf tool creates separate AUX buffers for every
CPU, but the tracer will be enabled only when the profiled program is
scheduled onto the corresponding CPU, this might lead to record very
old trace data when snapshot.

Let's see below diagram:
snapshot
CPU0: ______###P1###__________________________________________|
CPU1: __________________________###P3###____________###P5###__|
CPU2: ____________________________________###P4###____________|
CPU3: ________________###P2###________________________________V

In this diagram, the program runs for 5 periods (from P1 to P5), these 5
periods show the task run on different CPUs, e.g. during P1 period the
program runs on CPU0, and during P2 period the program is migrated to
CPU1, and so on. At the end of P1 period when the program is switched
out from CPU0, the ETR trace data is saved into AUX trace buffer, this
AUX buffer is a dedicated buffer for CPU0's tracer. With the same
logic, P2's trace data is saved into CPU3's tracer buffer, P4's trace
data is saved into CPU2's buffer, P3 and P5's trace data is saved into
CPU1's. Therefore, when snapshot, it saves the trace data from all AUX
ring buffers (in this case, it have total 4 AUX ring buffers) into perf
data file.

This is why we can see varied trace data size, it's quite dependent on
the task scheduling on CPUs, if the task is spinned to only one CPU and
without scheduling out, it will only record trace data from only one
AUX trace buffer. If the task is frequently scheduled in and out, then
it gives more chance to fill trace data into the AUX buffer.

In this example, it also causes the discontinuous trace data. If P3's
trace data is lost after P5's trace data overwrites the AUX trace data,
thus perf tool fails to record continuous trace data if only have
trace data for P1/P2/P4/P5.

For snapshot mode, usually the user only wants to capture the trace data
for the specific time point and prior to the that point the tracer
should work with free run mode. This means it's not necessary to
capture trace data for task's scheduling in and out until the perf tool
explicitly disables tracers for snapshot. This can be fulfilled by
checking the variable "event->ctx->is_active", when the task is
scheduled out this variable is set to zero, and when snapshot this
variable is still non-zero value. So the driver can only record trace
data only when "event->ctx->is_active" is non-zero.

After applying this change, the perf tool can record the consistent
trace data size for snapshot.

Signed-off-by: Leo Yan <[email protected]>
---
.../hwtracing/coresight/coresight-etm-perf.c | 30 +++++++++++++++++--
.../hwtracing/coresight/coresight-etm-perf.h | 2 ++
2 files changed, 29 insertions(+), 3 deletions(-)

diff --git a/drivers/hwtracing/coresight/coresight-etm-perf.c b/drivers/hwtracing/coresight/coresight-etm-perf.c
index 6f398377fec9..fd36d0530087 100644
--- a/drivers/hwtracing/coresight/coresight-etm-perf.c
+++ b/drivers/hwtracing/coresight/coresight-etm-perf.c
@@ -284,6 +284,7 @@ static void *etm_setup_aux(struct perf_event *event, void **pages,
if (!event_data)
return NULL;
INIT_WORK(&event_data->work, free_event_data);
+ event_data->overwrite = overwrite;

/* First get the selected sink from user space. */
if (event->attr.config2) {
@@ -517,9 +518,32 @@ static void etm_event_stop(struct perf_event *event, int mode)
if (!sink_ops(sink)->update_buffer)
return;

- size = sink_ops(sink)->update_buffer(sink, handle,
- event_data->snk_config);
- perf_aux_output_end(handle, size);
+ /*
+ * In the snapshot mode, if only specifies option '-S' (note,
+ * user doesn't specify option '-a' in this case), the AUX ring
+ * buffers are allocated for every CPU but the AUX trace is
+ * recorded in per-thread mode. In this mode, it's needless to
+ * save AUX trace data into the AUX ring buffer when the
+ * profiled program is scheduled out from a CPU, alternatively,
+ * the driver should only capture AUX trace data when the perf
+ * tool receives USR2 signal for taking snapshot.
+ *
+ * The variable "event->ctx->is_active" can be used to
+ * distinguish the cases between the program scheduling out and
+ * snapshot: its value is zero when the profiled task scheduled
+ * out, and it is a non-zero value when perf tool invokes ioctl
+ * PERF_EVENT_IOC_DISABLE for snapshot.
+ *
+ * Only updates AUX ring buffer for snapshot, or for the perf
+ * session which is not in snapshot mode.
+ */
+ if (!event_data->overwrite || event->ctx->is_active) {
+ size = sink_ops(sink)->update_buffer(sink, handle,
+ event_data->snk_config);
+ perf_aux_output_end(handle, size);
+ } else {
+ perf_aux_output_end(handle, 0);
+ }
}

/* Disabling the path make its elements available to other sessions */
diff --git a/drivers/hwtracing/coresight/coresight-etm-perf.h b/drivers/hwtracing/coresight/coresight-etm-perf.h
index 3e4f2ad5e193..2cc3af05495f 100644
--- a/drivers/hwtracing/coresight/coresight-etm-perf.h
+++ b/drivers/hwtracing/coresight/coresight-etm-perf.h
@@ -49,12 +49,14 @@ struct etm_filters {
* @mask: Hold the CPU(s) this event was set for.
* @snk_config: The sink configuration.
* @path: An array of path, each slot for one CPU.
+ * @overwrite: Flag for snapshot mode.
*/
struct etm_event_data {
struct work_struct work;
cpumask_t mask;
void *snk_config;
struct list_head * __percpu *path;
+ bool overwrite;
};

#if IS_ENABLED(CONFIG_CORESIGHT)
--
2.25.1


2021-06-01 09:55:24

by James Clark

[permalink] [raw]
Subject: Re: [PATCH v1 1/3] coresight: etm-perf: Correct buffer syncing for snapshot



On 28/05/2021 19:15, Leo Yan wrote:
> The perf tool records the Arm CoreSight trace data with snapshot mode
> with the option '-S', when receiving USR2 signal, it is observed the
> captured trace data size is very varied: from several MBs to ~20MBs.
> This can be reproduced with the command:
>
> perf record -e cs_etm// -S \
> -- dd if=/dev/zero of=/dev/null > /dev/null 2>&1 &
> PERFPID=$!
> sleep 1
> kill -USR2 $PERFPID
>
> It's different for only specifying option '-S' than options '-a -S'. If
> without option '-a', perf tool creates separate AUX buffers for every
> CPU, but the tracer will be enabled only when the profiled program is
> scheduled onto the corresponding CPU, this might lead to record very
> old trace data when snapshot.
>
> Let's see below diagram:
> snapshot
> CPU0: ______###P1###__________________________________________|
> CPU1: __________________________###P3###____________###P5###__|
> CPU2: ____________________________________###P4###____________|
> CPU3: ________________###P2###________________________________V
>
> In this diagram, the program runs for 5 periods (from P1 to P5), these 5
> periods show the task run on different CPUs, e.g. during P1 period the
> program runs on CPU0, and during P2 period the program is migrated to
> CPU1, and so on. At the end of P1 period when the program is switched
> out from CPU0, the ETR trace data is saved into AUX trace buffer, this
> AUX buffer is a dedicated buffer for CPU0's tracer. With the same
> logic, P2's trace data is saved into CPU3's tracer buffer, P4's trace
> data is saved into CPU2's buffer, P3 and P5's trace data is saved into
> CPU1's. Therefore, when snapshot, it saves the trace data from all AUX
> ring buffers (in this case, it have total 4 AUX ring buffers) into perf
> data file.

Hi Leo,

I was testing out snapshot mode (without your patch) and I noticed that it
only ever collects from the last CPU. For example on a 4 core system,
the CPU ID of the AUX records and the AUXTRACE buffers is always 3.

This is with systemwide tracing, and running "stress -m 2 -c 2".
Is this something that your patch fixes, or am I doing something wrong, or
is it just a coincidence?

Here's a snippet of the output:

./perf report -D | grep AUX
0 0 0x200 [0x168]: PERF_RECORD_AUXTRACE_INFO type: 3
0 0 0x152248 [0x30]: PERF_RECORD_AUXTRACE size: 0x400000 offset: 0 ref: 0x75e0bdc44ea1bb65 idx: 3 tid: -1 cpu: 3
3 583600975364460 0x152160 [0x40]: PERF_RECORD_AUX offset: 0x400000 size: 0x400000 flags: 0x2 [O]
0 0 0x55c950 [0x30]: PERF_RECORD_AUXTRACE size: 0x400000 offset: 0x400000 ref: 0x6f506d2d02841da4 idx: 3 tid: -1 cpu: 3
3 583602209157460 0x55c908 [0x40]: PERF_RECORD_AUX offset: 0x800000 size: 0x400000 flags: 0x2 [O]
0 0 0x9624d8 [0x30]: PERF_RECORD_AUXTRACE size: 0x400000 offset: 0x800000 ref: 0x2d83d30161e1117a idx: 3 tid: -1 cpu: 3
3 583602526365800 0x962490 [0x40]: PERF_RECORD_AUX offset: 0xc00000 size: 0x400000 flags: 0x2 [O]
0 0 0xd65f00 [0x30]: PERF_RECORD_AUXTRACE size: 0x400000 offset: 0xc00000 ref: 0x5013e6e2a3c97c9 idx: 3 tid: -1 cpu: 3
3 583602714310320 0xd65eb8 [0x40]: PERF_RECORD_AUX offset: 0x1000000 size: 0x400000 flags: 0x2 [O]
0 0 0x1169be8 [0x30]: PERF_RECORD_AUXTRACE size: 0x400000 offset: 0x1000000 ref: 0x67b37e157f843269 idx: 3 tid: -1 cpu: 3
3 583602874193840 0x1169ba0 [0x40]: PERF_RECORD_AUX offset: 0x1400000 size: 0x400000 flags: 0x2 [O]
0 0 0x156d550 [0x30]: PERF_RECORD_AUXTRACE size: 0x400000 offset: 0x1400000 ref: 0x3cb268b926f22d41 idx: 3 tid: -1 cpu: 3
3 583603044203980 0x156d508 [0x40]: PERF_RECORD_AUX offset: 0x1800000 size: 0x400000 flags: 0x2 [O]
0 0 0x1971238 [0x30]: PERF_RECORD_AUXTRACE size: 0x400000 offset: 0x1800000 ref: 0x4905e0a21d5d35d7 idx: 3 tid: -1 cpu: 3
3 583603211393440 0x19711f0 [0x40]: PERF_RECORD_AUX offset: 0x1c00000 size: 0x400000 flags: 0x2 [O]
0 0 0x1d747e0 [0x30]: PERF_RECORD_AUXTRACE size: 0x400000 offset: 0x1c00000 ref: 0x4f8f48007f7d70e7 idx: 3 tid: -1 cpu: 3
3 583603362643100 0x1d74798 [0x40]: PERF_RECORD_AUX offset: 0x2000000 size: 0x400000 flags: 0x2 [O]
0 0 0x2178368 [0x30]: PERF_RECORD_AUXTRACE size: 0x400000 offset: 0x2000000 ref: 0x770d07213be2d29a idx: 3 tid: -1 cpu: 3
3 583603526029900 0x2178320 [0x40]: PERF_RECORD_AUX offset: 0x2400000 size: 0x400000 flags: 0x2 [O]
0 0 0x257bfb0 [0x30]: PERF_RECORD_AUXTRACE size: 0x400000 offset: 0x2400000 ref: 0x2e4ed1454815c13e idx: 3 tid: -1 cpu: 3
3 583603687951260 0x257bf68 [0x40]: PERF_RECORD_AUX offset: 0x2800000 size: 0x400000 flags: 0x2 [O]
0 0 0x297fb18 [0x30]: PERF_RECORD_AUXTRACE size: 0x400000 offset: 0x2800000 ref: 0x644eba01d391129 idx: 3 tid: -1 cpu: 3

Thanks
James

2021-06-01 10:35:58

by Leo Yan

[permalink] [raw]
Subject: Re: [PATCH v1 1/3] coresight: etm-perf: Correct buffer syncing for snapshot

Hi James,

On Tue, Jun 01, 2021 at 12:53:16PM +0300, James Clark wrote:

[...]

> Hi Leo,
>
> I was testing out snapshot mode (without your patch) and I noticed that it
> only ever collects from the last CPU. For example on a 4 core system,
> the CPU ID of the AUX records and the AUXTRACE buffers is always 3.
>
> This is with systemwide tracing, and running "stress -m 2 -c 2".
> Is this something that your patch fixes, or am I doing something wrong, or
> is it just a coincidence?

No, I think it's quite likely caused by blow code:

static unsigned long
tmc_update_etr_buffer(struct coresight_device *csdev,
struct perf_output_handle *handle,
void *config)
{
unsigned long flags, offset, size = 0;

...

/* Don't do anything if another tracer is using this sink */
if (atomic_read(csdev->refcnt) != 1) {
spin_unlock_irqrestore(&drvdata->spinlock, flags);
goto out;
}

...

return size;
}

When using the system wide tracing, it updates the AUX ring buffer
until the last tracer is stopped. Thus whis is why it only records
AUX ring buffer for the last CPU.

But this makes sense for me, this is because the last CPU is used to
copy trace data to AUX ring buffer (so the perf event PERF_RECORD_AUX
occurs on CPU3), but when you decode the trace data, you should can
see the activities from other CPUs.

Thanks,
Leo

2021-06-08 21:47:02

by Mathieu Poirier

[permalink] [raw]
Subject: Re: [PATCH v1 1/3] coresight: etm-perf: Correct buffer syncing for snapshot

On Sat, May 29, 2021 at 12:15:50AM +0800, Leo Yan wrote:
> The perf tool records the Arm CoreSight trace data with snapshot mode
> with the option '-S', when receiving USR2 signal, it is observed the
> captured trace data size is very varied: from several MBs to ~20MBs.
> This can be reproduced with the command:
>
> perf record -e cs_etm// -S \
> -- dd if=/dev/zero of=/dev/null > /dev/null 2>&1 &
> PERFPID=$!
> sleep 1
> kill -USR2 $PERFPID
>
> It's different for only specifying option '-S' than options '-a -S'. If
> without option '-a', perf tool creates separate AUX buffers for every
> CPU, but the tracer will be enabled only when the profiled program is
> scheduled onto the corresponding CPU, this might lead to record very
> old trace data when snapshot.

I'm very perplexed by this paragraph... The '-a' option means tracing on all
CPUs, which will definitely allocate an AUX buffer per CPU.

>
> Let's see below diagram:
> snapshot
> CPU0: ______###P1###__________________________________________|
> CPU1: __________________________###P3###____________###P5###__|
> CPU2: ____________________________________###P4###____________|
> CPU3: ________________###P2###________________________________V
>
> In this diagram, the program runs for 5 periods (from P1 to P5), these 5
> periods show the task run on different CPUs, e.g. during P1 period the
> program runs on CPU0, and during P2 period the program is migrated to
> CPU1, and so on. At the end of P1 period when the program is switched
> out from CPU0, the ETR trace data is saved into AUX trace buffer, this
> AUX buffer is a dedicated buffer for CPU0's tracer. With the same
> logic, P2's trace data is saved into CPU3's tracer buffer, P4's trace
> data is saved into CPU2's buffer, P3 and P5's trace data is saved into
> CPU1's. Therefore, when snapshot, it saves the trace data from all AUX
> ring buffers (in this case, it have total 4 AUX ring buffers) into perf
> data file.
>

When a snapshot happens and if the event is currently active, traces
accumulated since the event was _installed_ on the CPU will be copied from the
coresight buffer to the AUX buffer. Trace data accumulated in other buffers will
already have been copied when the event was scheduled out.

I *think* what is happening here is that if P5 was still active when the
snapshot occurs, we would get trace data from P3 and P5, and not P4. Is my
understanding correct?

> This is why we can see varied trace data size, it's quite dependent on
> the task scheduling on CPUs, if the task is spinned to only one CPU and
> without scheduling out, it will only record trace data from only one
> AUX trace buffer. If the task is frequently scheduled in and out, then
> it gives more chance to fill trace data into the AUX buffer.
>
> In this example, it also causes the discontinuous trace data. If P3's
> trace data is lost after P5's trace data overwrites the AUX trace data,
> thus perf tool fails to record continuous trace data if only have
> trace data for P1/P2/P4/P5.
>
> For snapshot mode, usually the user only wants to capture the trace data
> for the specific time point and prior to the that point the tracer
> should work with free run mode. This means it's not necessary to
> capture trace data for task's scheduling in and out until the perf tool
> explicitly disables tracers for snapshot. This can be fulfilled by
> checking the variable "event->ctx->is_active", when the task is
> scheduled out this variable is set to zero, and when snapshot this
> variable is still non-zero value. So the driver can only record trace
> data only when "event->ctx->is_active" is non-zero.

The problem with this approach is that if the AUX buffer is 4MB and the CS
buffer is 1MB then we only record 1MB, but because of N:1 topologies we may not
be able to do better. I haven't looked at the code yet, something I will do
tomorrow.

>
> After applying this change, the perf tool can record the consistent
> trace data size for snapshot.
>
> Signed-off-by: Leo Yan <[email protected]>
> ---
> .../hwtracing/coresight/coresight-etm-perf.c | 30 +++++++++++++++++--
> .../hwtracing/coresight/coresight-etm-perf.h | 2 ++
> 2 files changed, 29 insertions(+), 3 deletions(-)
>
> diff --git a/drivers/hwtracing/coresight/coresight-etm-perf.c b/drivers/hwtracing/coresight/coresight-etm-perf.c
> index 6f398377fec9..fd36d0530087 100644
> --- a/drivers/hwtracing/coresight/coresight-etm-perf.c
> +++ b/drivers/hwtracing/coresight/coresight-etm-perf.c
> @@ -284,6 +284,7 @@ static void *etm_setup_aux(struct perf_event *event, void **pages,
> if (!event_data)
> return NULL;
> INIT_WORK(&event_data->work, free_event_data);
> + event_data->overwrite = overwrite;
>
> /* First get the selected sink from user space. */
> if (event->attr.config2) {
> @@ -517,9 +518,32 @@ static void etm_event_stop(struct perf_event *event, int mode)
> if (!sink_ops(sink)->update_buffer)
> return;
>
> - size = sink_ops(sink)->update_buffer(sink, handle,
> - event_data->snk_config);
> - perf_aux_output_end(handle, size);
> + /*
> + * In the snapshot mode, if only specifies option '-S' (note,
> + * user doesn't specify option '-a' in this case), the AUX ring
> + * buffers are allocated for every CPU but the AUX trace is
> + * recorded in per-thread mode. In this mode, it's needless to
> + * save AUX trace data into the AUX ring buffer when the
> + * profiled program is scheduled out from a CPU, alternatively,
> + * the driver should only capture AUX trace data when the perf
> + * tool receives USR2 signal for taking snapshot.
> + *
> + * The variable "event->ctx->is_active" can be used to
> + * distinguish the cases between the program scheduling out and
> + * snapshot: its value is zero when the profiled task scheduled
> + * out, and it is a non-zero value when perf tool invokes ioctl
> + * PERF_EVENT_IOC_DISABLE for snapshot.
> + *
> + * Only updates AUX ring buffer for snapshot, or for the perf
> + * session which is not in snapshot mode.
> + */
> + if (!event_data->overwrite || event->ctx->is_active) {
> + size = sink_ops(sink)->update_buffer(sink, handle,
> + event_data->snk_config);
> + perf_aux_output_end(handle, size);
> + } else {
> + perf_aux_output_end(handle, 0);
> + }
> }
>
> /* Disabling the path make its elements available to other sessions */
> diff --git a/drivers/hwtracing/coresight/coresight-etm-perf.h b/drivers/hwtracing/coresight/coresight-etm-perf.h
> index 3e4f2ad5e193..2cc3af05495f 100644
> --- a/drivers/hwtracing/coresight/coresight-etm-perf.h
> +++ b/drivers/hwtracing/coresight/coresight-etm-perf.h
> @@ -49,12 +49,14 @@ struct etm_filters {
> * @mask: Hold the CPU(s) this event was set for.
> * @snk_config: The sink configuration.
> * @path: An array of path, each slot for one CPU.
> + * @overwrite: Flag for snapshot mode.
> */
> struct etm_event_data {
> struct work_struct work;
> cpumask_t mask;
> void *snk_config;
> struct list_head * __percpu *path;
> + bool overwrite;
> };
>
> #if IS_ENABLED(CONFIG_CORESIGHT)
> --
> 2.25.1
>

2021-06-09 12:23:05

by Leo Yan

[permalink] [raw]
Subject: Re: [PATCH v1 1/3] coresight: etm-perf: Correct buffer syncing for snapshot

On Wed, Jun 09, 2021 at 09:35:55AM +0800, Leo Yan wrote:

[...]

> > The problem with this approach is that if the AUX buffer is 4MB and the CS
> > buffer is 1MB then we only record 1MB, but because of N:1 topologies we may not
> > be able to do better. I haven't looked at the code yet, something I will do
> > tomorrow.
>
> Yes, the fixing in this patch copies the trace data is limited by the
> CoreSight bounce buffer length. So if CoreSight buffer length is
> 1MiB, then we have no chance to allocate 4MiB for AUX buffer.

Sorry for typo, just correct:

if CoreSight buffer length is 1MiB, then we have no chance to *copy*
4MiB trace data for AUX buffer.

2021-06-09 17:05:16

by Leo Yan

[permalink] [raw]
Subject: Re: [PATCH v1 1/3] coresight: etm-perf: Correct buffer syncing for snapshot

On Tue, Jun 08, 2021 at 03:41:49PM -0600, Mathieu Poirier wrote:
> On Sat, May 29, 2021 at 12:15:50AM +0800, Leo Yan wrote:
> > The perf tool records the Arm CoreSight trace data with snapshot mode
> > with the option '-S', when receiving USR2 signal, it is observed the
> > captured trace data size is very varied: from several MBs to ~20MBs.
> > This can be reproduced with the command:
> >
> > perf record -e cs_etm// -S \
> > -- dd if=/dev/zero of=/dev/null > /dev/null 2>&1 &
> > PERFPID=$!
> > sleep 1
> > kill -USR2 $PERFPID
> >
> > It's different for only specifying option '-S' than options '-a -S'. If
> > without option '-a', perf tool creates separate AUX buffers for every
> > CPU, but the tracer will be enabled only when the profiled program is
> > scheduled onto the corresponding CPU, this might lead to record very
> > old trace data when snapshot.
>
> I'm very perplexed by this paragraph... The '-a' option means tracing on all
> CPUs, which will definitely allocate an AUX buffer per CPU.

Sorry for confusion. We can understand the mechanism based on two factors:
one factor is AUX buffer allocation (per CPU or single AUX buffer
shared by all CPUs), another factor is what's the occasion to enable tracers.

If with only option '-a -S', as you said, perf allocates an AUX buffer per CPU.
And it always enable ETMs for all CPUs.

If with option '-S', perf also allocates an AUX buffer per CPU, but
it's different for enabling tracers from the option '-a -S'; in this
case, perf works like per-thread mode, the tracer (ETM) is only enabled
when the profiled process is scheduled on a specific CPU. e.g. when
the task is scheduled on CPU2, then the ETM attached to CPU2 is
enabled for tracing.

> > Let's see below diagram:
> > snapshot
> > CPU0: ______###P1###__________________________________________|
> > CPU1: __________________________###P3###____________###P5###__|
> > CPU2: ____________________________________###P4###____________|
> > CPU3: ________________###P2###________________________________V
> >
> > In this diagram, the program runs for 5 periods (from P1 to P5), these 5
> > periods show the task run on different CPUs, e.g. during P1 period the
> > program runs on CPU0, and during P2 period the program is migrated to
> > CPU1, and so on. At the end of P1 period when the program is switched
> > out from CPU0, the ETR trace data is saved into AUX trace buffer, this
> > AUX buffer is a dedicated buffer for CPU0's tracer. With the same
> > logic, P2's trace data is saved into CPU3's tracer buffer, P4's trace
> > data is saved into CPU2's buffer, P3 and P5's trace data is saved into
> > CPU1's. Therefore, when snapshot, it saves the trace data from all AUX
> > ring buffers (in this case, it have total 4 AUX ring buffers) into perf
> > data file.
> >
>
> When a snapshot happens and if the event is currently active, traces
> accumulated since the event was _installed_ on the CPU will be copied from the
> coresight buffer to the AUX buffer. Trace data accumulated in other buffers will
> already have been copied when the event was scheduled out.

Yes.

> I *think* what is happening here is that if P5 was still active when the
> snapshot occurs, we would get trace data from P3 and P5, and not P4. Is my
> understanding correct?

No, in current code, when the snapshot occurs, we get trace data from
P1 to P5.

Keep in mind that the AUX ring buffer and CoreSight's bounce buffer are
allocated per CPU. So P1 trace data is stored into AUX buffer 0, P3 and
P5 trace data is stored in AUX buffer 1, and so on.

When the snapshot is taken, it iterates the AUX buffers one bye one
from buffer 0 to buffer 3, see the function
record__auxtrace_read_snapshot_all() in the perf source file builtin-record.c.
Since every AUX buffer contains the trace data, so P1 to P5's trace
data will be recorded into perf data file.

> > This is why we can see varied trace data size, it's quite dependent on
> > the task scheduling on CPUs, if the task is spinned to only one CPU and
> > without scheduling out, it will only record trace data from only one
> > AUX trace buffer. If the task is frequently scheduled in and out, then
> > it gives more chance to fill trace data into the AUX buffer.
> >
> > In this example, it also causes the discontinuous trace data. If P3's
> > trace data is lost after P5's trace data overwrites the AUX trace data,
> > thus perf tool fails to record continuous trace data if only have
> > trace data for P1/P2/P4/P5.
> >
> > For snapshot mode, usually the user only wants to capture the trace data
> > for the specific time point and prior to the that point the tracer
> > should work with free run mode. This means it's not necessary to
> > capture trace data for task's scheduling in and out until the perf tool
> > explicitly disables tracers for snapshot. This can be fulfilled by
> > checking the variable "event->ctx->is_active", when the task is
> > scheduled out this variable is set to zero, and when snapshot this
> > variable is still non-zero value. So the driver can only record trace
> > data only when "event->ctx->is_active" is non-zero.
>
> The problem with this approach is that if the AUX buffer is 4MB and the CS
> buffer is 1MB then we only record 1MB, but because of N:1 topologies we may not
> be able to do better. I haven't looked at the code yet, something I will do
> tomorrow.

Yes, the fixing in this patch copies the trace data is limited by the
CoreSight bounce buffer length. So if CoreSight buffer length is
1MiB, then we have no chance to allocate 4MiB for AUX buffer.

Seems to me, it's unlikely that we have the AUX buffer with 4MiB and
CoreSight bounce buffer with 1MiB. I read the function
tmc_alloc_etr_buffer(), in most case, the AUX buffer size and
CoreSight bounce buffer size is consistent.

If have any furter questions, just let me know. Thanks for reviewing.

Leo

2021-06-10 14:58:07

by James Clark

[permalink] [raw]
Subject: Re: [PATCH v1 1/3] coresight: etm-perf: Correct buffer syncing for snapshot



On 01/06/2021 13:35, Leo Yan wrote:
> Hi James,
>
> On Tue, Jun 01, 2021 at 12:53:16PM +0300, James Clark wrote:
>
> [...]
>
>> Hi Leo,
>>
>> I was testing out snapshot mode (without your patch) and I noticed that it
>> only ever collects from the last CPU. For example on a 4 core system,
>> the CPU ID of the AUX records and the AUXTRACE buffers is always 3.
>>
>> This is with systemwide tracing, and running "stress -m 2 -c 2".
>> Is this something that your patch fixes, or am I doing something wrong, or
>> is it just a coincidence?
>
> No, I think it's quite likely caused by blow code:
>
> static unsigned long
> tmc_update_etr_buffer(struct coresight_device *csdev,
> struct perf_output_handle *handle,
> void *config)
> {
> unsigned long flags, offset, size = 0;
>
> ...
>
> /* Don't do anything if another tracer is using this sink */
> if (atomic_read(csdev->refcnt) != 1) {
> spin_unlock_irqrestore(&drvdata->spinlock, flags);
> goto out;
> }
>
> ...
>
> return size;
> }
>
> When using the system wide tracing, it updates the AUX ring buffer
> until the last tracer is stopped. Thus whis is why it only records
> AUX ring buffer for the last CPU.
>
> But this makes sense for me, this is because the last CPU is used to
> copy trace data to AUX ring buffer (so the perf event PERF_RECORD_AUX
> occurs on CPU3), but when you decode the trace data, you should can
> see the activities from other CPUs.
>
> Thanks,
> Leo
>

I have one more issue around snapshot mode which I'd like to check if it's
related to this patchset.

In "[PATCH v5 0/1] perf cs-etm: Split Coresight decode by aux records",
I added the warning for a missing AUXTRACE buffer as you suggested.
Now this warning gets triggered on the last AUX record when using
snapshot mode. I don't know if you are able to reproduce this.

Thanks
James

2021-06-11 14:01:06

by James Clark

[permalink] [raw]
Subject: Re: [PATCH v1 1/3] coresight: etm-perf: Correct buffer syncing for snapshot



On 10/06/2021 17:54, James Clark wrote:
>
>
> On 01/06/2021 13:35, Leo Yan wrote:
>> Hi James,
>>
>> On Tue, Jun 01, 2021 at 12:53:16PM +0300, James Clark wrote:
>>
>> [...]
>>
>>> Hi Leo,
>>>
>>> I was testing out snapshot mode (without your patch) and I noticed that it
>>> only ever collects from the last CPU. For example on a 4 core system,
>>> the CPU ID of the AUX records and the AUXTRACE buffers is always 3.
>>>
>>> This is with systemwide tracing, and running "stress -m 2 -c 2".
>>> Is this something that your patch fixes, or am I doing something wrong, or
>>> is it just a coincidence?
>>
>> No, I think it's quite likely caused by blow code:
>>
>> static unsigned long
>> tmc_update_etr_buffer(struct coresight_device *csdev,
>> struct perf_output_handle *handle,
>> void *config)
>> {
>> unsigned long flags, offset, size = 0;
>>
>> ...
>>
>> /* Don't do anything if another tracer is using this sink */
>> if (atomic_read(csdev->refcnt) != 1) {
>> spin_unlock_irqrestore(&drvdata->spinlock, flags);
>> goto out;
>> }
>>
>> ...
>>
>> return size;
>> }
>>
>> When using the system wide tracing, it updates the AUX ring buffer
>> until the last tracer is stopped. Thus whis is why it only records
>> AUX ring buffer for the last CPU.
>>
>> But this makes sense for me, this is because the last CPU is used to
>> copy trace data to AUX ring buffer (so the perf event PERF_RECORD_AUX
>> occurs on CPU3), but when you decode the trace data, you should can
>> see the activities from other CPUs.
>>
>> Thanks,
>> Leo
>>
>
> I have one more issue around snapshot mode which I'd like to check if it's
> related to this patchset.
>
> In "[PATCH v5 0/1] perf cs-etm: Split Coresight decode by aux records",
> I added the warning for a missing AUXTRACE buffer as you suggested.
> Now this warning gets triggered on the last AUX record when using
> snapshot mode. I don't know if you are able to reproduce this.
>

Hi Leo,

So I tested this set with my aux split patch, and I still get the warning about the
last AUX record not being found, so this is an independent issue. Whether
it could be (or needs to be fixed) at the same time, I'm not sure.

One thing seems to have improved with your set is the number of aux records
produced. For each SIGUSR2, I now get one aux record. Previously I got a random
number that didn't seem to match up, which didn't seem right to me.

But one thing that could be worse is the offsets and sizes. Now the size of the
aux records is always 0x100000, no matter what the -m arguments are, and the size
of the AUX record exceeds the size of the buffer. This makes the split patchset
fall back to processing the whole buffer because it never finds a buffer that the
AUX record fits in. For example:

0 0 0xad0 [0x30]: PERF_RECORD_AUXTRACE size: 0x20000 offset: 0xe0000 ref: 0x406971eb0346c919 idx: 2 tid: 6794 cpu: 2
2 5644375601060 0xa88 [0x40]: PERF_RECORD_AUX offset: 0x100000 size: 0x100000 flags: 0x2 [O]

The buffer is only 0x20000 long, but the aux record is 0x100000.

Another issue is that now the offsets don't match up:
0 0 0xad0 [0x30]: PERF_RECORD_AUXTRACE size: 0x20000
offset: 0xe0000 ref: 0x406971eb0346c919 idx: 2 tid: 6794 cpu: 2
2 5644375601060 0xa88 [0x40]: PERF_RECORD_AUX offset: 0x100000 size: 0x100000 flags: 0x2 [O]
0 0 0x20bb0 [0x30]: PERF_RECORD_AUXTRACE size: 0x20000 offset: 0x1e0000 ref: 0x1a3abb5c2407536a idx: 2 tid: 6794 cpu: 2
2 5644942278600 0x20b68 [0x40]: PERF_RECORD_AUX offset: 0x200000 size: 0x100000 flags: 0x2 [O]
0 0 0x40c90 [0x30]: PERF_RECORD_AUXTRACE size: 0x20000 offset: 0x2e0000 ref: 0x7477d3d43d0a2ac7 idx: 2 tid: 6794 cpu: 2
2 5645263266480 0x40c48 [0x40]: PERF_RECORD_AUX offset: 0x300000 size: 0x100000 flags: 0x2 [O]
0 0 0x60d70 [0x30]: PERF_RECORD_AUXTRACE size: 0x20000 offset: 0x3e0000 ref: 0x202b939740c4f041 idx: 2 tid: 6794 cpu: 2
2 5645569318020 0x60d28 [0x40]: PERF_RECORD_AUX offset: 0x400000 size: 0x100000 flags: 0x2 [O]

The buffers are offset by 0xe0000, but the aux records are on round 0x100000 offsets.

Maybe we need to re-think the aux split patchset, do we not need to split in snapshot mode? Or can we fix this
set to produce aux records that match up?

James