Deleting patrons can exceed staff client timeouts

Bug #1758160 reported by Blake GH on 2018-03-22
18
This bug affects 3 people
Affects Status Importance Assigned to Milestone
Evergreen
Undecided
Unassigned
3.0
Undecided
Unassigned

Bug Description

It's possible for patrons with a large number of circulations and other related things to cause postgres to take to long to get results back to the OpenSRF call.

The logs show this:
open-ils.cstore.json_query.atomic {"from":["actor.usr_delete",PATRONID,null]}

The subsequent query is:

select from actor.usr_delete(PATRONID,null)

That query will do many things. One of which is calling:
perform actor.usr_purge_data( src_usr, dest_usr );

which eventually calls
DELETE FROM action.circulation WHERE usr = src_usr;
followed by

  BEFORE DELETE
  ON action.circulation
  FOR EACH ROW
  EXECUTE PROCEDURE action.age_circ_on_delete();

There is a slowness here. I executed explain analyze DELETE FROM action.circulation WHERE usr = TESTUSERID;

and I found that
Trigger for constraint usr_circ_history_source_circ_fkey: time=116932.556 calls=978

Took the lions share of the time. This lead me to create and index

CREATE INDEX action_usr_circ_history_source_circ_idx
  ON action.usr_circ_history
  USING btree
  (source_circ);

And viola - the same explain analyze

Trigger for constraint usr_circ_history_source_circ_fkey: time=13.212 calls=978

Branch soon.

Dan Wells (dbw2) on 2018-03-29
Changed in evergreen:
milestone: none → 3.1.1
status: New → Confirmed
Dan Wells (dbw2) wrote :

Blake, thanks for this fix! Just a note, the branch has the upgrade script, but it still needs to add the same thing to the main schema files somewhere.

Blake GH (bmagic) wrote :

Oops! I knew that. Push forced, same link.

Changed in evergreen:
milestone: 3.1.1 → 3.1.2
Michele Morgan (mmorgan) wrote :

This patch did not do the trick in my testing. Attempts to delete *some* patrons still times out in the client.

Here's an EXPLAIN ANALYZE for one such patron subsequent to applying the patch :

EXPLAIN ANALYZE delete from action.circulation where usr = 2082592;

                                                QUERY PLAN
--------------------------------------------------------------------------------------------------------
 Delete on circulation (cost=0.44..951.43 rows=481 width=6) (actual time=532.420..532.420 rows=0 loops=1)
   -> Index Scan using circ_all_usr_idx on circulation (cost=0.44..951.43 rows=481 width=6) (actual time=0.234..19.172 rows=1313 loops=1)
         Index Cond: (usr = 2082592)
 Planning time: 1.751 ms
 Trigger for constraint circulation_limit_group_map_circ_fkey: time=59.308 calls=1261
 Trigger for constraint usr_circ_history_source_circ_fkey: time=156220.717 calls=1261
 Trigger action_circulation_aging_tgr: time=505.381 calls=1313
 Trigger age_parent_circ: time=6492.583 calls=1261
 Trigger mat_summary_remove_tgr: time=133.659 calls=1261
 Execution time: 163442.200 ms
(10 rows)

It is interesting to note that this patron has zero rows in action.usr_circ_history.

Leaving the pullrequest tag in place and would welcome other testers.

Changed in evergreen:
milestone: 3.1.2 → 3.1.3
Jason Boyer (jboyer) wrote :

For me this issue addresses both user purging and circ aging. I've got a signoff branch with tweaked upgrade script here: http://git.evergreen-ils.org/?p=working/Evergreen.git;a=shortlog;h=refs/heads/user/jboyer/lp1758160_auch_index_signoff working/user/jboyer/lp1758160_auch_index_signoff

I'll also mark my bug about aging circs as a duplicate of this one.

tags: added: signedoff
Jason Stephenson (jstephenson) wrote :

I have also been testing this patch and it works for me, too. I have seen an 80% drop in the time to age circulations and a 75% drop in the time to purge users on my test database with this index added.

Michele's comment raises a valid concern, but I think adding the index is better than nothing at this point. We can always revisit the performance of this later if something else comes up.

I have signed off and pushed this to master, rel_3_1, and rel_3_0 for posterity.

Changed in evergreen:
status: Confirmed → Fix Committed
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.

Duplicates of this bug

Other bug subscribers