call number browse at top org_unit extremely slow

Bug #1373693 reported by Chris Sharp
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Evergreen
Fix Released
Medium
Unassigned
2.5
Fix Released
Medium
Unassigned
2.6
Fix Released
Medium
Unassigned

Bug Description

Call number browse in the PINES OPAC times out when the top level org_unit, "PINES" is selected.

What follows is the EXPLAIN ANALYZE output of the resulting query:

 Limit (cost=4428591.74..4428591.75 rows=4 width=99) (actual time=29400.367..29400.369 rows=4 loops=1)
   -> Sort (cost=4428591.74..4436305.56 rows=3085528 width=99) (actual time=29400.366..29400.366 rows=4 loops=1)
         Sort Key: ((regexp_replace(upper(label_sortkey), '\\'::text, '\\\\'::text, 'g'::text))::bytea), ((regexp_replace(upper(label), '\\'::text, '\\\\'::text, 'g'::text))::bytea), id, owning_lib
         Sort Method: top-N heapsort Memory: 25kB
         -> Bitmap Heap Scan on call_number acn (cost=111712.83..4382308.82 rows=3085528 width=99) (actual time=1028.886..26430.204 rows=4051517 loops=1)
               Recheck Cond: ((regexp_replace(upper(label_sortkey), '\\'::text, '\\\\'::text, 'g'::text))::bytea < '\x464943'::bytea)
               Filter: ((NOT deleted) AND (owning_lib = ANY ('{1,6,6,9,9,10,10,11,11,12,12,13,13,14,14,15,15,16,16,18,18,19,19,20,20,17,17,7,7,8,8,25,25,27,27,26,26,28,28,29,29,30,30,33,33,35,35,34,34,36,36,38,38,37,37,39,39,44,44,42,42,43,43,40,40,45,45,41,41,211,211,212,212,21,21,23,23,24,24,22,22,177,177,178,178,181,181,180,180,179,179,301,301,307,307,309,309,305,305,310,310,303,303,306,306,308,308,304,304,213,213,214,214,215,215,361,361,182,182,183,183,65,65,67,67,66,66,203,203,136,136,204,204,206,206,207,207,208,208,210,210,205,205,209,209,87,87,88,88,89,89,90,90,91,91,92,92,93,93,94,94,95,95,197,197,198,198,200,200,201,201,199,199,202,202,55,55,57,57,56,56,347,347,46,46,48,48,49,49,366,366,51,51,52,52,53,53,54,54,357,357,47,47,50,50,58,58,59,59,60,60,62,62,63,63,64,64,61,61,80,80,81,81,82,82,84,84,83,83,102,102,103,103,104,104,105,105,106,106,114,114,107,107,108,108,109,109,110,110,111,111,112,112,113,113,369,369,122,122,123,123,124,124,129,129,125,125,127,127,128,128,126,126,130,130,152,152,155,155,153,153,154,154,156,156,159,159,157,157,158,158,161,161,160,160,351,351,162,162,216,216,217,217,218,218,219,219,220,220,221,221,224,224,223,223,222,222,225,225,226,226,227,227,228,228,229,229,230,230,231,231,342,342,232,232,340,340,233,233,239,239,240,240,241,241,242,242,243,243,244,244,246,246,247,247,248,248,249,249,250,250,251,251,237,237,238,238,245,245,234,234,236,236,235,235,260,260,261,261,263,263,264,264,266,266,265,265,318,318,267,267,269,269,270,270,271,271,273,273,272,272,268,268,292,292,293,293,297,297,294,294,298,298,299,299,295,295,296,296,140,140,142,142,300,300,143,143,144,144,367,367,141,141,115,115,117,117,118,118,116,116,360,360,68,68,77,77,73,73,76,76,79,79,71,71,72,72,75,75,69,69,78,78,184,184,186,186,185,185,189,189,191,191,193,193,187,187,188,188,194,194,190,190,196,196,192,192,195,195,311,311,315,315,314,314,313,313,316,316,317,317,312,312,119,119,120,120,121,121,131,131,132,132,134,134,135,135,137,137,138,138,139,139,133,133,353,353,356,356,354,354,355,355,321,321,326,326,323,323,324,324,322,322,346,346,262,262,328,328,333,333,337,337,329,329,336,336,331,331,330,330,335,335,145,145,146,146,149,149,150,150,151,151,148,148,147,147,350,350,163,163,166,166,352,352,165,165,168,168,169,169,172,172,174,174,170,170,176,176,349,349,167,167,164,164,171,171,175,175,173,173,320,320,319,319,358,358,344,344,345,345,96,96,99,99,97,97,100,100,101,101,98,98,2,2,3,3,5,5,4,4,252,252,254,254,257,257,258,258,256,256,259,259,255,255,343,343,253,253,31,31,32,32,85,85,86,86,362,362,74,74,70,70,365,365,289,289,284,284,285,285,286,286,287,287,288,288,291,291,290,290,275,275,278,278,279,279,280,280,281,281,282,282,276,276}'::integer[])))
               Rows Removed by Filter: 434547
               -> Bitmap Index Scan on asset_call_number_label_sortkey (cost=0.00..110941.44 rows=4421450 width=0) (actual time=958.373..958.373 rows=4489554 loops=1)
                     Index Cond: ((regexp_replace(upper(label_sortkey), '\\'::text, '\\\\'::text, 'g'::text))::bytea < '\x464943'::bytea)
 Total runtime: 29400.527 ms

This occurs after creating a new index:

evergreen=# create index concurrently pines_asset_call_number_upper_label_id_owning_lib_idx on asset.call_number (oils_text_as_bytea(label), owning_lib) where not deleted;

Evergreen 2.5.1
Postgres 9.3
OpenSRF 2.2
Ubuntu 14.04 LTS (database server)

Tags: pullrequest
Revision history for this message
Chris Sharp (chrissharp123) wrote :

Thanks to Mike Rylander and Ben Shum for their help getting this done:

http://git.evergreen-ils.org/?p=working/Evergreen.git;a=shortlog;h=refs/heads/user/csharp/lp_1373693_fix_slow_cn_browse

user/csharp/lp_1373693_fix_slow_cn_browse

Changed in evergreen:
assignee: nobody → Chris Sharp (chrissharp123)
importance: Undecided → High
importance: High → Medium
milestone: none → 2.7.1
tags: added: pullrequest
Revision history for this message
Ben Shum (bshum) wrote :

Worked for me in testing, pushed to master and backported to rel_2_7, rel_2_6, and rel_2_5.

Changed in evergreen:
status: New → Fix Committed
assignee: Chris Sharp (chrissharp123) → nobody
Changed in evergreen:
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.