vault

The Function Graph Tracer

14 min read

The Function Graph Tracer

The function graph tracer (function_graph) is ftrace’s call-flow visualizer: where the plain function tracer records only that a function was entered, the function-graph tracer hooks both function entry and return, so it can draw an indented call tree and print, on each function’s closing brace, how long that function took in wall-clock microseconds. Hooking the entry is easy — it rides the same __fentry__/mcount call site as the function tracer. Hooking the return is the clever part: at entry it overwrites the function’s return address on the stack with the address of a trampoline (return_to_handler), saving the real return address in a per-task shadow return stack; when the function returns it lands in the trampoline, which times the call, logs the return, and restores the real return address so execution continues. This is the same “hijack the return address” trick used by a kretprobe. Enable it with echo function_graph > current_tracer, and read the famous DURATION | FUNCTION CALLS output from the tracefs trace file.

Mental Model

The function tracer answers “what ran?”; the function graph tracer answers “what called what, and where did the time go?” To do that it needs to observe two events per function — entry and exit — and pair them. Entry is observed exactly like the function tracer: via the compiler-inserted hook at the start of every function. Exit has no such hook (the compiler does not inject anything at ret), so the tracer manufactures one. At entry, it reads the return address sitting on the stack (the address the function will jump back to when it finishes), stashes it in a private per-task stack of its own, and replaces the on-stack return address with the address of a kernel trampoline called return_to_handler. When the traced function executes its ret, it returns not to its real caller but into return_to_handler, which records the return event (and the elapsed time), pops the saved real return address off the shadow stack, and jumps there — so the caller never notices.

flowchart TD
  ENT["Function entry hook fires<br/>(__fentry__ -> ftrace -> trace_graph_entry)"] --> SAVE["function_graph_enter():<br/>push frame onto per-task shadow stack<br/>{ real return addr, func, calltime }"]
  SAVE --> SWAP["overwrite on-stack return address<br/>with &return_to_handler"]
  SWAP --> LOGE["write ENTRY record to ring buffer<br/>(depth, func)"]
  LOGE --> BODY["function body runs<br/>(its own callees do the same -> deeper indent)"]
  BODY --> RET["function executes 'ret' -><br/>lands in return_to_handler trampoline"]
  RET --> POP["ftrace_return_to_handler():<br/>pop shadow frame, rettime = now"]
  POP --> DUR["duration = rettime - calltime"]
  DUR --> LOGR["trace_graph_return(): write RETURN<br/>record (duration) to ring buffer"]
  LOGR --> JMP["jump to the real saved return address<br/>(caller resumes, none the wiser)"]

The entry-and-return mechanism. What it shows: at entry the tracer pushes a frame onto a shadow stack and swaps in a trampoline return address; at the real ret, the trampoline pops the frame, computes the duration, logs it, and forwards to the true caller. The insight to take: the per-function duration is just rettime − calltime, two timestamps captured by the shared infrastructure — but getting the second timestamp requires diverting the return through a trampoline, which is why the function-graph tracer needs a per-task shadow return stack that the plain function tracer does not.

Mechanical Walk-through

The fgraph infrastructure underneath

The entry/return plumbing does not live in the tracer file — it lives in kernel/trace/fgraph.c, a shared piece of infrastructure (“Infrastructure to hook into function calls and returns”, originally by Frédéric Weisbecker, 2008–2009, “mostly borrowed from function tracer” by Steven Rostedt) (fgraph.c). A user of fgraph registers a struct fgraph_ops carrying two callbacks: .entryfunc (called at entry, returns nonzero to request that the return also be traced) and .retfunc (called at return). The function-graph tracer’s instance is funcgraph_ops, whose callbacks are trace_graph_entry() and trace_graph_return() (trace_functions_graph.c). The tracer registers itself in graph_trace_init() via register_ftrace_graph(tr->gops).

The core entry path is function_graph_enter(). It calls ftrace_push_return_trace() to allocate a frame on the per-task shadow stack — the struct ftrace_ret_stack, which stores the saved real return pointer, the function address, the call timestamp, and a frame pointer used for validation — then overwrites the on-stack return address with the trampoline return_to_handler (fgraph.c). The return path is ftrace_return_to_handler(), which pops the frame, calls the registered .retfunc, and returns the real address for the assembly trampoline to jump to. The per-task shadow stack is one page (SHADOW_STACK_SIZE), allocated by ftrace_graph_init_task() for new tasks and alloc_retstack_tasklist() for already-running tasks when tracing is switched on; the idle tasks get per-CPU stacks via ftrace_graph_init_idle_task().

The v6.11 multi-user rework — and what it did not yet do

Uncertain

Verify: the precise kernel versions in this subsection. They were confirmed by a subagent against the GitHub mirror of torvalds/linux (raw file contents per tag + commit-ancestry comparison via the GitHub REST API) because git.kernel.org was behind an anti-bot wall and could not be quoted directly. The commit hashes are upstream hashes and the per-tag ancestry was checked programmatically, but the canonical kernel.org commit pages were not fetched. To resolve: confirm commits 7aa1eaef9f42 / 518d6804a865 are in v6.11 and absent in v6.10, and that commit 4346ba160409 (“fprobe: Rewrite fprobe on function-graph tracer”) is in v6.14 and absent in v6.13, against git.kernel.org once reachable. uncertain

Historically, only one user could attach to the function-graph machinery at a time (older fgraph.c returned -EBUSY from register_ftrace_graph() if something was already attached). In the v6.11 merge window, Steven Rostedt’s 20-patch series “function_graph: Allow multiple users for function graph tracing” reworked fgraph so that up to 16 independent fgraph_ops can be registered simultaneously (cover letter). The mechanism: a global fgraph_array[FGRAPH_ARRAY_SIZE] (with FGRAPH_ARRAY_SIZE = 16) holds the registered ops, each assigned an index in gops->idx; on entry, function_graph_enter() walks the registered ops and, for each whose .entryfunc returns nonzero, sets that ops’ bit in a per-call bitmap word stored on the shadow stack (the comment documents “bits 12–27” as the bitmap of fgraph_array indices). On return, ftrace_return_to_handler() reads that bitmap and invokes only the .retfuncs of the ops that asked to see this function’s return (fgraph.c). This is what makes the shared return machinery multiplexable — several subsystems can hang off the same per-task shadow stack at once.

Crucially, in v6.12 that shared machinery is used by the function-graph tracer (and the BPF function-graph attach path), but fprobe still uses the older rethook shadow stack, not fgraph — kernel/trace/fprobe.c at v6.12 (and still at v6.13) includes linux/rethook.h and calls rethook_alloc()/rethook_hook() ([v6.12 fprobe still rethook; verified by subagent]). The migration of fprobe onto the fgraph return machinery (“fprobe: Rewrite fprobe on function-graph tracer”, Masami Hiramatsu) landed later, in the v6.14 merge window — at v6.14 fprobe.c drops rethook and registers a struct fgraph_ops fprobe_graph_ops via register_ftrace_graph() (v6.14 fprobe.c; patch). So the popular shorthand “function-graph was reworked to share the fprobe/fgraph return machinery” is directionally right but the timeline matters: fgraph became multi-user in v6.11; fprobe started using it in v6.14. On a 6.12 LTS kernel, fgraph is multi-user but fprobe is not yet an fgraph client; on a 6.18-era kernel, fprobe is an fgraph client.

Computing the per-call duration

Each shadow-stack frame records a calltime taken at entry; at return, rettime is taken, and the duration is simply rettime − calltime (trace_functions_graph.c). The timestamps come from trace_clock_local(), a fast, monotonic, per-CPU clock. This duration is inclusive: it counts everything that happened between entry and return, including time spent in callees and — unless you tell it otherwise — time the task spent scheduled out (sleeping/blocked). Two options control what the duration includes:

  • sleep-time (on by default) — when set, the duration includes time the task was scheduled out. Turn it off if you want to see only on-CPU time. (ftrace.rst)
  • graph-time (relevant to the function profiler) — when set, a function’s reported time includes its nested callees; when cleared, only the time the function itself executed (excluding callees) is reported.

This is the most common source of “why is this trivial function showing 8 milliseconds?” — it slept, and sleep-time was on.

Leaf vs nested rendering

The tracer distinguishes a leaf call (entered and returned with nothing traced in between) from a nested call (it called other traced functions before returning). A leaf is printed compactly on one line — func(); with its duration — by print_graph_entry_leaf(). A nested call opens a brace func() { at entry (print_graph_entry_nested()) and closes it with } at return (print_graph_return()), with the body indented by TRACE_GRAPH_INDENT (2 spaces) per level. That brace-matching, indented layout is the function-graph tracer’s signature.

Configuration / Options

Enabling and scoping

cd /sys/kernel/tracing
echo function_graph > current_tracer
cat trace
 
# Scope to a function and everything it calls (function_graph-specific files):
echo schedule > set_graph_function     # trace 'schedule' and its callees only
echo do_idle  > set_graph_notrace      # ...but never descend into do_idle

set_graph_function restricts the tracer to the listed functions and the functions they call — exactly the right granularity for “show me the call tree under this entry point.” set_graph_notrace is the inverse: do not descend into these. These are distinct from the plain set_ftrace_filter/set_ftrace_notrace (which the function-graph tracer also honors), because graph scoping is about subtrees, not individual functions (ftrace.rst).

The funcgraph-* options

The output is heavily configurable via boolean options under options/ (or written to trace_options). The set in v6.12, defined in trace_opts[] (trace_functions_graph.c):

  • funcgraph-cpu — show the CPU number where the trace occurred.
  • funcgraph-overhead — when a function exceeds a threshold, prefix it with a delay marker (see below).
  • funcgraph-overrun — show the shadow-stack “overrun” after each function (how far the call depth exceeded the reserved per-task stack).
  • funcgraph-proc — by default the process command name is shown only at a context switch; enabling this prints the command on every line.
  • funcgraph-abstime — print an absolute timestamp at each line (rather than only durations).
  • funcgraph-duration — print the per-function duration at each return (on by default; this is the DURATION column).
  • funcgraph-irqs — when disabled, functions executing inside an interrupt are not traced.
  • funcgraph-tail — when set, the return line names the function it closes (} /* func */) instead of a bare } — invaluable for matching braces in deep traces. Off by default. (ftrace.rst)
  • funcgraph-retval / funcgraph-retval-hex — print each function’s return value after an = (the hex variant forces hexadecimal). These are config-dependent (require CONFIG_FUNCTION_GRAPH_RETVAL).
echo 1 > options/funcgraph-tail      # name functions on their closing braces
echo 1 > options/funcgraph-abstime   # add an absolute timestamp column
echo 1 > options/funcgraph-proc      # show task name on every line
echo 0 > options/sleep-time          # exclude scheduled-out time from durations

The duration overhead markers

When funcgraph-duration is on, durations over certain thresholds get a single-character flag in the overhead column, so long calls jump out visually (ftrace.rst):

'$' - greater than 1 second
'@' - greater than 100 millisecond
'*' - greater than 10 millisecond
'#' - greater than 1000 microsecond
'!' - greater than 100 microsecond
'+' - greater than 10 microsecond
' ' - less than or equal to 10 microsecond

So a line beginning with ! 234.5 us is a call that took between 100 µs and 1 ms — a quick visual scan of the left margin finds the expensive calls without reading every number.

Reading the output

# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |
 0)               |  sys_open() {
 0)               |    do_sys_open() {
 0)   1.382 us    |      getname() {
 0)   2.478 us    |      }
 0) + 12.853 us   |    }
 0)   0.420 us    |    fput();
 0) ! 134.881 us  |  }

Walking it: column one (0)) is the CPU. The DURATION column is blank on entry lines (the duration is not known until return) and filled on the closing brace with the inclusive time for that function. sys_open() { opened a nested call; getname() { … } is a nested child whose own duration (1.382 us would appear on its }); fput(); with no braces is a leaf (it called nothing traced). The + 12.853 us and ! 134.881 us are durations with overhead markers (+ = >10 µs, ! = >100 µs). The two-space indent per level is the call-depth made visible.

Failure Modes and Common Misunderstandings

  • “A simple function shows milliseconds.” It almost certainly slept. The default sleep-time includes scheduled-out time in the duration. Disable sleep-time to see CPU time only, or recognize that the big number is wait time, not compute time.
  • “Durations look inflated everywhere.” Remember the duration is inclusive of callees. A function whose body is cheap but which calls something expensive will report a large duration. Read the indented children to see where the time actually went — that is the whole point of the call graph.
  • “Braces don’t match in a deep trace / I can’t tell which } closes what.” Turn on funcgraph-tail so each return names its function (} /* sys_open */).
  • Higher overhead than the function tracer. It is doing strictly more work: an entry hook and a return trampoline, two ring-buffer writes per function, two timestamps, and shadow-stack pushes/pops. The shadow stack is also bounded (one page per task), so extremely deep recursion can overrun it — funcgraph-overrun exposes when this happens.
  • Interrupts confuse the indentation. A function entered inside an interrupt that fires mid-call can appear as an unexpected subtree. funcgraph-irqs 0 removes interrupt-context functions from the trace, cleaning up the picture when you only care about the task’s own work.
  • set_ftrace_filter vs set_graph_function confusion. set_ftrace_filter filters individual functions; set_graph_function traces a function and its entire callee subtree. For “show me everything under tcp_sendmsg,” you want set_graph_function, not set_ftrace_filter (which would show only tcp_sendmsg itself and lose the tree).

Alternatives and When to Choose Them

  • function tracer — when you only need “what ran and who called it,” without timing or tree structure. It is cheaper (no return trampoline, no shadow stack, one record per call).
  • perf + flame graphs — when you want aggregate “where does time go” over a long run. The function-graph tracer gives an exact, ordered trace of one execution; a flame graph gives a statistical summary of many. For “is this function hot across the whole workload,” sample with perf; for “trace this one slow request end to end,” use function_graph.
  • kretprobe / fprobe — when you want custom logic and arguments at return (e.g. log the return value only when it is an error code), not a full call tree. fprobe is the modern API and, from v6.14 on, is built on the same fgraph return machinery described above.
  • bpftrace kfunc/kretfunc — when you want to compute latency histograms in-kernel without rendering the full tree. For “distribution of vfs_read durations,” a bpftrace one-liner beats reading thousands of function-graph lines by hand.

Production Notes

The function-graph tracer is the kernel engineer’s go-to for understanding an unfamiliar code path and finding where latency hides inside it. The canonical pattern is: set_graph_function <entry point>, enable function_graph, trigger the path once, disable, and read the indented tree to see both the structure (who calls whom) and the timing (which subtree dominates). Turning off sleep-time is the usual first move when chasing on-CPU latency; turning on funcgraph-tail is the usual first move when the trace is deep. Because every function pays the entry-plus-return cost, this is a targeted tool: always scope it with set_graph_function/set_ftrace_filter and a PID rather than tracing the whole kernel. The trace-cmd front-end (trace-cmd record -p function_graph -g schedule) drives exactly these files and is what most people run in practice; bpftrace is the better choice once you want aggregation rather than a literal call tree.

See Also

Graph View

Backlinks