Evaluating total time taken by OPA server to return authz decision

[dushyant7917]

Below is the metrics section from the response returned by OPA server when evaluating a policy bundle.

"metrics": {
    "counter_server_query_cache_hit": 1,
    "timer_rego_external_resolve_ns": 466600,
    "timer_rego_input_parse_ns": 65900,
    "timer_rego_query_eval_ns": 594200,
    "timer_server_handler_ns": 784800,
    "timer_wasm_pool_acquire_ns": 9200,
    "timer_wasm_pool_release_ns": 9200,
    "timer_wasm_vm_eval_call_ns": 80200,
    "timer_wasm_vm_eval_ns": 149200,
    "timer_wasm_vm_eval_prepare_input_ns": 11900
  }

How to find out time taken by the OPA server to get the decision/output.
Do we need to add the values for following keys?

• WASM
  -- timer_wasm_pool_acquire_ns
  -- timer_wasm_pool_release_ns
  -- timer_wasm_vm_eval_call_ns
  -- timer_wasm_vm_eval_ns
  -- timer_wasm_vm_eval_prepare_input_ns
• Rego
  -- timer_rego_external_resolve_ns
  -- timer_rego_input_parse_ns
  -- timer_rego_query_eval_ns
  -- timer_rego_query_eval_ns

So, for evaluation using WASM total time taken by server is 9200 + 9200 + 80200 + 149200 + 11900 ns and for evaluation using Rego total time taken is 466600 + 65900 + 594200 + 784800 ns?

[charlieegan3]

Hi @dushyant7917, I think that timer_wasm_vm_eval_ns includes timer_wasm_vm_eval_prepare_input_ns and that it is most comparable to the timer_rego_query_eval_ns metric on the Rego side.

Are you comparing a wasm policy against a Rego one?

[dushyant7917]

@charlieegan3
Above metrics are printed if I use a bundle.tar.gz containing .wasm file. Why both rego and wasm related metrics are printed?
And if I use a normal bundle.tar.gz (not containing .wasm) then only rego related metrics are printed.

[dushyant7917]

I'm just curling the OPA server with some input
curl -v "http://127.0.0.1:8181/v1/data/httpapi/authz?metrics&pretty" -d '{"input": {...}}'

[charlieegan3]

When you use a WASM bundle in an OPA instance, there are other functions such as the parsing of the input and the server handler which are not running in the Wasm VM.

If you see this function evalWasm:

https://github.com/open-policy-agent/opa/blob/a23086258f0ccd496e8e11c31e61700bf122d1e6/rego/rego.go#L2027

It's called by eval:

https://github.com/open-policy-agent/opa/blob/a23086258f0ccd496e8e11c31e61700bf122d1e6/rego/rego.go#L1954

Which is called by Eval:

https://github.com/open-policy-agent/opa/blob/a23086258f0ccd496e8e11c31e61700bf122d1e6/rego/rego.go#L402

Which is called by the server in v1 data get:

https://github.com/open-policy-agent/opa/blob/a23086258f0ccd496e8e11c31e61700bf122d1e6/server/server.go#L1469

As you can see, by the time the wasm is executed, we are already a few layers into the Rego package. This means that we see some of the rego metrics in the result.

[dushyant7917]

Thanks for above information.
Regarding the time, timer_wasm_vm_eval_ns is inclusive of timer_wasm_vm_eval_call_ns and timer_wasm_vm_eval_prepare_input_ns.

[charlieegan3]

Yes, that's what I see here: https://github.com/open-policy-agent/opa/blob/1c36d3c25ca314aa5b8f49e264f7efcfc8f4e612/internal/wasm/sdk/internal/wasm/vm.go#L282-L337