| Message ID | 20241206101132.1094545-1-jerome.forissier@linaro.org |
|---|---|
| State | New |
| Headers | show |
| Series | trace: proftool: dump-ftrace should write funcgraph times in ns not us | expand |
On Fri, 6 Dec 2024 at 03:11, Jerome Forissier <jerome.forissier@linaro.org> wrote: > > 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 <jerome.forissier@linaro.org> > --- > tools/proftool.c | 4 ++-- > 1 file changed, 2 insertions(+), 2 deletions(-) > Reviewed-by: Simon Glass <sjg@chromium.org>
On Fri, 6 Dec 2024 at 12:11, Jerome Forissier <jerome.forissier@linaro.org> wrote: > > 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 <jerome.forissier@linaro.org> > --- > 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 > Reviewed-by: Ilias Apalodimas <ilias.apalodimas@linaro.org>
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); } }
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 <jerome.forissier@linaro.org> --- tools/proftool.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-)