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
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.
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.
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).
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.
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.
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.
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.
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
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
The following options can be used with the profile command (see prism profile -h for more details):
| Option | Default | Description |
|---|---|---|
| --build-cmd value | an optional build command to execute before running the patched project | |
| --run-cmd value | find . -d 1 -type f -name *\\.go ! -name *_test\\.go -exec go run {} + |
a command for running the patched project; e.g. make run |
| --profile-target value, -t value | a FQ target name to be hooked; this option may be specified multiple times | |
| --profile-dir value | $HOME/prism | the folder where captured profiles will be stored |
| --profile-label value | a label used for tagging captured profiles; e.g. your commit SHA | |
| --profile-vendored-pkg regex | also hook functions in vendored packages matching this regex; this option may be specified multiple times | |
| --output-dir value -o value | System's temp folder | the directory for storing the copied project files |
| --preserve-output | keep the cloned project copy instead of deleting it (default) after prism exits | |
| --no-ansi | disable color output; prism does this automatically if it detects a non-TTY terminal |
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.
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:
targetis the fully qualified target name (with slashes replaced by underscores)timestampis the UTC timestamp (in nanoseconds) when the profile was capturedgoidis 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.
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 |
+-----------------------------------------------------+--------+--------+--------+--------+---------+
The following options can be used with the print command (see prism print -h for more details):
| Option | Default | Description |
|---|---|---|
| --display-columns, --dc value | total,min,mean,max,invocations | the columns to include in the output; see supported column types for the list of supported values |
| --display-format, --df value | time | set format for columns containing time values; supported options are: time and percent |
| --display-unit, --du value | ms | set time unit format for columns containing time values; supported options are: auto, ms, us, ns |
| --display-threshold value | 0 | mask time-related entries less than value; uses the same unit as --display-unit unless --display-format is percent where value is used to threshold displayed percentages |
| --no-ansi | disable color output; prism does this automatically if it detects a non-TTY terminal |
The following column types are supported by the --display-columns option when
running either the print or diff prism commands:
| Column type | Description |
|---|---|
| invocations | number of invocations |
| total | total time spent in function for all its invocations |
| min | min invocation time |
| max | max invocation time |
| mean | mean invocation time |
| median | median invocation time |
| p50 | 50th percentile of invocation total time |
| p75 | 75th percentile of invocation total time |
| p90 | 90th percentile of invocation total time |
| p99 | 99th percentile of invocation total time |
| stddev | standard deviation for invocation time |
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 |
+-----------------------------------------------------+-----------+-----------+-----------+-----------+---------+---------------------+---------------------+---------------------+---------------------+---------+
The following options can be used with the diff command (see prism diff -h for more details):
| Option | Default | Description |
|---|---|---|
| --display-columns, --dc value | total,min,mean,max,invocations | the columns to include in the output; see supported column types for the list of supported values |
| --display-unit, --du value | ms | set time unit format for columns containing time values; supported options are: auto, ms, us, ns |
| --display-threshold value | 0 | mask comparison entries with abs delta time less than value; uses the same unit as --display-unit |
| --no-ansi | disable color output; prism does this automatically if it detects a non-TTY terminal |
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/*.jsonYou 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
A brief introduction on prism and a simple example of its use can be found in the introducing prism blog post.
Please read our contributing guide.
Prism is released under the MIT license.