Indexes needed on A/T event output fields

[Jason Boyer]

Now that we have a consistent method to clean up action trigger events they and their outputs are actually being deleted more commonly. Anecdotally it used to take 20 minutes to delete a single action_trigger.event_output entry, but that was when we needed to delete many more millions of rows than we currently do. Even having only 1.1 million entries remaining takes almost 2 seconds to delete a single entry:

 Delete on event_output (cost=0.42..8.44 rows=1 width=6) (actual time=0.075..0.075 rows=0 loops=1)
   -> Index Scan using event_output_pkey on event_output (cost=0.42..8.44 rows=1 width=6) (actual time=0.040..0.041 rows=1 loops=1)
         Index Cond: (id = 12369927)
 Planning time: 0.086 ms
 Trigger for constraint event_async_output_fkey: time=948.152 calls=1
 Trigger for constraint event_error_output_fkey: time=342.124 calls=1
 Trigger for constraint event_template_output_fkey: time=487.213 calls=1
 Execution time: 1777.614 ms

So it takes .04ms to locate the entry to delete, but before deletion referential integrity must be maintained so aysnc_output, error_output, and template_output are each hit with a seq scan to make sure it's ok to delete that output entry, adding up to almost 2 seconds.

Then I added indexes on action_trigger.event.template_output, async_output, and error_output:

 Delete on event_output (cost=0.42..8.44 rows=1 width=6) (actual time=0.273..0.273 rows=0 loops=1)
   -> Index Scan using event_output_pkey on event_output (cost=0.42..8.44 rows=1 width=6) (actual time=0.145..0.147 rows=1 loops=1)
         Index Cond: (id = 12369928)
 Planning time: 0.553 ms
 Trigger for constraint event_async_output_fkey: time=0.588 calls=1
 Trigger for constraint event_error_output_fkey: time=0.444 calls=1
 Trigger for constraint event_template_output_fkey: time=1.053 calls=1
 Execution time: 2.389 ms

Why, hello. 4 index lookups instead of 1 + 3 seq scans on the same enormous table. Repairs en route.

[Jason Boyer (jboyer)]

A little slower than I'd hoped but here it is: http://git.evergreen-ils.org/?p=working/Evergreen.git;a=shortlog;h=refs/heads/user/jboyer/lp1778940_ate_indexes working/user/jboyer/lp1778940_ate_indexes

[Josh Stompro (u-launchpad-stompro-org)]

I was curious how much extra space this would take up, so here are the stats from our system.

Before:

select count(*)
,pg_size_pretty (pg_relation_size('action_trigger.event')) "Table Size"
,pg_size_pretty (pg_total_relation_size('action_trigger.event')) "Total Table Size"
,pg_size_pretty (pg_indexes_size('action_trigger.event')) "Index Size"
from action_trigger.event
;
  count | Table Size | Total Table Size | Index Size
---------+------------+------------------+------------
 2904488 | 311 MB | 548 MB | 237 MB

After:

  count | Table Size | Total Table Size | Index Size
---------+------------+------------------+------------
 2904488 | 311 MB | 735 MB | 424 MB

So with 2,904,488 events, the indices size increased by 187MB. This is before using the new event purging features, so I think the actual impact will be much less than that after the purging is done. It seems worth it for us, to have the event purging finish in seconds rather than hours, and the amount of space used should be fine.

The other option would be to add and remove the indices only when needed, as part of the purging process since that seems like the only time they are normally used. If a site had a problem with the extra space used, they could go that route.

I'll work on a signoff.
Josh

[Josh Stompro (u-launchpad-stompro-org)]

Signoff branch at
user/stompro/lp1778940_ate_indexes_signoff

https://git.evergreen-ils.org/?p=working/Evergreen.git;a=shortlog;h=refs/heads/user/stompro/lp1778940_ate_indexes_signoff

Josh

[Galen Charlton (gmc)]

Pushed to master, rel_3_3, and rel_3_2. Thanks Jason and Josh!