Skip to content

Commit

Permalink
uflow: Add man page and companion examples file
Browse files Browse the repository at this point in the history
  • Loading branch information
goldshtn committed Dec 19, 2016
1 parent c0a6352 commit af05e5a
Show file tree
Hide file tree
Showing 2 changed files with 196 additions and 0 deletions.
84 changes: 84 additions & 0 deletions man/man8/uflow.8
Original file line number Diff line number Diff line change
@@ -0,0 +1,84 @@
.TH uflow 8 "2016-11-07" "USER COMMANDS"
.SH NAME
uflow \- Print a flow graph of method calls in high-level languages.
.SH SYNOPSIS
.B uflow [-h] [-M METHOD] [-C CLAZZ] [-v] {java,python,ruby} pid
.SH DESCRIPTION
uflow traces method calls and prints them in a flow graph that can facilitate
debugging and diagnostics by following the program's execution (method flow).

This tool relies on USDT probes embedded in many high-level languages, such as
Node, Java, Python, and Ruby. It requires a runtime instrumented with these
probes, which in some cases requires building from source with a USDT-specific
flag, such as "--enable-dtrace" or "--with-dtrace". For Java processes, the
startup flag "-XX:+ExtendedDTraceProbes" is required.

Since this uses BPF, only the root user can use this tool.
.SH REQUIREMENTS
CONFIG_BPF and bcc.
.SH OPTIONS
.TP
\-M METHOD
Print only method calls where the method name begins with this string.
.TP
\-C CLAZZ
Print only method calls where the class name begins with this string. The class
name interpretation strongly depends on the language. For example, in Java use
"package/subpackage/ClassName" to refer to classes.
.TP
\-v
Print the resulting BPF program, for debugging purposes.
.TP
{java,python,ruby}
The language to trace.
.TP
pid
The process id to trace.
.SH EXAMPLES
.TP
Follow method flow in a Ruby process:
#
.B uflow ruby 148
.TP
Follow method flow in a Java process where the class name is java.lang.Thread:
#
.B uflow -C java/lang/Thread java 1802
.SH FIELDS
.TP
CPU
The CPU number on which the method was invoked. This is useful to easily see
where the output skips to a different CPU.
.TP
PID
The process id.
.TP
TID
The thread id.
.TP
TIME
The duration of the method call.
.TP
METHOD
The method name.
.SH OVERHEAD
This tool has extremely high overhead because it prints every method call. For
some scenarios, you might see lost samples in the output as the tool is unable
to keep up with the rate of data coming from the kernel. Filtering by class
or method prefix can help reduce the amount of data printed, but there is still
a very high overhead in the collection mechanism. Do not use for performance-
sensitive production scenarios, and always test first.
.SH SOURCE
This is from bcc.
.IP
https://github.com/iovisor/bcc
.PP
Also look in the bcc distribution for a companion _example.txt file containing
example usage, output, and commentary for this tool.
.SH OS
Linux
.SH STABILITY
Unstable - in development.
.SH AUTHOR
Sasha Goldshtein
.SH SEE ALSO
trace(8), ustat(8)
112 changes: 112 additions & 0 deletions tools/uflow_example.txt
Original file line number Diff line number Diff line change
@@ -0,0 +1,112 @@
Demonstrations of uflow.


uflow traces method entry and exit events and prints a visual flow graph that
shows how methods are entered and exited, similar to a tracing debugger with
breakpoints. This can be useful for understanding program flow in high-level
languages such as Java, Python, and Ruby, which provide USDT probes for method
invocations.


For example, trace all Ruby method calls in a specific process:

# ./uflow ruby 27245
Tracing method calls in ruby process 27245... Ctrl-C to quit.
CPU PID TID TIME(us) METHOD
3 27245 27245 4.536 <- IO.gets
3 27245 27245 4.536 <- IRB::StdioInputMethod.gets
3 27245 27245 4.536 -> IRB::Context.verbose?
3 27245 27245 4.536 -> NilClass.nil?
3 27245 27245 4.536 <- NilClass.nil?
3 27245 27245 4.536 -> IO.tty?
3 27245 27245 4.536 <- IO.tty?
3 27245 27245 4.536 -> Kernel.kind_of?
3 27245 27245 4.536 <- Kernel.kind_of?
3 27245 27245 4.536 <- IRB::Context.verbose?
3 27245 27245 4.536 <- IRB::Irb.signal_status
3 27245 27245 4.536 -> String.chars
3 27245 27245 4.536 <- String.chars
^C

In the preceding output, indentation indicates the depth of the flow graph,
and the <- and -> arrows indicate the direction of the event (exit or entry).

Often, the amount of output can be overwhelming. You can filter specific
classes or methods. For example, trace only methods from the Thread class:

# ./uflow -C java/lang/Thread java $(pidof java)
Tracing method calls in java process 27722... Ctrl-C to quit.
CPU PID TID TIME(us) METHOD
3 27722 27731 3.144 -> java/lang/Thread.<init>
3 27722 27731 3.144 -> java/lang/Thread.init
3 27722 27731 3.144 -> java/lang/Thread.init
3 27722 27731 3.144 -> java/lang/Thread.currentThread
3 27722 27731 3.144 <- java/lang/Thread.currentThread
3 27722 27731 3.144 -> java/lang/Thread.getThreadGroup
3 27722 27731 3.144 <- java/lang/Thread.getThreadGroup
3 27722 27731 3.144 -> java/lang/ThreadGroup.checkAccess
3 27722 27731 3.144 <- java/lang/ThreadGroup.checkAccess
3 27722 27731 3.144 -> java/lang/ThreadGroup.addUnstarted
3 27722 27731 3.144 <- java/lang/ThreadGroup.addUnstarted
3 27722 27731 3.145 -> java/lang/Thread.isDaemon
3 27722 27731 3.145 <- java/lang/Thread.isDaemon
3 27722 27731 3.145 -> java/lang/Thread.getPriority
3 27722 27731 3.145 <- java/lang/Thread.getPriority
3 27722 27731 3.145 -> java/lang/Thread.getContextClassLoader
3 27722 27731 3.145 <- java/lang/Thread.getContextClassLoader
3 27722 27731 3.145 -> java/lang/Thread.setPriority
3 27722 27731 3.145 -> java/lang/Thread.checkAccess
3 27722 27731 3.145 <- java/lang/Thread.checkAccess
3 27722 27731 3.145 -> java/lang/Thread.getThreadGroup
3 27722 27731 3.145 <- java/lang/Thread.getThreadGroup
3 27722 27731 3.145 -> java/lang/ThreadGroup.getMaxPriority
3 27722 27731 3.145 <- java/lang/ThreadGroup.getMaxPriority
3 27722 27731 3.145 -> java/lang/Thread.setPriority0
3 27722 27731 3.145 <- java/lang/Thread.setPriority0
3 27722 27731 3.145 <- java/lang/Thread.setPriority
3 27722 27731 3.145 -> java/lang/Thread.nextThreadID
3 27722 27731 3.145 <- java/lang/Thread.nextThreadID
3 27722 27731 3.145 <- java/lang/Thread.init
3 27722 27731 3.145 <- java/lang/Thread.init
3 27722 27731 3.145 <- java/lang/Thread.<init>
3 27722 27731 3.145 -> java/lang/Thread.start
3 27722 27731 3.145 -> java/lang/ThreadGroup.add
3 27722 27731 3.145 <- java/lang/ThreadGroup.add
3 27722 27731 3.145 -> java/lang/Thread.start0
3 27722 27731 3.145 <- java/lang/Thread.start0
3 27722 27731 3.146 <- java/lang/Thread.start
2 27722 27742 3.146 -> java/lang/Thread.run
^C

The reason that the CPU number is printed in the first column is that events
from different threads can be reordered when running on different CPUs, and
produce non-sensible output. By looking for changes in the CPU column, you can
easily see if the events you're following make sense and belong to the same
thread running on the same CPU.


USAGE message:

# ./uflow -h
usage: uflow.py [-h] [-M METHOD] [-C CLAZZ] [-v] {java,python,ruby} pid

Trace method execution flow in high-level languages.

positional arguments:
{java,python,ruby} language to trace
pid process id to attach to

optional arguments:
-h, --help show this help message and exit
-M METHOD, --method METHOD
trace only calls to methods starting with this prefix
-C CLAZZ, --class CLAZZ
trace only calls to classes starting with this prefix
-v, --verbose verbose mode: print the BPF program (for debugging
purposes)

examples:
./uflow java 185 # trace Java method calls in process 185
./uflow ruby 1344 # trace Ruby method calls in process 1344
./uflow -M indexOf java 185 # trace only 'indexOf'-prefixed methods
./uflow -C '<stdin>' python 180 # trace only REPL-defined methods

0 comments on commit af05e5a

Please sign in to comment.