When converting a U-Boot trace records file to ftrace function graph
format for use by trace-cmd ('proftool -f funcgraph dump-ftrace'), the
time associated to each function is incorrectly saved in microseconds
instead of nanoseconds. Multuply the value by 1000 to fix the issue.
With this change, the trace-cmd output looks consistent. Here is an
example with udelay(25) added to mem_malloc_init() as a test case:
$ ./tools/proftool -m System.map -t /tmp/trace.bin -f funcgraph \
dump-ftrace -o /tmp/trace.dat
$ trace-cmd report /tmp/trace.dat >/tmp/trace.log
$ vi /tmp/trace.log
[...]
u-boot-1 [000] 6.719659: funcgraph_entry: |
mem_malloc_init() {
u-boot-1 [000] 6.719659: funcgraph_entry: |
udelay() {
u-boot-1 [000] 6.719660: funcgraph_entry: |
schedule() {
u-boot-1 [000] 6.719660: funcgraph_entry: |
cyclic_run() {
u-boot-1 [000] 6.719660: funcgraph_entry: 1.000 us |
cyclic_get_list();
u-boot-1 [000] 6.719661: funcgraph_exit: 1.000 us |
}
u-boot-1 [000] 6.719661: funcgraph_exit: 1.000 us |
}
u-boot-1 [000] 6.719661: funcgraph_entry: |
__udelay() {
u-boot-1 [000] 6.719662: funcgraph_entry: 0.000 us |
usec_to_tick();
u-boot-1 [000] 6.719687: funcgraph_exit: + 26.000 us |
}
u-boot-1 [000] 6.719687: funcgraph_exit: + 28.000 us | }
u-boot-1 [000] 6.719687: funcgraph_entry: # 37971.000 us |
memset();
u-boot-1 [000] 6.757658: funcgraph_exit: # 37999.000 us | }
u-boot-1 [000] 6.757658: funcgraph_exit: # 38000.000 us | }
In the above dump, the udelay() call is reported as taking 26 us which
is consistent with the timestamps (6.719687 - 6.719659 = 0.000026).
Without this patch we would have "0.026 us" instead of "+ 26.000 us".
Signed-off-by: Jerome Forissier <[email protected]>
---
tools/proftool.c | 4 ++--
1 file changed, 2 insertions(+), 2 deletions(-)
diff --git a/tools/proftool.c b/tools/proftool.c
index c2e38099354..af2cdb6d584 100644
--- a/tools/proftool.c
+++ b/tools/proftool.c
@@ -1456,8 +1456,8 @@ static int write_pages(struct twriter *tw, enum
out_format_t out_format,
}
tw->ptr += tputl(fout, 0); /* overrun */
tw->ptr += tputq(fout, 0); /* calltime */
- /* rettime */
- tw->ptr += tputq(fout, func_duration);
+ /* rettime (nanoseconds) */
+ tw->ptr += tputq(fout, func_duration * 1000);
}
}
--
2.43.0
