[PATCH] trace: proftool: dump-ftrace should write funcgraph times in ns not us

[Ilias Apalodimas]

On Fri, 6 Dec 2024 at 12:11, Jerome Forissier
<jerome.forissier at 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 at 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 at linaro.org>