Report: Support max/min timestamp in report output by Cosh-y · Pull Request #1925 · namhyung/uftrace

Cosh-y · 2024-05-12T08:55:45Z

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 · 2024-05-14T22:27:41Z

 	REPORT_F_SELF_TIME_MIN,
+	REPORT_F_SELF_TIME_MIN_TS,
 	REPORT_F_SELF_TIME_MAX,
+	REPORT_F_SELF_TIME_MAX_TS,


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

namhyung · 2024-05-14T22:31:59Z

+	static void print_##_func(struct field_data *fd)                                           \
+	{                                                                                          \
+		struct uftrace_report_node *node = fd->arg;                                        \
+		print_time_unit_padding(node->_field, 2);                                          \


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

I think I have fixed these two problems.

MichelleJin12 · 2024-06-06T08:27:45Z

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 · 2024-06-06T11:59:29Z

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 · 2024-06-06T13:16:20Z

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 · 2024-06-09T22:26:29Z

 	__print_time_unit(delta_nsec, false);
 }

+void print_timestamp_unit(uint64_t timestamp)


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.

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: namhyung#1898 Signed-off-by: Hanyu Cui <ambition0316@126.com>

junyeong0619 · 2026-03-11T02:51:50Z

Hi @namhyung, it seems like this PR has been quiet for a while. I'm interested in this issue — would it be okay if I take over or submit a new PR based on this work? Or is there anything remaining that needs to be addressed in this PR?

namhyung · 2026-03-11T04:46:39Z

Sorry, I haven't take a look at this for a while. @Cosh-y may have updated the code after the final review. Let me check the code first.

namhyung

Sorry for the super late review. I think it's mostly good but I left a couple of small suggestions. Please update your change and rebase it to the current master.

namhyung · 2026-03-11T05:05:22Z

 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");


Can you please move these after STDV so that they can be aligned with the field order?

namhyung · 2026-03-11T05:06:17Z

+	REPORT_F_TOTAL_TIME_MIN_TS,
+	REPORT_F_TOTAL_TIME_MAX_TS,
+	REPORT_F_SELF_TIME_MIN_TS,
+	REPORT_F_SELF_TIME_MAX_TS,


I think we can remove 'TIME' part here like REPORT_F_TOTAL_MIN_TS.

namhyung · 2026-03-11T05:06:47Z

 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");


These also should be moved after STDV.

namhyung · 2026-03-11T05:08:21Z

@@ -917,8 +907,6 @@ 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_UINT_DIFF(REPORT_F_CALL, call, call, call, "Calls");
 FIELD_UINT_DIFF(REPORT_F_SIZE, size, size, size, "Size");


We need to think about what to do with diff. I guess we can just ignore them or show warning if one of timestamp fields is selected. But this could be a separate change.

namhyung · 2026-03-11T05:11:43Z

Also, please feel free to ping me if I haven't replied to a PR for more than 2 weeks.

junyeong0619 · 2026-03-11T05:58:49Z

If @Cosh-y is no longer able to continue, would it be okay if I take over and address the review comments?

Cosh-y · 2026-03-11T07:31:39Z

If @Cosh-y is no longer able to continue, would it be okay if I take over and address the review comments?

Sorry for the large gap, I'm happy if you can finish my work. @junyeong0619

namhyung · 2026-03-11T07:41:47Z

Great, then we can add sort support and handle diff in separate commits.

junyeong0619 · 2026-03-11T09:10:06Z

Great, then we can add sort support and handle diff in separate commits.

Before I open a new PR, I have a couple of questions:

Should I create a separate issue for sort and diff support, or should they be tracked under Support max/min timestamp in report output #1898?
Is it okay to open a new PR based on this work?

namhyung · 2026-03-11T15:36:03Z

I think you need to create a new PR to push changes. I suggest you to take over @Cosh-y's work with minimal changes and keep the original author. Then you can work on the additional changes in a separate PR. And please consider adding test codes.

Copilot

Pull request overview

Adds support for reporting entry timestamps associated with min/max total/self time cases, per issue #1898, so users can correlate slow/fast calls with when they occurred in the trace.

Changes:

Extend struct report_time_stat to track min_ts/max_ts alongside min/max durations.
Compute and store entry timestamps during report_update_node() updates, and expose them as new report output fields (total-min-ts, total-max-ts, self-min-ts, self-max-ts).
Add formatting support for timestamps in CLI output (print_timestamp) and extend TUI report columns accordingly.

Reviewed changes

Copilot reviewed 7 out of 7 changed files in this pull request and generated 3 comments.

Show a summary per file

File	Description
utils/utils.h	Exposes `print_timestamp()` for shared timestamp formatting.
utils/debug.c	Implements `print_timestamp()` for CLI-style output.
utils/report.h	Extends `report_time_stat` to store min/max entry timestamps.
utils/report.c	Records timestamps in stats and adds new report fields for display.
utils/field.h	Adds new `REPORT_F_*_TS` display field IDs.
cmds/tui.c	Adds new TUI report columns and per-column timestamp printing.
cmds/replay.c	Renames local timestamp printer to avoid symbol conflict and reuses `print_timestamp()`.

Comments suppressed due to low confidence (1)

cmds/tui.c:212

NUM_REPORT_FIELD was increased to 16, but report_sort_key[] still has only 12 entries. The loops that index report_sort_key[i] up to NUM_REPORT_FIELD (e.g., building selected_report_sort_key) will read past the end of the array, leading to invalid pointers/UB when sorting in the TUI. report_sort_key needs to be extended to 16 entries (and ideally add corresponding sort keys in report.c for the new timestamp columns, or use a safe placeholder like OPT_SORT_KEYS/NULL for columns that can’t be sorted).

#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 MIN TS", "TOTAL MAX TS", "SELF MIN TS", "SELF MAX TS",
};

static const char *field_help[] = {
	"DOWN/UP ARROW Move down/up",
	"j/k           Move down/up",
	"Enter         Apply checked fields",
	"SPACE         Check or uncheck a field",
	"f/q           Close the window without any changes",
};

enum tui_mode {
	TUI_MODE_GRAPH,
	TUI_MODE_REPORT,
	TUI_MODE_OTHER,
};

static char *report_sort_key[] = {
	OPT_SORT_KEYS, "total_avg", "total_min", "total_max", "self",	    "self_avg",
	"self_min",    "self_max",  "call",	 "size",      "total_stdv", "self_stdv",
};

static char *selected_report_sort_key[NUM_REPORT_FIELD];

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

You can also share your feedback on Copilot code review. Take the survey.

Copilot · 2026-03-11T19:52:25Z


 	total_time = fstack->total_time;
 	self_time = fstack->total_time - fstack->child_time;
+	timestamp = task->rstack->time - total_time;


report_update_node() now derives the entry timestamp from task->rstack->time, but this function is also used by the UNIT_TESTs in this file with a synthetic struct uftrace_task_reader that never initializes task->rstack. That will cause a NULL dereference (and even in non-test callers it can underflow if the chosen timestamp isn’t the matching EXIT time). Consider passing the EXIT timestamp into report_update_node() (or using a consistently-populated field like task->timestamp_last) so the computation doesn’t depend on task->rstack being non-NULL and always uses the correct end time (including the add_remaining_fstack path).

Suggested change

timestamp = task->rstack->time - total_time;

timestamp = task->timestamp_last - total_time;

Copilot · 2026-03-11T19:52:25Z

+	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;
+	}


update_time_stat() updates max_ts only when time_ns is strictly greater than the current max. Since max is implicitly 0 for a freshly zeroed node, the first sample with time_ns == 0 will never set max_ts (and min_ts/max_ts are also never initialized explicitly). To keep timestamps consistent, initialize min_ts/max_ts to a sentinel in init_time_stat() and/or update max_ts on the first observation (e.g., when max_ts is unset), not only on strictly-greater values.

Copilot · 2026-03-11T19:52:25Z

+		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_TIMESTAMP uses printw("%8lu.%09lu", sec, nsec) but sec/nsec are uint64_t. On 32-bit platforms unsigned long is 32-bit, so this is a varargs format/type mismatch (undefined behavior) and can truncate timestamps. Please use the PRIu64 macros (or cast to unsigned long long with %llu) to match uint64_t consistently.

Suggested change

printw("%8lu.%09lu", sec, nsec); \

printw("%8" PRIu64 ".%09" PRIu64, sec, nsec); \

honggyukim · 2026-03-11T19:55:15Z

I haven't looked into the details of this PR yet so this copilot review is just for your reference. You don't have to strictly follow copilot review.

namhyung reviewed May 14, 2024

View reviewed changes

Cosh-y force-pushed the master branch from 79b3f75 to 2cad9d4 Compare June 6, 2024 02:21

namhyung reviewed Jun 9, 2024

View reviewed changes

Cosh-y force-pushed the master branch from 2cad9d4 to 27bee29 Compare June 15, 2024 02:53

namhyung requested changes Mar 11, 2026

View reviewed changes

honggyukim requested a review from Copilot March 11, 2026 19:46

Copilot started reviewing on behalf of honggyukim March 11, 2026 19:47 View session

Copilot AI reviewed Mar 11, 2026

View reviewed changes

junyeong0619 mentioned this pull request Mar 12, 2026

Report: Support max/min timestamp in report output #2032

Merged

namhyung closed this Mar 22, 2026

	timestamp = task->rstack->time - total_time;
	timestamp = task->timestamp_last - total_time;

	printw("%8lu.%09lu", sec, nsec); \
	printw("%8" PRIu64 ".%09" PRIu64, sec, nsec); \

Conversation

Cosh-y commented May 12, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

namhyung left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

MichelleJin12 commented Jun 6, 2024

Uh oh!

Cosh-y commented Jun 6, 2024

Uh oh!

MichelleJin12 commented Jun 6, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

namhyung left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

junyeong0619 commented Mar 11, 2026

Uh oh!

namhyung commented Mar 11, 2026

Uh oh!

namhyung left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

namhyung commented Mar 11, 2026

Uh oh!

junyeong0619 commented Mar 11, 2026

Uh oh!

Cosh-y commented Mar 11, 2026

Uh oh!

namhyung commented Mar 11, 2026

Uh oh!

junyeong0619 commented Mar 11, 2026

Uh oh!

namhyung commented Mar 11, 2026

Uh oh!

Copilot AI left a comment

Choose a reason for hiding this comment

Pull request overview

Reviewed changes

Uh oh!

Copilot AI Mar 11, 2026

Choose a reason for hiding this comment

Uh oh!

Copilot AI Mar 11, 2026

Choose a reason for hiding this comment

Uh oh!

Copilot AI Mar 11, 2026

Choose a reason for hiding this comment

Uh oh!

honggyukim commented Mar 11, 2026

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

6 participants

Cosh-y commented May 12, 2024 •

edited

Loading

MichelleJin12 commented Jun 6, 2024 •

edited

Loading