Slow queries when events of a type are rare.

[macosgrove]

RSS, an Event Sourcery project, was having problems with the database CPU usage increasing over time:

We turned on Postgres logging to look for slow queries and found these two:

SELECT * FROM "events" 
WHERE ("type" IN ('revenue_period_voided', 'revenue_period_ended')) 
ORDER BY "id" DESC 
LIMIT 1

and

SELECT * FROM "events" 
WHERE ((id >= 3616762) AND ("type" IN ('revenue_period_voided', 'revenue_period_ended'))) 
ORDER BY "id" 
LIMIT 1000

RSS stopped emitting events of type revenue_period_ended and revenue_period_voided some time ago but we had not turned off their projector.

The dip in the CPU graph is when we disabled the relevant projector.

The implication here is that any projector that deals with RARE events will run slow.

@envatopoho is investigating indexes that may resolve the issue.

[envatopoho]

Have done some digging (many thanks to @gstib for his help) and found that we are pretty well as optimised as we are going to get with the database indexes. We tried a bunch of different indexes, combinations etc but it always decided to use the primary key index and filter the results.

I think a possible fix is for Event Sourcery to maintain an index to the 'top' of the event store (since it last checked for that particular event type) and only check for subsequent events of that type from when it last checked (rather than for all time).

[macosgrove]

Looks like that first query is coming from latest_event_id and the second from get_next_from in EventStore

But I can't find any calls of latest_event_id

[macosgrove]

Our next slowest query is

SELECT * FROM "events" 
WHERE ("type" IN ('subscriber_billing_details_update_failed')) 
ORDER BY "id" DESC 
LIMIT 1

'subscriber_billing_details_update_failed' is a rare event.

Even after turning off the revenue period projector, we are seeing a slow rise in CPU usage:

[envatopoho]

Same thing with this query, it uses the primary key index to get results and then filters:

"QUERY PLAN"
"Limit  (cost=0.43..32.78 rows=1 width=413) (actual time=302.200..302.201 rows=1 loops=1)"
"  ->  Index Scan Backward using events_pkey on events  (cost=0.43..517975.03 rows=16015 width=413) (actual time=302.198..302.198 rows=1 loops=1)"
"        Filter: ((type)::text = 'subscriber_billing_details_update_failed'::text)"
"        Rows Removed by Filter: 723668"
"Planning time: 0.109 ms"
"Execution time: 302.224 ms"

[ricobl]

We have identified this issue again where there were no recent events that a certain projector cares about, the tracker was stuck in a past event while the event store keeps growing.

The challenge here is keeping a good compromise in performance, only loading specific event types but also finding a way to advance the tracker when there are no event types for the processor.

We could consider loading all types of events and only forwarding the ones that the processor cares about. This would allow for advancing the tracker but would have additional burden on all projectors.

Also considered having an additional query to get the latest event (of any type) after an empty result, but this could cause skipping events.

In the meantime, our workaround was to register a dummy handler for another event type that is known to be frequent:

project FrequentEvent do
  # no-op
end