Skip to content

Commit

Permalink
Report: Support max/min timestamp in report output
Browse files Browse the repository at this point in the history 
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
  ==================  ==================  ====================
       583.957018293       583.957018293  main
       583.957026996       583.957026996  __isoc99_scanf
       585.431639051       585.431610568  printf
       585.431609834       585.431609834  fibonacci
       585.431639443       585.431639443  putchar
       583.957012086       583.957012086  __monstartup
       583.957013929       583.957013929  __cxa_atexit

Resolves: #1898

Signed-off-by: Hanyu Cui <ambition0316@126.com>
  • Loading branch information
@Cosh-y
Cosh-y committed Jun 15, 2024
1 parent d79deba commit 27bee29
Show file tree
Hide file tree
Showing 7 changed files with 72 additions and 21 deletions.
9 changes: 3 additions & 6 deletions cmds/replay.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -54,14 +54,11 @@ static void print_addr(struct field_data *fd)
pr_out("%*" PRIx64, width, effective_addr(fstack->addr));
}

static void print_timestamp(struct field_data *fd)
static void print_timestamp_field(struct field_data *fd)
{
struct uftrace_task_reader *task = fd->task;

uint64_t sec = task->timestamp / NSEC_PER_SEC;
uint64_t nsec = task->timestamp % NSEC_PER_SEC;

pr_out("%8" PRIu64 ".%09" PRIu64, sec, nsec);
print_timestamp(task->timestamp);
}

static void print_timedelta(struct field_data *fd)
Expand Down Expand Up @@ -156,7 +153,7 @@ static struct display_field field_time = {
.name = "time",
.header = " TIMESTAMP ",
.length = 18,
.print = print_timestamp,
.print = print_timestamp_field,
.list = LIST_HEAD_INIT(field_time.list),
};

Expand Down
32 changes: 25 additions & 7 deletions cmds/tui.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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[] = {
Expand Down Expand Up @@ -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) \
{ \
Expand All @@ -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");
Expand All @@ -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,
Expand Down
8 changes: 8 additions & 0 deletions utils/debug.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -384,6 +384,14 @@ void print_time_unit(uint64_t delta_nsec)
__print_time_unit(delta_nsec, false);
}

void print_timestamp(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;
Expand Down
5 changes: 5 additions & 0 deletions utils/field.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down
36 changes: 28 additions & 8 deletions utils/report.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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)
Expand Down Expand Up @@ -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;

Expand All @@ -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)
Expand Down Expand Up @@ -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(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) \
{ \
Expand Down Expand Up @@ -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");
Expand Down Expand Up @@ -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 */
Expand Down
2 changes: 2 additions & 0 deletions utils/report.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down
1 change: 1 addition & 0 deletions utils/utils.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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(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);
Expand Down

0 comments on commit 27bee29

Please sign in to comment.