viztracer 0.3.2

A debugging and profiling tool that can trace and visualize python code execution

VizTracer

VizTracer is a deterministic debugging/profiling tool that can trace and visualize your python code to help you intuitively understand your code better and figure out the time consuming part of your code.

VizTracer can display every function executed and the corresponding entry/exit time from the beginning of the program to the end, which is helpful for programmers to catch sporatic performance issues. VizTracer is also capable of generating traditional flamegraph which is a good summary of the execution of the program

You can take a look at the demo result of multiple example programs(sort algorithms, mcts, modulo algorithms, multithread tracing, etc.)

trace viewer is used to display the stand alone html data.

VizTracer also supports json output that complies with Chrome trace event format, which can be loaded using perfetto

VizTracer generates HTML report for flamegraph using d3-flamegraph

Requirements

VizTracer requires python 3.6+. No other package is needed. For now, VizTracer only supports CPython + Linux/MacOS.

Install

The prefered way to install VizTracer is via pip

pip install viztracer

You can also download the source code and build it yourself.

Usage

There are a couple ways to use VizTracer

Command Line

The easiest way to use VizTracer is through command line. Assume you have a python script to profile and the normal way to run it is:

python3 my_script.py

You can simply use VizTracer as

python3 -m viztracer my_script.py

which will generate a result.html file in the directory you run this command. Open it in browser and there's your result.

If your script needs arguments like

python3 my_script.py arg1 arg2

Just feed it as it is to VizTracer

python3 -m viztracer my_script.py arg1 arg2

You can also specify the tracer to be used in command line by passing --tracer argument. c tracer is the default value, you can use python tracer(deprecated) instead

python3 -m viztracer --tracer c my_script.py
python3 -m viztracer --tracer python my_script.py

You can specify the output file using -o or --output_file argument. The default output file is result.html. Two types of files are supported, html and json.

python3 -m viztracer -o other_name.html my_script.py
python3 -m viztracer -o other_name.json my_script.py

By default, VizTracer only generates trace file, either in HTML format or json. You can have VizTracer to generate a flamegraph as well by

python3 -m viztracer --save_flamegraph my_script.py

Inline

Sometimes the command line may not work as you expected, or you do not want to profile the whole script. You can manually start/stop the profiling in your script as well.

First of all, you need to import VizTracer class from the package, and make an object of it.

from viztracer import VizTracer

tracer = VizTracer()

If your code is executable by exec function, you can simply call tracer.run()

tracer.run("import random;random.randrange(10)")

This will as well generate a result.html file in your current directory. You can pass other file path to the function if you do not like the name result.html

tracer.run("import random; random.randrange(10)", output_file="better_name.html")

When you need a more delicate profiler, you can manually enable/disable the profile using start() and stop() function.

tracer.start()
# Something happens here
tracer.stop()
tracer.save() # also takes output_file as an optional argument

Or, you can do it with with statement

with VizTracer(output_file="optional.html") as tracer:
    # Something happens here

You can record only the part that you are interested in

# Some code that I don't care
tracer.start()
# Some code I do care
tracer.stop()
# Some code that I want to skip
tracer.start()
# Important code again
tracer.stop()
tracer.save()

It is higly recommended that start() and stop() function should be in the same frame(same level on call stack). Problem might happen if the condition is not met

Display Result

By default, VizTracer will generate a stand alone HTML file which you can simply open with Chrome(maybe Firefox?). The front-end uses trace-viewer to show all the data.

However, you can generate json file as well, which complies to the chrome trace event format. You can load the json file on perfetto, which will replace the deprecated trace viewer in the future.

At the moment, perfetto does not support locally stand alone HTML file generation, so I'm not able to switch completely to it. The good news is that once you load the perfetto page, you can use it even when you are offline.

Trace Filter

Sometimes your code is really complicated or you need to run you program for a long time, which means the parsing time would be too long and the HTML/JSON file would be too large. There are ways in VizTracer to filter out the data you don't need.

The filter mechanism only works in C tracer, and it works at tracing time, not parsing time. That means, using filters will introduce some extra overhead while your tracing, but will save significant memory, parsing time and disk space.

Currently we support the following kinds of filters:

max_stack_depth

max_stack_depth is a straight forward way to filter your data. It limits the stack depth VizTracer will trace, which cuts out deep call stacks, including some nasty recursive calls.

You can specify max_stack_depth in command line:

python3 -m viztracer --max_stack_depth 10 my_script.py

Or you can pass it as an argument to the VizTracer object:

from viztracer import VizTracer

tracer = VizTracer(max_stack_depth=10)

include_files and exclude_files

There are cases when you are only interested in functions in certain files. You can use include_files and exclude_files feature to filter out data you are not insterested in.

When you are using include_files, only the files and directories you specify are recorded. Similarly, when you are using exclude_files, files and directories you specify will not be recorded.

IMPORTANT: include_files and exclude_files can't be both spcified. You can only use one of them.

If a function is not recorded based on include_files or exclude_files rules, none of its descendent functions will be recorded, even if they match the rules

You can specify include_files and exclude_files in command line, but they can take more than one argument, which will make the following command ambiguous:

# Ambiguous command which should NOT be used
python3 -m viztracer --include_files ./src my_script.py

Instead, when you are using --include_files or --exclude_files, --run should be passed for the command that you actually want to execute:

# --run is used to solve ambiguity
python3 -m viztracer --include_files ./src --run my_script.py

However, if you have some other commands that can separate them and solve ambiguity, that works as well:

# This will work too
python3 -m viztracer --include_files ./src --max_stack_depth 5 my_script.py

You can also pass a list as an argument to VizTracer:

from viztracer import VizTracer

tracer = VizTracer(include_files=["./src", "./test/test1.py"])

ignore_c_function

By default, VizTracer will record all the C functions called by python script. You can turn it off by:

python3 -m viztracer --ignore_c_function my_script.py

You can turn it off in your script as well:

tracer = VizTracer(ignore_c_function=True)

ignore_function

Unlike ignore_c_function, ignore_function is a decorator which you can apply to any function to skip tracing it and its descendants.

from viztracer import ignore_function
@ignore_function
def some_function():
    # nothing inside will be traced

Choose Tracer

The default tracer for current version is c tracer, which introduces a relatively small overhead(worst case 2-3x) but only works for CPython on Linux. However, if there's other reason that you would prefer a pure-python tracer, you can use python tracer using tracer argument when you initialize VizTracer object.

tracer = VizTracer(tracer="python")

python tracer will be deprecated because of the performance issue in the future No filter feature is supported with python tracer

Cleanup of c Tracer

The interface for c trace is almost exactly the same as python tracer. However, to achieve lower overhead, some optimization is applied to c tracer so it will withhold the memory it allocates for future use to reduce the time it calls malloc(). If you want the c trace to free all the memory it allocates while collecting trace, use

tracer.cleanup()

Add Custom Event

VizTracer supports inserting custom events while the program is running. This works like a print debug, but you can know when this print happens while looking at trace data.

Instant Event

Instant event is used to bookmark time point with arbitrary data.

When your code is running with VizTracer on, you can use

tracer.add_instant(name, args, scope)

to add an event that will be shown in the report. In trace viewer, you would be able to see what args is.

name should be a string for this event. args should be a json serializable object(dict, list, string, number). scope is an optional argument, default is "g" for global. You can use p for process or t for thread. This affects how long the event shows in the final report.

Counter Event

Counter event is used to track a numeric variable through time. You can track CPU usage, memory usage, or any numeric variable you are interested in using Counter event.

To use Counter event, you need to instantiate a VizCounter object with a valid VizTracer and a name

from viztraer import VizTracer, VizCounter
tracer = VizTracer()
tracer.start()
counter = VizCounter(tracer, "counter name")

Then you can assign any attributes with numeric value and the counter will log it

counter.a = 2
counter.b = 1.2

VizCounter will only log attributes when it does NOT start with _. Everytime you write to an attribute of VizCounter, it will generate a log that contains ALL attributes in the object.

You can turn the automatic trigger off by setting trigger_on_change to False

counter = VizCounter(tracer, "counter name", trigger_on_change=False)
# OR
counter = VizCounter(tracer, "counter name")
counter.config("trigger_on_change", False)

Then writing to the attributes will NOT trigger the log, you need to manually trigger it using log function

counter = VizCounter(tracer, "counter name")
counter.config("trigger_on_change", False)
counter.a = 1
counter.b = 1
# Until here, nothing happens
counter.log() # trigger the log

You can also specify include_attributes and exclude_attributes to limit the attributes you want to log(or trigger on). They both take a list of string

counter = VizCounter(tracer, "counter name", include_attributes=["a", "b"])
# OR
counter = VizCounter(tracer, "counter name")
counter.config("include_attributes", ["a", "b"])

counter.a = 1 # Will trigger log
counter.c = 2 # Will NOT trigger log
counter.b = 3 # Will trigger log and log {"a": 1, "b": 2}, c is not logged

VizCounter will check include_attributes first, if it's not an empty list(default), then it will behave like whitelist, exclude_attributes is ignore. If include_attributes is an empty list, it will use exclude_attributes as blacklist, which could also be empty(default)

Object Event

Object event is almost exactly the same as Counter Event, with the exeption that Object Event logs an jsonifiable Object(dict, list, string, int, float)

Instead of VizCounter, you should use VizObject. The other usage is the same.

from viztracer import VizTracer, VizObject
tracer = VizTracer()
tracer.start()
obj = VizObject(tracer, "my object")
obj.a = ["a", "b", "c"]

However, there are a couple things you need to be careful of.

First, when you are on trigger_on_change, the log is triggered by __setattr__, which means it will only be triggered by obj.a = <something>, but not obj.a["a"] = 1.

Second, the object you logged could be complicated with many variables, so it's a good idea to turn off trigger_on_change and log it manually.

Inherit VizCounter and VizObject

In practice, you can inherit from VizCounter or VizObject class and build your own class so it will be much easier to track the data in your class. Remember you need to do __init__ function of the base class! If your class has a lot of attributes and they are frequently being written to, it is wise to turn off trigger_on_change

class MyClass(VizObject):
    def __init__(self, tracer):
        super().__init__(tracer, "my name", trigger_on_change=False)

You can manually do log by

obj = MyClass(tracer)
obj.log()

or you can decorate your class method with triggerlog to trigger log on function call

class MyClass(VizObject):
    @VizObject.triggerlog
    def log_on_this_function():
        #function

triggerlog takes an optional keyword argument when, which could be "before", "after" or "both" to specify when the log should be triggered. "after" is the default value

class MyClass(VizObject):
    @VizObject.triggerlog(when="before")
    def log_before_this_function():
        # function

It's possible your class needs to use the popular name config and log. They are just aliases of _viztracer_config and _viztracer_log. You can use them instead.

Log Print

VizTracer can log your print to the report using instant events. In this way, you can simply add print functions in your code just like you are doing print debug and see what happens on the timeline.

You can specify --log_print on the command line

python -m viztracer --log_print my_script.py

Or do it when you initialize your VizTracer object

tracer = VizTracer(log_print=True)

Multi Thread Support

VizTracer supports python native threading module without the need to do any modification to your code. Just start VizTracer before you create threads and it will just work.

Multi Process Support

VizTracer can support multi process with some extra steps. The current structure of VizTracer keeps one single buffer for one process, which means the user will have to produce multiple results from multiple processes and combine them together.

If you are using os.fork() or libraries using similiar mechanism, you can use VizTracer the normal way you do, with an extra option pid_suffix.

python -m viztracer --pid_suffix multi_process_program.py

This way, the program will generate mutliple json files in current working directory. Notice here, if --pid_suffix is passed to VizTracer, the default output format will be json because this is only expected to be used by multi-process programs.

You can specify the output directory if you want

python -m viztracer --pid_suffix --output_dir ./temp_dir multi_process_program.py

After generating json files, you need to combine them

python -m viztracer --combine ./temp_dir/*.json

This will generate the HTML report with all the process info. You can specify --output_file when using --combine.

Actually, you can combine any json reports together to an HTML report.

If your code is using subprocess to spawn processes, the newly spawned process won't be traced(We could do something to PATH but that feels sketchy). There are a couple ways to deal with that:

• You can change the subprocess or popen code manually, to attach VizTracer to sub-process. You will have json results from differnt processes and you just need to combine them together. This is a generic way to do multi-process tracing and could work pretty smoothly if you don't have many entries for your subprocess

• Or you can hack your PATH env to use python -m viztracer <args> to replace python. This will make VizTracer attach your spawned process automatically, but could have other side effects.

JSON alternative

VizTracer needs to dump the internal data to json format. It is recommended for the users to install orjson, which is much faster than the builtin json library. VizTracer will try to import orjson and fall back to the builtin json library if orjson does not exist.

Performance

Overhead is a big consideration when people choose profilers. VizTracer now has a similar overhead as native cProfiler. It works slightly worse in the worst case(Pure FEE) and better in easier case because even though it collects some extra information than cProfiler, the structure is lighter.

Admittedly, VizTracer is only focusing on FEE now, so cProfiler also gets other information that VizTracer does not acquire.

An example run for test_performance with Python 3.8 / Ubuntu 18.04.4 on Github VM

fib       (10336, 10336): 0.000852800 vs 0.013735200(16.11)[py] vs 0.001585900(1.86)[c] vs 0.001628400(1.91)[cProfile]
hanoi     (8192, 8192): 0.000621400 vs 0.012924899(20.80)[py] vs 0.001801800(2.90)[c] vs 0.001292900(2.08)[cProfile]
qsort     (10586, 10676): 0.003457500 vs 0.042572898(12.31)[py] vs 0.005594100(1.62)[c] vs 0.007573200(2.19)[cProfile]
slow_fib  (1508, 1508): 0.033606299 vs 0.038840998(1.16)[py] vs 0.033270399(0.99)[c] vs 0.032577599(0.97)[cProfile]

Limitations

VizTracer uses sys.setprofile() for its profiler capabilities, so it will conflict with other profiling tools which also use this function. Be aware of it when using VizTracer.

Bugs/Requirements

Please send bug reports and feature requirements through github issue tracker. VizTracer is currently under development now and it's open to any constructive suggestions.

License

Copyright Tian Gao, 2020.

Distributed under the terms of the Apache 2.0 license.