replay: Show callsite location with --srcline#2047
Conversation
|
Thanks for working on this! A few comments before looking at the code. I feel like requiring For memcpy, there's Regarding the precision of the location, I think it's out of scope. We can just show whatever compiler generated for the code and don't care about the value itself (unless it's definitely wrong). Please don't change the test code or settings just to pass the test, it'd be better to leave it failing so that we can be aware of the issue - or we can check whether it generates any callsite info. |
|
Thanks for the review!
Will push the updates along these lines. |
06c462b to
8fceea8
Compare
|
Pushed the revisions. Now we can use for 4 versions. Usage: $ uftrace record -T 'a@callsite' tests/t-abc
$ uftrace replay
# DURATION TID FUNCTION
0.714 us [ 189072] | __monstartup();
12.921 us [ 189072] | __cxa_atexit();
[ 189072] | main() {
[ 189072] | a() { /* from s-abc.c:33 */
[ 189072] | b() {
[ 189072] | c() {
0.390 us [ 189072] | getpid();
0.989 us [ 189072] | } /* c */
1.357 us [ 189072] | } /* b */
1.905 us [ 189072] | } /* a */
2.186 us [ 189072] | } /* main */
$ uftrace replay --srcline
# DURATION TID FUNCTION [SOURCE]
0.714 us [ 189072] | __monstartup();
12.921 us [ 189072] | __cxa_atexit();
[ 189072] | main() { /* s-abc.c:26 */
[ 189072] | a() { /* s-abc.c:11 from s-abc.c:33 */
[ 189072] | b() { /* s-abc.c:16 */
[ 189072] | c() { /* s-abc.c:21 */
0.390 us [ 189072] | getpid();
0.989 us [ 189072] | } /* c */
1.357 us [ 189072] | } /* b */
1.905 us [ 189072] | } /* a */
2.186 us [ 189072] | } /* main */
$ uftrace replay --no-callsite
# DURATION TID FUNCTION
0.714 us [ 189072] | __monstartup();
12.921 us [ 189072] | __cxa_atexit();
[ 189072] | main() {
[ 189072] | a() {
[ 189072] | b() {
[ 189072] | c() {
0.390 us [ 189072] | getpid();
0.989 us [ 189072] | } /* c */
1.357 us [ 189072] | } /* b */
1.905 us [ 189072] | } /* a */
2.186 us [ 189072] | } /* main */
$ uftrace replay --srcline --no-callsite
# DURATION TID FUNCTION [SOURCE]
0.714 us [ 189072] | __monstartup();
12.921 us [ 189072] | __cxa_atexit();
[ 189072] | main() { /* s-abc.c:26 */
[ 189072] | a() { /* s-abc.c:11 */
[ 189072] | b() { /* s-abc.c:16 */
[ 189072] | c() { /* s-abc.c:21 */
0.390 us [ 189072] | getpid();
0.989 us [ 189072] | } /* c */
1.357 us [ 189072] | } /* b */
1.905 us [ 189072] | } /* a */
2.186 us [ 189072] | } /* main */Also Treated the write with mcount_memcpy1(). |
8fceea8 to
535551f
Compare
|
Rewrite the commit message for the changes. |
namhyung
left a comment
There was a problem hiding this comment.
I have some concerns if it would
- work well with other events and arguments. (I'm a bit worried about the timestamp management now)
- print "function+offset" when DWARF is not available.
Also please pick a single prefix in the commit subject line. More general and/or important one would be preferred. Maybe you want to split the commit otherwise.
|
Here is full dump and replay output. root@server:~/uftrace# uftrace record -W var:mydata -T 'bar@callsite' -T 'foo@callsite' t-watch
root@server:~/uftrace# uftrace dump | head -50
uftrace file header: magic = 4674726163652100
uftrace file header: version = 4
uftrace file header: header size = 40
uftrace file header: endian = 1 (little)
uftrace file header: class = 2 (64 bit)
uftrace file header: features = 0x1763 (PLTHOOK | TASK_SESSION | SYM_REL_ADDR | MAX_STACK | PERF_EVENT | AUTO_ARGS | DEBUG_INFO | SYM_SIZE)
uftrace file header: info = 0xfbff (EXE_NAME | EXE_BUILD_ID | EXIT_STATUS | CMDLINE | CPUINFO | MEMINFO | OSINFO | TASKINFO | USAGEINFO | LOADINFO | RECORD_DATE | PATTERN_TYPE | VERSION | UTC_OFFSET | SYSCTL)
reading 1355229.dat
646618.687034679 1355229: [entry] __monstartup(62efea147090) depth: 0
646618.687036364 1355229: [exit ] __monstartup(62efea147090) depth: 0
646618.687037419 1355229: [entry] __cxa_atexit(62efea1470a0) depth: 0
646618.687037792 1355229: [exit ] __cxa_atexit(62efea1470a0) depth: 0
646618.687038474 1355229: [entry] main(62efea147269) depth: 0
646618.687038640 1355229: [event] trigger:callsite(186ad) depth: 0
646618.687038640 1355229: [data ] length = 8
trigger:callsite: callsite=0x62efea14729d
646618.687038641 1355229: [entry] foo(62efea147233) depth: 1
646618.687038895 1355229: [event] trigger:callsite(186ad) depth: 0
646618.687038895 1355229: [data ] length = 8
trigger:callsite: callsite=0x62efea14724a
646618.687038895 1355229: [event] watch:var(186ac) depth: 0
646618.687038895 1355229: [data ] length = 12
watch:var: mydata=1
646618.687038896 1355229: [entry] bar(62efea14720b) depth: 2
646618.687040199 1355229: [exit ] bar(62efea14720b) depth: 2
646618.687041376 1355229: [event] watch:var(186ac) depth: 0
646618.687041376 1355229: [data ] length = 12
watch:var: mydata=2
646618.687041377 1355229: [exit ] foo(62efea147233) depth: 1
646618.687041612 1355229: [exit ] main(62efea147269) depth: 0
reading perf-cpu4.dat
646618.675870741 1355229: [event] linux:task-name(200006)
646618.685026396 1355229: [event] linux:sched-out (pre-empted)(200007)
646618.685077278 1355229: [event] linux:sched-in(200001)
646618.687172426 1355229: [event] linux:task-exit(200005)
root@server:~/uftrace# uftrace replay
# DURATION TID FUNCTION
1.685 us [1355229] | __monstartup();
0.373 us [1355229] | __cxa_atexit();
[1355229] | main() {
[1355229] | foo() { /* from tests/s-watch-global.c:26 */
[1355229] | /* watch:var (mydata=1) */
1.303 us [1355229] | bar(); /* from tests/s-watch-global.c:15 */
[1355229] | /* watch:var (mydata=2) */
2.736 us [1355229] | } /* foo */
3.138 us [1355229] | } /* main */ |
|
Followed up with a deliberate-collision case using watch:var on a global variable changed inside the traced functions (tests/s-watch-global.c): $ uftrace record -W var:mydata -T 'foo@callsite' -T 'bar@callsite' t-watch
$ uftrace dump | head -40
646618.687038895 [event] trigger:callsite # entry-1 for bar
646618.687038895 [event] watch:var (mydata=1) # same nanosecond
646618.687038896 [entry] barTwo events do share a timestamp here. The ordering is still deterministic: The resulting replay output keeps both visible without any mixing: $ uftrace replay
[1355229] | main() {
[1355229] | foo() { /* from tests/s-watch-global.c:26 /
[1355229] | / watch:var (mydata=1) /
1.303 us [1355229] | bar(); / from tests/s-watch-global.c:15 /
[1355229] | / watch:var (mydata=2) /
2.736 us [1355229] | } / foo /
3.138 us [1355229] | } / main */ |
535551f to
9afd1c5
Compare
|
Also treated the case that Dwarf is not available. root@server:~/uftrace# uftrace record -T 'a@callsite' tests/t-abc-nodbg (t-abc with no -g)
root@server:~/uftrace# uftrace replay
# DURATION TID FUNCTION
0.632 us [1360511] | __monstartup();
0.282 us [1360511] | __cxa_atexit();
[1360511] | main() {
[1360511] | a() { /* from main+0x41 */
[1360511] | b() {
[1360511] | c() {
0.265 us [1360511] | getpid();
0.801 us [1360511] | } /* c */
1.066 us [1360511] | } /* b */
1.477 us [1360511] | } /* a */
1.747 us [1360511] | } /* main */ |
|
Thanks, I've check it with other options and it has some side effects. And if they are used together, it doesn't work well. So it lost the diff:pmu-cycle event. Removing the argument ( |
| xasprintf(&evt_name, "watch:var"); | ||
| break; | ||
| case EVENT_ID_CALLSITE: | ||
| xasprintf(&evt_name, "trigger:callsite"); |
There was a problem hiding this comment.
Let's show it as just "callsite".
There was a problem hiding this comment.
Changed it to callsite.
| * @callsite trigger), unless the user opted out | ||
| */ | ||
| needs_dbg = opts->srcline || (opts->loc_filter != NULL); | ||
| if (!opts->no_callsite && (handle->hdr.feat_mask & DEBUG_INFO)) |
There was a problem hiding this comment.
The location filter check is new. Also I think checking DEBUG_INFO is not enough and you need to add a new CALLSITE feature bit. Loading dwarf file should depend on the CALLSITE flag.
Also opts->no_callsite doesn't exist at this point which means it'd break the build and bisect.
There was a problem hiding this comment.
Added a CALLSITE feature bit (dwarf auto-load now depends on it), reverted the accidental loc_filter check in read_task_file(), and verified the entire series bisects cleanly.
| * match the trailing path against existing entries so callsite filenames | ||
| * stay consistent with the --srcline output | ||
| */ | ||
| static struct uftrace_dbg_file *find_or_get_debug_file(struct uftrace_dbg_info *dinfo, |
There was a problem hiding this comment.
Maybe rename to get_debug_file_suffix()?
There was a problem hiding this comment.
Renamed it to get_debug_file_suffix.
|
|
||
| /* | ||
| * PC-precise variant of task_find_loc_addr() — returns the source line | ||
| * at the instruction, not the enclosing function's entry |
There was a problem hiding this comment.
It returns a boolean. Also you need to mention that it uses DWARF directly.
There was a problem hiding this comment.
Updated the comment to mention DWARF usage and the bool return.
| if (task_find_exact_loc_addr(sessions, task, rstack->time, | ||
| task->callsite_ip, &csloc)) { | ||
| snprintf(cs_buf, sizeof(cs_buf), "%s:%d", csloc.file->name, | ||
| csloc.line); |
There was a problem hiding this comment.
You need to make sure it has NUL character at the end.
There was a problem hiding this comment.
Added explicit cs_buf[sizeof(cs_buf) - 1] = '\0' after the snprintf (and same in the function+offset helper).
| snprintf(cs_buf, sizeof(cs_buf), "%s+%#lx", | ||
| cs_sym->name, | ||
| (unsigned long)(mod_addr - | ||
| cs_sym->addr)); |
There was a problem hiding this comment.
Doesn't look pretty. Can we reduce the indention level or factor it out as a function?
There was a problem hiding this comment.
Extracted into a format_callsite_symbol() helper.
| bool list_event; | ||
| bool event_skip_out; | ||
| bool no_event; | ||
| bool no_callsite; |
There was a problem hiding this comment.
Personally, I'd like to keep the options as positive even if the option name itself is negative. For example, I think it's natural to check if (opts->callsite) rather than if (!opts->no_callsite).
I don't plan to change the existing ones, but I want new ones in positive form.
There was a problem hiding this comment.
Treated it as positive.
| return TestBase.build(self, name, cflags, ldflags) | ||
|
|
||
| def setup(self): | ||
| self.option = '-T a@callsite -T b@callsite -T c@callsite' |
There was a problem hiding this comment.
Couldn't it be -T '^.$@callsite'?
There was a problem hiding this comment.
Done. Tests still pass.
| # strip directory prefix from filenames in comments | ||
| rest = re.sub(r'/[\w./-]+/(\S+\.c)', r'\1', rest) | ||
| # normalize source line numbers | ||
| rest = re.sub(r'(\.c):\d+', r'\1:N', rest) |
There was a problem hiding this comment.
Maybe you can just combine two lines as re.sub(r'/[\w./-]+/(\S+\.c):\d+', r'\1:N', rest).
9afd1c5 to
1b715ec
Compare
namhyung
left a comment
There was a problem hiding this comment.
Thanks for the update, I think it's almost there. Please make sure to rebase your changes on to the latest commit whenever you push them.
| The call site display can be suppressed with `--no-callsite` at replay | ||
| time. The reported line itself comes from the compiler's dwarf line | ||
| program and is shown as-is. | ||
|
|
There was a problem hiding this comment.
Please add this to uftrace live man page too.
| read_task_txt_file(sessions, opts->dirname, opts->with_syms ?: opts->dirname, | ||
| true, sym_rel, | ||
| opts->srcline | (opts->loc_filter != NULL)) < 0) { | ||
| opts->srcline | (opts->loc_filter != NULL) | callsite_dbg) < |
There was a problem hiding this comment.
I think it's better to split callsite and srcline/loc-filter as the latter only requires the dbg file. You may introduce a local variable for srcline/loc-filter like needs_srcline. That means you need to pass it to load_debug_info() through create_session().
There was a problem hiding this comment.
For this to reach load_debug_info(), create_session() would need to take both flags:
create_session(sess, &smsg, dirname, symdir, exename, sym_rel_addr,
needs_symtab, needs_srcline, needs_callsite_dbg);Does that look right?
| * program at replay time. finish_debug_info() releases it. | ||
| */ | ||
| if (needs_srcline && dinfo->dw == NULL) | ||
| setup_dwarf_info(map->libname, dinfo, map->start, true); |
There was a problem hiding this comment.
I think this part should belong to the next commit. Also I don't think it's using callsite info precisely.
There was a problem hiding this comment.
To make this precise, would you prefer introducing a separate flag like needs_callsite_dbg?
For example:
if (needs_callsite_dbg && dinfo->dw == NULL)
setup_dwarf_info(map->libname, dinfo, map->start, true);There was a problem hiding this comment.
Yes, something like needs_callsite.
There was a problem hiding this comment.
Thanks for the quick review. I will change the check line in that way.
1b715ec to
c4e3e83
Compare
|
Rebased onto master. If there is something wrong let me know. Thanks. |
| 0 && | ||
| read_task_file(&link, fha->opts->dirname, false, false, false) < 0) | ||
| if (read_task_txt_file(&link, fha->opts->dirname, fha->opts->dirname, false, false, false, | ||
| false) < 0 && |
There was a problem hiding this comment.
Whitespace is up to clang-format, so I shortened the line by introducing
char *dir = fha->opts->dirname;. Under 100 columns, clang-format leaves it alone.
| read_task_txt_file(sessions, opts->dirname, opts->with_syms ?: opts->dirname, | ||
| true, sym_rel, | ||
| opts->srcline | (opts->loc_filter != NULL)) < 0) { | ||
| true, sym_rel, opts->srcline | (opts->loc_filter != NULL), |
There was a problem hiding this comment.
Similarly, let's introduce needs_srcline variable.
There was a problem hiding this comment.
Done — introduced needs_srcline = opts->srcline | (opts->loc_filter != NULL).
| if (!debug_info_has_location(dinfo) && !debug_info_has_argspec(dinfo)) { | ||
| load_debug_file(dinfo, stab, sinfo->symdir, map->libname, map->build_id, | ||
| needs_srcline); | ||
| needs_srcline || needs_callsite); |
| if (!debug_info_has_location(dinfo) && !debug_info_has_argspec(dinfo)) { | ||
| load_debug_file(dinfo, &mod->symtab, dirname, mod->name, mod->build_id, | ||
| needs_srcline); | ||
| needs_srcline || needs_callsite); |
There was a problem hiding this comment.
I don't think this is necessary as callsite doesn't use the debug (.dbg) file.
There was a problem hiding this comment.
Right, callsite doesn't read the .dbg file. Dropped needs_callsite from load_debug_file() in both load_debug_info() and load_module_debug_info().
Add the `callsite` trigger action which makes uftrace remember the return address of a matched function call. At record time it just sets a flag (TRIGGER_FL_CALLSITE); the actual address is captured later by libmcount. A new event id (EVENT_ID_CALLSITE) is reserved to carry the return address inside the trace data. This commit only wires up the option plumbing; the recording side and the replay-side display are added in subsequent commits. Signed-off-by: Jun Yeong Kim <junyeonggim5@gmail.com>
When the @callsite trigger fires at function entry, libmcount emits an EVENT_ID_CALLSITE record whose payload is the caller's return address (rstack->parent_ip). The event is timestamped one nanosecond before the entry record so it always precedes the matching ENTRY in the trace. The @callsite trigger also implicitly turns on debug info saving at record time and a new CALLSITE feature bit is set on the file header so the replay side can later resolve the recorded address to a source line without requiring --srcline. The replay-side reader decodes the 8-byte payload into task->args so existing event consumers (dump, replay, ...) can find it. event.c gains "callsite" naming and "callsite=0xADDR" formatting for the raw dump output. Signed-off-by: Jun Yeong Kim <junyeonggim5@gmail.com>
task_find_loc_addr() returns the symbol's entry line stored in dinfo->locs[], which is fine for a function definition but loses the precision needed for a call site. Add task_find_exact_loc_addr() which goes through libdw directly: dwarf_addrdie() + dwarf_getsrc_die() against the function's module-relative address. This drills into the dwarf line program so a PC anywhere inside a function resolves to the matching source line. To make this work at replay time, load_debug_info() now also opens the libdw handle per module (kept until finish_debug_info()). The shared session/map lookup is factored into task_find_addr_module() used by both helpers. Signed-off-by: Jun Yeong Kim <junyeonggim5@gmail.com>
When the trace contains an EVENT_ID_CALLSITE record, intercept it in
the UFTRACE_EVENT branch, stash the return address on the task, and
suppress the default event-as-comment output.
The next ENTRY consumes that address: replay resolves it to file:line
via task_find_exact_loc_addr() and appends it to the source comment.
The call site is shown by default and can be turned off with the new
--no-callsite option. When --srcline is also given, both the callee
definition line and the call site are shown.
When dwarf info is unavailable (e.g. when the binary is built without
-g), replay falls back to a "function+offset" form so the call site is
still informative. The fallback path is factored into a small helper
format_callsite_symbol() to keep the caller flat.
open_data_file() also loads debug info automatically when the trace
carries the CALLSITE feature bit (unless --no-callsite is given), so
the call site is resolved without having to pass --srcline.
Simple usage:
$ uftrace record -T 'a@callsite' t-abc
$ uftrace replay
# DURATION TID FUNCTION
[3615820] | main() {
[3615820] | a() { /* from s-abc.c:33 */
[3615820] | b() {
[3615820] | c() {
...
$ uftrace replay --srcline
# DURATION TID FUNCTION [SOURCE]
[3615820] | main() { /* s-abc.c:26 */
[3615820] | a() { /* s-abc.c:11 from s-abc.c:33 */
...
$ uftrace replay --no-callsite
# DURATION TID FUNCTION
[3615820] | main() {
[3615820] | a() {
...
$ uftrace replay # binary built without -g
[3615820] | a() { /* from main+0x41 */
...
When the call site cannot be resolved at all (e.g. coming from libc)
the suffix is silently dropped.
closes namhyung#2027
Signed-off-by: Jun Yeong Kim <junyeonggim5@gmail.com>
t305 records s-abc with -T '^.$@callsite' and verifies that the replay output contains a "from <file>:<line>" suffix for each function. The expected output normalizes line numbers and strips directory prefixes (in sort()) so the test stays stable across optimization levels and build environments — the exact line reported by the compiler's dwarf line program is not asserted, only the presence of the callsite info itself. The default --no-event option is dropped via a runcmd() override so the EVENT_ID_CALLSITE records reach replay (same pattern as the existing read-trigger tests). The test is skipped when dwarf info is unavailable. Signed-off-by: Jun Yeong Kim <junyeonggim5@gmail.com>
Add `callsite` to the trigger action BNF in uftrace-record.md and uftrace-live.md and describe the new behaviour with examples showing the "from file:N" suffix in the default replay output and the combined "file:N from file:N" output under --srcline. uftrace-replay.md gains a new entry for --no-callsite that explains how to suppress the call site display, and clarifies that --srcline only controls the callee definition line. Signed-off-by: Jun Yeong Kim <junyeonggim5@gmail.com>
c4e3e83 to
d28e9f5
Compare
namhyung
left a comment
There was a problem hiding this comment.
LGTM! I'm curious when you sleep.. take care. :)
|
Haha, just happened to wake up and couldn't help picking it up :) Thanks for the kind words — and for the thorough reviews! |
closes #2027
I've added the
callsitetrigger action proposed in the issue.Setting
-T <func>@callsiterecords the return address of the matchedcall, and
uftrace replay --srclineshows it after the existing sourceline, e.g.
a() { /* file.c:11 from file.c:33 */.Changes:
TRIGGER_FL_CALLSITE/EVENT_ID_CALLSITEand thecallsitetrigger action parser.
before the matching ENTRY when the trigger fires.
task_find_exact_loc_addr()that uses libdw'sdwarf_addrdie()+dwarf_getsrc_die()for PC-precise line lookup(the existing
task_find_loc_addr()only knows the symbol's entryline).
load_debug_info()now keeps libdw open at replay time sothis lookup works there.
task, and appends
from file:lineto the source comment on thenext ENTRY.
--srclinepaths.doc/uftrace-record.mdwith an exampleand a short note about line precision under optimization.
Testing on Rocky Linux 9.7 (GCC 11.5, x86_64):
One thing I'd like your feedback on:
save_callsite_event()writes the 8-byte payload with a direct*(uint64_t *)event->data = ...rather than the existingmcount_memcpy4(). Using the memcpy helper here recorded zero on mysetup. My guess is strict aliasing —
mcount_memcpy4reinterprets thesource as
unsigned int *, and the 8-byte return address write throughthat path gets optimized away. The direct write goes through the
uint8_t event->data[]member, which is well-defined. I'm happy to addan
mcount_memcpy8helper (or updatemcount_memcpy4to use byte-wiseloads) if you prefer either of those.
Also a precision note (also in the doc): the resolved call site line
depends on the dwarf line program.
-O0/-Ogbuilds report theexact line; with
-O1or higher the call instruction can be foldedwith surrounding code so the reported line may shift by 1–2 lines.
-finstrument-functionsbuilds are stable across optimization levels.t305 forces
-O0in cflags for this reason.Please let me know if you'd like changes to the approach or naming.
Thanks!