Hello,
On 02/05/2019, 16:33, "Mathieu Poirier" mathieu.poirier@linaro.org wrote:
Thanks for this great write-up. So, concatenating this as well as Al's suggestions, I think what needs to be done is the following:
- When timestamp packet is encountered, get the packet queue and iterate backwards, until the previous
timestamp packet or discontinuity occurs. 2. For each encountered range/exception/exception_ret packet:
- if this packet happened immediately before the timestamp packet, mark it with value of this timestamp,
decremented by the number of instructions executed in this range
- if this is a subsequent non-TS packet, mark it with the timestamp value of the previous non-TS packet,
Decremented further in the same fashion.
This seems very similar to what is currently done to correlate traces from different processors in the CPU-wide implementation. Without a patch to look at I can't really say much more.
Mathieu, thank you very much for your suggestions.
I tried to implement steps quoted above. The result is still not perfect. Could you please take a look at the code below? Perhaps you can notice if I overlooked something obvious.
One problem I cannot solve is that I still see samples that are not timestamped. Majority of samples get the timestamp, but several always end with value 0x0 (or other, if as experiment I initialize the timestamp field with different value). It looks like some packets, that later are turned into samples, do not hit my modified code path, but I cannot figure out where do they come from. I try to timestamp everything including discontinuity, since it also is converted into a sample. I'm testing in per-thread mode, if it may be a clue.
Also, I wonder if my change in cs_etm__synth_branch_sample() is correct. I know that a sample is composed of two consecutive packets. If I understand correctly, tidq->prev_packet in this context refer to a packet previous w.r.t. to the slot in the queue, but not the one that came earlier in time. I chose tidq->packet instead of tidq->prev_packet to get the earlier timestamp, which would be the approximate timestamp of the first instruction in the range. I hope that makes sense.
Thank you very much, Wojciech
From a7008abcceaf6489dfac6e91fb8bae5ba6880dca Mon Sep 17 00:00:00 2001 From: Wojciech Zmuda wzmuda@n7space.com Date: Tue, 30 Apr 2019 15:11:19 +0200 Subject: [PATCH] perf tools: associate samples with timestamp
--- tools/perf/util/cs-etm-decoder/cs-etm-decoder.c | 31 +++++++++++++++++++++++++ tools/perf/util/cs-etm.c | 3 +++ tools/perf/util/cs-etm.h | 3 +++ 3 files changed, 37 insertions(+)
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..cd3b1d9dbb54 100644 --- a/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c +++ b/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c @@ -269,6 +269,31 @@ cs_etm_decoder__create_etm_packet_printer(struct cs_etm_trace_params *t_params, trace_config); }
+static void +cs_etm_decoder__timestamp_previous_packets(struct cs_etm_packet_queue *packet_queue, + const ocsd_generic_trace_elem *timestamp_elem) +{ + u32 count, packet_id; + struct cs_etm_packet *packet, *prev_packet; + + count = packet_queue->timestamp_pending_count; + prev_packet = NULL; + while (count--) { + packet_id = packet_queue->timestamp_pending[count]; + packet = &packet_queue->packet_buffer[packet_id]; + + /* TODO: find better approximation of the number of instructions per cycle. */ + if (!prev_packet) + packet->timestamp = timestamp_elem->timestamp - packet->instr_count; + else + packet->timestamp = prev_packet->timestamp - packet->instr_count; + + prev_packet = packet; + } + + packet_queue->timestamp_pending_count = 0; +} + static ocsd_datapath_resp_t cs_etm_decoder__do_soft_timestamp(struct cs_etm_queue *etmq, struct cs_etm_packet_queue *packet_queue, @@ -302,6 +327,8 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq, if (!packet_queue) return OCSD_RESP_FATAL_SYS_ERR;
+ cs_etm_decoder__timestamp_previous_packets(packet_queue, elem); + /* * We've seen a timestamp packet before - simply record the new value. * Function do_soft_timestamp() will report the value to the front end, @@ -372,6 +399,10 @@ 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 (sample_type != CS_ETM_EMPTY) + packet_queue->timestamp_pending[packet_queue->timestamp_pending_count++] = et;
if (packet_queue->packet_count == CS_ETM_PACKET_MAX_BUFFER - 1) return OCSD_RESP_WAIT; diff --git a/tools/perf/util/cs-etm.c b/tools/perf/util/cs-etm.c index 8496190ad553..1f1ef69ff06c 100644 --- a/tools/perf/util/cs-etm.c +++ b/tools/perf/util/cs-etm.c @@ -190,6 +190,7 @@ static void cs_etm__clear_packet_queue(struct cs_etm_packet_queue *queue) queue->head = 0; queue->tail = 0; queue->packet_count = 0; + queue->timestamp_pending_count = 0; for (i = 0; i < CS_ETM_PACKET_MAX_BUFFER; i++) { queue->packet_buffer[i].isa = CS_ETM_ISA_UNKNOWN; queue->packet_buffer[i].start_addr = CS_ETM_INVAL_ADDR; @@ -204,6 +205,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; } }
@@ -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 diff --git a/tools/perf/util/cs-etm.h b/tools/perf/util/cs-etm.h index 1f6ec7babe70..c67d47654c8d 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; @@ -154,6 +155,8 @@ struct cs_etm_packet_queue { u32 instr_count; u64 timestamp; u64 next_timestamp; + u32 timestamp_pending_count; + u32 timestamp_pending[CS_ETM_PACKET_MAX_BUFFER]; struct cs_etm_packet packet_buffer[CS_ETM_PACKET_MAX_BUFFER]; };