UFTRACE-GRAPH(1)

πŸ‘‘ uftrace-graph (from the General Commands Manual) πŸ’…

okay bestie, buckle up, this one is a long one but it's so worth it ✨


🌸 NAME 🌸

uftrace-graph β€” show function call graph πŸ¦‹


✨ SYNOPSIS ✨

uftrace graph [options] [FUNCTION]

πŸ’– DESCRIPTION πŸ’–

So this command? It shows you a function call graph ✨ for either the whole binary or for a specific function you name, using a uftrace record datafile. iykyk.

If you don't give it a function name, it literally shows the whole function call graph. No filter, no cap. If you do hand it a function name, it shows you the backtrace and the calling functions for that one. Obsessed honestly.

Every single function in the output gets annotated with a hit count and the total time spent running that function. Periodt. πŸ’…


🌈 GRAPH OPTIONS 🌈

  • -f FIELD, --output-fields=FIELD β€” customize the fields in the output, bestie. The possible values are: total, self, addr, total-avg, total-max, total-min, self-avg, self-max, and self-min. You can set multiple fields by using a comma. There's also this special little field called none that can be used (solely, like all by itself) to hide all the fields. Default is total. Go peek at FIELDS if you want the deets 🫢
  • --task β€” print a task graph instead of the normal function graph. Each node in the output shows a process or a thread (and it's printed in green color 🌿, cute).
  • --srcline β€” show the source location of each function if available. Not gonna lie, when it's available it's giving major main character energy πŸŽ€
  • --format=TYPE β€” show output in a format style. Currently normal and html styles are supported 🌸

πŸ’œ COMMON OPTIONS πŸ’œ

  • -F FUNC, --filter=FUNC β€” set a filter so you only trace the selected functions and their children functions. This option can be used more than once. See uftrace-replay(1) for an explanation of filters πŸ’–
  • -N FUNC, --notrace=FUNC β€” set a filter to not trace the selected functions and their children functions. This one can also be used more than once. See uftrace-replay(1) for an explanation of filters ✨
  • -C FUNC, --caller-filter=FUNC β€” set a filter to trace callers of selected functions only. Yep, this option can be used more than once too. See uftrace-replay(1) for an explanation of filters πŸ¦‹
  • -T TRG, --trigger=TRG β€” set a trigger on the selected functions. This option can be used more than once. See uftrace-replay(1) for an explanation of triggers πŸ”₯
  • -D DEPTH, --depth DEPTH β€” set the trace limit in nesting level. So like, how deep it goes before it just stops, no cap πŸ’…
  • -t TIME, --time-filter=TIME β€” do not show functions which run under the time threshold. But heads up: if some functions explicitly have the trace trigger applied, those are always traced regardless of execution time. no exceptions, periodt.
  • -Z SIZE, --size-filter=SIZE β€” do not show functions smaller than SIZE bytes.
  • -L LOCATION, --loc-filter=LOCATION β€” set a filter to trace selected source locations. This option can be used more than once πŸ“
  • --no-libcall β€” do not show library calls. bye library calls πŸ‘‹
  • --no-event β€” do not show any events. (Heads up: this implies --no-sched.)
  • --no-sched β€” do not show schedule events.
  • --no-sched-preempt β€” do not show preempt schedule events, but still show the regular (sleeping) schedule events. like, we still want some tea 🍡
  • --match=TYPE β€” use pattern matching with TYPE. The possible types are regex and glob. Default is regex.
  • --with-syms=DIR β€” read symbol data from the .sym files in the DIR directory instead of from the binary. This can be super useful to deal with stripped binaries ngl. Warning though: the file name of the main binary should be the same when saved and used 🫢

πŸ‘‘ COMMON ANALYSIS OPTIONS πŸ‘‘

  • -H FUNC, --hide=FUNC β€” set a filter not to trace the selected functions. It doesn't affect their subtrees, it just hides only the given functions. This option can be used more than once. See uftrace-replay(1) for an explanation of filters πŸ™ˆ
  • --kernel-full β€” show all kernel functions called outside of user functions. full send into the kernel 🌌
  • --kernel-only β€” show kernel functions only, without user functions.
  • --event-full β€” show all (user) events outside of user functions. ✨
  • --tid=TID[,TID,...] β€” only print functions called by the given tasks. To see the list of tasks in the data file, you can use uftrace report --task or uftrace info. This option can also be used more than once, bestie 🧚
  • --demangle=TYPE β€” use demangled C++ symbol names for filters, triggers, arguments and/or return values. Possible values are full, simple and no. Default is simple, which ignores function arguments and template parameters. lowkey the sane choice ngl πŸ’…
  • -r RANGE, --time-range=RANGE β€” only show functions executed within the time RANGE. The RANGE can be <start>~<stop> (separated by ~) and one of <start> and <stop> can be omitted. The <start> and <stop> are timestamp or elapsed time if they have a <time_unit> postfix, for example 100us. The timestamp or elapsed time can be shown with -f time or -f elapsed option respectively in uftrace replay(1) ⏰

πŸ’– that's the end of part 1, bestie β€” there's more coming so don't go anywhere! πŸ¦‹

πŸŽ€ EXAMPLES πŸŽ€

ok bestie watch this, here's what the data looks like when you record and replay. First you do:

$ uftrace record loop

$ uftrace replay
# DURATION    TID     FUNCTION
            [24447] | main() {
            [24447] |   foo() {
   8.134 us [24447] |     loop();
   7.296 us [24447] |     loop();
   7.234 us [24447] |     loop();
  24.324 us [24447] |   } /* foo */
            [24447] |   foo() {
   7.234 us [24447] |     loop();
   7.231 us [24447] |     loop();
   7.231 us [24447] |     loop();
  22.302 us [24447] |   } /* foo */
            [24447] |   bar() {
  10.100 ms [24447] |     usleep();
  10.138 ms [24447] |   } /* bar */
  10.293 ms [24447] | } /* main */

and then the graph command serves you the function call graph, like so:

$ uftrace graph
# Function Call Graph for 'loop' (session: 073f1e84aa8b09d3)
========== FUNCTION CALL GRAPH ==========
  10.293 ms : (1) loop
  10.293 ms : (1) main
  46.626 us :  +-(2) foo
  44.360 us :  | (6) loop
            :  |
  10.138 ms :  +-(1) bar
  10.100 ms :    (1) usleep

ok so the graph root isn't a function, bestie, it's the actual executing process itself. the left side = total time that function on the right ran. and the number in parentheses before the function name? that's the invocation count, obviously πŸ’… so like, main was called once and it ran for 10 msec. it called foo twice, and then foo called loop 6 times in total. the printed time is the total execution time for all the invocations of that function, no cap.

you can also see that main called bar once, and bar then called usleep once. to minimize nesting, the output shows calls at the same level if only a single call path exists. and since usleep and main are not directly connected, usleep is not called from main directly. periodt.


now if you run the graph command on the main function you get the called functions plus the backtrace, like:

$ uftrace graph main
# Function Call Graph for 'main' (session: 073f1e84aa8b09d3)
=============== BACKTRACE ===============
 backtrace #0: hit 1, time  10.293 ms
   [0] main (0x4004f0)

========== FUNCTION CALL GRAPH ==========
# TOTAL TIME   FUNCTION
   10.293 ms : (1) main
   46.626 us :  +-(2) foo
   44.360 us :  | (6) loop
             :  |
   10.138 ms :  +-(1) bar
   10.100 ms :    (1) usleep

lowkey important: main is the top-level function so it has like, literally zero backtrace above itself 🫢 and running the graph command on a leaf function looks like this:

$ uftrace graph loop
# Function Call Graph for 'loop' (session: 073f1e84aa8b09d3)
=============== BACKTRACE ===============
 backtrace #0: hit 6, time  44.360 us
   [0] main (0x4004b0)
   [1] foo (0x400622)
   [2] loop (0x400f5f6)

========== FUNCTION CALL GRAPH ==========
# TOTAL TIME   FUNCTION
   44.360 us : (6) loop

the backtrace shows that loop is called from foo, and foo is called from main. since loop is a leaf function it didn't call any other function (iconic of it honestly). in this case loop was called only from a single path so backtrace #0 is hit 6 times ✨


so like, while the graph command shows the function-level call graph, the --task option makes the output a task-level graph which shows how processes and threads are created. and "task" here includes both process and thread, fyi.

for example, the task graph of the GCC compiler can be shown like this:

$ uftrace record --force /usr/bin/gcc hello.c

$ uftrace graph --task
========== TASK GRAPH ==========
# TOTAL TIME   SELF TIME     TID     TASK NAME
  159.854 ms    4.440 ms  [ 82723] : gcc
                                   :  |
   90.951 ms   90.951 ms  [ 82734] :  +----cc1
                                   :  |
   17.150 ms   17.150 ms  [ 82735] :  +----as
                                   :  |
   45.183 ms    6.076 ms  [ 82736] :  +----collect2
                                   :        |
   38.880 ms   38.880 ms  [ 82737] :        +----ld

so that output is saying gcc created cc1, as, and collect2 processes, and then collect2 created the ld process. ate πŸ’…

TOTAL TIME is the lifetime of the task from its creation to termination, and SELF TIME is also lifetime, but it excludes internal idle time. TID is the thread id of the task.

and here's the task graph of uftrace recording itself. it shows uftrace created a t-abc process, and also created many threads whose names are all WriterThread:

$ uftrace record -P. ./uftrace record -d uftrace.data.abc t-abc

$ uftrace graph --task
========== TASK GRAPH ==========
# TOTAL TIME   SELF TIME     TID     TASK NAME
  404.929 ms  321.692 ms  [  4230] : uftrace
                                   :  |
  278.662 us  278.662 us  [  4241] :  +----t-abc
                                   :  |
   33.754 ms    4.061 ms  [  4242] :  +-WriterThread
   27.415 ms  120.992 us  [  4244] :  +-WriterThread
   27.212 ms    8.119 ms  [  4245] :  +-WriterThread
   26.754 ms    6.616 ms  [  4248] :  +-WriterThread
   26.859 ms    8.154 ms  [  4247] :  +-WriterThread
   26.509 ms    1.645 ms  [  4243] :  +-WriterThread
   25.320 ms   57.350 us  [  4246] :  +-WriterThread
   24.757 ms    4.391 ms  [  4249] :  +-WriterThread
   26.040 ms    3.707 ms  [  4250] :  +-WriterThread
   24.004 ms    3.999 ms  [  4251] :  +-WriterThread
⚠️ bestie pls note: the indentation depth of a thread is different from that of a process.

running the graph command with --srcline shows the source location right there in the call graph, like below:

$ uftrace record --srcline t-abc
$ uftrace graph --srcline
# Function Call Graph for 't-abc' (session: 60195bac953d8736)
========== FUNCTION CALL GRAPH ==========
# TOTAL TIME   FUNCTION [SOURCE]
  8.909 us : (1) t-abc
  1.260 us :  +-(1) __monstartup
           :  |
  0.179 us :  +-(1) __cxa_atexit
           :  |
  7.470 us :  +-(1) main [tests/s-abc.c:26]
  5.522 us :    (1) a [tests/s-abc.c:11]
  4.912 us :    (1) b [tests/s-abc.c:16]
  4.176 us :    (1) c [tests/s-abc.c:21]
  0.794 us :    (1) getpid

🌸 FIELDS 🌸

uftrace lets you customize the graph output with some fields, bestie. and the "field" here means the info on the left side of the : character. by default it uses the time only, but you can use other fields in any order you want, like:

$ uftrace record tests/t-abc
$ uftrace graph -f total,self,addr
# Function Call Graph for 't-sort' (session: b007f4b7cf792878)
========== FUNCTION CALL GRAPH ==========
# TOTAL TIME  SELF TIME      ADDRESS     FUNCTION
   10.145 ms              561f652cd610 : (1) t-sort
   10.145 ms   39.890 us  561f652cd610 : (1) main
   16.773 us    0.734 us  561f652cd7ce :  +-(2) foo
   16.039 us   16.039 us  561f652cd7a0 :  | (6) loop
                                       :  |
   10.088 ms   14.740 us  561f652cd802 :  +-(1) bar
   10.073 ms   10.073 ms  561f652cd608 :    (1) usleep

each field means this:

  • total β€” function execution time in total
  • total-avg β€” average of total time of each function.
  • total-max β€” max of total time of each function.
  • total-min β€” min of total time of each function.
  • self β€” function execution time excluding its children's
  • self-avg β€” average of self time of each function.
  • self-max β€” max of self time of each function.
  • self-min β€” min of self time of each function.
  • addr β€” address of the function

the default value is total. and if the field name you give starts with "+", then it'll be appended to the default fields 🫢 so -f +addr is the same as -f total,addr. it also accepts a special field name of none which disables the field display and shows the function output only:

$ uftrace graph -f none
# Function Call Graph for 't-sort' (session: b007f4b7cf792878)
========== FUNCTION CALL GRAPH ==========
(1) t-sort
(1) main
 +-(2) foo
 | (6) loop
 |
 +-(1) bar
   (1) usleep

this output can be useful when comparing two different call graph outputs using a diff tool. chef's kiss, honestly 🧚


it also supports field customization for the task graph. the default field set is total,self,tid, but the field option can be used like this too:

$ uftrace graph --task -f tid,self
========== TASK GRAPH ==========
#    TID     SELF TIME   TASK NAME
  [ 82723]    4.440 ms : gcc
                       :  |
  [ 82734]   90.951 ms :  +----cc1
                       :  |
  [ 82735]   17.150 ms :  +----as
                       :  |
  [ 82736]    6.076 ms :  +----collect2
                       :        |
  [ 82737]   38.880 ms :        +----ld

each field means this:

  • total β€” total task lifetime from its creation to termination
  • self β€” task execution time excluding its idle time
  • tid β€” task id (obtained by gettid(2))

it also accepts a special field none, which hides all the fields on the left:

$ uftrace graph --task -f none
========== TASK GRAPH ==========
gcc
 |
 +----cc1
 |
 +----as
 |
 +----collect2
       |
       +----ld

⭐ SEE ALSO ⭐

uftrace(1), uftrace-record(1), uftrace-replay(1), uftrace-tui(1)


πŸ‘‘ AUTHORS πŸ‘‘

Namhyung Kim namhyung@gmail.com


and that's a wrap bestie!! this whole thing is the Uftrace User Manuals, dropped way back in Sep, 2018, and you just read UFTRACE-GRAPH(1) β€” thanks for staying till the end, mwah πŸ’– go forth and graph slay ✨🌈

πŸ“¦ where this page comes from