Received-SPF: pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) client-ip=209.132.180.67;
Date:   Tue, 22 May 2018 16:39:20 +0800
From:   Leo Yan <leo.yan@linaro.org>
To:     Robert Walker <robert.walker@arm.com>
Cc:     Arnaldo Carvalho de Melo <acme@kernel.org>,
        Mathieu Poirier <mathieu.poirier@linaro.org>,
        Jonathan Corbet <corbet@lwn.net>,
        Peter Zijlstra <peterz@infradead.org>,
        Ingo Molnar <mingo@redhat.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-doc@vger.kernel.org,
        linux-kernel@vger.kernel.org, Tor Jeremiassen <tor@ti.com>,
        mike.leach@linaro.org, kim.phillips@arm.com,
        coresight@lists.linaro.org, Mike Leach <mike.leach@arm.com>
Subject: Re: [RFT v2 1/4] perf cs-etm: Generate sample for missed packets
Message-ID: <20180522083920.GD31075@leoy-ThinkPad-X240s>
References: <1526892748-326-1-git-send-email-leo.yan@linaro.org>
 <1526892748-326-2-git-send-email-leo.yan@linaro.org>
 <bc320d6d-a21d-b5a4-e30d-511bb69aba32@arm.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <bc320d6d-a21d-b5a4-e30d-511bb69aba32@arm.com>
User-Agent: Mutt/1.5.24 (2015-08-30)
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk

Hi Rob,

On Mon, May 21, 2018 at 12:27:42PM +0100, Robert Walker wrote:
> Hi Leo,
> 
> On 21/05/18 09:52, Leo Yan wrote:
> >Commit e573e978fb12 ("perf cs-etm: Inject capabilitity for CoreSight
> >traces") reworks the samples generation flow from CoreSight trace to
> >match the correct format so Perf report tool can display the samples
> >properly.  But the change has side effect for packet handling, it only
> >generate samples when 'prev_packet->last_instr_taken_branch' is true,
> >this results in the start tracing packet and exception packets are
> >dropped.
> >
> >This patch checks extra two conditions for complete samples:
> >
> >- If 'prev_packet->sample_type' is zero we can use this condition to
> >   get to know this is the start tracing packet; for this case, the start
> >   packet's end_addr is zero as well so we need to handle it in the
> >   function cs_etm__last_executed_instr();
> >
> 
> I think you also need to add something in to handle discontinuities in
> trace - for example it is possible to configure the ETM to only trace
> execution in specific code regions or to trace a few cycles every so
> often. In these cases, prev_packet->sample_type will not be zero, but
> whatever the previous packet was.  You will get a CS_ETM_TRACE_ON packet in
> such cases, generated by an I_TRACE_ON element in the trace stream.
> You also get this on exception return.
> 
> However, you should also keep the test for prev_packet->sample_type == 0
> as you may not see a CS_ETM_TRACE_ON when decoding a buffer that has
> wrapped.

Thanks for reviewing.  Let's dig more detailed into this issue,
especially for handling packet CS_ETM_TRACE_ON, I'd like divide into two
sub cases.

- The first case is for using python script:

  I use python script to analyze packets with below command:
  ./perf script --itrace=ril128 -s arm-cs-trace-disasm.py -F cpu,event,ip,addr,sym -- -v -d objdump -k ./vmlinux

  What I observe is after we pass python script with parameter '-s
  arm-cs-trace-disasm.py', then instruction tracing options
  '--itrace=ril128' isn't really used;  the perf tool creates another
  new process for launch python script and re-enter cmd_script()
  function, but at the second time when invoke cmd_script() for python
  script execution the option '--itrace=ril128' is dropped and all
  parameters are only valid defined by the python script.

  As result, I can the variable 'etmq->etm->synth_opts.last_branch' is
  always FALSE for running python script.  So all CS_ETM_TRACE_ON
  packets will be ignored in the function cs_etm__flush().

  Even the CS_ETM_TRACE_ON packets are missed to handle, the program
  flow still can work well.  The reason is without the interference by
  CS_ETM_TRACE_ON, the CS_ETM_RANGE packets can smoothly create
  instruction range by ignore the middle CS_ETM_TRACE_ON packet.

  Please see below example, in this example there have 3 packets, the
  first one packet is CS_ETM_RANGE packet which is labelled with
  'PACKET_1', the first one packet can properly generate branch sample
  data with previous packet as expected;  the second packet is
  PACKET_2 which is CS_ETM_TRACE_ON, but
  'etmq->etm->synth_opts.last_branch' is false so function
  cs_etm__flush() doesn't handle it and skip the swap operation
  "etmq->prev_packet = tmp"; the third packet is PACKET_3, which is
  CS_ETM_RANGE packet and we can see it's smoontly to create
  continous instruction range between PACKET_1 and PACKET_3.

  cs_etm__sample: prev_packet: sample_type=1 exc=0 exc_ret=0 cpu=1 start_addr=0xffff000008a5f79c end_addr=0xffff000008a5f7bc last_instr_taken_branch=1
  PACKET_1: cs_etm__sample: packet: sample_type=1 exc=0 exc_ret=0 cpu=1 start_addr=0xffff000008a5f858 end_addr=0xffff000008a5f864 last_instr_taken_branch=1
  cs_etm__synth_branch_sample: ip=0xffff000008a5f7b8 addr=0xffff000008a5f858 pid=2290 tid=2290 id=1000000021 stream_id=1000000021 period=1 cpu=1 flags=0 cpumode=2

  cs_etm__flush: prev_packet: sample_type=1 exc=0 exc_ret=0 cpu=1 start_addr=0xffff000008a5f858 end_addr=0xffff000008a5f864 last_instr_taken_branch=1
  PACKET_2: cs_etm__flush: packet: sample_type=2 exc=0 exc_ret=0 cpu=2 start_addr=0xdeadbeefdeadbeef end_addr=0xdeadbeefdeadbeef last_instr_taken_branch=1

  cs_etm__sample: prev_packet: sample_type=1 exc=0 exc_ret=0 cpu=1 start_addr=0xffff000008a5f858 end_addr=0xffff000008a5f864 last_instr_taken_branch=1
  PACKET_3: cs_etm__sample: packet: sample_type=1 exc=0 exc_ret=0 cpu=2 start_addr=0xffff000008be7528 end_addr=0xffff000008be7538 last_instr_taken_branch=1
  cs_etm__synth_branch_sample: ip=0xffff000008a5f860 addr=0xffff000008be7528 pid=2290 tid=2290 id=1000000021 stream_id=1000000021 period=1 cpu=2 flags=0 cpumode=2

  So seems to me, the CS_ETM_TRACE_ON packet doesn't introduce trouble
  for the program flow analysis if we can handle all CS_ETM_RANGE
  packets and without handling CS_ETM_TRACE_ON packet for branch
  samples.

- The second case is for --itrace option without python script:
  ./perf script --itrace=ril -F cpu,event,ip,addr,sym -k ./vmlinux

  In this case, the flag 'etmq->etm->synth_opts.last_branch' is true
  so CS_ETM_TRACE_ON packet will be handled; but I can observe the
  CS_ETM_RANGE packet in etmq->prev_packet isn't handled in the
  function cs_etm__flush() for branch sample, so actually we miss some
  branch sample for this case.

  So I think we also need handle CS_ETM_RANGE packet in function
  cs_etm__flush() to generate branch samples.  But this has side
  effect, we introduce the extra track for CS_ETM_TRACE_ON packet for
  branch samples, so we will see one branch range like:
  [ 0xdeadbeefdeadbeef .. 0xdeadbeefdeadbeef ].

Please reivew below change is okay for you?  Thanks a lot for
suggestions.

diff --git a/tools/perf/util/cs-etm.c b/tools/perf/util/cs-etm.c
index 822ba91..37d3722 100644
--- a/tools/perf/util/cs-etm.c
+++ b/tools/perf/util/cs-etm.c
@@ -495,6 +495,13 @@ static inline void cs_etm__reset_last_branch_rb(struct cs_etm_queue *etmq)
 static inline u64 cs_etm__last_executed_instr(struct cs_etm_packet *packet)
 {
 	/*
+	 * The packet is the start tracing packet if the end_addr is zero,
+	 * returns 0 for this case.
+	 */
+	if (!packet->end_addr)
+		return 0;
+
+	/*
 	 * The packet records the execution range with an exclusive end address
 	 *
 	 * A64 instructions are constant size, so the last executed
@@ -897,13 +904,28 @@ static int cs_etm__sample(struct cs_etm_queue *etmq)
 		etmq->period_instructions = instrs_over;
 	}
 
-	if (etm->sample_branches &&
-	    etmq->prev_packet &&
-	    etmq->prev_packet->sample_type == CS_ETM_RANGE &&
-	    etmq->prev_packet->last_instr_taken_branch) {
-		ret = cs_etm__synth_branch_sample(etmq);
-		if (ret)
-			return ret;
+	if (etm->sample_branches && etmq->prev_packet) {
+		bool generate_sample = false;
+
+		/* Generate sample for start tracing packet */
+		if (etmq->prev_packet->sample_type == 0 ||
+		    etmq->prev_packet->sample_type == CS_ETM_TRACE_ON)
+			generate_sample = true;
+
+		/* Generate sample for exception packet */
+		if (etmq->prev_packet->exc == true)
+			generate_sample = true;
+
+		/* Generate sample for normal branch packet */
+		if (etmq->prev_packet->sample_type == CS_ETM_RANGE &&
+		    etmq->prev_packet->last_instr_taken_branch)
+			generate_sample = true;
+
+		if (generate_sample) {
+			ret = cs_etm__synth_branch_sample(etmq);
+			if (ret)
+				return ret;
+		}
 	}
 
 	if (etm->sample_branches || etm->synth_opts.last_branch) {
@@ -921,12 +943,17 @@ static int cs_etm__sample(struct cs_etm_queue *etmq)
 
 static int cs_etm__flush(struct cs_etm_queue *etmq)
 {
+	struct cs_etm_auxtrace *etm = etmq->etm;
 	int err = 0;
 	struct cs_etm_packet *tmp;
 
-	if (etmq->etm->synth_opts.last_branch &&
-	    etmq->prev_packet &&
-	    etmq->prev_packet->sample_type == CS_ETM_RANGE) {
+	if (!etmq->prev_packet)
+		return 0;
+
+	if (etmq->prev_packet->sample_type != CS_ETM_RANGE)
+		return 0;
+
+	if (etmq->etm->synth_opts.last_branch) {
 		/*
 		 * Generate a last branch event for the branches left in the
 		 * circular buffer at the end of the trace.
@@ -939,18 +966,25 @@ static int cs_etm__flush(struct cs_etm_queue *etmq)
 		err = cs_etm__synth_instruction_sample(
 			etmq, addr,
 			etmq->period_instructions);
+		if (err)
+			return err;
 		etmq->period_instructions = 0;
+	}
 
-		/*
-		 * Swap PACKET with PREV_PACKET: PACKET becomes PREV_PACKET for
-		 * the next incoming packet.
-		 */
-		tmp = etmq->packet;
-		etmq->packet = etmq->prev_packet;
-		etmq->prev_packet = tmp;
+	if (etm->sample_branches) {
+		err = cs_etm__synth_branch_sample(etmq);
+		if (err)
+			return err;
 	}
 
-	return err;
+	/*
+	 * Swap PACKET with PREV_PACKET: PACKET becomes PREV_PACKET for
+	 * the next incoming packet.
+	 */
+	tmp = etmq->packet;
+	etmq->packet = etmq->prev_packet;
+	etmq->prev_packet = tmp;
+	return 0;
 }
 
 static int cs_etm__run_decoder(struct cs_etm_queue *etmq)
-- 
2.7.4