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 <[email protected]>

Author: Cosh-y

utils/debug.c

@@ -384,6 +384,12 @@ void print_time_unit(uint64_t delta_nsec)
 	__print_time_unit(delta_nsec, false);
 }
 
+void print_time_unit_padding(uint64_t delta_nsec, uint32_t padding)
+{
+	pr_out("%*s", padding, "");
+	__print_time_unit(delta_nsec, false);
+}
+
 void print_diff_percent(uint64_t base_nsec, uint64_t pair_nsec)
 {
 	double percent;

utils/field.h

@@ -39,12 +39,16 @@ enum display_field_id {
 	REPORT_F_TOTAL_TIME = 0,
 	REPORT_F_TOTAL_TIME_AVG,
 	REPORT_F_TOTAL_TIME_MIN,
+	REPORT_F_TOTAL_TIME_MIN_TS,
 	REPORT_F_TOTAL_TIME_MAX,
+	REPORT_F_TOTAL_TIME_MAX_TS,
 
 	REPORT_F_SELF_TIME,
 	REPORT_F_SELF_TIME_AVG,
 	REPORT_F_SELF_TIME_MIN,
+	REPORT_F_SELF_TIME_MIN_TS,
 	REPORT_F_SELF_TIME_MAX,
+	REPORT_F_SELF_TIME_MAX_TS,
 
 	REPORT_F_CALL,
 	REPORT_F_SIZE,

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_time_unit_padding(node->_field, 2);                                          \
+	}                                                                                          \
+	FIELD_STRUCT(_id, _name, _func, _header, 12)
+
 #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_min_ts,
+	&field_total_max, &field_total_max_ts, &field_self,	  &field_self_avg,
+	&field_self_min,  &field_self_min_ts,  &field_self_max,	  &field_self_max_ts,
+	&field_call,	  &field_size,	       &field_total_stdv, &field_self_stdv,
 };
 
 /* index of this table should be matched to display_field_id */

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 {

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_time_unit_padding(uint64_t delta_nsec, uint32_t padding);
 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);