Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Support max/min timestamp in report output #1898

Open
namhyung opened this issue Mar 3, 2024 · 8 comments
Open

Support max/min timestamp in report output #1898

namhyung opened this issue Mar 3, 2024 · 8 comments

Comments

@namhyung
Copy link
Owner

namhyung commented Mar 3, 2024

I think it's useful to provide timestamp information in the report so that users can replay at the given time later. For example, when some function is called a lot, it runs mostly very short but sometimes it takes long. Then users want to see where it is, and what happened during the call. So I suggest 4 more output fields - total-max-ts, total-min-ts, self-max-ts, and self-min-ts. They will have a timestamp of function ENTRY for the cases respectively.

struct uftrace_report_node has struct report_time_stat for total and self time already. So it's easier to extend it to save timestamp.

@honggyukim
Copy link
Collaborator

That looks a good idea.

So I suggest 4 more output fields - total-max-ts, total-min-ts, self-max-ts, and self-min-ts.

But I worry adding many fields as each result of report -f all will be too long to fit into a single line. We might have to consider if -f all should show the entire field if we want to add many more fields.

@namhyung
Copy link
Owner Author

namhyung commented Mar 4, 2024

Right, but I think -f all is too long already and it's not encouraged to use that. But it shouldn't mean to prevent adding new fields. I think something like -f +total-max-ts is more useful and using uftrace tui would be the best as it can change the fields dynamically (with f key).

@honggyukim
Copy link
Collaborator

Yeah, the current -f all is already long. How about making -f accept pattern matching for simplicity?

@namhyung
Copy link
Owner Author

namhyung commented Mar 5, 2024

Sounds good.

@Cosh-y
Copy link

Cosh-y commented Apr 10, 2024

Hello @namhyung @honggyukim,

I am an undergraduate student from Beihang University in Beijing, China, currently enrolled in a course focused on open source projects. I believe you both are welcoming to newcomers like me. I appreciate that you've labeled the issue with the "good-first-issue" tag and provided helpful guidance. I'm thankful for that and eager to contribute.

I'd like to start by working on the four additional fields for the report. Given the existing codebase, I believe this task should be manageable.

Additionally, the "too long for display" issue seems interesting and practical. I am also interested in implementing the pattern matching function.

Could I please have the opportunity to contribute to such an excellent project? I would be grateful for the chance to participate.

Thank you.

@namhyung
Copy link
Owner Author

Hello @Cosh-y! We always welcome new contributors. :)

Please read the CONTRIBUTING.md carefully and try to follow the existing convention in the commit history. I'm looking forward to seeing your PR soon!

@Cosh-y
Copy link

Cosh-y commented May 11, 2024

Hello @namhyung ,

I have learned your code and similar work #1913. I learned how to add new fields in report output, but I still have a question before coding.

How can I get the correct timestamp? I have noticed that in cmds/report.c build_function_tree passes task and tampstamp into find_insert_node, and uftrace_report_node is finally updated in insert_node. So which timestamp should I use?

  • four timestamp fields in struct uftrace_task_reader *task
  • arg timestamp of find_insert_node
  • other

I found it's difficult for me to figure out the exactly meaning of these variables. Should I read more codes and learn about how uftrace collects these data or would you give me some hints so that I can do the remaining work?

Thanks For Your Help!

@namhyung
Copy link
Owner Author

The uftrace_task_reader->rstack->time is same as timestamp in the find_insert_node(). But it's a timestamp at the exit and you need to get the start time. I think you should subtract fstack->total_time from the (end) timestamp to get the start timestamp.

Cosh-y added a commit to Cosh-y/uftrace that referenced this issue May 12, 2024
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: namhyung#1898

Signed-off-by: Hanyu Cui <ambition0316@126.com>
Cosh-y added a commit to Cosh-y/uftrace that referenced this issue May 12, 2024
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: namhyung#1898

Signed-off-by: Hanyu Cui <ambition0316@126.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

3 participants