Report: Support max/min timestamp in report output#2032
Conversation
| def __init__(self): | ||
| TestBase.__init__(self, 'ts-report', """ | ||
| foo : OK | ||
| child : OK |
There was a problem hiding this comment.
Can you please use an actual output here? That'd be useful to understand what's going on even if the timestamps are different. I expect the final output would be like above (after processed by the sort function) and you can put it in a comment.
There was a problem hiding this comment.
No, I meant the the comment and the result parts should be exchanged. The result should go to the sort function and to be processed in the same way.
|
Sorry. I'm testing now through force push and clone it on linux environment. When I corrected all of your suggestions I will mention you. Thank you!! |
2a3901a to
cbb8f3d
Compare
|
@namhyung, I’ve addressed all of your suggestions and updated the tests to be more consistent with s-ts-report.c. |
|
I’ve added one more commit to address an issue I found during testing. The out-of-bounds error I previously encountered on my AArch64 Ubuntu (UTM) environment actually only happened in TUI mode. I found that this was caused by the missing sort_key registrations for the newly added timestamp fields. Since NUM_REPORT_FIELD increased, iterating through the fields caused an out-of-bounds read. Interestingly, my WSL environment is also the exact same AArch64 architecture, but it didn't cause a visible crash there, which is why I missed it initially. I remember we agreed to defer the sort and diff features, but I inevitably had to add the missing sort arrays and macros in this patch to prevent the TUI from breaking. Also, regarding the fpatchable-function-entry NG issue, it fails on AArch64 Ubuntu (UTM) but passes perfectly on my AArch64 WSL. This strongly indicates that it's an OS or VM-specific dynamic patching issue, rather than a logic flaw in this PR. Please let me know if this looks good to you! |
| def __init__(self): | ||
| TestBase.__init__(self, 'ts-report', """ | ||
| foo : OK | ||
| child : OK |
There was a problem hiding this comment.
No, I meant the the comment and the result parts should be exchanged. The result should go to the sort function and to be processed in the same way.
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
Fix namhyung#1898
Co-developed-by: Hanyu Cui <ambition0316@126.com>
Signed-off-by: Jun Yeong Kim <junyeonggim5@gmail.com>
To check new report fields: - total-min-ts, total-max-ts - self-min-ts, self-max-ts Added s-ts-report.c as a test binary where foo() and child() are each called twice with different durations. This allows verifying that min-ts and max-ts are recorded from different calls (i.e., they are not the same value). Each test also verifies that all timestamp values are positive for every function in the report output. $ make test TESTARG=report_field_ts Start 1 tests without worker pool Compiler gcc clang Runtime test case pg finstrument-fu fpatchable-fun pg finstrument-fu fpatchable-fun ------------------------: O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os 298 report_field_ts : OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK Signed-off-by: Jun Yeong Kim <junyeonggim5@gmail.com>
As the timestamp fields added. uftrace tui is needed to support it. So like other fields fill arrays and macros. Signed-off-by: Jun Yeong Kim <junyeonggim5@gmail.com>
Thank you so much for the review and the LGTM! I really appreciate your time and the helpful feedback. |
This PR is a continuation of the work started by @Cosh-y in #1925 to address the requirements in issue #1898.
Changes & Updates in this PR:
I have addressed the feedback left in the previous PR (#1925) and added a new test case:
Note on Testing & Environment:
I successfully verified the new test case on an x86_64 WSL environment (Rocky Linux 9.7), where all tests passed perfectly and outputted correct timestamps (e.g., 533.xxx).
However, when testing the exact same code on my MacBook Air AArch64 Ubuntu 24.04 LTS VM (via UTM), I noticed anomalous behaviors: the "fpatchable-fun" method occasionally returned NG, and some timestamps underflowed to a massive number (18446744073.7..., near the 64-bit maximum). Since the logic is proven perfectly stable on x86_64, this strongly indicates an underlying architecture-specific issue with uftrace's dynamic patching and timestamp calculation on AArch64, rather than a flaw in this PR.
Please let me know if there are any further adjustments needed.