geckoboard/prism

Prism is a tool that allows you to collect and analyze profiling data from your go applications. It is not meant to be used as a replacement for tools like pprof but rather as an alternative for cases when you:

• want to collect profile data per go-routine,
• do not want to manually modify your project's source to include the profiler instrumentation code,
• want to quickly compare the performance of code between a set of git commits

Installing

Prism requires go 1.5+. To install it run:

go get github.com/geckoboard/prism && go install github.com/geckoboard/prism.

You can then run prism -h for details on the command line arguments.

How it works

Prism receives as input the path to your project and a list of fully qualified (FQ) function targets to be profiled. It then creates a temporary go workspace containing a copy of your project and analyzes its sources looking for the specified profile targets.

Target call graph construction

For each found target, prism uses [Rapid Type Analysis](https://godoc.org/golang.org/x/tools/go/call graph/rta) (RTA) to discover its call graph. The call graph includes all functions potentially reachable either directly or indirectly via the profile target. Whenever RTA encounters an interface it will properly expand the set of reachable functions to include the types that satisfy that particular interface.

In the following example, running RTA on DoStuff will treat the implementation of Work() for both aProvider and otherProvider as reachable and include both in the generated call graph.

type Provider interface {
	Work()
}

func provider(type string) Provider {
	switch type {
		case "A": 
			return &aProvider{}
		default:
			return &otherProvider{}
	}
}

// This is our profile target
func DoStuff(providerType string) {
	provider(providerType).Work()
}

The call graph is then pruned to remove any functions that do not belong to the project package or any of its sub-packages. The prune step is required as prism is not able to hook code imported from external packages; prism can only parse and modify code present in the cloned project folder (and optionally in vendored packages).

Profiler injection

Once the call graphs for each profile target have been generated, prism will parse each source file into an abstract syntax tree (AST) and visit each node looking for function declarations matching the call graph entries. Each matched function is modified to inject the following profiler hooks:

• BeginProfile/Enter
• EndProfile/Leave (using a defer statement)

The Begin/End profile hooks are used for the profile targets whereas the Enter/Leave hooks are used for any function reachable via the profile target's call graph.

In addition, prism will also hook the main() function of the project and inject some additional hooks to init/configure the profiler (see profile command below) and ensure that all captured profiles are properly processed before the program exits.

Building/running the patched project

Once the profiler code has been injected into the project copy, prism will build and run it capturing any generated profiling data. Both the build and the run steps use a modified GOPATH with the temporary go workspace prepended. This allows the compiler to use the patched version of the project and its sub-packages while still being able to lookup external packages residing in the original GOPATH.

The collected data can be displayed using the print command or compared with previously collected data using the diff command.

Caveats

Profiling inlineable functions

Our profiler relies on the injection of hooks to each tracked function for collecting data. If your code uses inlineable functions, the profiler will overestimate the total time spent in the function as injection of the hook invocations will prevent the compiler from inlining those functions.

Profiler overhead

The profiler hooks introduce overhead to all profiled targets. This overhead adds up if your code invokes a profiled function a large number of times and is likely to slow down the execution of the program.

The implementation of the profiler goes into great lengths to ensure that this overhead is tracked and accounted for when calculating the various time-related metrics. Still, our approach to tracking overhead is not 100% accurate and may introduce a small error; a few μsec up to a few ms depending on the number of invocations of each profiled function. If you need more accuracy we recommend using pprof instead.

Using prism

profile

The profile command allows you to clone your project, inject profile hooks to a set of target functions, build and run the project to collect profiling data.

Usage:
prism profile [command options] path_to_project

Example:
prism profile -t github.com/example/test/main $GOPATH/example/test

Constructing the fully qualified (FQ) target names

When constructing the FQ target name the following rules apply:

If the function does not use a receiver, e.g. func foo(){...} concatenate:

• the name of your project's package, e.g. github.com/prism
• a '/' character
• the name of the function, e.g. foo, yielding the FQ target: github.com/prism/foo

If the function uses a receiver (pointer or non-pointer), e.g func (a *A) foo(){...} concatenate:

• the name of your project's package, e.g. github.com/prism
• a '/' character
• the name of the receiver type, e.g. A
• a '.' character
• the name of the function, e.g. foo, yielding the FQ target: github.com/prism/A.foo

Supported options

The following options can be used with the profile command (see prism profile -h for more details):

Running the profiled project

Once prism has injected the profile hooks, it wil run the patched program saving captured profiles into the folder specified by the --profile-dir option. While the project is running, prism will relay the following signals to the running process:

• HUP
• INT
• TERM
• QUIT

This allows you to stop long-running processes (e.g. if the profiled project implements an http server) and return control back to prism by pressing CTRL+C.

Profile output

All captured profiles are stored as JSON files in the directory specified by the --profile-dir command. The generated profile filenames match the pattern profile-target-timestamp-goid.json where:

• target is the fully qualified target name (with slashes replaced by underscores)
• timestamp is the UTC timestamp (in nanoseconds) when the profile was captured
• goid is the ID of the go-routine which invoked the profile target.

This format makes it very easy to use shell expansion and get a time-sorted list of profiles to feed into the diff command.

print

The print command allows you to display a captured profile into tabular form.

Usage:
prism print [command options] profile

Example:
prism print profile-before.json

+-----------------------------------------------------+-----------+-----------+-----------+-----------+---------+
| Before change - call stack                          |     total |       min |      mean |       max |   invoc |
+-----------------------------------------------------+-----------+-----------+-----------+-----------+---------+
| + github.com/geckoboard/test/main                   | 284.00 ms | 284.00 ms | 284.00 ms | 284.00 ms |       1 |
| | + github.com/geckoboard/test/processor.processRow | 158.30 ms |   1.10 ms |   1.53 ms |   1.98 ms | 1000000 |
| | | - github.com/geckoboard/test/processor.encrypt  | 150.00 ms |   1.00 ms |   1.40 ms |   1.80 ms | 1000000 |
+-----------------------------------------------------+-----------+-----------+-----------+-----------+---------+

prism print --display-format=percent profile-before.json 

+-----------------------------------------------------+--------+--------+--------+--------+---------+
| Before change - call stack                          |  total |    min |   mean |    max |   invoc |
+-----------------------------------------------------+--------+--------+--------+--------+---------+
| + github.com/geckoboard/test/main                   | 100.0% | 100.0% | 100.0% | 100.0% |       1 |
| | + github.com/geckoboard/test/processor.processRow |  55.7% |   0.4% |   0.5% |   0.7% | 1000000 |
| | | - github.com/geckoboard/test/processor.encrypt  |  52.8% |   0.4% |   0.5% |   0.6% | 1000000 |
+-----------------------------------------------------+--------+--------+--------+--------+---------+

Supported options

The following options can be used with the print command (see prism print -h for more details):

Supported column names

The following column types are supported by the --display-columns option when running either the print or diff prism commands:

diff

The diff command allows you compare a set of profiles and display the results in tabular form. It expects two or more profiles as its input. The first profile argument will be treated as the baseline and each other profile argument will be compared against the baseline.

When comparing values, prism will use symbols ↑, ↓ or ≈ to indicate whether a profile value is greater, less or approximately equal to the baseline profile and also format the difference as a percent.

Usage:
prism diff [command options] baseline_profile profile_1 ... profile_n

Example:
prism diff profile-before.json profile-after.json

+-----------------------------------------------------+---------------------------------------------------------+-------------------------------------------------------------------------------------------------+
|                                                     | Before change - baseline                                | After change                                                                                    |
+-----------------------------------------------------+---------------------------------------------------------+-------------------------------------------------------------------------------------------------+
| call stack                                          |     total |       min |      mean |       max |   invoc |               total |                 min |                mean |                 max |   invoc |
+-----------------------------------------------------+-----------+-----------+-----------+-----------+---------+---------------------+---------------------+---------------------+---------------------+---------+
| - github.com/geckoboard/test/main                   | 284.00 ms | 284.00 ms | 284.00 ms | 284.00 ms |       1 | 254.00 ms (↓ 11.8%) | 254.00 ms (↓ 11.8%) | 254.00 ms (↓ 11.8%) | 254.00 ms (↓ 11.8%) |       1 |
| | - github.com/geckoboard/test/processor.processRow | 158.30 ms |   1.10 ms |   1.53 ms |   1.98 ms | 1000000 | 128.30 ms (↓ 23.4%) |   1.11 ms  (↑ 0.9%) |   1.15 ms (↓ 33.0%) |   1.20 ms (↓ 65.0%) | 1000000 |
| | | + github.com/geckoboard/test/processor.encrypt  | 150.00 ms |   1.00 ms |   1.40 ms |   1.80 ms | 1000000 | 120.00 ms (↓ 25.0%) |   1.00 ms       (≈) |   1.10 ms (↓ 27.3%) |   1.82 ms  (↑ 1.1%) | 1000000 |
+-----------------------------------------------------+-----------+-----------+-----------+-----------+---------+---------------------+---------------------+---------------------+---------------------+---------+

Supported options

The following options can be used with the diff command (see prism diff -h for more details):

Running prism for a range of Git commits

One particular use of prism is to collect and diff profiling data for a sequence of Git commits. To this end, we have come up with a simple shell script to automate that.

The script checks out all commits between the two hashes and runs prism profile for each commit using its SHA as the profile label, storing the captured profiles in a temporary directory. Once all profiles have been collected it will runs a prism diff command to print a table comparing each profile against the one obtained for the first commit.

#!/bin/bash

set -euo pipefail

if [ "$#" -lt 3 ]; then
    echo "Generate prism profiles for a sequence of commit SHAs and output their diff"
    echo
    echo "Usage: "
    echo "git-prism.sh start_commit end_commit target..."
    echo
    exit 1
fi

if [[ ! -z $(git status -s) ]]; then
    echo "git-prism: target repo is dirty; please commit or stash your changes and try again"
    exit 1
fi

CUR_BRANCH=`git rev-parse --abbrev-ref HEAD`
START_COMMIT=$1
END_COMMIT=$2
shift 2

TARGETS=""
for target in "$@"
do
    TARGETS=${TARGETS}" -t $target"
done

# Setup tmp dir for profiles
TMPDIR=`mktemp -d`
trap 'git checkout "$CUR_BRANCH" ; rm -rf "$TMPDIR" ; exit 255;' EXIT

# Generate profile for each SHA
for sha in `git rev-list --reverse --abbrev-commit $START_COMMIT $END_COMMIT`; do
    git checkout -q $sha && prism profile --profile-dir="$TMPDIR" --profile-label="$sha" $TARGETS ./
done

# Output diff
prism diff $TMPDIR/*.json

You can run this script directly or define a Git alias such as:

git config --global alias.prismdiff '!bash /usr/local/bin/prism-diff.sh'

which allows you to get a diff for all commits between two SHAs by running:

git prismdiff start_SHA end_SHA target_1 ... targetN

Related articles

A brief introduction on prism and a simple example of its use can be found in the introducing prism blog post.

Contributing

Please read our contributing guide.

License

Prism is released under the MIT license.