report: support standard deviation (STDDEV) in report output

This commit introduces the ability to display the standard deviation for function execution times in the uftrace report output. This feature helps in understanding the variability in function performance across different runs. Example usage: $ uftrace report -f total-avg,total-stdv Example output: Function Total avg Total stddev foo 15.234 ms 1.530 ms bar 22.341 ms 2.300 ms This enhancement adds the 'total-stdv' field, which can be specified alongside other fields like 'total-avg'. Resolves: #1897 Signed-off-by: ziming <[email protected]>
namhyung · Apr 13, 2024 · 080a1cf · 080a1cf
1 parent c9da63f
commit 080a1cf
Show file tree

Hide file tree

Showing 9 changed files with 88 additions and 68 deletions.
diff --git a/Makefile b/Makefile
@@ -93,13 +93,13 @@ LIB_CFLAGS += -fno-builtin -fno-tree-vectorize -DLIBMCOUNT
 TEST_CFLAGS = $(COMMON_CFLAGS) -DUNIT_TEST
 PYTHON_CFLAGS = $(COMMON_CFLAGS) -fPIC
 
-UFTRACE_LDFLAGS = $(COMMON_LDFLAGS) $(LDFLAGS_$@) $(LDFLAGS_uftrace)
+UFTRACE_LDFLAGS = $(COMMON_LDFLAGS) $(LDFLAGS_$@) $(LDFLAGS_uftrace) -lm
 DEMANGLER_LDFLAGS = $(COMMON_LDFLAGS) $(LDFLAGS_$@) $(LDFLAGS_demangler)
 SYMBOLS_LDFLAGS = $(COMMON_LDFLAGS) $(LDFLAGS_$@) $(LDFLAGS_symbols)
 DBGINFO_LDFLAGS = $(COMMON_LDFLAGS) $(LDFLAGS_$@) $(LDFLAGS_dbginfo)
 BENCH_LDFLAGS = -Wl,-z,noexecstack $(LDFLAGS_$@) $(LDFLAGS_bench)
 LIB_LDFLAGS = $(COMMON_LDFLAGS) $(LDFLAGS_$@) $(LDFLAGS_lib) -Wl,--no-undefined
-TEST_LDFLAGS = $(COMMON_LDFLAGS)
+TEST_LDFLAGS = $(COMMON_LDFLAGS) -lm
 
 _DEFAULT_SANITIZERS := address,leak
 ifeq ($(ARCH), riscv64)

diff --git a/cmds/tui.c b/cmds/tui.c
@@ -182,11 +182,11 @@ static const char *graph_field_names[NUM_GRAPH_FIELD] = {
  "ADDRESS",
 };
 
-#define NUM_REPORT_FIELD 10
+#define NUM_REPORT_FIELD 12
 
 static const char *report_field_names[NUM_REPORT_FIELD] = {
- "TOTAL TIME", "TOTAL AVG", "TOTAL MIN", "TOTAL MAX", "SELF TIME",
- "SELF AVG", "SELF MIN", "SELF MAX", "CALL",   "SIZE",
+ "TOTAL TIME", "TOTAL AVG", "TOTAL MIN", "TOTAL MAX", "TOTAL STDV", "SELF TIME",
+ "SELF AVG", "SELF MIN", "SELF MAX", "SELF STDV", "CALL", "SIZE",
 };
 
 static const char *field_help[] = {
@@ -204,8 +204,8 @@ enum tui_mode {
 };
 
 static char *report_sort_key[] = {
- OPT_SORT_KEYS, "total_avg", "total_min", "total_max", "self",
- "self_avg", "self_min", "self_max", "call",   "size",
+ OPT_SORT_KEYS, "total_avg", "total_min", "total_max", "total_std", "self",
+ "self_avg", "self_min", "self_max", "self_std", "call",  "size",
 };
 
 static char *selected_report_sort_key[NUM_REPORT_FIELD];
@@ -369,20 +369,22 @@ REPORT_FIELD_TIME(REPORT_F_TOTAL_TIME, total, total.sum, total, "TOTAL TIME");
 REPORT_FIELD_TIME(REPORT_F_TOTAL_TIME_AVG, total-avg, total.avg, total_avg, "TOTAL AVG");
 REPORT_FIELD_TIME(REPORT_F_TOTAL_TIME_MIN, total-min, total.min, total_min, "TOTAL MIN");
 REPORT_FIELD_TIME(REPORT_F_TOTAL_TIME_MAX, total-max, total.max, total_max, "TOTAL MAX");
+REPORT_FIELD_TIME(REPORT_F_TOTAL_TIME_STDV, total-stdv, total.stdv, total_stdv, "TOTAL STDV");
 REPORT_FIELD_TIME(REPORT_F_SELF_TIME, self, self.sum, self, "SELF TIME");
 REPORT_FIELD_TIME(REPORT_F_SELF_TIME_AVG, self-avg, self.avg, self_avg, "SELF AVG");
 REPORT_FIELD_TIME(REPORT_F_SELF_TIME_MIN, self-min, self.min, self_min, "SELF MIN");
 REPORT_FIELD_TIME(REPORT_F_SELF_TIME_MAX, self-max, self.max, self_max, "SELF MAX");
+REPORT_FIELD_TIME(REPORT_F_SELF_TIME_STDV, self-stdv, self.stdv, self_stdv, "SELF STDV");
 REPORT_FIELD_UINT(REPORT_F_CALL, call, call, call, "CALL");
 REPORT_FIELD_UINT(REPORT_F_SIZE, size, size, size, "SIZE");
 
 /* clang-format on */
 
 static struct display_field *report_field_table[] = {
- &report_field_total, &report_field_total_avg, &report_field_total_min,
- &report_field_total_max, &report_field_self, &report_field_self_avg,
- &report_field_self_min, &report_field_self_max, &report_field_call,
- &report_field_size,
+ &report_field_total, &report_field_total_avg,  &report_field_total_min,
+ &report_field_total_max, &report_field_total_stdv, &report_field_self,
+ &report_field_self_avg, &report_field_self_min,  &report_field_self_max,
+ &report_field_self_stdv, &report_field_call, &report_field_size,
 };
 
 static void setup_default_graph_field(struct list_head *fields, struct uftrace_opts *opts,

diff --git a/doc/uftrace-report.md b/doc/uftrace-report.md
@@ -24,25 +24,26 @@ REPORT OPTIONS
 ==============
 -f *FIELD*, \--output-fields=*FIELD*
 : Customize field in the output. Possible values are: `total`, `total-avg`,
- `total-min`, `total-max`, `self`, `self-avg`, `self-min`, `self-max`, `size`,
- `call` and `all`. Multiple fields can be set by using comma. Special field
+ `total-min`, `total-max`, `total-stdv`, `self`, `self-avg`, `self-min`, `self-max`,
+ `self-stdv`, `size`, `call` and `all`. Multiple fields can be set by using comma. Special field
  of 'none' can be used (solely) to hide all fields and 'all' can be used to
  show all fields.
- Default is 'total,self,call'. See *FIELDS*.
+ Default is 'total,self,call'. See *FIELDS*. `stdv` stands for standard deviation, it would only contain value
+ if the function is invoked multiple times.
 
 -s *KEYS*[,*KEYS*,...], \--sort=*KEYS*[,*KEYS*,...]
 : Sort functions by given KEYS. Multiple KEYS can be given, separated by
  comma (,). Possible keys are `total` (time), `total-avg`, `total-min`,
- `total-max`, `self` (time), `self-avg`, `self-min`, `self-max`, `size`,
+ `total-max`, `total-stdv`, `self` (time), `self-avg`, `self-min`, `self-max`, `self-stdv`, `size`,
  `call` and `func`. But if either `--avg-total` or `--avg-self` is used,
  the possible keys can be `avg`, `min` and `max` that apply to total or self
  time respectively.
 
 \--avg-total
-: Show average, min, max of each function's total time.
+: Show average, min, max, stdv of each function's total time.
 
 \--avg-self
-: Show average, min, max of each function's self time.
+: Show average, min, max, stdv of each function's self time.
 
 \--task
 : Report task summary information rather than function statistics.
@@ -177,41 +178,35 @@ EXAMPLE
 =======
 This command shows information like the following:
 
- $ uftrace record abc
+ $ uftrace record fibonacci
  $ uftrace report
   Total time Self time Calls Function
   ========== ========== ========== ====================
-  150.829 us 150.829 us 1 __cxa_atexit
-  27.289 us 1.243 us 1 main
-  26.046 us 0.939 us 1 a
-  25.107 us 0.934 us 1 b
-  24.173 us 1.715 us 1 c
-  22.458 us 22.458 us 1 getpid
+  3.781 us 0.124 us 1 main
+  3.657 us 3.657 us 41 fib
+  0.345 us 0.345 us 1 __monstartup
+  0.269 us 0.269 us 1 __cxa_atexit
 
  $ uftrace report -s call,self
   Total time Self time Calls Function
   ========== ========== ========== ====================
-  150.829 us 150.829 us 1 __cxa_atexit
-  22.458 us 22.458 us 1 getpid
-  24.173 us 1.715 us 1 c
-  27.289 us 1.243 us 1 main
-  26.046 us 0.939 us 1 a
-  25.107 us 0.934 us 1 b
+  3.657 us 3.657 us 41 fib
+  0.345 us 0.345 us 1 __monstartup
+  0.269 us 0.269 us 1 __cxa_atexit
+  3.781 us 0.124 us 1 main
 
  $ uftrace report --avg-self
-  Avg self Min self Max self Function
-  ========== ========== ========== ====================
-  150.829 us 150.829 us 150.829 us __cxa_atexit
-  22.458 us 22.458 us 22.458 us getpid
-  1.715 us 1.715 us 1.715 us c
-  1.243 us 1.243 us 1.243 us main
-  0.939 us 0.939 us 0.939 us a
-  0.934 us 0.934 us 0.934 us b
+  Self avg Self min Self max Self stdv Function
+  ========== ========== ========== ========== ====================
+  0.345 us 0.345 us 0.345 us __monstartup
+  0.269 us 0.269 us 0.269 us __cxa_atexit
+  0.124 us 0.124 us 0.124 us main
+  0.089 us 0.032 us 0.348 us 0.065 us fib
 
  $ uftrace report --task
-  Total time Self time Num funcs   TID Task name
-  ========== ========== ========== ====== ================
-  22.178 us 22.178 us 7 29955 t-abc
+  Total time Self time  TID Num funcs Task name
+  ========== ========== ====== ========== ====================
+   4.395 us  4.395 us 28662  44 fibonacci
 
  $ uftrace record --srcline abc
  $ uftrace report --srcline
@@ -360,7 +355,8 @@ Each field has following meaning:
 
 The default value is 'total,self,call'. If given field name starts with "+",
 then it'll be appended to the default fields. So "-f +total-avg" is as same as
-"-f total,self,call,total-avg". And it also accepts a special field name of
+"-f total,self,call,total-avg", and "-f +total-avg,self-stdv" is as same as
+"-f total,self,call,total-avg,self-stdv". And it also accepts a special field name of
 'none' which disables the field display and shows function output only.
 
 TASK FIELDS

diff --git a/doc/uftrace-tui.md b/doc/uftrace-tui.md
@@ -27,12 +27,14 @@ TUI OPTIONS
  Possible values are total, self and addr. The default value is 'total'.
  But if this option is used with --report option,
  this option indicates report fields. Possible values are total, total-avg,
- total-min, total-max, self, self-avg, self-min, self-max, call and size.
+ total-min, total-max, total-stdv, self, self-avg, self-min, self-max, self-stdv, call and size.
  The default value is 'total,self,call'.
  Multiple fields can be set by using comma.
  If given field name starts with "+", then it'll be appended to the default fields.
  The special field 'none' can be used (solely) to hide all fields.
  See `uftrace-graph`(1) or `uftrace-report`(1) for an explanation of fields.
+ The `stdv` in total-stdv and self-stdv stands for standard deviation, it would only contain value
+ if the function is invoked multiple times.
 
 -s *KEYS*[,*KEYS*,...], \--sort=*KEYS*[,*KEYS*,...]
 : Sort functions by given KEYS. Multiple KEYS can be given, separated by comma (,).

diff --git a/tests/t044_report_avg_total.py b/tests/t044_report_avg_total.py
@@ -5,15 +5,15 @@
 class TestCase(TestBase):
  def __init__(self):
  TestBase.__init__(self, 'sort', """
- Total avg Total min Total max Function
- ========== ========== ========== ====================
- 11.378 ms 11.378 ms 11.378 ms main
- 10.537 ms 10.537 ms 10.537 ms bar
- 10.288 ms 10.288 ms 10.288 ms usleep
- 120.947 us 120.605 us 121.290 us foo
- 39.967 us 39.801 us 40.275 us loop
- 0.701 us 0.701 us 0.701 us __monstartup
- 0.270 us 0.270 us 0.270 us __cxa_atexit
+ Total avg Total min Total max Total stdv Function
+ ========== ========== ========== ========== ====================
+ 10.277 ms 10.277 ms 10.277 ms  main
+ 10.224 ms 10.224 ms 10.224 ms  bar
+ 10.210 ms 10.210 ms 10.210 ms  usleep
+  7.849 us  7.713 us  7.985 us 0.136 us foo
+  2.499 us  2.483 us  2.547 us 0.046 us loop
+ 0.765 us 0.765 us 0.765 us  __monstartup
+ 0.486 us 0.486 us 0.486 us  __cxa_atexit
 """)
 
  def prepare(self):

diff --git a/tests/t045_report_avg_self.py b/tests/t045_report_avg_self.py
@@ -5,15 +5,15 @@
 class TestCase(TestBase):
  def __init__(self):
  TestBase.__init__(self, 'sort', """
- Self avg Self min Self max Function
- ========== ========== ========== ====================
- 10.288 ms 10.288 ms 10.288 ms usleep
- 598.518 us 598.518 us 598.518 us main
- 249.854 us 249.854 us 249.854 us bar
- 39.967 us 39.801 us 40.275 us loop
- 1.044 us 0.884 us 1.205 us foo
- 0.701 us 0.701 us 0.701 us __monstartup
- 0.270 us 0.270 us 0.270 us __cxa_atexit
+ Self avg Self min Self max  Self stdv Function
+ ========== ========== ========== ========== ====================
+ 10.119 ms 10.119 ms 10.119 ms  usleep
+  37.325 us  37.325 us  37.325 us  main
+  14.836 us  14.836 us  14.836 us  bar
+  2.500 us  2.480 us  2.569 us 0.031 us loop
+ 0.845 us 0.845 us 0.845 us  __monstartup
+ 0.546 us 0.546 us 0.546 us  __cxa_atexit
+ 0.342 us 0.234 us 0.450 us  0.108 us foo
 """)
 
  def prepare(self):

diff --git a/utils/field.h b/utils/field.h
@@ -40,10 +40,14 @@ enum display_field_id {
  REPORT_F_TOTAL_TIME_AVG,
  REPORT_F_TOTAL_TIME_MIN,
  REPORT_F_TOTAL_TIME_MAX,
+ REPORT_F_TOTAL_TIME_STDV,
+
  REPORT_F_SELF_TIME,
  REPORT_F_SELF_TIME_AVG,
  REPORT_F_SELF_TIME_MIN,
  REPORT_F_SELF_TIME_MAX,
+ REPORT_F_SELF_TIME_STDV,
+
  REPORT_F_CALL,
  REPORT_F_SIZE,
 

diff --git a/utils/report.c b/utils/report.c
@@ -1,4 +1,5 @@
 #include <inttypes.h>
+#include <math.h>
 #include <stdio.h>
 #include <string.h>
 
@@ -15,10 +16,14 @@ static void init_time_stat(struct report_time_stat *ts)
 
 static void update_time_stat(struct report_time_stat *ts, uint64_t time_ns, bool recursive)
 {
- if (recursive)
+ if (recursive) {
  ts->rec += time_ns;
- else
+ ts->rec_sq += time_ns * time_ns;
+ }
+ else {
  ts->sum += time_ns;
+ ts->sum_sq += time_ns * time_ns;
+ }
 
  if (ts->min > time_ns)
  ts->min = time_ns;
@@ -29,6 +34,7 @@ static void update_time_stat(struct report_time_stat *ts, uint64_t time_ns, bool
 static void finish_time_stat(struct report_time_stat *ts, unsigned long call)
 {
  ts->avg = (ts->sum + ts->rec) / call;
+ ts->stdv = (int)sqrt((ts->sum_sq + ts->rec_sq) / call - ts->avg * ts->avg);
 }
 
 static struct uftrace_report_node *find_or_create_node(struct rb_root *root, const char *name,
@@ -850,21 +856,25 @@ FIELD_TIME(REPORT_F_TOTAL_TIME, total, total.sum, total, "Total time");
 FIELD_TIME(REPORT_F_TOTAL_TIME_AVG, total-avg, total.avg, total_avg, "Total avg");
 FIELD_TIME(REPORT_F_TOTAL_TIME_MIN, total-min, total.min, total_min, "Total min");
 FIELD_TIME(REPORT_F_TOTAL_TIME_MAX, total-max, total.max, total_max, "Total max");
+FIELD_TIME(REPORT_F_TOTAL_TIME_STDV, total-stdv, total.stdv, total_stdv, "Total stdv");
 FIELD_TIME(REPORT_F_SELF_TIME, self, self.sum, self, "Self time");
 FIELD_TIME(REPORT_F_SELF_TIME_AVG, self-avg, self.avg, self_avg, "Self avg");
 FIELD_TIME(REPORT_F_SELF_TIME_MIN, self-min, self.min, self_min, "Self min");
 FIELD_TIME(REPORT_F_SELF_TIME_MAX, self-max, self.max, self_max, "Self max");
+FIELD_TIME(REPORT_F_SELF_TIME_STDV, self-stdv, self.stdv, self_stdv, "Self stdv");
 FIELD_UINT(REPORT_F_CALL, call, call, call, "Calls");
 FIELD_UINT(REPORT_F_SIZE, size, size, size, "Size");
 
 FIELD_TIME_DIFF(REPORT_F_TOTAL_TIME, total, total.sum, total, "Total time");
 FIELD_TIME_DIFF(REPORT_F_TOTAL_TIME_AVG, total-avg, total.avg, total_avg, "Total avg");
 FIELD_TIME_DIFF(REPORT_F_TOTAL_TIME_MIN, total-min, total.min, total_min, "Total min");
 FIELD_TIME_DIFF(REPORT_F_TOTAL_TIME_MAX, total-max, total.max, total_max, "Total max");
+FIELD_TIME_DIFF(REPORT_F_TOTAL_TIME_STDV, total-stdv, total.stdv, total_stdv, "Total stdv");
 FIELD_TIME_DIFF(REPORT_F_SELF_TIME, self, self.sum, self, "Self time");
 FIELD_TIME_DIFF(REPORT_F_SELF_TIME_AVG, self-avg, self.avg, self_avg, "Self avg");
 FIELD_TIME_DIFF(REPORT_F_SELF_TIME_MIN, self-min, self.min, self_min, "Self min");
 FIELD_TIME_DIFF(REPORT_F_SELF_TIME_MAX, self-max, self.max, self_max, "Self max");
+FIELD_TIME_DIFF(REPORT_F_SELF_TIME_STDV, self-stdv, self.stdv, self_stdv, "Self stdv");
 FIELD_UINT_DIFF(REPORT_F_CALL, call, call, call, "Calls");
 FIELD_UINT_DIFF(REPORT_F_SIZE, size, size, size, "Size");
 
@@ -898,15 +908,16 @@ FIELD_UINT(REPORT_F_TASK_NR_FUNC, func, call, task_nr_func, "Num funcs");
 
 /* index of this table should be matched to display_field_id */
 static struct display_field *field_table[] = {
- &field_total, &field_total_avg, &field_total_min, &field_total_max, &field_self,
- &field_self_avg, &field_self_min, &field_self_max, &field_call, &field_size,
+ &field_total, &field_total_avg, &field_total_min, &field_total_max,
+ &field_total_stdv, &field_self, &field_self_avg, &field_self_min,
+ &field_self_max, &field_self_stdv, &field_call, &field_size,
 };
 
 /* index of this table should be matched to display_field_id */
 static struct display_field *field_diff_table[] = {
- &field_total_diff, &field_total_avg_diff, &field_total_min_diff, &field_total_max_diff,
- &field_self_diff, &field_self_avg_diff, &field_self_min_diff, &field_self_max_diff,
- &field_call_diff, &field_size_diff,
+ &field_total_diff, &field_total_avg_diff, &field_total_min_diff, &field_total_max_diff,
+ &field_total_stdv_diff, &field_self_diff,  &field_self_avg_diff, &field_self_min_diff,
+ &field_self_max_diff, &field_self_stdv_diff, &field_call_diff,  &field_size_diff,
 };
 
 /* index of this table should be matched to display_field_id */
@@ -948,6 +959,7 @@ static void setup_avg_total_field(struct list_head *fields, struct uftrace_opts
  add_field(fields, p_field_table[REPORT_F_TOTAL_TIME_AVG]);
  add_field(fields, p_field_table[REPORT_F_TOTAL_TIME_MIN]);
  add_field(fields, p_field_table[REPORT_F_TOTAL_TIME_MAX]);
+ add_field(fields, p_field_table[REPORT_F_TOTAL_TIME_STDV]);
 }
 
 static void setup_avg_self_field(struct list_head *fields, struct uftrace_opts *opts,
@@ -956,6 +968,7 @@ static void setup_avg_self_field(struct list_head *fields, struct uftrace_opts *
  add_field(fields, p_field_table[REPORT_F_SELF_TIME_AVG]);
  add_field(fields, p_field_table[REPORT_F_SELF_TIME_MIN]);
  add_field(fields, p_field_table[REPORT_F_SELF_TIME_MAX]);
+ add_field(fields, p_field_table[REPORT_F_SELF_TIME_STDV]);
 }
 
 static void setup_default_task_field(struct list_head *fields, struct uftrace_opts *opts,

diff --git a/utils/report.h b/utils/report.h
@@ -17,7 +17,10 @@ enum avg_mode {
 struct report_time_stat {
  uint64_t sum;
  uint64_t rec; /* time in recursive call */
+ uint64_t sum_sq;
+ uint64_t rec_sq;
  uint64_t avg;
+ uint64_t stdv;
  uint64_t min;
  uint64_t max;
 };