Messages in this thread | | | From | Mike Leach <> | Date | Thu, 6 Feb 2020 15:01:52 +0000 | Subject | Re: [PATCH v4 5/5] perf cs-etm: Synchronize instruction sample with the thread stack |
| |
Hi Leo,
On Mon, 3 Feb 2020 at 02:08, Leo Yan <leo.yan@linaro.org> wrote: > > The synthesized flow use 'tidq->packet' for instruction samples; on the > other hand, 'tidp->prev_packet' is used to generate the thread stack and > the branch samples, this results in the instruction samples using one > packet ahead than thread stack and branch samples ('tidp->prev_packet' > vs 'tidq->packet'). > > This leads to an instruction's callchain error as shows in below > example: > > main 1579 100 instructions: > ffff000010214854 perf_event_update_userpage+0x4c ([kernel.kallsyms]) > ffff000010214850 perf_event_update_userpage+0x48 ([kernel.kallsyms]) > ffff000010219360 perf_swevent_add+0x88 ([kernel.kallsyms]) > ffff0000102135f4 event_sched_in.isra.57+0xbc ([kernel.kallsyms]) > ffff0000102137a0 group_sched_in+0x60 ([kernel.kallsyms]) > ffff000010213b84 flexible_sched_in+0xfc ([kernel.kallsyms]) > ffff00001020c0b4 visit_groups_merge+0x12c ([kernel.kallsyms]) > > In the callchain log, for the two continuous lines the up line contains > one child function info and the followed line contains the caller > function info, and so forth. So the first two lines are: > > perf_event_update_userpage+0x4c => the sampled instruction > perf_event_update_userpage+0x48 => the parent function's calling > > The child function and parent function both are the same function > perf_event_update_userpage(), but this isn't a recursive function, thus > the sequence for perf_event_update_userpage() calling itself shouldn't > never happen. This callchain error is caused by the instruction sample > using an ahead packet than the thread stack, the thread stack is deferred > to process the new packet and misses to pop stack if it is just a return > packet. > > To fix this issue, we can simply change to use 'tidq->prev_packet' to > generate the instruction samples, this allows the thread stack to push > and pop synchronously with instruction sample. Finally, the callchain > can be displayed correctly as below: > > main 1579 100 instructions: > ffff000010214854 perf_event_update_userpage+0x4c ([kernel.kallsyms]) > ffff000010219360 perf_swevent_add+0x88 ([kernel.kallsyms]) > ffff0000102135f4 event_sched_in.isra.57+0xbc ([kernel.kallsyms]) > ffff0000102137a0 group_sched_in+0x60 ([kernel.kallsyms]) > ffff000010213b84 flexible_sched_in+0xfc ([kernel.kallsyms]) > ffff00001020c0b4 visit_groups_merge+0x12c ([kernel.kallsyms]) > > Signed-off-by: Leo Yan <leo.yan@linaro.org> > --- > tools/perf/util/cs-etm.c | 8 +++++--- > 1 file changed, 5 insertions(+), 3 deletions(-) > > diff --git a/tools/perf/util/cs-etm.c b/tools/perf/util/cs-etm.c > index 8f805657658d..410e40ce19f2 100644 > --- a/tools/perf/util/cs-etm.c > +++ b/tools/perf/util/cs-etm.c > @@ -1414,7 +1414,7 @@ static int cs_etm__sample(struct cs_etm_queue *etmq, > struct cs_etm_packet *tmp; > int ret; > u8 trace_chan_id = tidq->trace_chan_id; > - u64 instrs_executed = tidq->packet->instr_count; > + u64 instrs_executed = tidq->prev_packet->instr_count; > > tidq->period_instructions += instrs_executed; > > @@ -1505,7 +1505,8 @@ static int cs_etm__sample(struct cs_etm_queue *etmq, > * instruction) > */ > addr = cs_etm__instr_addr(etmq, trace_chan_id, > - tidq->packet, offset - 1); > + tidq->prev_packet, > + offset - 1); > ret = cs_etm__synth_instruction_sample( > etmq, tidq, addr, > etm->instructions_sample_period); > @@ -1525,7 +1526,8 @@ static int cs_etm__sample(struct cs_etm_queue *etmq, > * instruction) > */ > addr = cs_etm__instr_addr(etmq, trace_chan_id, > - tidq->packet, offset - 1); > + tidq->prev_packet, > + offset - 1); > ret = cs_etm__synth_instruction_sample( > etmq, tidq, addr, > etm->instructions_sample_period); > -- > 2.17.1 > I am really not convinced that this is a correct solution.
Consider a set of trace range packet inputs: current: 0x3000-0x3050 prev: 0x2000-0x2100 prev-1: 0x1020-0x1080
Before your modification..... cs_etm__sample() processes the current packet....
On entry, the branch stack will contain:0x1080=>0x2000;
We add to this from the current packet to get: 0x1080=>0x2000; 0x2100=>0x3000;
This is then copied by cs_etm__copy_last_branch_rb()
We find the instruction sample address in the range 0x3000 to 0x3050, e.g. 0x3010. cs_etm__synth_instruction_sample() will then generate a sample with values
sample.ip = 0x3010 sample.branch_stack = 0x1080=>0x2000; 0x2100=>0x3000;
to be passed to the perf session / injected as required. This sample has the correct branch context for the sampled address - i.e. how the code arrived @0x3010
After the modification..... The branch stack will be the same, but the sample address will be from the range 0x2000-0x2010, e.g. 0x2008 to give a sample in cs_etm__synth_instruction_sample() of sample.ip = 0x2008 sample.branch_stack = 0x1080=>0x2000; 0x2100=>0x3000;
This really does not make much sense - the branch stack no longer relates to the sample.ip.
Further - cs_etm__synth_instruction_sample() calls cs_etm__copy_insn() using the _current_ packet and sample.ip. This is a clear mismatch.
I don't know what is causing the apparent error in the callchain, but given that the previous features added in this set, work without this alteration, I feel there must be another solution.
Regards
Mike
-- Mike Leach Principal Engineer, ARM Ltd. Manchester Design Centre. UK
| |