From af05e5aeef8f4a94b9c888e78c014b1cfbeaf7eb Mon Sep 17 00:00:00 2001 From: Sasha Goldshtein Date: Sat, 29 Oct 2016 14:00:25 -0700 Subject: [PATCH] uflow: Add man page and companion examples file --- man/man8/uflow.8 | 84 ++++++++++++++++++++++++++++++++++++ tools/uflow_example.txt | 112 ++++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 196 insertions(+) create mode 100644 man/man8/uflow.8 create mode 100644 tools/uflow_example.txt diff --git a/man/man8/uflow.8 b/man/man8/uflow.8 new file mode 100644 index 0000000..35daff2 --- /dev/null +++ b/man/man8/uflow.8 @@ -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) diff --git a/tools/uflow_example.txt b/tools/uflow_example.txt new file mode 100644 index 0000000..34dd533 --- /dev/null +++ b/tools/uflow_example.txt @@ -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. +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. +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 '' python 180 # trace only REPL-defined methods -- 2.7.4