From 2cad9d4a3f5cf99dfc9ad6d3e38451cfa8cab422 Mon Sep 17 00:00:00 2001 From: Hanyu Cui Date: Sun, 12 May 2024 16:52:57 +0800 Subject: [PATCH] Report: Support max/min timestamp in report output This patch introduces timestamps for special function calls that take the minimum or maximum time. With this capability, users can identify function calls that exhibit unusual execution times and investigate the underlying reasons. Example usage: $ uftrace report -f total-min-ts,total-max-ts Total min ts Total max ts Function ============ ============ ==================== 12.009 h 12.009 h main 12.009 h 12.009 h printf 12.009 h 12.009 h __monstartup 12.009 h 12.009 h __cxa_atexit Resolves: #1898 Signed-off-by: Hanyu Cui --- cmds/tui.c | 32 +++++++++++++++++++++++++------- utils/debug.c | 8 ++++++++ utils/field.h | 5 +++++ utils/report.c | 36 ++++++++++++++++++++++++++++-------- utils/report.h | 2 ++ utils/utils.h | 1 + 6 files changed, 69 insertions(+), 15 deletions(-) diff --git a/cmds/tui.c b/cmds/tui.c index 7b02444ae..f2039a460 100644 --- a/cmds/tui.c +++ b/cmds/tui.c @@ -182,11 +182,12 @@ static const char *graph_field_names[NUM_GRAPH_FIELD] = { "ADDRESS", }; -#define NUM_REPORT_FIELD 12 +#define NUM_REPORT_FIELD 16 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 STDV", "SELF STDV", + "TOTAL TIME", "TOTAL AVG", "TOTAL MIN", "TOTAL MAX", "SELF TIME", "SELF AVG", + "SELF MIN", "SELF MAX", "CALL", "SIZE", "TOTAL STDV", "SELF STDV", + "TOTAL MIN TS", "TOTAL MAX TS", "SELF MIN TS", "SELF MAX TS", }; static const char *field_help[] = { @@ -354,6 +355,17 @@ static void print_report_##_func(struct field_data *fd) } \ REPORT_FIELD_STRUCT(_id, _name, _func, _header, 10) +#define REPORT_FIELD_TIMESTAMP(_id, _name, _field, _func, _header) \ + static void print_report_##_func(struct field_data *fd) \ + { \ + struct uftrace_report_node *node = fd->arg; \ + uint64_t timestamp = node->_field; \ + uint64_t sec = timestamp / NSEC_PER_SEC; \ + uint64_t nsec = timestamp % NSEC_PER_SEC; \ + printw("%8lu.%09lu", sec, nsec); \ + } \ + REPORT_FIELD_STRUCT(_id, _name, _func, _header, 18) + #define REPORT_FIELD_PERCENTAGE(_id, _name, _field, _func, _header) \ static void print_report_##_func(struct field_data *fd) \ { \ @@ -375,10 +387,14 @@ 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_TIMESTAMP(REPORT_F_TOTAL_TIME_MIN_TS, total-min-ts, total.min_ts, total_min_ts, "TOTAL MIN TS"); +REPORT_FIELD_TIMESTAMP(REPORT_F_TOTAL_TIME_MAX_TS, total-max-ts, total.max_ts, total_max_ts, "TOTAL MAX TS"); 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_TIMESTAMP(REPORT_F_SELF_TIME_MIN_TS, self-min-ts, self.min_ts, self_min_ts, "SELF MIN TS"); +REPORT_FIELD_TIMESTAMP(REPORT_F_SELF_TIME_MAX_TS, self-max-ts, self.max_ts, self_max_ts, "SELF MAX TS"); REPORT_FIELD_UINT(REPORT_F_CALL, call, call, call, "CALL"); REPORT_FIELD_UINT(REPORT_F_SIZE, size, size, size, "SIZE"); REPORT_FIELD_PERCENTAGE(REPORT_F_TOTAL_TIME_STDV, total-stdv, total.stdv, total_stdv, "TOTAL STDV"); @@ -387,10 +403,12 @@ REPORT_FIELD_PERCENTAGE(REPORT_F_SELF_TIME_STDV, self-stdv, self.stdv, self_stdv /* 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_stdv, &report_field_self_stdv, + &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_stdv, &report_field_self_stdv, + &report_field_total_min_ts, &report_field_total_max_ts, &report_field_self_min_ts, + &report_field_self_max_ts, }; static void setup_default_graph_field(struct list_head *fields, struct uftrace_opts *opts, diff --git a/utils/debug.c b/utils/debug.c index ddd31092f..0b0d4f54a 100644 --- a/utils/debug.c +++ b/utils/debug.c @@ -384,6 +384,14 @@ void print_time_unit(uint64_t delta_nsec) __print_time_unit(delta_nsec, false); } +void print_timestamp_unit(uint64_t timestamp) +{ + uint64_t sec = timestamp / NSEC_PER_SEC; + uint64_t nsec = timestamp % NSEC_PER_SEC; + + pr_out("%8" PRIu64 ".%09" PRIu64, sec, nsec); +} + void print_diff_percent(uint64_t base_nsec, uint64_t pair_nsec) { double percent; diff --git a/utils/field.h b/utils/field.h index 4a391f1a4..89db18bb3 100644 --- a/utils/field.h +++ b/utils/field.h @@ -52,6 +52,11 @@ enum display_field_id { REPORT_F_TOTAL_TIME_STDV, REPORT_F_SELF_TIME_STDV, + REPORT_F_TOTAL_TIME_MIN_TS, + REPORT_F_TOTAL_TIME_MAX_TS, + REPORT_F_SELF_TIME_MIN_TS, + REPORT_F_SELF_TIME_MAX_TS, + REPORT_F_TASK_TOTAL_TIME = 0, REPORT_F_TASK_SELF_TIME, REPORT_F_TASK_TID, diff --git a/utils/report.c b/utils/report.c index cb6026775..1bea5c75b 100644 --- a/utils/report.c +++ b/utils/report.c @@ -14,7 +14,8 @@ static void init_time_stat(struct report_time_stat *ts) ts->min = -1ULL; } -static void update_time_stat(struct report_time_stat *ts, uint64_t time_ns, bool recursive) +static void update_time_stat(struct report_time_stat *ts, uint64_t time_ns, uint64_t timestamp, + bool recursive) { if (recursive) { ts->rec += time_ns; @@ -25,10 +26,14 @@ static void update_time_stat(struct report_time_stat *ts, uint64_t time_ns, bool ts->sum_sq += time_ns * time_ns; } - if (ts->min > time_ns) + if (ts->min > time_ns) { ts->min = time_ns; - if (ts->max < time_ns) + ts->min_ts = timestamp; + } + if (ts->max < time_ns) { ts->max = time_ns; + ts->max_ts = timestamp; + } } static void finish_time_stat(struct report_time_stat *ts, unsigned long call) @@ -98,6 +103,7 @@ void report_update_node(struct uftrace_report_node *node, struct uftrace_task_re struct uftrace_fstack *fstack; uint64_t total_time; uint64_t self_time; + uint64_t timestamp; bool recursive = false; int i; @@ -118,9 +124,10 @@ void report_update_node(struct uftrace_report_node *node, struct uftrace_task_re total_time = fstack->total_time; self_time = fstack->total_time - fstack->child_time; + timestamp = task->rstack->time - total_time; - update_time_stat(&node->total, total_time, recursive); - update_time_stat(&node->self, self_time, false); + update_time_stat(&node->total, total_time, timestamp, recursive); + update_time_stat(&node->self, self_time, timestamp, false); node->call++; node->loc = loc; if (task->func != NULL) @@ -769,6 +776,14 @@ void report_sort_tasks(struct uftrace_data *handle, struct rb_root *name_root, } \ FIELD_STRUCT(_id, _name, _func, _header, 10) +#define FIELD_TIMESTAMP(_id, _name, _field, _func, _header) \ + static void print_##_func(struct field_data *fd) \ + { \ + struct uftrace_report_node *node = fd->arg; \ + print_timestamp_unit(node->_field); \ + } \ + FIELD_STRUCT(_id, _name, _func, _header, 18) + #define FIELD_UINT(_id, _name, _field, _func, _header) \ static void print_##_func(struct field_data *fd) \ { \ @@ -869,10 +884,14 @@ 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_TIMESTAMP(REPORT_F_TOTAL_TIME_MIN_TS, total-min-ts, total.min_ts, total_min_ts, "Total min ts"); +FIELD_TIMESTAMP(REPORT_F_TOTAL_TIME_MAX_TS, total-max-ts, total.max_ts, total_max_ts, "Total max ts"); 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_TIMESTAMP(REPORT_F_SELF_TIME_MIN_TS, self-min-ts, self.min_ts, self_min_ts, "Self min ts"); +FIELD_TIMESTAMP(REPORT_F_SELF_TIME_MAX_TS, self-max-ts, self.max_ts, self_max_ts, "Self max ts"); FIELD_UINT(REPORT_F_CALL, call, call, call, "Calls"); FIELD_UINT(REPORT_F_SIZE, size, size, size, "Size"); FIELD_PERCENTAGE(REPORT_F_TOTAL_TIME_STDV, total-stdv, total.stdv, total_stdv, "Total stdv"); @@ -919,9 +938,10 @@ 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_stdv, &field_self_stdv, + &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_stdv, &field_self_stdv, + &field_total_min_ts, &field_total_max_ts, &field_self_min_ts, &field_self_max_ts, }; /* index of this table should be matched to display_field_id */ diff --git a/utils/report.h b/utils/report.h index c46acb016..c5f8ecf25 100644 --- a/utils/report.h +++ b/utils/report.h @@ -23,6 +23,8 @@ struct report_time_stat { double stdv; uint64_t min; uint64_t max; + uint64_t min_ts; + uint64_t max_ts; }; struct uftrace_report_node { diff --git a/utils/utils.h b/utils/utils.h index 20b2551cc..b526b6ef7 100644 --- a/utils/utils.h +++ b/utils/utils.h @@ -363,6 +363,7 @@ extern clockid_t clock_source; void setup_clock_id(const char *clock_str); void print_time_unit(uint64_t delta_nsec); +void print_timestamp_unit(uint64_t timestamp); void print_diff_percent(uint64_t base_nsec, uint64_t delta_nsec); void print_diff_time_unit(uint64_t base_nsec, uint64_t pair_nsec); void print_diff_count(uint64_t base, uint64_t pair);