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