iovisor / iovisor/bcc

Tracing event pairs in `trace` and `argdist`

Open
#923 1 comment 0 reactions 0 assignees View on GitHub
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

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.