Predicate has a unique execution style that makes traditional profiling tools ill-suited to finding opportunities for performance improvements. To improve this, Predicate has built into it an intrusive (it impacts the code) profiling system which can be analyzed offline.
There are two directives to be aware of.
Directive | Value | Description |
---|---|---|
PredicateProfile |
|
Turn profiling on or off. |
PredicateProfileDir |
|
Path to where profiling files may be written. This directory’s layout is described later. |
# Profile everything. PredicateProfile on PredicateProfileDir /var/tmp/predicate_profiling/ <Site mySite> ... # Do not profile *this* site. PredicateProfile off ... </Site>
A profile directory contains two types of files. The first is a .descr
file
which is a Graph Description File. The second type is the profile data per
transaction, being identified by the file ending .bin
.
The Graph Description file is a plain-text file that, while extremely large
and verbose, can be opened with any text editor. Graph Description Files are
generated for every context with a graph and placed in a directory named
after the context. Thus, there is almost always a directory main
that
contains a predicate .descr
file when profiling is run.
Each line in the description file represents a single node in the predicate
DAG (Directed Acyclic Graph). The line may be separated into columns on
the tab (\t
) character. The first column is a natural number (including 0)
which is the node’s index in the list of all nodes. For analyzing
profiling data it only matters that the index be unique to that node, and
so it functions as an identifier. Following the index column is
the S-Expression optionally followed by the origins for that node.
The origins of an S-Expression are the locations in configuration files where Predicate believes an S-Expression is defined. Because an expression may be defined in many files and merged into a single node, the final expression in Predicate will have a list of all origins.
Following the S-Expression are all its immediate sub-expressions, each listed on a single line, each being indented by a single tab character. Thus, an example Graph Description File might look like this:
1 (list (transformation 'urlDecode' '' (var 'REQUEST_URI_RAW'))) /opt/ironbee-0.13.0/etc/ironbee/rules/rules.conf:179 (ref 'input')
In the sample file there is a single origin,
/opt/ironbee-0.13.0/etc/ironbee/rules/rules.conf:179 (ref 'input')
,
that lists the configuration file and that Predicate believes the S-Expression
came from using a template (the ref
operator).
0 (operator 'rx' '(?i:\\<\\!\\-\\-[^\\w\\#]*+\\#[^\\w]*+(?:c(?:md|onfig)|e(?:cho|xec)|include|printenv|set))' (foperator 'rx' '[^a-zA-Z\\d]' (transformation 'urlDecode' '' (var 'REQUEST_COOKIES')))) 1 (operator 'rx' '(?i:\\<\\!\\-\\-[^\\w\\#]*+\\#[^\\w]*+(?:c(?:md|onfig)|e(?:cho|xec)|include|printenv|set))' (foperator 'rx' '[^a-zA-Z\\d]' (var 'REQUEST_BODY_PARAMS'))) 2 (operator 'rx' '(?i:\\<\\!\\-\\-[^\\w\\#]*+\\#[^\\w]*+(?:(?:end)?if|el(?:if|se)))' (foperator 'rx' '[^a-zA-Z\\d]' (transformation 'urlDecode' '' (var 'REQUEST_HEADERS'))))
The profile format is extremely simple. Each profile data file represents the work done in a single IronBee transaction. It begins with two native endian uint32_t values. The first is a magic value to denote a predicate data file. It is currently 799596757. The next is the file version number. After this come the data records. When a predicate node finishes evaluating it records:
-
The time, in microseconds, it took for the node to evaluate, including its children.
-
The time, in microseconds, it took for the node to evaluate, excluding its children.
-
The index of the node.
The two time duration values are written to a data file as native-endian
uint32_t
values. The node index is also written as a native-endian
uint32_t
.
There are two Ruby libraries maintained for analyzing predicate profiling
information. Both are located in ironbee/predicate
. The first is
a utility to parse S-Expressions into Ruby objects called, s_expr.rb
.
The second, ppa.rb
is the PredicateProfileAnalyzer. It defines
a class that can load predicate profile data file and graph description files
and sort by self-time, total-time, or number of calls.