Tracing event pairs in `trace` and `argdist`
- Dominant language
- C
- Stars
- 22.7k
- Forks
- 4.1k
- Avg merge
- 10d 4h
- Merged PRs (30d)
- 3
Description
When working with USDT tracepoints specifically, but sometimes also with other types of probes, it is desirable to trace a pair of events, typically start/stop, to identify latency. For example, to identify a slow garbage collection in a Node app, I'd want to trace `u:node:gc__begin` and `u:node:gc__end`, find the latency (probably based on thread id emitting the probe), and incorporate that in a report.
I'm thinking of a good, generic way to represent this for both `trace` and `argdist`. Currently, `argdist` has something that works for method calls -- if you place a retprobe and use the special `$latency` keyword, the tool will emit both an entry probe and a return probe and calculate the latency for you. But here I'm looking for something that would look for disparate event pairs, not necessarily an entry and return from a single method. It would be even nicer if the correlation could be by an arbitrary parameter (say, u64) and not always the thread id. For example, we could use this to determine an allocated block's lifetime from `malloc` to `free`, or a socket connection's lifetime, and so on.
Here are some syntax ideas I had, but I'd appreciate other thoughts and ideas. @brendangregg @4ast
Tracing an event pair, correlated by thread id or by process id:
```
# Both probes can have a trace statement, but only the second can use $latency
trace -p $(pidof node) --pair 'u:node:gc__begin' 'u:node:gc__end "GC done, took %lldns", $latency'
# Only the second probe can have a trace statement, but syntax is cleaner
trace -p $(pidof node) 'u:node:gc__{begin,end} "GC done, took %lldns", $latency'
# Both probes can have a trace statement
trace -p $(pidof node) --from 'u:node:gc__begin "GC starting"' --to 'u:node:gc__end "GC done, took %lldns", $latency'
# Correlating by something other than pid/tid
trace -p $(pidof node) --from 'r:c:malloc//retval' --to 'p:c:free//arg1 "alloc lifetime: %lld", $latency'
```
Argument summary for an event pair that includes latency:
```
argdist -p $(pidof node) --histpair 'u:node:gc__begin()' 'u:node:gc__end():u64:$latency/1000'
argdist -p $(pidof mysqld) --histpair 'u:mysqld:query__{start,end}():u64:$latency'
```
Yet another option is that we simply don't do any of it, and build a custom tool for whenever something like this is desired. It's just that I'm seeing this more and more often when I work with tracepoints (both kernel and USDT).
Contributor guide
No contributing guide indexed for this repository
Research direction
Start at the `trace` and `argdist` entry points, and compare `argdist`'s existing retprobe and `$latency` behavior with the proposed disparate-event pairs. Define whether correlation uses thread or process IDs or arbitrary parameters, and what syntax and output should mark the feature complete.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- c
- Domain
- observability
- Issue type
- Feature
- Difficulty
- 5/5
- Estimated time
- Over a week
- Activity status
- Stale
- Clarity
- Needs clarification
- Newbie friendliness
- 20/100