Re: [RFC PATCH v3 1/1] perf cs-etm: Set time value for samples

Hi Wojciech,

On Fri, Jun 07, 2019 at 05:06:42PM +0000, Wojciech Żmuda wrote:

From: Wojciech Zmuda wzmuda@n7space.com

Populate the 'time' field in branches and instruction samples generated from RANGE and DISCONTINUITY packets. The time value is based on TIMESTAMP packets that may appear in the trace.

The time value may be accessed through perf-script built-in script engine in the sample dict 'time' field or printed in 'perf script -F time' output (the latter only in CPU-wide mode at the moment).

Signed-off-by: Wojciech Zmuda wzmuda@n7space.com

tools/perf/util/cs-etm-decoder/cs-etm-decoder.c | 70 ++++++++++++++++++------- tools/perf/util/cs-etm.c | 3 ++ tools/perf/util/cs-etm.h | 1 + 3 files changed, 55 insertions(+), 19 deletions(-)

diff --git a/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c b/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c index 33e975c8d11b..a4d470eccbcf 100644 --- a/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c +++ b/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c @@ -269,25 +269,44 @@ cs_etm_decoder__create_etm_packet_printer(struct cs_etm_trace_params *t_params, trace_config); } -static ocsd_datapath_resp_t -cs_etm_decoder__do_soft_timestamp(struct cs_etm_queue *etmq,

• 		  struct cs_etm_packet_queue *packet_queue,
  

• 		  const uint8_t trace_chan_id)
  

+static void +cs_etm_decoder__timestamp_pending_packets(struct cs_etm_packet_queue *queue) +{

• struct cs_etm_packet *packet;
• u64 next_timestamp;
• u32 count, head;
• count = queue->packet_count;
• if (count == 0)

• return;
  

• head = queue->head;
• next_timestamp = queue->timestamp;
• while (count--) {

• head = (head + 1) & (CS_ETM_PACKET_MAX_BUFFER - 1);
  

• packet = &queue->packet_buffer[head];
  

• if (packet->sample_type != CS_ETM_RANGE)
  

• 	continue;
  

• packet->timestamp = next_timestamp;
  

• /* TODO: better approximation of instruction range duration */
  

• next_timestamp += packet->instr_count;
  

• }

+}

+static void +cs_etm_decoder__do_soft_timestamp(struct cs_etm_packet_queue *packet_queue) { /* No timestamp packet has been received, nothing to do */ if (!packet_queue->timestamp)

• return OCSD_RESP_CONT;
  

• return;
  

packet_queue->timestamp = packet_queue->next_timestamp; /* Estimate the timestamp for the next range packet */ packet_queue->next_timestamp += packet_queue->instr_count; packet_queue->instr_count = 0;

• /* Tell the front end which traceid_queue needs attention */
• cs_etm__etmq_set_traceid_queue_timestamp(etmq, trace_chan_id);
• return OCSD_RESP_WAIT;

} static ocsd_datapath_resp_t @@ -324,6 +343,9 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq, packet_queue->next_timestamp = elem->timestamp; packet_queue->instr_count = 0;

• /* Timestamp range packets that got queued up to this point */
• cs_etm_decoder__timestamp_pending_packets(packet_queue);
• /* Tell the front end which traceid_queue needs attention */ cs_etm__etmq_set_traceid_queue_timestamp(etmq, trace_chan_id);

@@ -372,6 +394,7 @@ cs_etm_decoder__buffer_packet(struct cs_etm_packet_queue *packet_queue, packet_queue->packet_buffer[et].flags = 0; packet_queue->packet_buffer[et].exception_number = UINT32_MAX; packet_queue->packet_buffer[et].trace_chan_id = trace_chan_id;

• packet_queue->packet_buffer[et].timestamp = 0;

if (packet_queue->packet_count == CS_ETM_PACKET_MAX_BUFFER - 1) return OCSD_RESP_WAIT; @@ -435,10 +458,9 @@ cs_etm_decoder__buffer_range(struct cs_etm_queue *etmq, } packet->last_instr_size = elem->last_instr_sz;

• /* per-thread scenario, no need to generate a timestamp */
• if (cs_etm__etmq_is_timeless(etmq))

• goto out;
  

• packet_queue->instr_count += elem->num_instr_range;
• cs_etm_decoder__do_soft_timestamp(packet_queue);
• packet->timestamp = packet_queue->timestamp;

/* * The packet queue is full and we haven't seen a timestamp (had we @@ -448,10 +470,9 @@ cs_etm_decoder__buffer_range(struct cs_etm_queue *etmq, if (ret == OCSD_RESP_WAIT) goto out;

• packet_queue->instr_count += elem->num_instr_range; /* Tell the front end we have a new timestamp to process */
• ret = cs_etm_decoder__do_soft_timestamp(etmq, packet_queue,

• 				trace_chan_id);
  

• if (!cs_etm__etmq_is_timeless(etmq))

• cs_etm__etmq_set_traceid_queue_timestamp(etmq, trace_chan_id);
  

out: return ret; } @@ -460,13 +481,24 @@ static ocsd_datapath_resp_t cs_etm_decoder__buffer_discontinuity(struct cs_etm_packet_queue *queue, const uint8_t trace_chan_id) {

• int ret;
• struct cs_etm_packet *packet;
• ret = cs_etm_decoder__buffer_packet(queue, trace_chan_id,

• 			    CS_ETM_DISCONTINUITY);
  

• packet = &queue->packet_buffer[queue->tail];
• packet->timestamp = queue->timestamp;
• /*
  • Something happened and who knows when we'll get new traces so
  • reset time statistics.

• * Record the last observed timestamp, so the last branch sample
  

• * before discontinuity can be marked with it.
  

  */ cs_etm_decoder__reset_timestamp(queue);

• return cs_etm_decoder__buffer_packet(queue, trace_chan_id,

• 			     CS_ETM_DISCONTINUITY);
  

• return ret;

} static ocsd_datapath_resp_t diff --git a/tools/perf/util/cs-etm.c b/tools/perf/util/cs-etm.c index 8496190ad553..84d615ae3a1a 100644 --- a/tools/perf/util/cs-etm.c +++ b/tools/perf/util/cs-etm.c @@ -204,6 +204,7 @@ static void cs_etm__clear_packet_queue(struct cs_etm_packet_queue *queue) queue->packet_buffer[i].exception_number = UINT32_MAX; queue->packet_buffer[i].trace_chan_id = UINT8_MAX; queue->packet_buffer[i].cpu = INT_MIN;

• queue->packet_buffer[i].timestamp = 0;
  

  }

} @@ -1098,6 +1099,7 @@ static int cs_etm__synth_instruction_sample(struct cs_etm_queue *etmq, sample.flags = tidq->prev_packet->flags; sample.insn_len = 1; sample.cpumode = event->sample.header.misc;

• sample.time = tidq->packet->timestamp;

if (etm->synth_opts.last_branch) { cs_etm__copy_last_branch_rb(etmq, tidq); @@ -1157,6 +1159,7 @@ static int cs_etm__synth_branch_sample(struct cs_etm_queue *etmq, sample.cpu = tidq->packet->cpu; sample.flags = tidq->prev_packet->flags; sample.cpumode = event->sample.header.misc;

• sample.time = tidq->packet->timestamp;

I think here we should use 'tidq->prev_packet->timstamp', since this sample is generated for the previous packet finishing and jump to the new address in the next packet.

If the timestamp value means the previous packet finish time but not its start time, it's more suitable to use the previous packet's timestamp.

@Mike, @Mathieu, could you double confirm for this?

I tested this patch on DB410c board, so get below result; seems to me we need to convert the raw timestamp to readable time format (e.g. to raw counter value to seconds format). I know before we have some discussion for this, should we firstly get ready for passing timestamp counter from CoreSight driver to perf firstly?

perf 10802 [001] 0.476703: 1 branches:u: 0 [unknown] ([unknown]) => ffffa68e8c9c __GI___ioctl+0xc (/lib/aarch64-linux-gnu/libc-2.27.so) perf 10802 [001] 0.476703: 1 branches:u: ffffa68e8ca4 __GI___ioctl+0x14 (/lib/aarch64-linux-gnu/libc-2.27.so) => aaaae9c8ada4 perf_evsel__enable+0x84 (/mnt/linux-kernel/linux/tools/perf/perf) perf 10802 [001] 0.476703: 1 branches:u: aaaae9c8ada4 perf_evsel__enable+0x84 (/mnt/linux-kernel/linux/tools/perf/perf) => aaaae9c8ad70 perf_evsel__enable+0x50 (/mnt/linux-kernel/linux/tools/perf/perf) perf 10802 [001] 0.476703: 1 branches:u: aaaae9c8ad84 perf_evsel__enable+0x64 (/mnt/linux-kernel/linux/tools/perf/perf) => aaaae9c8add0 perf_evsel__enable+0xb0 (/mnt/linux-kernel/linux/tools/perf/perf) perf 10802 [001] 0.476703: 1 branches:u: aaaae9c8ade0 perf_evsel__enable+0xc0 (/mnt/linux-kernel/linux/tools/perf/perf) => aaaae9c8ad60 perf_evsel__enable+0x40 (/mnt/linux-kernel/linux/tools/perf/perf) perf 10802 [001] 0.476703: 1 branches:u: aaaae9c8ad68 perf_evsel__enable+0x48 (/mnt/linux-kernel/linux/tools/perf/perf) => aaaae9c8ad88 perf_evsel__enable+0x68 (/mnt/linux-kernel/linux/tools/perf/perf) perf 10802 [001] 0.476703: 1 branches:u: aaaae9c8ada0 perf_evsel__enable+0x80 (/mnt/linux-kernel/linux/tools/perf/perf) => aaaae9be77e0 ioctl@plt+0x0 (/mnt/linux-kernel/linux/tools/perf/perf) perf 10802 [001] 0.476703: 1 branches:u: aaaae9be77ec ioctl@plt+0xc (/mnt/linux-kernel/linux/tools/perf/perf) => ffffa68e8c90 __GI___ioctl+0x0 (/lib/aarch64-linux-gnu/libc-2.27.so) perf 10802 [001] 0.476703: 1 branches:u: ffffa68e8c98 __GI___ioctl+0x8 (/lib/aarch64-linux-gnu/libc-2.27.so) => 0 [unknown] ([unknown]) perf 10802 [001] 0.476711: 1 branches:u: 0 [unknown] ([unknown]) => ffffa68e8c9c __GI___ioctl+0xc (/lib/aarch64-linux-gnu/libc-2.27.so) perf 10802 [001] 0.476711: 1 branches:u: ffffa68e8ca4 __GI___ioctl+0x14 (/lib/aarch64-linux-gnu/libc-2.27.so) => aaaae9c8ada4 perf_evsel__enable+0x84 (/mnt/linux-kernel/linux/tools/perf/perf) perf 10802 [001] 0.476711: 1 branches:u: aaaae9c8ada4 perf_evsel__enable+0x84 (/mnt/linux-kernel/linux/tools/perf/perf) => aaaae9c8ad70 perf_evsel__enable+0x50 (/mnt/linux-kernel/linux/tools/perf/perf) perf 10802 [001] 0.476711: 1 branches:u: aaaae9c8ad84 perf_evsel__enable+0x64 (/mnt/linux-kernel/linux/tools/perf/perf) => aaaae9c8add0 perf_evsel__enable+0xb0 (/mnt/linux-kernel/linux/tools/perf/perf) perf 10802 [001] 0.476711: 1 branches:u: aaaae9c8ade0 perf_evsel__enable+0xc0 (/mnt/linux-kernel/linux/tools/perf/perf) => aaaae9c8ad60 perf_evsel__enable+0x40 (/mnt/linux-kernel/linux/tools/perf/perf) perf 10802 [001] 0.476711: 1 branches:u: aaaae9c8ad68 perf_evsel__enable+0x48 (/mnt/linux-kernel/linux/tools/perf/perf) => aaaae9c8ad88 perf_evsel__enable+0x68 (/mnt/linux-kernel/linux/tools/perf/perf) perf 10802 [001] 0.476711: 1 branches:u: aaaae9c8ada0 perf_evsel__enable+0x80 (/mnt/linux-kernel/linux/tools/perf/perf) => aaaae9be77e0 ioctl@plt+0x0 (/mnt/linux-kernel/linux/tools/perf/perf) perf 10802 [001] 0.476711: 1 branches:u: aaaae9be77ec ioctl@plt+0xc (/mnt/linux-kernel/linux/tools/perf/perf) => ffffa68e8c90 __GI___ioctl+0x0 (/lib/aarch64-linux-gnu/libc-cs_etm__etmq_get_traceid_queue: enter

Thanks, Leo Yan

/* * perf report cannot handle events without a branch stack diff --git a/tools/perf/util/cs-etm.h b/tools/perf/util/cs-etm.h index 1f6ec7babe70..a14b0220eaa7 100644 --- a/tools/perf/util/cs-etm.h +++ b/tools/perf/util/cs-etm.h @@ -122,6 +122,7 @@ struct cs_etm_packet { enum cs_etm_isa isa; u64 start_addr; u64 end_addr;

• u64 timestamp; u32 instr_count; u32 last_instr_type; u32 last_instr_subtype;

-- 2.11.0