Skip to content

Commit

Permalink
profiler: Add number of generated expr to profile o/p
Browse files Browse the repository at this point in the history 
The number of EVAL/REDO counts in the profile result
are sometimes difficult to understand. This is mainly due to the
fact that the compiler rewrites expressions and assigns the
same location to each generated expression and the profiler
keys the counters by the location. So users have no idea
that multiple expressions may be contributing to the profile
result for a given line in the policy.

This change attempts to provide more clarity to the profile
output by including the number of generated expressions for
each given expression thereby helping to better understand
the result and also how the evaluation works.

Fixes: #2552

Signed-off-by: Ashutosh Narkar <anarkar4387@gmail.com>
  • Loading branch information
@ashutosh-narkar
ashutosh-narkar committed Apr 19, 2023
1 parent 23164c9 commit 7f2895d
Show file tree
Hide file tree
Showing 5 changed files with 231 additions and 83 deletions.
31 changes: 30 additions & 1 deletion cmd/eval_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -131,13 +131,19 @@ func TestEvalWithProfiler(t *testing.T) {
files := map[string]string{
"x.rego": `package x
p = 1`,
p {
a := 1
b := 2
c := 3
x = a + b * c
}`,
}

test.WithTempFS(files, func(path string) {

params := newEvalCommandParams()
params.profile = true
params.profileCriteria = newrepeatedStringFlag([]string{"line"})
params.dataPaths = newrepeatedStringFlag([]string{path})

var buf bytes.Buffer
Expand All @@ -156,6 +162,29 @@ p = 1`,
if len(output.Profile) == 0 {
t.Fatal("Expected profile output to be non-empty")
}

expectedNumEval := []int{3, 1, 1, 1, 1}
expectedNumRedo := []int{3, 1, 1, 1, 1}
expectedRow := []int{7, 6, 5, 4, 1}
expectedNumGenExpr := []int{3, 1, 1, 1, 1}

for idx, actualExprStat := range output.Profile {
if actualExprStat.NumEval != expectedNumEval[idx] {
t.Fatalf("Index %v: Expected number of evals %v but got %v", idx, expectedNumEval[idx], actualExprStat.NumEval)
}

if actualExprStat.NumRedo != expectedNumRedo[idx] {
t.Fatalf("Index %v: Expected number of redos %v but got %v", idx, expectedNumRedo[idx], actualExprStat.NumRedo)
}

if actualExprStat.Location.Row != expectedRow[idx] {
t.Fatalf("Index %v: Expected row %v but got %v", idx, expectedRow[idx], actualExprStat.Location.Row)
}

if actualExprStat.NumGenExpr != expectedNumGenExpr[idx] {
t.Fatalf("Index %v: Expected number of generated expressions %v but got %v", idx, expectedNumGenExpr[idx], actualExprStat.NumGenExpr)
}
}
})
}

Expand Down
163 changes: 102 additions & 61 deletions docs/content/policy-performance.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -387,24 +387,65 @@ why policy evaluation is slow.

The `opa eval` command provides the following profiler options:

| Option | Detail | Default |
| --- | --- | --- |
| <span class="opa-keep-it-together">`--profile`</span> | Enables expression profiling and outputs profiler results. | off |
| <span class="opa-keep-it-together">`--profile-sort`</span> | Criteria to sort the expression profiling results. This options implies `--profile`. | total_time_ns => num_eval => num_redo => file => line |
| <span class="opa-keep-it-together">`--profile-limit`</span> | Desired number of profiling results sorted on the given criteria. This options implies `--profile`. | 10 |
| <span class="opa-keep-it-together">`--count`</span> | Desired number of evaluations that profiling metrics are to be captured for. With `--format=pretty`, the output will contain min, max, mean and the 90th and 99th percentile. All collected percentiles can be found in the JSON output. | 1 |
| Option | Detail | Default |
| --- | --- |-----------------------------------------------------------------------|
| <span class="opa-keep-it-together">`--profile`</span> | Enables expression profiling and outputs profiler results. | off |
| <span class="opa-keep-it-together">`--profile-sort`</span> | Criteria to sort the expression profiling results. This options implies `--profile`. | total_time_ns => num_eval => num_redo => num_gen_expr => file => line |
| <span class="opa-keep-it-together">`--profile-limit`</span> | Desired number of profiling results sorted on the given criteria. This options implies `--profile`. | 10 |
| <span class="opa-keep-it-together">`--count`</span> | Desired number of evaluations that profiling metrics are to be captured for. With `--format=pretty`, the output will contain min, max, mean and the 90th and 99th percentile. All collected percentiles can be found in the JSON output. | 1 |

#### Sort criteria for the profile results

* `total_time_ns` - Results are displayed is decreasing order of *expression evaluation time*
* `num_eval` - Results are displayed is decreasing order of *number of times an expression is evaluated*
* `num_redo` - Results are displayed is decreasing order of *number of times an expression is re-evaluated(redo)*
* `num_gen_expr` - Results are displayed is decreasing order of *number of generated expressions*
* `file` - Results are sorted in reverse alphabetical order based on the *rego source filename*
* `line` - Results are displayed is decreasing order of *expression line number* in the source file

When the sort criteria is not provided `total_time_ns` has the **highest** priority
while `line` has the **lowest**.

The `num_gen_expr` represents the number of expressions generated for a given statement on a particular line. For example,
let's take the following policy:

```rego
package test
p {
a := 1
b := 2
c := 3
x = a + b * c
}
```

If we profile the above policy we would get something like the following output:

```ruby
+----------+----------+----------+--------------+-------------+
| TIME | NUM EVAL | NUM REDO | NUM GEN EXPR | LOCATION |
+----------+----------+----------+--------------+-------------+
| 20.291µs | 3 | 3 | 3 | test.rego:7 |
| 1µs | 1 | 1 | 1 | test.rego:6 |
| 2.333µs | 1 | 1 | 1 | test.rego:5 |
| 6.333µs | 1 | 1 | 1 | test.rego:4 |
| 84.75µs | 1 | 1 | 1 | data |
+----------+----------+----------+--------------+-------------+
```

The first entry indicates that line `test.rego:7` has a `EVAL/REDO` count of `3`. If we look at the expression on line `test.rego:7`
ie `x = a + b * c` it's not immediately clear why this line has a `EVAL/REDO` count of `3`. But we also notice that there
are `3` generated expressions (ie. `NUM GEN EXPR`) at line `test.rego:7`. This is because the compiler rewrites the above policy to
something like below:

`p = true { __local0__ = 1; __local1__ = 2; __local2__ = 3; mul(__local1__, __local2__, __local3__); plus(__local0__, __local3__, __local4__); x = __local4__ }`

And that line `test.rego:7` is rewritten to `mul(__local1__, __local2__, __local3__); plus(__local0__, __local3__, __local4__); x = __local4__` which
results in a `NUM GEN EXPR` count of `3`. Hence the `NUM GEN EXPR` count can help to better understand the `EVAL/REDO` counts
for a given expression and also provide more clarity into the profile results and how policy evaluation works.


#### Example Policy

The different profiling examples shown later on this page use the below
Expand Down Expand Up @@ -483,20 +524,20 @@ opa eval --data rbac.rego --profile --format=pretty 'data.rbac.allow'
```ruby
false

+----------+----------+----------+-----------------+
| TIME | NUM EVAL | NUM REDO | LOCATION |
+----------+----------+----------+-----------------+
| 47.148µs | 1 | 1 | data.rbac.allow |
| 28.965µs | 1 | 1 | rbac.rego:11 |
| 24.384µs | 1 | 1 | rbac.rego:41 |
| 23.064µs | 2 | 1 | rbac.rego:47 |
| 15.525µs | 1 | 1 | rbac.rego:38 |
| 14.137µs | 1 | 2 | rbac.rego:46 |
| 13.927µs | 1 | 0 | rbac.rego:42 |
| 13.568µs | 1 | 1 | rbac.rego:55 |
| 12.982µs | 1 | 0 | rbac.rego:56 |
| 12.763µs | 1 | 2 | rbac.rego:52 |
+----------+----------+----------+-----------------+
+----------+----------+----------+--------------+-----------------+
| TIME | NUM EVAL | NUM REDO | NUM GEN EXPR | LOCATION |
+----------+----------+----------+--------------+-----------------+
| 47.148µs | 1 | 1 | 1 | data.rbac.allow |
| 28.965µs | 1 | 1 | 1 | rbac.rego:11 |
| 24.384µs | 1 | 1 | 1 | rbac.rego:41 |
| 23.064µs | 2 | 1 | 1 | rbac.rego:47 |
| 15.525µs | 1 | 1 | 1 | rbac.rego:38 |
| 14.137µs | 1 | 2 | 1 | rbac.rego:46 |
| 13.927µs | 1 | 0 | 1 | rbac.rego:42 |
| 13.568µs | 1 | 1 | 1 | rbac.rego:55 |
| 12.982µs | 1 | 0 | 1 | rbac.rego:56 |
| 12.763µs | 1 | 2 | 1 | rbac.rego:52 |
+----------+----------+----------+--------------+-----------------+

+------------------------------+----------+
| METRIC | VALUE |
Expand Down Expand Up @@ -532,20 +573,20 @@ false
| timer_rego_query_eval_ns | 161812 | 1198092 | 637754 | 1.1846622e+06 | 1.198092e+06 |
| timer_rego_query_parse_ns | 6078 | 6078 | 6078 | 6078 | 6078 |
+------------------------------+---------+----------+---------------+----------------+---------------+
+----------+-------------+-------------+-------------+-------------+----------+----------+-----------------+
| MIN | MAX | MEAN | 90% | 99% | NUM EVAL | NUM REDO | LOCATION |
+----------+-------------+-------------+-------------+-------------+----------+----------+-----------------+
| 43.875µs | 26.135469ms | 11.494512ms | 25.746215ms | 26.135469ms | 1 | 1 | data.rbac.allow |
| 21.478µs | 211.461µs | 98.102µs | 205.72µs | 211.461µs | 1 | 1 | rbac.rego:13 |
| 19.652µs | 123.537µs | 73.161µs | 122.75µs | 123.537µs | 1 | 1 | rbac.rego:40 |
| 12.303µs | 117.277µs | 61.59µs | 116.733µs | 117.277µs | 2 | 1 | rbac.rego:50 |
| 12.224µs | 93.214µs | 51.289µs | 92.217µs | 93.214µs | 1 | 1 | rbac.rego:44 |
| 5.561µs | 84.121µs | 43.002µs | 83.469µs | 84.121µs | 1 | 1 | rbac.rego:51 |
| 5.56µs | 71.712µs | 36.545µs | 71.158µs | 71.712µs | 1 | 0 | rbac.rego:45 |
| 4.958µs | 66.04µs | 33.161µs | 65.636µs | 66.04µs | 1 | 2 | rbac.rego:49 |
| 4.326µs | 65.836µs | 30.461µs | 65.083µs | 65.836µs | 1 | 1 | rbac.rego:6 |
| 3.948µs | 43.399µs | 24.167µs | 43.055µs | 43.399µs | 1 | 2 | rbac.rego:55 |
+----------+-------------+-------------+-------------+-------------+----------+----------+-----------------+
+----------+-------------+-------------+-------------+-------------+----------+----------+--------------+------------------+
| MIN | MAX | MEAN | 90% | 99% | NUM EVAL | NUM REDO | NUM GEN EXPR | LOCATION |
+----------+-------------+-------------+-------------+-------------+----------+----------+--------------+------------------+
| 43.875µs | 26.135469ms | 11.494512ms | 25.746215ms | 26.135469ms | 1 | 1 | 1 | data.rbac.allow |
| 21.478µs | 211.461µs | 98.102µs | 205.72µs | 211.461µs | 1 | 1 | 1 | rbac.rego:13 |
| 19.652µs | 123.537µs | 73.161µs | 122.75µs | 123.537µs | 1 | 1 | 1 | rbac.rego:40 |
| 12.303µs | 117.277µs | 61.59µs | 116.733µs | 117.277µs | 2 | 1 | 1 | rbac.rego:50 |
| 12.224µs | 93.214µs | 51.289µs | 92.217µs | 93.214µs | 1 | 1 | 1 | rbac.rego:44 |
| 5.561µs | 84.121µs | 43.002µs | 83.469µs | 84.121µs | 1 | 1 | 1 | rbac.rego:51 |
| 5.56µs | 71.712µs | 36.545µs | 71.158µs | 71.712µs | 1 | 0 | 1 | rbac.rego:45 |
| 4.958µs | 66.04µs | 33.161µs | 65.636µs | 66.04µs | 1 | 2 | 1 | rbac.rego:49 |
| 4.326µs | 65.836µs | 30.461µs | 65.083µs | 65.836µs | 1 | 1 | 1 | rbac.rego:6 |
| 3.948µs | 43.399µs | 24.167µs | 43.055µs | 43.399µs | 1 | 2 | 1 | rbac.rego:55 |
+----------+-------------+-------------+-------------+-------------+----------+----------+--------------+------------------+
```

##### Example: Display top `5` profile results
Expand All @@ -557,15 +598,15 @@ opa eval --data rbac.rego --profile-limit 5 --format=pretty 'data.rbac.allow'
**Sample Output**

```ruby
+----------+----------+----------+-----------------+
| TIME | NUM EVAL | NUM REDO | LOCATION |
+----------+----------+----------+-----------------+
| 46.329µs | 1 | 1 | data.rbac.allow |
| 26.656µs | 1 | 1 | rbac.rego:11 |
| 24.206µs | 2 | 1 | rbac.rego:47 |
| 23.235µs | 1 | 1 | rbac.rego:41 |
| 18.242µs | 1 | 1 | rbac.rego:38 |
+----------+----------+----------+-----------------+
+----------+----------+----------+--------------+-----------------+
| TIME | NUM EVAL | NUM REDO | NUM GEN EXPR | LOCATION |
+----------+----------+----------+--------------+-----------------+
| 46.329µs | 1 | 1 | 1 | data.rbac.allow |
| 26.656µs | 1 | 1 | 1 | rbac.rego:11 |
| 24.206µs | 2 | 1 | 1 | rbac.rego:47 |
| 23.235µs | 1 | 1 | 1 | rbac.rego:41 |
| 18.242µs | 1 | 1 | 1 | rbac.rego:38 |
+----------+----------+----------+--------------+-----------------+
```

The profile results are sorted on the default sort criteria.
Expand All @@ -580,15 +621,15 @@ opa eval --data rbac.rego --profile-limit 5 --profile-sort num_eval --format=pr
**Sample Profile Output**

```ruby
+----------+----------+----------+-----------------+
| TIME | NUM EVAL | NUM REDO | LOCATION |
+----------+----------+----------+-----------------+
| 26.675µs | 2 | 1 | rbac.rego:47 |
| 9.274µs | 2 | 1 | rbac.rego:53 |
| 43.356µs | 1 | 1 | data.rbac.allow |
| 22.467µs | 1 | 1 | rbac.rego:41 |
| 22.425µs | 1 | 1 | rbac.rego:11 |
+----------+----------+----------+-----------------+
+----------+----------+----------+--------------+-----------------+
| TIME | NUM EVAL | NUM REDO | NUM GEN EXPR | LOCATION |
+----------+----------+----------+--------------+-----------------+
| 26.675µs | 2 | 1 | 1 | rbac.rego:47 |
| 9.274µs | 2 | 1 | 1 | rbac.rego:53 |
| 43.356µs | 1 | 1 | 1 | data.rbac.allow |
| 22.467µs | 1 | 1 | 1 | rbac.rego:41 |
| 22.425µs | 1 | 1 | 1 | rbac.rego:11 |
+----------+----------+----------+--------------+-----------------+
```

As seen from the above table, the results are arranged first in decreasing
Expand All @@ -606,15 +647,15 @@ opa eval --data rbac.rego --profile-limit 5 --profile-sort num_eval,num_redo --f
**Sample Profile Output**

```ruby
+----------+----------+----------+-----------------+
| TIME | NUM EVAL | NUM REDO | LOCATION |
+----------+----------+----------+-----------------+
| 22.892µs | 2 | 1 | rbac.rego:47 |
| 8.831µs | 2 | 1 | rbac.rego:53 |
| 13.767µs | 1 | 2 | rbac.rego:46 |
| 10.78µs | 1 | 2 | rbac.rego:52 |
| 42.338µs | 1 | 1 | data.rbac.allow |
+----------+----------+----------+-----------------+
+----------+----------+----------+--------------+-----------------+
| TIME | NUM EVAL | NUM REDO | NUM GEN EXPR | LOCATION |
+----------+----------+----------+--------------+-----------------+
| 22.892µs | 2 | 1 | 1 | rbac.rego:47 |
| 8.831µs | 2 | 1 | 1 | rbac.rego:53 |
| 13.767µs | 1 | 2 | 1 | rbac.rego:46 |
| 10.78µs | 1 | 2 | 1 | rbac.rego:52 |
| 42.338µs | 1 | 1 | 1 | data.rbac.allow |
+----------+----------+----------+--------------+-----------------+
```

As seen from the above table, result are first arranged based on *number of evaluations*,
Expand Down
11 changes: 7 additions & 4 deletions internal/presentation/presentation.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -496,14 +496,16 @@ func prettyAggregatedMetrics(w io.Writer, ms map[string]interface{}, limit int)

func prettyProfile(w io.Writer, profile []profiler.ExprStats) error {
tableProfile := generateTableProfile(w)

for _, rs := range profile {
line := []string{}
timeNs := time.Duration(rs.ExprTimeNs) * time.Nanosecond
timeNsStr := timeNs.String()
numEval := strconv.FormatInt(int64(rs.NumEval), 10)
numRedo := strconv.FormatInt(int64(rs.NumRedo), 10)
numGenExpr := strconv.FormatInt(int64(rs.NumGenExpr), 10)
loc := rs.Location.String()
line = append(line, timeNsStr, numEval, numRedo, loc)
line = append(line, timeNsStr, numEval, numRedo, numGenExpr, loc)
tableProfile.Append(line)
}
if tableProfile.NumLines() > 0 {
Expand All @@ -513,7 +515,7 @@ func prettyProfile(w io.Writer, profile []profiler.ExprStats) error {
}

func prettyAggregatedProfile(w io.Writer, profile []profiler.ExprStatsAggregated) error {
tableProfile := generateTableWithKeys(w, append(statKeys, "num eval", "num redo", "location")...)
tableProfile := generateTableWithKeys(w, append(statKeys, "num eval", "num redo", "num gen expr", "location")...)
for _, rs := range profile {
line := []string{}
for _, k := range statKeys {
Expand All @@ -526,8 +528,9 @@ func prettyAggregatedProfile(w io.Writer, profile []profiler.ExprStatsAggregated
}
numEval := strconv.FormatInt(int64(rs.NumEval), 10)
numRedo := strconv.FormatInt(int64(rs.NumRedo), 10)
numGenExpr := strconv.FormatInt(int64(rs.NumGenExpr), 10)
loc := rs.Location.String()
line = append(line, numEval, numRedo, loc)
line = append(line, numEval, numRedo, numGenExpr, loc)
tableProfile.Append(line)
}
if tableProfile.NumLines() > 0 {
Expand Down Expand Up @@ -611,7 +614,7 @@ func generateTableWithKeys(writer io.Writer, keys ...string) *tablewriter.Table
}

func generateTableProfile(writer io.Writer) *tablewriter.Table {
return generateTableWithKeys(writer, "Time", "Num Eval", "Num Redo", "Location")
return generateTableWithKeys(writer, "Time", "Num Eval", "Num Redo", "Num Gen Expr", "Location")
}

func populateTableMetrics(m metrics.Metrics, table *tablewriter.Table, prettyLimit int) {
Expand Down
Loading

0 comments on commit 7f2895d

Please sign in to comment.