Indexes needed on A/T event output fields

Bug #1778940 reported by Jason Boyer on 2018-06-27
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Evergreen
Medium
Unassigned
3.2
Medium
Unassigned

Bug Description

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) wrote :

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

tags: added: pullrequest
Jason Boyer (jboyer) on 2018-10-09
Changed in evergreen:
milestone: none → 3.2.1
Changed in evergreen:
milestone: 3.2.1 → 3.2.2
Changed in evergreen:
milestone: 3.2.2 → 3.2.3
Changed in evergreen:
milestone: 3.2.3 → 3.3-beta1
tags: added: actiontrigger

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

tags: added: signedoff
Changed in evergreen:
milestone: 3.3-beta1 → 3.3-rc
Changed in evergreen:
milestone: 3.3-rc → 3.3.1
Galen Charlton (gmc) on 2019-04-24
Changed in evergreen:
assignee: nobody → Galen Charlton (gmc)
Galen Charlton (gmc) on 2019-04-24
Changed in evergreen:
status: New → Confirmed
importance: Undecided → Medium
status: Confirmed → Fix Committed
assignee: Galen Charlton (gmc) → nobody
Galen Charlton (gmc) wrote :

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

Changed in evergreen:
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers