Report: Support max/min timestamp in report output

[Cosh-y]

Hi @namhyung

According to the requirements in the issue #1898 , I have currently made a simple addition of four optional output fields: total-min-ts, total-max-ts, self-min-ts, and self-max-ts. Due to the longer field names, I have adjusted the output format accordingly.

The current problem is that the timestamp's starting time seems too early, resulting in excessively large timestamps. Additionally, the code hasn't passed through the pipeline yet, so I will further investigate the problem.

I hope you could review my work and provide valuable feedback.

Thank you very much!

[namhyung]

Thanks for working on this. Patch looks fine. I've left some comments below.

[namhyung]

Adding new fields in the middle created some problems. Let's add them after the STDV fields.

[namhyung]

Nop, timestamp should not be printed using print_time_unit(). Please add something similar to print_timestamp() in cmds/replay.c file.

[Cosh-y]

I think I have fixed these two problems.

[MichelleJin12]

Hello, it fails unittest, I think it's because of the missing structure field in unittest.

If I fix it like below, there is no unittest fail, but I don't know if this is the best way to fix the fail. :)

diff --git a/utils/report.c b/utils/report.c
index 1bea5c75..dc54d9cb 100644
--- a/utils/report.c
+++ b/utils/report.c
@@ -1095,6 +1095,7 @@ TEST_CASE(report_sort)
        struct rb_node *rbnode;
        struct uftrace_report_node *node;
        static struct uftrace_fstack fstack[TEST_NODES];
+       static struct uftrace_record r;
        struct uftrace_data handle = {
                .hdr = {
                        .max_stack = TEST_NODES,
@@ -1104,6 +1105,7 @@ TEST_CASE(report_sort)
        struct uftrace_task_reader task = {
                .h = &handle,
                .func_stack = fstack,
+               .rstack = &r,
        };
        int i;

@@ -1207,14 +1209,17 @@ TEST_CASE(report_diff)
                .nr_tasks = 2,
        };
        struct uftrace_fstack orig_fstack[TEST_NODES];
+       struct uftrace_record r;
        struct uftrace_task_reader orig_task = {
                .h = &handle,
                .func_stack = orig_fstack,
+               .rstack = &r,
        };
        struct uftrace_fstack pair_fstack[TEST_NODES];
        struct uftrace_task_reader pair_task = {
                .h = &handle,
                .func_stack = pair_fstack,
+               .rstack = &r,
        };

        const char *orig_name[] = { "abc", "foo", "bar" };
@@ -1314,3 +1319,4 @@ TEST_CASE(report_diff)
 }

 #endif /* UNIT_TEST */
+

It can be reproduced with make unittest ASAN=1 DEBUG=1 TESTARG="-v"

[Cosh-y]

Thanks for @MichelleJin12 's suggestion. The failure of unittest is because of that I use task->rstack->time in report_update_node() when the testcase does not init tast.rstack. I'm not clear about the test logic. I'm not sure if your patch valuable for testing or not.

Moreover, I found that the timestamp I print is always the same. I doubt if i set the timestamp correctly by timestamp = task->rstack->time - total_time; in report_update_node(). The output is always like this in my tests.

harry@harry-virtual-machine:~/Documents/C-Compilor-Test$ uftrace report -f total-max-ts,self-max-ts
        Total max ts         Self max ts  Function
  ==================  ==================  ====================
       331.253750424       331.253750424  main
       331.253759126       331.253759126  __isoc99_scanf
       334.663205183       334.663205183  printf
       334.663204200       334.663204200  fibonacci
       334.663219655       334.663219655  putchar
       331.253744685       331.253744685  __monstartup
       331.253747282       331.253747282  __cxa_atexit

[MichelleJin12]

I think you'll have to run uftrace record again for the output to be different.

$ uftrace record ./a.out

$ uftrace report -f total-max-ts,self-max-ts,total,self,total-max,total-min
  Total time   Total min   Total max   Self time        Total max ts         Self max ts  Function
  ==========  ==========  ==========  ==========  ==================  ==================  ====================
    1.186 us    1.186 us    1.186 us    0.144 us      7971.631198721      7971.631198721  main
    1.042 us    1.042 us    1.042 us    0.119 us      7971.631198807      7971.631198807  a
    0.923 us    0.923 us    0.923 us    0.144 us      7971.631198871      7971.631198871  b
    0.779 us    0.779 us    0.779 us    0.279 us      7971.631198924      7971.631198924  c
    0.524 us    0.524 us    0.524 us    0.524 us      7971.631195215      7971.631195215  __monstartup
    0.500 us    0.500 us    0.500 us    0.500 us      7971.631198989      7971.631198989  getpid
    0.188 us    0.188 us    0.188 us    0.188 us      7971.631196827      7971.631196827  __cxa_atexit

$ uftrace replay -f time,delta
#     TIMESTAMP      TIMEDELTA   FUNCTION
     7971.631195215            | __monstartup();
     7971.631196827   1.612 us | __cxa_atexit();
     7971.631198721   1.894 us | main() {
     7971.631198807   0.086 us |   a() {
     7971.631198871   0.064 us |     b() {
     7971.631198924   0.053 us |       c() {
     7971.631198989   0.065 us |         getpid();
     7971.631199703   0.714 us |       } /* c */
     7971.631199794   0.091 us |     } /* b */
     7971.631199849   0.055 us |   } /* a */
     7971.631199907   0.058 us | } /* main */

$ uftrace record ./a.out

$ uftrace report -f total-max-ts,self-max-ts,total,self,total-max,total-min
  Total time   Total min   Total max   Self time        Total max ts         Self max ts  Function
  ==========  ==========  ==========  ==========  ==================  ==================  ====================
    1.253 us    1.253 us    1.253 us    0.132 us      8090.845433163      8090.845433163  main
    1.121 us    1.121 us    1.121 us    0.139 us      8090.845433237      8090.845433237  a
    0.982 us    0.982 us    0.982 us    0.193 us      8090.845433307      8090.845433307  b
    0.789 us    0.789 us    0.789 us    0.299 us      8090.845433362      8090.845433362  c
    0.490 us    0.490 us    0.490 us    0.490 us      8090.845433428      8090.845433428  getpid
    0.464 us    0.464 us    0.464 us    0.464 us      8090.845430594      8090.845430594  __monstartup
    0.155 us    0.155 us    0.155 us    0.155 us      8090.845431766      8090.845431766  __cxa_atexit

$ uftrace replay -f time,delta
#     TIMESTAMP      TIMEDELTA   FUNCTION
     8090.845430594            | __monstartup();
     8090.845431766   1.172 us | __cxa_atexit();
     8090.845433163   1.397 us | main() {
     8090.845433237   0.074 us |   a() {
     8090.845433307   0.070 us |     b() {
     8090.845433362   0.055 us |       c() {
     8090.845433428   0.066 us |         getpid();
     8090.845434151   0.723 us |       } /* c */
     8090.845434289   0.138 us |     } /* b */
     8090.845434358   0.069 us |   } /* a */
     8090.845434416   0.058 us | } /* main */

[namhyung]

Thanks for the update, can you please also update the example in the commit message?

[namhyung]

Timestamp has no units, so it'd be print_timestamp().

If you care about the name colision in cmds/replay.c, I suggest rename one in cmds/replay.c to print_timestamp_field() and call print_timestamp() internally with task->timestamp.