Re: [PATCH v7 1/2] perf cs-etm: Split Coresight decode by aux records

From: Leo Yan <leo.yan@linaro.org>
To: James Clark <james.clark@arm.com>
Cc: acme@kernel.org, mathieu.poirier@linaro.org,
	coresight@lists.linaro.org, al.grant@arm.com,
	branislav.rankov@arm.com, denik@chromium.org,
	suzuki.poulose@arm.com, anshuman.khandual@arm.com,
	John Garry <john.garry@huawei.com>, Will Deacon <will@kernel.org>,
	Mike Leach <mike.leach@linaro.org>,
	Mark Rutland <mark.rutland@arm.com>,
	Alexander Shishkin <alexander.shishkin@linux.intel.com>,
	Jiri Olsa <jolsa@redhat.com>, Namhyung Kim <namhyung@kernel.org>,
	linux-arm-kernel@lists.infradead.org,
	linux-perf-users@vger.kernel.org, linux-kernel@vger.kernel.org
Subject: Re: [PATCH v7 1/2] perf cs-etm: Split Coresight decode by aux records
Date: Sun, 27 Jun 2021 19:50:13 +0800	[thread overview]
Message-ID: <20210627115013.GA13045@leoy-ThinkPad-X240s> (raw)
In-Reply-To: <20210624164303.28632-2-james.clark@arm.com>

On Thu, Jun 24, 2021 at 05:43:02PM +0100, James Clark wrote:
> Populate the auxtrace queues using AUX records rather than whole
> auxtrace buffers so that the decoder is reset between each aux record.

[...]

> Signed-off-by: James Clark <james.clark@arm.com>

I tested this patch with kprobe/uprobe events; and confirmed this
patch works as expected.  So:

Tested-by: Leo Yan <leo.yan@linaro.org>

Below shares my testing steps.

- The rationale for the testing is to use "perf probe" to add trace
  points for PERF_RECORD_AUX/PERF_RECORD_AUXTRACE, and add another
  uprobe event for parsing AUX fragment.  So we can compare the
  recorded PERF_RECORD_AUX events, and check if AUX fragment can
  reorganize the perf AUX trace data correctly or not.

- The testing script test_cs_etm_snapshot.sh:
  http://paste.debian.net/1202563/

- Add kprobe event for perf_event_aux_event() so that it can trace
  the perf event PERF_RECORD_AUX:

  # perf probe --add "perf_event_aux_event head=head:x64 size=size:x64"

- Add uprobe event for __auxtrace_mmap__read() so that it can trace
  the perf event PERF_RECORD_AUXTRACE:

  # perf probe -x /mnt/linux-kernel/linux-cs-dev/tools/perf/perf \
     --add "__auxtrace_mmap__read:58 idx=mm->idx head=head:x64 offset=offset:x64 size=size:x64"

- Add uprobe event for cs_etm__queue_aux_fragment():

  # perf probe -x /mnt/linux-kernel/linux-cs-dev/tools/perf/perf \
     --add "cs_etm__queue_aux_fragment:63 aux_offset=aux_offset:x64 aux_size=aux_event->aux_size:x64"

- Enable trace events:

  # cd /sys/kernel/debug/tracing
  # echo 1 > events/probe/enable
  # echo 1 > events/probe_perf/enable

- Executed the testing script and perf report command:

  # sh test_cs_etm_snapshot.sh
  [ perf record: Woken up 7 times to write data ]
  [ perf record: Captured and wrote 19.534 MB /tmp/__perf_test.perf.data.miRDs ]
  # perf report -i /tmp/__perf_test.perf.data.miRDs

- At the end, I can get the tracing result:

  # cd /sys/kernel/debug/tracing
  # cat trace

  # entries-in-buffer/entries-written: 21/21   #P:6
  #
  #                                _-----=> irqs-off
  #                               / _----=> need-resched
  #                              | / _---=> hardirq/softirq
  #                              || / _--=> preempt-depth
  #                              ||| /     delay
  #           TASK-PID     CPU#  ||||   TIMESTAMP  FUNCTION
  #              | |         |   ||||      |         |
                dd-2206    [001] d.h3  1395.922396: perf_event_aux_event: (perf_event_aux_event+0x0/0x108) head=0x400000 size=0x400000
              perf-2204    [002] ....  1395.922565: __auxtrace_mmap__read_L58: (0xaaaaab154394) idx=1 head=0x400000 offset=0x0 size=0x400000
                dd-2206    [001] d.h3  1395.942658: perf_event_aux_event: (perf_event_aux_event+0x0/0x108) head=0x50b3f0 size=0x10b3f0
              perf-2204    [002] ....  1395.942739: __auxtrace_mmap__read_L58: (0xaaaaab154394) idx=1 head=0x50b3f0 offset=0x400000 size=0x10b3f0
                dd-2206    [001] d.h3  1396.000040: perf_event_aux_event: (perf_event_aux_event+0x0/0x108) head=0x90b3f0 size=0x400000
              perf-2204    [002] ....  1396.000150: __auxtrace_mmap__read_L58: (0xaaaaab154394) idx=1 head=0x90b3f0 offset=0x50b3f0 size=0x400000
                dd-2206    [001] d.h3  1396.023098: perf_event_aux_event: (perf_event_aux_event+0x0/0x108) head=0xb87ae0 size=0x27c6f0
              perf-2204    [002] ....  1396.023197: __auxtrace_mmap__read_L58: (0xaaaaab154394) idx=1 head=0xb87ae0 offset=0x90b3f0 size=0x27c6f0
                dd-2206    [001] d.h3  1396.087722: perf_event_aux_event: (perf_event_aux_event+0x0/0x108) head=0xf87ae0 size=0x400000
              perf-2204    [002] ....  1396.087838: __auxtrace_mmap__read_L58: (0xaaaaab154394) idx=1 head=0xf87ae0 offset=0xb87ae0 size=0x400000
                dd-2206    [001] d.h3  1396.131696: perf_event_aux_event: (perf_event_aux_event+0x0/0x108) head=0x1387ae0 size=0x400000
              perf-2204    [002] ....  1396.131808: __auxtrace_mmap__read_L58: (0xaaaaab154394) idx=1 head=0x1387ae0 offset=0xf87ae0 size=0x400000
              perf-2217    [003] ....  1439.581363: cs_etm__queue_aux_fragment_L63: (0xaaaac9582ba8) aux_offset=0x0 aux_size=0x400000
              perf-2217    [003] ....  1439.581467: cs_etm__queue_aux_fragment_L63: (0xaaaac9582ba8) aux_offset=0x400000 aux_size=0x10b3f0
              perf-2217    [003] ....  1439.581510: cs_etm__queue_aux_fragment_L63: (0xaaaac9582ba8) aux_offset=0x50b3f0 aux_size=0x400000
              perf-2217    [003] ....  1439.581553: cs_etm__queue_aux_fragment_L63: (0xaaaac9582ba8) aux_offset=0x90b3f0 aux_size=0x27c6f0
              perf-2217    [003] ....  1439.581595: cs_etm__queue_aux_fragment_L63: (0xaaaac9582ba8) aux_offset=0xb87ae0 aux_size=0x400000
              perf-2217    [003] ....  1439.581638: cs_etm__queue_aux_fragment_L63: (0xaaaac9582ba8) aux_offset=0xf87ae0 aux_size=0x400000

  We can see the recording AUX trace data in perf_event_aux_event()
  can be decoded properly in events cs_etm__queue_aux_fragment_L63().

Thanks,
Leo