Add profile command to REPL

[tsandall]

Users should be able to enable profiling in the REPL (just like they can enable tracing, metrics, etc.) For example, by entering profile in the REPL, the setting is toggled.

To get started, take a look at how the metrics command is implemented in the REPL. At a high-level here are the pieces that need to be implemented:

• Add profile case to switch statement that handles REPL commands
• Add profile entry to command list for help output
• Update evalBody to pass in profiler
• Add test case in repl_test.go that exercises the new functionality

[BenderScript]

I will take a stab at this one

[BenderScript]

okay, so I believe there is small problem. When I look at profiler_test.go it seems to me profiling is enabled by passing it as a buffer to tracer:

	eval := rego.New(
		rego.Module("test.rego", module),
		rego.Query("data.test.foo"),
		rego.Tracer(profiler),
	)

This would mean that we can have a tracing(explain) XOR profile. The issue then is that in eval.body we would need to check if tracing and profile are enabled and choose one. It makes sense that when tracing is enabled profile is somewhat useless.

https://gist.github.com/repenno/36043a2538ddd0dd71d6c6a74d9cbdbf

[tsandall]

Yes, they're mutually exclusive currently. We need to add support for multiple tracers. We have an open issue for that #979.

For now, we could just do some simple toggling (e.g., if profiling is enabled, tracing is turned off, and vice-versa.)

[BenderScript]

This is turning out to be much more complicated than I originally thought...

In eval.Body I have to do something like this:

func (r *REPL) evalBody(ctx context.Context, compiler *ast.Compiler, input ast.Value, body ast.Body) error {
	
	var buf *topdown.BufferTracer
	var bufInterface topdown.Tracer

	if r.explain != explainOff {
		buf = topdown.NewBufferTracer()
		bufInterface = buf
	}

	if r.profiler != nil {
		bufInterface = r.profiler
	}

because later we call

rego.Tracer(bufInterface)

and when it is time to present actual tracing (not profile) we call

mangleTrace(ctx, r.store, r.txn, *buf)

which expects []*topdown.Event and not BufferTracer.

I am letting you know so you can comment before I go too far. Otherwise I am chipping at it little by little

[tsandall]

Here's roughly how I'd approach this.

• Update REPL with cmdProfile function that toggles a flag on the REPL struct to indicate that profiling should/should not be performed. Clear the tracing flag to deal with mutually exclusive behaviour for now.

• evalBody should be extended to instantiate the profiler and output the results if the flag is on. Something like this might work...

var tracer topdown.Tracer
var buf *topdown.BufferTracer
var prof *profiler.Profiler

// <add comment about mutually exclusive behaviour here. Once we solve that problem we can support both.
if r.explain != explainOff {
  // instantiate buffer tracer & set buf
  // set tracer
} else if r.profile {
  // instantiate profiler & set prof
  // set tracer
}

eval := rego.New(..., rego.Tracer(tracer), ...)

// handle output...

Hope this helps.

[BenderScript]

yep, that is what I did, I am trying to hook the results back to the REPL

[tsandall]

If you set the profiler result on the output struct, the presentation package will handle it for you.

[BenderScript]

Yes, I did like this:

	output := pr.Output{
		Error:   err,
		Result:  rs,
		Metrics: r.metrics,
		Profile: r.profiler.ReportTopNResults(-1, []string{}),
	}

The issue is that I had to choose defaults for the report function.

[ashutosh-narkar]

In the opa eval command when we don't pass a sort order on the command line, the cmd package calls profiler.ReportTopNResults with a default sort order which is "total_time_ns", "num_eval", "num_redo", "file", "line" ie var defaultSortOrder = []string{"total_time_ns", "num_eval", "num_redo", "file", "line"} . If you don't provide the sort order to profiler.ReportTopNResults, the result will be unsorted.

[BenderScript]

okay, will use that. Good suggestion

[BenderScript]

> show debug
{
	"trace": false,
	"metrics": false,
	"instrument": false,
	"profiler": false
}
> profile
> show debug
{
	"trace": false,
	"metrics": false,
	"instrument": false,
	"profiler": true
}
> trace
> show debug
{
	"trace": true,
	"metrics": false,
	"instrument": false,
	"profiler": false
}
> trace
> show debug
{
	"trace": false,
	"metrics": false,
	"instrument": false,
	"profiler": false
}
> trace
> show debug
{
	"trace": true,
	"metrics": false,
	"instrument": false,
	"profiler": false
}
> profile
> show debug
{
	"trace": false,
	"metrics": false,
	"instrument": false,
	"profiler": true
}
> help

Examples
========

> data               # show all documents
> data[x] = _        # show all top level keys
> data.repl.version  # drill into specific document

Commands
========

                       <stmt> : evaluate the statement
               package <term> : change active package
                import <term> : add import to active module
                        show  : show active module definition
                  show debug  : show REPL settings
                  unset <var> : undefine rules in currently active module
                         json : set output format to JSON
                       pretty : set output format to pretty
                 pretty-limit : set pretty value output limit
                        trace : toggle full trace and turns off profiler
                      metrics : toggle metrics
                   instrument : toggle instrumentation
                      profile : toggle profiler and turns off trace
                        types : toggle type information
unknown [ref-1 [ref-2 [...]]] : toggle partial evaluation mode
                  dump [path] : dump raw data in storage
                 help [topic] : print this message
                         exit : exit out of shell (or ctrl+d)
                       ctrl+l : clear the screen

Additional Topics
=================

                   help input : how to set input document
                 help partial : how to use partial evaluation

>

[BenderScript]

I have hit a snag that I do not know how to solve it since it might be inside the bowels of rego. I am using the same exact example from https://www.openpolicyagent.org/docs/how-do-i-test-policies.html#profiling

The issue is that I never get the second part, i.e., the metric-value table

+------------------------------+----------+
|            METRIC            |  VALUE   |
+------------------------------+----------+
| timer_rego_module_compile_ns | 1871613  |
| timer_rego_query_compile_ns  | 82290    |
| timer_rego_query_eval_ns     | 257952   |
| timer_rego_query_parse_ns    | 12337169 |
+------------------------------+----------+

My result is as follows:

API server listening at: 127.0.0.1:54732
=== RUN   TestProfile
false
+--------------+----------+----------+-----------------+
|     TIME     | NUM EVAL | NUM REDO |    LOCATION     |
+--------------+----------+----------+-----------------+
| 3.093497022s | 1        | 1        | mod2:33         |
| 287.414µs    | 1        | 1        | mod2:19         |
| 272.083µs    | 1        | 1        | mod2:8          |
| 241.618µs    | 1        | 1        | mod2:49         |
| 201.037µs    | 1        | 2        | mod2:47         |
| 197.956µs    | 1        | 1        | mod2:50         |
| 191.245µs    | 2        | 1        | mod2:42         |
| 171.735µs    | 1        | 0        | mod2:37         |
| 164.699µs    | 2        | 1        | mod2:48         |
| 156.249µs    | 1        | 2        | mod2:41         |
| 149.059µs    | 1        | 1        | mod2:43         |
| 142.839µs    | 1        | 1        | data.rbac.allow |
| 142.803µs    | 1        | 1        | mod2:36         |
| 137.068µs    | 1        | 0        | mod2:51         |
| 76.174µs     | 1        | 1        | mod2:3          |
+--------------+----------+----------+-----------------+

Here is the patch

https://gist.github.com/repenno/3e68c166f72c44ab672a61932f0da5ab

[BenderScript]

Scratch that, I figured it out. eval --profile is turning on metrics under the covers.