Hi Leo,
-----Original Message----- From: Leo Yan leo.yan@linaro.org Sent: Thursday, May 23, 2019 11:37 AM To: Wojciech Żmuda wzmuda@n7space.com Cc: coresight@lists.linaro.org; Michal Mosdorf mmosdorf@n7space.com; Michał Kurowski mkurowski@n7space.com; mathieu.poirier@linaro.org; Al.Grant@arm.com Subject: Re: [RFC PATCH 1/1] perf cs-etm: Set time value for samples
Hi Wojciech,
On Fri, May 10, 2019 at 01:54:25PM +0000, Wojciech Żmuda wrote:
From: Wojciech Zmuda wzmuda@n7space.com
Populate the time field in branches and instruction samples generated from RANGE, EXCEPTION and EXCEPTION_RET 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.c | 36 ++++++++++++++++++++++++++++++++++++ tools/perf/util/cs-etm.h | 1 + 2 files changed, 37 insertions(+)
diff --git a/tools/perf/util/cs-etm.c b/tools/perf/util/cs-etm.c index 8496190ad553..838726748cd7 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;
/*
- perf report cannot handle events without a branch stack @@
-1894,6 +1897,37 @@ static int cs_etm__decode_data_block(struct
cs_etm_queue *etmq)
return ret; }
+static void +cs_etm__timestamp_traceid_queue_packet(struct cs_etm_traceid_queue +*tidq) {
- /**
* At this point, packet queue's timestamp and next_timestamp fields* represent start and stop timestamp value for range packetsbuffered
* in the queue. Since timestamp packets come once for every N rangepackets,
* we cannot directly assign timestamp values to specific rangepackets.
* Some estimation is done to tell at what approximate timestamp* has execution of each instruction range started.*/- if (!tidq->prev_packet->timestamp) {
/* First range packet in this queue */tidq->packet->timestamp = tidq->packet_queue.timestamp;- } else {
/** Similarly to what is done incs_etm_decoder__do_{soft|hard}_timestamp(),
* adjust timestamp value by the number of executedinstructions,
* so that packets representing ranges of instructionsexecuted later,
* have higher timestamp value than those executed earlier, inline with
* number of instruction executed in the previous range.* Currently, the assumption is that execution time of eachinstruction
* equals 1 timestamp cycle.** TODO find better approximation.*/tidq->packet->timestamp = tidq->prev_packet->timestamp +tidq->prev_packet->instr_count;- }
+}
static int cs_etm__process_traceid_queue(struct cs_etm_queue *etmq, struct cs_etm_traceid_queue *tidq) { @@ -
1926,6 +1960,7 @@
static int cs_etm__process_traceid_queue(struct cs_etm_queue *etmq,
switch (tidq->packet->sample_type) { case CS_ETM_RANGE:
cs_etm__timestamp_traceid_queue_packet(tidq); /* * If the packet contains an instruction * range, generate instruction sequence @@ -1935,6+1970,7 @@
static int cs_etm__process_traceid_queue(struct cs_etm_queue *etmq, break; case CS_ETM_EXCEPTION: case CS_ETM_EXCEPTION_RET:
cs_etm__timestamp_traceid_queue_packet(tidq); /* * If the exception packet is coming, * make sure the previous instructionPlease note for handling the branch packet for discontinuity in trace, if the trace is discontinuity then the function cs_etm__flush() will be invoked to generate the last branch sample before discontinuity; but this patch misses to set timestamp for the last branch sample.
Thank you for your input. I've just sent V2 that addresses this issue. I've verified in gdb, that the branch sample created out of a discontinuity packet is indeed timestamped, as is the previous one (with the same time value, but I think this is expected, as it's not the real branching event and we don't adjust queue timestamp for it).
Best regards, Wojciech
Thanks, Leo Yan
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