Hello,Sorry for the delay. I appreciate your posts.I have recorded a different program now("ping 8.8.8.8"), and it seems that decodingthe trace using the "ping" ELF file gives no issues now. I cannot explain how "ls"is the only corrupt trace(i rerecorded, same results). Perhaps the image is indeed wrong.I will check it further.Thank you very much!Mike.On Thu, Sep 20, 2018 at 1:28 AM, Mike Leach <mike.leach@linaro.org> wrote:Hi Mike,
I have looked into this issue further, found my previous assumption to
be wrong, and unfortunately have come to the conclusion that the
generated trace is somehow wrong / corrupt, or the supplied image is
not what was run when the trace was generated.
If you look at the attached analysis of the trace generated from the
ls_api.cs data [analysis001.txt] This is at the very start of the
traced image.
The first few packets [raw packets (0)] show the sync and start at
00000000004003f0 <_start>:
followed by the first 'E' atom that marks the branch to 0x41a158. The
next two 'E' atoms get us to 0x41a028.
At this point we get an exception packet, followed by a preferred
return address packet [ raw packets (2)].
This return address is 0x400630.
The rules from the ETM architecture specification 4.0-4.4 p6-242 state:-
"The Exception packet contains an address. This means that execution
has continued from the target of the most
recent P0 element, up to, but not including, that address, and a trace
analyzer must analyze each instruction in this
range."
Thus the decoder is required to analyze from the previous P0 element -
the 'E' atom that marked the branch to 0x41a028, until the preferred
return address.
This is actually lower than the start address, which results in a huge
range seen here, and also seen by you in the example you described.
The decoder effectively runs off the end of the memory image before it
stops.
The trace should be indicating an address after but relatively close
to 0x41a028 - as otherwise an atom would have been emitted by the cbnz
41a054.
If I examine the start of the perf_ls.cs decode, I see the same 3 'E'
atoms followed by the odd data fault exception.
So for the first few branches at least, the perf and api captures go
in the same direction.
Given the it is unlikely that the generated trace packets are
incorrect - it seems more likely that the 'ls' image being used for
decode is not what is generating this trace. Since we have to analyze
opcodes to follow the 'E' and 'N' atoms, decode relies on accurate
memory images being fed into the decoder. The only actual addresses we
have explicitly stated in the trace are the start: 0x4003f0, and the
exception return address 0x400360. The others are synthesized from the
supplied image.
There may be a case for checking when decoding the exception packet
that the address is not behind the current location and throwing an
error, but beyond that I do not at this point believe that the decoder
is at fault.
Regards
Mike
On 18 September 2018 at 19:32, Mike Leach <mike.leach@linaro.org> wrote:
> Hi Mike,
>
> I've looked further at this today, and can see a location where a
> large block appears in both the api and perf trace data on decode
> using the library test program.
>
> There does appear to be an issue if the decoder is in a "waiting for
> address state" i.e. it has lost track usually because an area of
> memory is unavailable, and an exception packet is seen - the exception
> address appears to be used twice - both to complete an address range
> and as an exception return - hence in this case the improbable large
> block. I need to look into this in more detail and fix it up.
>
> However - I am seeing before this the api and perf decodes have
> diverged, which suggests an issue elsewhere too perhaps. I do need to
> look deeper into this as well.
> I am not 100% certain that using the ls.bin as a full memory image at
> 0x400000 is necessarily working in the snapshot tests - there might be
> another offset needed to access the correct opcodes for the trace.
>
> I'll let you know if I make further progress.
>
>
> On 17 September 2018 at 16:53, Mike Leach <mike.leach@linaro.org> wrote:
>> Hi Mike,
>>
>> I've looked at the data you supplied.
>>
>> I created test snapshot directories so that I could run each of the
>> trace data files through the trc_pkt_lister test program (the attached
>> .tgz file contains these, plus the results).
>>
>> Now the two trace files are different sizes - this is explained by the
>> fact that the api trace run had cycle counts switched on, whereas the
>> perf run did not - plus the perf run turned off the trace while in
>> kernel calls - the api left the trace on, though filtering out the
>> kernel - but a certain amount of sync packets have come through adding
>> to the size.
>>
>> Now looking at the results I cannot see the 0x4148f4 location in
>> either trace dump (perf_ls2.ppl and api_ls2.ppl in the .tgz).
>>
>> There are no obvious differences I could detect in the results, though
>> they are difficult to compare given the difference in output.
>>
>> The effect you are seeing does look like some sort of runaway - with
>> the decoder searching for opcodes - possibly in a section of the ls
>> binary file that does not contain executable code - till it happens
>> upon something that looks like an opcode.
>>
>> At this point I cannot explain the difference you and I are seeing
>> given the data provided. Can you look at the snapshot results, and see
>> if there is anything there? You can re-run the tests I ran if you
>> rename ls to ls.bin and put on level up from the ss-perf or ss-api
>> snapshot directories where the file is referenced to.
>>
>> Regards
>>
>> Mike
>>
>>
>>
>>
>> On 17 September 2018 at 13:44, Mike Bazov <mike@perception-point.io> wrote:
>>> Greetings,
>>>
>>> I recorded the program "ls" (statically linked to provide a single
>>> executable as a memory accesses file).
>>>
>>> I recorded the program using perf, and then extracted the actual raw trace
>>> data from the perf.data file using a little tool i wrote. I can use OpenCSD
>>> to fully decode the trace produced by perf.
>>>
>>> I also recorded the "ls" util using an API i wrote from kernel mode. I
>>> published the API here as an [RFC]. Basically, i start recording and stop
>>> recording whenever the __process__ of my interest is scheduling in.
>>> This post is not much about requesting a review for my API.. but i do have
>>> some issues with the trace that is produced by this API, and i'm not quite
>>> sure why.
>>>
>>> I use the OpenCSD directly in my code, and register a decoder callback for
>>> every generic trace element. When my callback is called, i simply print the
>>> element string representation(e.g. OCSD_GEN_TRC_ELEM_INSTR_RANGE).
>>>
>>> Now, the weird thing is the perf and API produce the same generic elements
>>> until a certain element:
>>>
>>> OCSD_GEN_TRC_ELEM_TRACE_ON()
>>> ...
>>> ...
>>> ... same elements...
>>> ... same elements...
>>> ... same elements...
>>> ...
>>> ...
>>>
>>> And eventually diverge from each other. I assume the perf trace is going in
>>> the right direction, but my trace simply starts going nuts. The last
>>> __common__ generic element is the following:
>>>
>>> OCSD_GEN_TRC_ELEM_INSTR_RANGE(exec range=0x4148f4:[0x414910] (ISA=A64) E iBR
>>> A64:ret )
>>>
>>> After this element, perf trace goes in a different route, and the API right
>>> afterwards produced a very weird instruction range element:
>>>
>>> OCSD_GEN_TRC_ELEM_INSTR_RANGE(exec range=0x414910:[0x498a20] (ISA=A64) E ---
>>> )
>>>
>>> There is no way this 0x498a20 address was reached, and i cannot see any
>>> proof for it in the trace itself(using ptm2human). It seems that the decoder
>>> keeps decoding and disassembling opcodes until it reaches 0x498a20... my
>>> memory callback(callback that is called if the decoder needs memory that
>>> isn't present) is called for the address 0x498a20. From the on, the trace
>>> just goes into a very weird path. I can't explain the address branches that
>>> are taken from here on.
>>>
>>>
>>> Any ideas on how to approach this? OpenCSD experts would be appreciated.
>>> I have attached the perf and API trace, and the "ls" executable which is
>>> loaded into address 0x400000. I also attached the ETMv4 config for every
>>> trace(trace id, etc..). There is no need to create multiple decoders for
>>> different trace ids, theres only a single ID for a single decoder.
>>>
>>> Thanks,
>>> Mike.
>>>
>>> _______________________________________________
>>> CoreSight mailing list
>>> CoreSight@lists.linaro.org
>>> https://lists.linaro.org/mailman/listinfo/coresight
>>>
>>
>>
>>
>> --
>> Mike Leach
>> Principal Engineer, ARM Ltd.
>> Manchester Design Centre. UK
>
>
>
> --
> Mike Leach
> Principal Engineer, ARM Ltd.
> Manchester Design Centre. UK
--
Mike Leach
Principal Engineer, ARM Ltd.
Manchester Design Centre. UK