Patron Search - certain barcodes can result in runaway query

[Doug Kyle]

EG 2.1
Pg 9.0

If you have many barcodes that are all numerals and start with a certain sequence, a query from the patron search form can result in a very bad plan, such as:

explain SELECT evergreen.lowercase(CAST(users.family_name AS text)), evergreen.lowercase(CAST(users.first_given_name AS text)), evergreen.lowercase(CAST(users.id AS text))
FROM actor.usr AS users JOIN (SELECT DISTINCT usr FROM actor.card WHERE evergreen.lowercase(barcode) LIKE '21307'||'%') AS card ON (card.usr = users.id)
JOIN actor.org_unit_descendants(10, 0) d ON (d.id = users.home_ou)
JOIN (SELECT id as id FROM actor.usr u WHERE evergreen.lowercase(CAST(profile AS text)) ~ '^') AS search ON (search.id = users.id)
                   WHERE users.deleted = FALSE

                   GROUP BY evergreen.lowercase(CAST(users.family_name AS text)), evergreen.lowercase(CAST(users.first_given_name AS text)), evergreen.lowercase(CAST(users.id AS text))
                   ORDER BY evergreen.lowercase(CAST(users.family_name AS text)) , evergreen.lowercase(CAST(users.first_given_name AS text)) , evergreen.lowercase(CAST(users.id AS text))
                   LIMIT 51;
                                                                           QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit (cost=-23493470903261368.00..-23493470903261368.00 rows=51 width=17)
   -> Sort (cost=-23493470903261368.00..-23493470903261360.00 rows=2801 width=17)
         Sort Key: (lowercase(users.family_name)), (lowercase(users.first_given_name)), (lowercase((users.id)::text))
         -> HashAggregate (cost=-23493470903263604.00..-23493470903261460.00 rows=2801 width=17)
               -> Merge Join (cost=-23493470903266188.00..-23493470903263624.00 rows=2801 width=17)
                     Merge Cond: (users.home_ou = d.id)
                     -> Sort (cost=-23493470903266188.00..-23493470903265984.00 rows=81232 width=21)
                           Sort Key: users.home_ou
                           -> Nested Loop (cost=-28783.12..-23493470903272812.00 rows=81232 width=21)
                                 Join Filter: (actor.card.usr = u.id)
                                 -> Seq Scan on usr u (cost=0.00..262462.50 rows=951148 width=4)
                                       Filter: (lowercase((profile)::text) ~ '^'::text)
                                 -> Nested Loop (cost=-28783.12..-24700122241.05 rows=81232 width=25)
                                       Join Filter: (users.id = actor.card.usr)
                                       -> Seq Scan on usr users (cost=0.00..17517.43 rows=944806 width=21)
                                             Filter: (NOT deleted)
                                       -> HashAggregate (cost=-28783.12..-27970.80 rows=81232 width=4)
                                             -> Index Scan using actor_card_barcode_evergreen_lowercase_idx on card (cost=0.50..-29305.58 rows=208984 width=4)
                                                   Index Cond: ((lowercase(barcode) >= '21307'::text) AND (lowercase(barcode) < '21308'::text))
                                                   Filter: (lowercase(barcode) ~~ '21307%'::text)
                     -> Materialize (cost=0.27..0.28 rows=1 width=4)
                           -> Sort (cost=0.27..0.28 rows=1 width=4)
                                 Sort Key: d.id
                                 -> Function Scan on org_unit_descendants d (cost=0.25..0.26 rows=1 width=4)

The client throws a network error and continues, but you have a runaway query in the database.

Removing the lowercase(barcode) function does much better:
explain SELECT evergreen.lowercase(CAST(users.family_name AS text)), evergreen.lowercase(CAST(users.first_given_name AS text)), evergreen.lowercase(CAST(users.id AS text))
FROM actor.usr AS users JOIN (SELECT DISTINCT usr FROM actor.card WHERE barcode LIKE '21307'||'%') AS card ON (card.usr = users.id)
JOIN actor.org_unit_descendants(10, 0) d ON (d.id = users.home_ou)
JOIN (SELECT id as id FROM actor.usr u WHERE evergreen.lowercase(CAST(profile AS text)) ~ '^') AS search ON (search.id = users.id)
                   WHERE users.deleted = FALSE

                   GROUP BY evergreen.lowercase(CAST(users.family_name AS text)), evergreen.lowercase(CAST(users.first_given_name AS text)), evergreen.lowercase(CAST(users.id AS text))
                   ORDER BY evergreen.lowercase(CAST(users.family_name AS text)) , evergreen.lowercase(CAST(users.first_given_name AS text)) , evergreen.lowercase(CAST(users.id AS text))
                   LIMIT 51;
                                                             QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------
 Limit (cost=28822.83..28822.96 rows=51 width=17)
   -> Sort (cost=28822.83..28829.84 rows=2801 width=17)
         Sort Key: (lowercase(users.family_name)), (lowercase(users.first_given_name)), (lowercase((users.id)::text))
         -> HashAggregate (cost=26586.62..28729.39 rows=2801 width=17)
               -> Nested Loop (cost=19721.73..26565.61 rows=2801 width=17)
                     -> Hash Join (cost=19721.73..21679.00 rows=2801 width=21)
                           Hash Cond: (actor.card.usr = users.id)
                           -> HashAggregate (cost=10224.77..11037.09 rows=81232 width=4)
                                 -> Bitmap Heap Scan on card (cost=2831.57..9702.31 rows=208984 width=4)
                                       Filter: (barcode ~~ '21307%'::text)
                                       -> Bitmap Index Scan on card_barcode_key (cost=0.00..2779.32 rows=201499 width=0)
                                             Index Cond: ((barcode >= '21307'::text) AND (barcode < '21308'::text))
                           -> Hash (cost=9089.71..9089.71 rows=32580 width=17)
                                 -> Nested Loop (cost=346.68..9089.71 rows=32580 width=17)
                                       -> Function Scan on org_unit_descendants d (cost=0.25..0.26 rows=1 width=4)
                                       -> Bitmap Heap Scan on usr users (cost=346.43..8679.44 rows=32801 width=21)
                                             Recheck Cond: (users.home_ou = d.id)
                                             Filter: (NOT users.deleted)
                                             -> Bitmap Index Scan on actor_usr_home_ou_idx (cost=0.00..338.28 rows=32801 width=0)
                                                   Index Cond: (users.home_ou = d.id)
                     -> Index Scan using usr_pkey on usr u (cost=0.00..0.98 rows=1 width=4)
                           Index Cond: (u.id = actor.card.usr)
                           Filter: (lowercase((u.profile)::text) ~ '^'::text)

Patch against master attached.

[Jason Stephenson (jstephenson)]

Branchified:

For sharing lp874603 via the remote repo working:

You need only add the remote once, regardless of how many branches you wish to look at.
To add this repo as working:
 Read-only (git protocol):
  git remote add working git://git.evergreen-ils.org/working/Evergreen
 Read-write (ssh protocol):
  git remote add working <email address hidden>:working/Evergreen

Once you have the remote added you can check out this branch:
git checkout -b lp874603 working/collab/dyrcona/lp874603

For sharing lp874603_2_1 via the remote repo working:

You need only add the remote once, regardless of how many branches you wish to look at.
To add this repo as working:
 Read-only (git protocol):
  git remote add working git://git.evergreen-ils.org/working/Evergreen
 Read-write (ssh protocol):
  git remote add working <email address hidden>:working/Evergreen

Once you have the remote added you can check out this branch:
git checkout -b lp874603_2_1 working/collab/dyrcona/lp874603_2_1

Not tested, and therefore not signed off, yet.

[Dan Scott (denials)]

Before we throw away case-insensitive search on the barcode column (someone must be using that somewhere, right?), let's dig into the history of this problem. It arose because we replaced the use of the native LOWER() function with the plperl evergreen.lowercase() function back in aa0ec9cba396a8b89322fc05a3c0664e16e69f2e - and as a result, the PostgreSQL planner assumes that the function will have an execution cost of 100 (vs. the native LOWER() function's cost of 1). The planner therefore ends up generating a bad plan, rather than relying on the index.

A much simpler fix, therefore, is simply to define a lower cost for this function:

-- For an existing database:
ALTER FUNCTION evergreen.lowercase(TEXT) COST 10;

Doing this resulted in sane results on our production database, versus the insane results that we saw with the default value.

If sites like Michigan with much larger patron databases than ours can reproduce this successfully, we can just add "COST 10" to the definition of the evergreen.lowercase() function and maintain case-insensitive search on the barcode column.

[Bill Ott (bott)]

Indeed, some planner teaching does seem to do the trick. Doing so here in Michigan (950K+ usr, 2.1M+ card), results in a plan for 34sec, and an actual execution of about 14sec.

[Jason Stephenson (jstephenson)]

So, is this a bug or just a question of optimization?

[Mike Rylander (mrylander)]

The latter, and one that can be addressed (if it isn't already) at schema creation/update time with Dan's ALTER command.

[Michael Peters (mrpeters)]

So, Won't Fix this one? Invalid?

[Tiffany Little (tslittle)]

From the comments, sounds like this is a Won't Fix. It can be revived if anyone objects.