My favorites | Sign in
Project Logo
                
Search
for
Updated Oct 22, 2009 by Jose.R.Fonseca
Labels: Featured, Script, Python
Gprof2Dot  
Convert profiling output to a dot graph.

About

This is a Python script to convert the output from many profilers into a dot graph.

It has the following features:

  • reads output from:
  • prunes nodes and edges below a certain threshold;
  • uses an heuristic to propagate time inside mutually recursive functions;
  • uses color efficiently to draw attention to hot-spots;
  • works on any platform where Python and graphviz is available, i.e, virtually anywhere.

If you want an interactive viewer for gprof2dot output graphs, check xdot.

Example

This is the result from the example data in the Linux Gazette article with the default settings:

Changelog

  • 2009-10-21: Support sysprof format.
  • 2009-10-20: Support Very Sleepy format.
  • 2009-08-09: Support hostshot profile format file (from tocer.deng,  issue #20 ).
  • 2009-03-04: Support AQtime xml format.
  • 2009-03-04: Support gprof indices > 10000 (by jkuzeja).
  • 2009-01-15: Add MacOSX Shark output parser; use rounded corners (contributed by Tomas Carnecky).
  • 2008-09-18: More complete theming. Black and white color theme.
  • 2008-06-29: Added an heuristic to propagate time inside cycles. This allows to determine the critical path for highly recursive code, such as the linux kernel code seen in issue 6.
  • 2008-04-08: Accept " " in oprofile profiles (contributed by Jakob Bornecrantz).
  • 2008-01-31: Handle oprofile output with profile specifications.
  • 2008-01-25: Propagate the self time spent in cycle member functions, which was being ignored yielding wrong results (mainly when pos-processing oprofile data).
  • 2007-12-20: Allow more than a single input file for pstats (contributed by Daniele Varrazzo).
  • 2007-11-18: Parse oprofile callgraph output (more detail here).
  • 2007-09-28: Get the total time not from the granularity time, but from the longest function call.
  • 2007-07-14: Added the ability to read output generated by the python profilers.
  • 2007-05-30: Handle the output produced by gprof with the static call graph option.
  • 2007-05-16: Strip template parameters from function names; add command options to control this behavior.
  • 2007-04-17: Fix bug parsing cycle entries, which have slightly different syntax than regular entries, and therefore are now parsed separately.
  • 2007-04-02: Consistent handling of cycles.
  • 2007-04-02: Handle output produced by non-GNU gprof.
  • 2007-03-30: Initial import.

Requirements

Windows users

Debian/Ubuntu users

Download

Documentation

Usage

Usage: 
	gprof2dot.py [options] [file] ...

Options:
  --version             show program's version number and exit
  -h, --help            show this help message and exit
  -o FILE, --output=FILE
                        output filename [stdout]
  -n PERCENTAGE, --node-thres=PERCENTAGE
                        eliminate nodes below this threshold [default: 0.5]
  -e PERCENTAGE, --edge-thres=PERCENTAGE
                        eliminate edges below this threshold [default: 0.1]
  -f FORMAT, --format=FORMAT
                        profile format: prof, oprofile, sysprof, shark,
                        sleepy, aqtime, or pstats [default: prof]
  -c THEME, --colormap=THEME
                        color map: color, pink, gray, or bw [default: color]
  -s, --strip           strip function parameters, template parameters, and
                        const modifiers from demangled C++ function names
  -w, --wrap            wrap function names

Examples

gprof

/path/to/your/executable arg1 arg2
gprof path/to/your/executable | gprof2dot.py | dot -Tpng -o output.png

oprofile

opcontrol --callgraph=16
opcontrol --start 
/path/to/your/executable arg1 arg2
opcontrol --stop
opcontrol --dump
opreport -cgf | gprof2dot.py -f oprofile | dot -Tpng -o output.png

python profile

python -m profile -o output.pstats path/to/your/script arg1 arg2
gprof2dot.py -f pstats output.pstats | dot -Tpng -o output.png

python cProfile (formerly known as lsprof)

python -m cProfile -o output.pstats path/to/your/script arg1 arg2
gprof2dot.py -f pstats output.pstats | dot -Tpng -o output.png

python hotshot profiler

The hotshot profiler does not include a main function. Download this hotshotmain.py script instead.

hotshotmain.py -o output.pstats path/to/your/script arg1 arg2
gprof2dot.py -f pstats output.pstats | dot -Tpng -o output.png

Output

A node in the output graph represents a function and has the following layout:

+------------------------------+
|        function name         |
| total time % ( self time % ) |
|         total calls          |
+------------------------------+

where:

An edge represents the calls between two functions and has the following layout:

           total time %
              calls
parent --------------------> children

Where:

Note that in recursive cycles, the total time % in the node is the same for the whole functions in the cycle, and there is no total time % figure in the edges inside the cycle, since such figure would make no sense.

The color of the nodes and edges varies according to the total time % value. In the default temperature-like color-map, functions where most time is spent (hot-spots) are marked as saturated red, and functions where little time is spent are marked as dark blue. Note that functions where negligible or no time is spent do not appear in the graph by default.

Frequently Asked Questions

How can I generate a call graph from gprof output?

By default gprof2dot.py generates a partial call graph, excluding nodes and edges with little or no impact in the total computation time. If you want the full call graph then set a zero threshold for nodes and edges via the -n / --node-thres and -e / --edge-thres options, as:

gprof2dot.py -n0 -e0

For an even more complete call graph, also run gprof with the -c / --static-call-graph, which identifies by statical analysis of the binary machine code other functions that could have been called, but never were.

The node labels are too wide. How can I narrow them?

The node labels can get very wide when profiling C++ code, due to inclusion of scope, function arguments, and template arguments in demangled C++ function names.

If you do not need function and template arguments information, then pass the -s / --strip option to strip them.

If you want to keep all that information, or if the labels are still too wide, then you can pass the -w / --wrap, to wrap the labels. Note that because dot does not wrap labels automatically the label margins will not be perfectly aligned.

Why there is no output, or it is all in the same color?

Likely, the total execution time is too short, so there is not enough precision in the profile to determine where time is being spent.

You can still force displaying the whole graph by setting a zero threshold for nodes and edges via the -n / --node-thres and -e / --edge-thres options, as:

gprof2dot.py -n0 -e0

But to get meaningful results you will need to find a way to run the program for a longer time period, or run gprof with multiple profiles. See also:

Why don't the percentages add up?

You likely have an execution time too short, causing the round-off errors to be large.

See question above for ways to increase execution time.

Which options should I pass to gcc when compiling for profiling?

Options which are essential to produce output suitable are:

You want the code you are profiling to be as close as possible as the code that you will be releasing. So you should include all options that you use in your release code, typically:

However, due to the profiling mechanism used by gprof (and other profilers), many of the optimizations performed by gcc interfere with the accuracy/granularity of the profiling. You should pass these options to disable those particular optimizations:

If the granularity is still too low, you may pass these options to achieve finer granularity:

Note however that with these last options the timings of functions called many times will be distorted due to the function call overhead. This is particularly true for typical C++ code which expects that these optimizations to be done for decent performance.

See the full list of gcc optimization options for more information.

Links

Profiling tools

Profile visualization tools

Call-graph generation tools

  • pycallgraph -- a call graph generator for Python programs.

Comment by fbisetti, Nov 12, 2007

Great job José. Thanks for making it available to all of us!

Comment by ncalexander, Apr 03, 2008

I just wanted to let you know that this script just saved me hours of deciphering the Python profiler's output. Thanks!

Comment by leandrosk, May 13, 2008

excellent work!! thanks a lot!

Comment by b...@users.sf.net, Dec 06, 2008

Excellent python profiling result viewer. I'm using inkscape as an SVG visualization tool (couldn't find easily a dot viewer on Windows).

Comment by jonasdeyson, Feb 10, 2009

It's just what I was looking for. Thanks.

Comment by jkuzeja, Mar 02, 2009

Very nice. There's a small problem when there are more than 10000 functions. At least some versions of gprof have a bug where the initial function index loses the closing bracket for indices > 10000. I just added a '?' to the initial closing bracket in the cg_primary_re and cg_cycle_header_re regexps to fix this.

Here is an example of the gprof bug:

-----------------------------------------------
                0.00    0.00    3778/3778        timing::ClockDef::~ClockDef() [3176]
[9999]   0.0    0.00    0.00    3778         timing::ClockEdge::~ClockEdge() [9999]
-----------------------------------------------
                0.00    0.00      14/3657        timing::BaseTranList::handleUserTransitions(clkdb::SmartPointerTP<circuit::Port>, bool) [836]
                0.00    0.00    3643/3657        timing::AllClockDefs::skipClockPropDueToInactiveClock(clkdb::SmartPointerTP<timing::ClockDef>) [2467]
[10000   0.0    0.00    0.00    3657         timing::ClockDef::getMasterSourceClock() const [10000]
-----------------------------------------------
                0.00    0.00    3503/3503        circuit::name::FindNameBaseTraverser::addFoundName(clkdb::SmartPointerTP<circuit::name::NameIFC>, clkdb::SmartPointerTP<clkdb::PersistentObject>) [2984]
[10001   0.0    0.00    0.00    3503         circuit::name::FindNameContainer<clkdb::ObjectContainer>::push_back(clkdb::SmartPointerTP<clkdb::PersistentObject>) [10001]
-----------------------------------------------
Comment by Jose.R.Fonseca, Mar 04, 2009

jkuzeja,

Commited. Thanks.

Comment by ekeroid, May 20, 2009

Very nice, thanks!

/Johan Eker

Comment by jon.x.hill, May 22, 2009

It would be very nice to have an option to colour nodes according to exclusive time rather than inclusive - having the main red hotspot "main" for every profile is not always helpful

Comment by thekswenson, Jun 22, 2009

Really quality tools man...

thanks.

Comment by rajat.goel2010, Jul 19, 2009

This is a life saver....great job.

Comment by geoffery.miller, Jul 27, 2009

This is an excellent program. Thank you very much for your hard work.

Comment by ChengHuige, Nov 15, 2009

Amazing, I finally find the tool I needed:) Is it possible to let user specify the function to output? I think it would be better if user can specify one function so to see the process flow of a specific function. For example,one program has 2 steps one is compressing and the following is decompressing,so the user can choose to draw only the work flow of decompressing.

Comment by ChengHuige, Nov 15, 2009

Comment by jon.x.hill, May 22, 2009 It would be very nice to have an option to colour nodes according to exclusive time rather than inclusive - having the main red hotspot "main" for every profile is not always helpful

I think you can achive this by simply copy it to another one say,gprof2dot2.py and then goto line 1898,modify it as below actually changing PRUNE_RATION to TIME_RATIO, hope the author will give one option for this:)

try:
weight = functionTIME_RATIO?
except UndefinedEvent?:
weight = 0.0

label = '\n'.join(labels) self.node(function.id,
label = label, color = self.color(theme.node_bgcolor(weight)), fontcolor = self.color(theme.node_fgcolor(weight)), fontsize = "%.2f" % theme.node_fontsize(weight),
)
for call in function.calls.itervalues():
callee = profile.functionscall.callee_id?
labels = for event in TOTAL_TIME_RATIO, CALLS:
if event in call.events:
label = event.format(callevent?) labels.append(label)
try:
weight = callTIME_RATIO?
except UndefinedEvent?:
try:
weight = calleeTIME_RATIO?
except UndefinedEvent?:
weight = 0.0

Sign in to add a comment
Hosted by Google Code