Sasha Goldshtein | af05e5a | 2016-10-29 14:00:25 -0700 | [diff] [blame] | 1 | Demonstrations of uflow. |
| 2 | |
| 3 | |
| 4 | uflow traces method entry and exit events and prints a visual flow graph that |
| 5 | shows how methods are entered and exited, similar to a tracing debugger with |
| 6 | breakpoints. This can be useful for understanding program flow in high-level |
Sasha Goldshtein | cfb5ee7 | 2017-02-08 14:32:51 -0500 | [diff] [blame] | 7 | languages such as Java, Python, Ruby, and PHP, which provide USDT probes for |
| 8 | method invocations. |
Sasha Goldshtein | af05e5a | 2016-10-29 14:00:25 -0700 | [diff] [blame] | 9 | |
| 10 | |
| 11 | For example, trace all Ruby method calls in a specific process: |
| 12 | |
Paul Chaignon | 4bb6d7f | 2017-03-30 19:05:40 +0200 | [diff] [blame] | 13 | # ./uflow -l ruby 27245 |
Sasha Goldshtein | af05e5a | 2016-10-29 14:00:25 -0700 | [diff] [blame] | 14 | Tracing method calls in ruby process 27245... Ctrl-C to quit. |
| 15 | CPU PID TID TIME(us) METHOD |
| 16 | 3 27245 27245 4.536 <- IO.gets |
| 17 | 3 27245 27245 4.536 <- IRB::StdioInputMethod.gets |
| 18 | 3 27245 27245 4.536 -> IRB::Context.verbose? |
| 19 | 3 27245 27245 4.536 -> NilClass.nil? |
| 20 | 3 27245 27245 4.536 <- NilClass.nil? |
| 21 | 3 27245 27245 4.536 -> IO.tty? |
| 22 | 3 27245 27245 4.536 <- IO.tty? |
| 23 | 3 27245 27245 4.536 -> Kernel.kind_of? |
| 24 | 3 27245 27245 4.536 <- Kernel.kind_of? |
| 25 | 3 27245 27245 4.536 <- IRB::Context.verbose? |
| 26 | 3 27245 27245 4.536 <- IRB::Irb.signal_status |
| 27 | 3 27245 27245 4.536 -> String.chars |
| 28 | 3 27245 27245 4.536 <- String.chars |
| 29 | ^C |
| 30 | |
| 31 | In the preceding output, indentation indicates the depth of the flow graph, |
| 32 | and the <- and -> arrows indicate the direction of the event (exit or entry). |
| 33 | |
| 34 | Often, the amount of output can be overwhelming. You can filter specific |
| 35 | classes or methods. For example, trace only methods from the Thread class: |
| 36 | |
Paul Chaignon | 4bb6d7f | 2017-03-30 19:05:40 +0200 | [diff] [blame] | 37 | # ./uflow -C java/lang/Thread $(pidof java) |
Sasha Goldshtein | af05e5a | 2016-10-29 14:00:25 -0700 | [diff] [blame] | 38 | Tracing method calls in java process 27722... Ctrl-C to quit. |
| 39 | CPU PID TID TIME(us) METHOD |
| 40 | 3 27722 27731 3.144 -> java/lang/Thread.<init> |
| 41 | 3 27722 27731 3.144 -> java/lang/Thread.init |
| 42 | 3 27722 27731 3.144 -> java/lang/Thread.init |
| 43 | 3 27722 27731 3.144 -> java/lang/Thread.currentThread |
| 44 | 3 27722 27731 3.144 <- java/lang/Thread.currentThread |
| 45 | 3 27722 27731 3.144 -> java/lang/Thread.getThreadGroup |
| 46 | 3 27722 27731 3.144 <- java/lang/Thread.getThreadGroup |
| 47 | 3 27722 27731 3.144 -> java/lang/ThreadGroup.checkAccess |
| 48 | 3 27722 27731 3.144 <- java/lang/ThreadGroup.checkAccess |
| 49 | 3 27722 27731 3.144 -> java/lang/ThreadGroup.addUnstarted |
| 50 | 3 27722 27731 3.144 <- java/lang/ThreadGroup.addUnstarted |
| 51 | 3 27722 27731 3.145 -> java/lang/Thread.isDaemon |
| 52 | 3 27722 27731 3.145 <- java/lang/Thread.isDaemon |
| 53 | 3 27722 27731 3.145 -> java/lang/Thread.getPriority |
| 54 | 3 27722 27731 3.145 <- java/lang/Thread.getPriority |
| 55 | 3 27722 27731 3.145 -> java/lang/Thread.getContextClassLoader |
| 56 | 3 27722 27731 3.145 <- java/lang/Thread.getContextClassLoader |
| 57 | 3 27722 27731 3.145 -> java/lang/Thread.setPriority |
| 58 | 3 27722 27731 3.145 -> java/lang/Thread.checkAccess |
| 59 | 3 27722 27731 3.145 <- java/lang/Thread.checkAccess |
| 60 | 3 27722 27731 3.145 -> java/lang/Thread.getThreadGroup |
| 61 | 3 27722 27731 3.145 <- java/lang/Thread.getThreadGroup |
| 62 | 3 27722 27731 3.145 -> java/lang/ThreadGroup.getMaxPriority |
| 63 | 3 27722 27731 3.145 <- java/lang/ThreadGroup.getMaxPriority |
| 64 | 3 27722 27731 3.145 -> java/lang/Thread.setPriority0 |
| 65 | 3 27722 27731 3.145 <- java/lang/Thread.setPriority0 |
| 66 | 3 27722 27731 3.145 <- java/lang/Thread.setPriority |
| 67 | 3 27722 27731 3.145 -> java/lang/Thread.nextThreadID |
| 68 | 3 27722 27731 3.145 <- java/lang/Thread.nextThreadID |
| 69 | 3 27722 27731 3.145 <- java/lang/Thread.init |
| 70 | 3 27722 27731 3.145 <- java/lang/Thread.init |
| 71 | 3 27722 27731 3.145 <- java/lang/Thread.<init> |
| 72 | 3 27722 27731 3.145 -> java/lang/Thread.start |
| 73 | 3 27722 27731 3.145 -> java/lang/ThreadGroup.add |
| 74 | 3 27722 27731 3.145 <- java/lang/ThreadGroup.add |
| 75 | 3 27722 27731 3.145 -> java/lang/Thread.start0 |
| 76 | 3 27722 27731 3.145 <- java/lang/Thread.start0 |
| 77 | 3 27722 27731 3.146 <- java/lang/Thread.start |
| 78 | 2 27722 27742 3.146 -> java/lang/Thread.run |
| 79 | ^C |
| 80 | |
| 81 | The reason that the CPU number is printed in the first column is that events |
| 82 | from different threads can be reordered when running on different CPUs, and |
| 83 | produce non-sensible output. By looking for changes in the CPU column, you can |
| 84 | easily see if the events you're following make sense and belong to the same |
| 85 | thread running on the same CPU. |
| 86 | |
| 87 | |
| 88 | USAGE message: |
| 89 | |
| 90 | # ./uflow -h |
Paul Chaignon | 4bb6d7f | 2017-03-30 19:05:40 +0200 | [diff] [blame] | 91 | usage: uflow.py [-h] [-l {java,python,ruby,php}] [-M METHOD] [-C CLAZZ] [-v] |
| 92 | pid |
Sasha Goldshtein | af05e5a | 2016-10-29 14:00:25 -0700 | [diff] [blame] | 93 | |
| 94 | Trace method execution flow in high-level languages. |
| 95 | |
| 96 | positional arguments: |
Sasha Goldshtein | af05e5a | 2016-10-29 14:00:25 -0700 | [diff] [blame] | 97 | pid process id to attach to |
| 98 | |
| 99 | optional arguments: |
| 100 | -h, --help show this help message and exit |
Paul Chaignon | 4bb6d7f | 2017-03-30 19:05:40 +0200 | [diff] [blame] | 101 | -l {java,python,ruby,php}, --language {java,python,ruby,php} |
| 102 | language to trace |
Sasha Goldshtein | af05e5a | 2016-10-29 14:00:25 -0700 | [diff] [blame] | 103 | -M METHOD, --method METHOD |
| 104 | trace only calls to methods starting with this prefix |
| 105 | -C CLAZZ, --class CLAZZ |
| 106 | trace only calls to classes starting with this prefix |
| 107 | -v, --verbose verbose mode: print the BPF program (for debugging |
| 108 | purposes) |
| 109 | |
| 110 | examples: |
Paul Chaignon | 4bb6d7f | 2017-03-30 19:05:40 +0200 | [diff] [blame] | 111 | ./uflow -l java 185 # trace Java method calls in process 185 |
| 112 | ./uflow -l ruby 134 # trace Ruby method calls in process 134 |
| 113 | ./uflow -M indexOf -l java 185 # trace only 'indexOf'-prefixed methods |
| 114 | ./uflow -C '<stdin>' -l python 180 # trace only REPL-defined methods |