Migration from v0.x to v1.x made policy evaluation significantly slower

[piax93]

Short description

We have recently modernized our policies and OPA deployment to v1. Unexpectedly, without any actual modification being made to the policy code (apart from the required additional v1 syntax) or the input data, we have been observing significantly slower policy evaluation. In our main use case, this brought the average eval time from 1.9ms to 3.5ms (yes, almost double).
I'd appreciate if you could comment on possible reasons why this is happening, because honestly it has been quite strange to see.

Steps To Reproduce

The OPA versions we have been working with are:

• Before: 0.70.0
• Now: 1.12.1

We tried to do a bit of profiling of our policies, and this is an example of what we see (the arrows indicate v0 -> v1 numbers):

path.rego
  METRICS:
  - timer_rego_external_resolve_ns: 260 -> 264
  - timer_rego_load_files_ns: 231987 -> 382944
  - timer_rego_module_compile_ns: 990473 -> 3554274
  - timer_rego_module_parse_ns: 184491 -> 327298
  - timer_rego_query_compile_ns: 50437 -> 83776
  - timer_rego_query_eval_ns: 11991 -> 22304
  - timer_rego_query_parse_ns: 19809 -> 19939
  PROFILE:
  - total_time_ns: 12771 -> 23436

Where path.rego is a module that looks something like this:

package path

default enabled := false
default rule_name := "UNKNOWN"
environment := opa.runtime().env.ENVIRONMENT
service_config := data.paths[input.service]

always_allowed_paths := data.always_allowed_paths if {
	data.always_allowed_paths
} else := ["/status"]

enabled if {
	service_config
	service_config.enabled
	not input.path in always_allowed_paths
} else if {
	service_config
	service_config.cluster_enabled[environment]
	not input.path in always_allowed_paths
}

match_longest_path_prefix(paths, search_path) := longest_prefix if {
	matching_prefixes := [[count(rule_path), rule_path] |
		rule_path := object.keys(paths)[_]
		startswith(search_path, rule_path)
	]
	longest_prefix := max(matching_prefixes)[1]
}

rule_name := rule if {
	enabled
	input.method
	count(service_config.paths_by_method) == 1
	rule := object.get(service_config.paths_by_method[""], input.method, "NO_HTTP_METHOD")
} else := rule if {
	enabled
	input.method
	path_prefix := match_longest_path_prefix(service_config.paths_by_method, input.path)
	rule := object.get(service_config.paths_by_method[path_prefix], input.method, "NO_HTTP_METHOD")
} else := rule if {
	enabled
	not input.method
	rule := "MISSING_METHOD_INPUT"
}

Our query input just has 4 simple string fields, and data.paths is just a few nested objects, not insanely large, can fit in <100KB of memory.

Expected behavior

I would have expected performance to remain more or less the same, if not better, considering that some of the 1.x releases in between the ones we have been using promise some optimizations happening.

Additional context

N/A

[anderseknert]

Hey!

And thanks for reporting this. That sounds odd indeed, as the performance improvements in mainly Eval since 0.x are many and clearly measurable. Looking at the numbers you provided, the time spent in evaluation seems to have gone from 0.01 milliseconds to 0.02 milliseconds. So that's just noise really. Where it looks like we have a more substantial regression is in compile time, as that accounts for almost the whole increase in total time reported.

That's obviously not good, and something for us to look into. But at the same time — compilation time in that span wouldn't normally be something you'd have to worry about, as it's a one-time cost paid only when your Rego is loaded and compiled into OPA. Subsequent queries would pay nothing for e.g. timer_rego_load_files_ns or timer_rego_module_compile_ns until you update your policies and/or data.

Another thing I'd be interested in — could you run the eval using the latest OPA but with --v0-compatible provided? That'll give us an idea about if the increase in cost comes from something introduced in the language since, or if there's a general regression in compiler performance even when dealing with an identical policy. Thanks!

[piax93]

I modified the experiment to be a bit closer to what may happen on production systems, using a whole policy bundle rather than a single package, and tried to be a bit more scientific about measurements, given the significant margins of error when dealing with microseconds, and now the situation is definitely favourable to v1 in the profiling data:

# v0
{
  "timer_rego_data_parse_ns": 11315100,
  "timer_rego_external_resolve_ns": 894,
  "timer_rego_load_bundles_ns": 21734034,
  "timer_rego_module_compile_ns": 13201034,
  "timer_rego_module_parse_ns": 2585363,
  "timer_rego_query_compile_ns": 108652,
  "timer_rego_query_eval_ns": 1226732,
  "timer_rego_query_parse_ns": 70599
}

# v1 v0-compat
{
  "timer_rego_data_parse_ns": 11478454,
  "timer_rego_external_resolve_ns": 552,
  "timer_rego_load_bundles_ns": 23263151,
  "timer_rego_module_compile_ns": 7858804,
  "timer_rego_module_parse_ns": 2739297,
  "timer_rego_query_compile_ns": 113338,
  "timer_rego_query_eval_ns": 919121,
  "timer_rego_query_parse_ns": 25840
}

# v1
{
  "timer_rego_data_parse_ns": 10839916,
  "timer_rego_external_resolve_ns": 494,
  "timer_rego_load_bundles_ns": 21088182,
  "timer_rego_module_compile_ns": 7420772,
  "timer_rego_module_parse_ns": 2337370,
  "timer_rego_query_compile_ns": 105134,
  "timer_rego_query_eval_ns": 843493,
  "timer_rego_query_parse_ns": 24552
}

# (values are medians of 500 evals)

So effectively profiling is not telling me much about why when deployed as a server, with the same hardware configuration, v1 appears to have slower evaluation time than v0.

I suppose this must be a matter of different ways load is handled, because that's definitely a factor that opa eval does not simulate. I do have noticed that the memory footprint for v1 is a little bit lower, so maybe there is less caching happening?

[anderseknert]

Thanks for that new data @piax93! That's very helpful, and indeed shows v1 performing better on pretty much every single metric, as far as I can see.

So effectively profiling is not telling me much about why [ ... ] v1 appears to have slower evaluation time than v0

Making me curious about what it is that's telling you that? You can get the same metrics from OPA running as a server by using some query params https://www.openpolicyagent.org/docs/rest-api#data-api

It'd be interesting to see what you find there.

[piax93]

We get performance metrics in decision logs. These are two 24h aggregations from v0 and v1 respectively:

# v0
{
    "median(metrics.timer_rego_external_resolve_ns)": "1385",
    "median(metrics.timer_rego_input_parse_ns)": "43030",
    "median(metrics.timer_rego_query_eval_ns)": "1721375",
    "median(metrics.timer_server_handler_ns)": "1817723"
}

# v1
{
    "median(metrics.timer_rego_external_resolve_ns)": "1092",
    "median(metrics.timer_rego_input_parse_ns)": "42483",
    "median(metrics.timer_rego_query_eval_ns)": "3601272",
    "median(metrics.timer_server_handler_ns)": "3709227"
}

Input parsing is very stable, and also the server handler overhead is comparable, while query eval goes through the roof.

And to give more context, we learnt a couple years ago that OPA tends to be fairly "core hungry" in order to provide good performance (I guess there are a few goroutines shoving data around), so the instance where we run this has 8 cores and 16gb of memory allocated to give it space. And we have a cache in front of it to avoid this latency propagating to downstream systems that does most of the heavy lifting, what OPA deals with is in the order of 10-20 req/s. CPU metrics never show anything over 1% considering how overprovisioned it is. Hence the confusion in seeing these numbers.