[FOLIO-2197] Research "get inventory items by status" slow in perf test Created: 29/Jul/19 Updated: 03/Jun/20 Resolved: 31/Jul/19 |
|
| Status: | Closed |
| Project: | FOLIO |
| Components: | None |
| Affects versions: | None |
| Fix versions: | None |
| Type: | Task | Priority: | P2 |
| Reporter: | Hongwei Ji | Assignee: | Hongwei Ji |
| Resolution: | Done | Votes: | 0 |
| Labels: | platform-backlog | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original estimate: | Not Specified | ||
| Issue links: |
|
||||||||||||||||
| Sprint: | CP: sprint 69 | ||||||||||||||||
| Story Points: | 2 | ||||||||||||||||
| Development Team: | Core: Platform | ||||||||||||||||
| Description |
|
Problem In the "perf-test-platform" run #206 "GET inventory_items?query=(status.name=="Available")&limit={limit} takes 160s. Tasks
According to the Postgres manual "If pattern does not contain percent signs or underscores, then the pattern only represents the string itself; in that case LIKE acts like the equals operator". https://www.postgresql.org/docs/current/functions-matching.html If the performance is indeed different we will need to update the CQL alogorithm to convert all exact string matching without wildcards to '='. If the performance is non-deterministic it might be related to the lack of statistics for JSON fields in Postgres. In this case it might make sense to consider the workaround Julian Ladisch implemented for FT queries in
|
| Comments |
| Comment by Hongwei Ji [ 29/Jul/19 ] |
|
Tested the query separately and the performance is not that bad. See below sql statements generated and the timing info. There were no index warning in mod-inventory-storage because all queried fields have the proper indexes defined. 2019-07-29 18:04:47.374 UTC [614] LOG: duration: 6863.689 ms statement: SELECT COUNT(*) FROM supertenant_mod_inventory_storage.item WHERE lower(f_unaccent(item.jsonb->'status'->>'name')) LIKE lower(f_unaccent('Available')) 2019-07-29 18:04:47.375 UTC [614] LOG: duration: 0.686 ms statement: SELECT * FROM supertenant_mod_inventory_storage.item WHERE lower(f_unaccent(item.jsonb->'status'->>'name')) LIKE lower(f_unaccent('Available')) LIMIT 20 OFFSET 0 2019-07-29 18:04:47.395 UTC [614] LOG: duration: 0.997 ms statement: SELECT COUNT(*) FROM supertenant_mod_inventory_storage.holdings_record WHERE (((((((((((((((((((id='cf5bc53e-0c06-427e-b35b-89eded77d76e') OR (id='450dca09-5974-47d7-b02a-db444ecc17b0')) OR (id='ea1dd83f-4534-4a24-85d1-b7c55bcda42b')) OR (id='e1a4ab4a-d5b7-476c-89f4-2e59ca3d40cf')) OR (id='d73d759d-4b49-4d4e-9879-f40e006226a1')) OR (id='2668bd61-60ea-4a02-a81f-5b5fdca39d6e')) OR (id='113accf7-4aed-401b-99ac-9b81427d86f0')) OR (id='3499b364-7e94-473a-a91d-bd597b5baa1b')) OR (id='172da435-8691-4fca-89a5-496b5ea7b022')) OR (id='97126271-cc04-4500-9d4e-cb1e95ab1f6d')) OR (id='3320dca8-c981-48b1-a5f3-a9e0023649ea')) OR (id='33a92173-d6bf-45d5-810a-8a97e5c7ad03')) OR (id='742b2044-b3f5-4c5c-8786-223cf655130d')) OR (id='6c22cfb7-4210-4820-ab0a-acaf75cf6781')) OR (id='645fbc55-065e-44ce-998c-e34970602882')) OR (id='78b607eb-7ce7-454b-9a88-5bf054d953c1')) OR (id='0556e281-b82b-4552-a265-9beef0467e37')) OR (id='675ff428-d701-46ef-9a36-94e5030ee67d')) OR (id='4f224a73-df30-45fc-a5b4-a49bc2463bcb')) OR (id='c9efe021-6b75-407e-acd5-69701a3fbc97') 2019-07-29 18:04:47.396 UTC [614] LOG: duration: 0.524 ms statement: SELECT * FROM supertenant_mod_inventory_storage.holdings_record WHERE (((((((((((((((((((id='cf5bc53e-0c06-427e-b35b-89eded77d76e') OR (id='450dca09-5974-47d7-b02a-db444ecc17b0')) OR (id='ea1dd83f-4534-4a24-85d1-b7c55bcda42b')) OR (id='e1a4ab4a-d5b7-476c-89f4-2e59ca3d40cf')) OR (id='d73d759d-4b49-4d4e-9879-f40e006226a1')) OR (id='2668bd61-60ea-4a02-a81f-5b5fdca39d6e')) OR (id='113accf7-4aed-401b-99ac-9b81427d86f0')) OR (id='3499b364-7e94-473a-a91d-bd597b5baa1b')) OR (id='172da435-8691-4fca-89a5-496b5ea7b022')) OR (id='97126271-cc04-4500-9d4e-cb1e95ab1f6d')) OR (id='3320dca8-c981-48b1-a5f3-a9e0023649ea')) OR (id='33a92173-d6bf-45d5-810a-8a97e5c7ad03')) OR (id='742b2044-b3f5-4c5c-8786-223cf655130d')) OR (id='6c22cfb7-4210-4820-ab0a-acaf75cf6781')) OR (id='645fbc55-065e-44ce-998c-e34970602882')) OR (id='78b607eb-7ce7-454b-9a88-5bf054d953c1')) OR (id='0556e281-b82b-4552-a265-9beef0467e37')) OR (id='675ff428-d701-46ef-9a36-94e5030ee67d')) OR (id='4f224a73-df30-45fc-a5b4-a49bc2463bcb')) OR (id='c9efe021-6b75-407e-acd5-69701a3fbc97') LIMIT 20 OFFSET 0 2019-07-29 18:04:47.418 UTC [614] LOG: duration: 0.591 ms statement: SELECT COUNT(*) FROM supertenant_mod_inventory_storage.instance WHERE (((((((((((((((((((id='4e645dcb-4818-4331-bac0-9e6b7e10dcb8') OR (id='d42d072a-6180-4125-ae8c-374dd0ad7bab')) OR (id='945a641d-5d11-49a7-a870-a0a9819d8f42')) OR (id='78f696a1-8903-4f3c-95b4-5602607d9a0a')) OR (id='c7b05d46-d8d1-421c-8eb7-1bdd65e92fb6')) OR (id='617d3a1d-fbd7-4e93-892e-aa2419fa7d83')) OR (id='d4b2bbec-924b-440d-bcef-dd43e299a004')) OR (id='1702dbde-a46c-402f-9ed4-9d971764d86b')) OR (id='9b054ccb-1de4-4b18-a2e6-9ac58923255f')) OR (id='6bb66d2b-2e9d-47e6-bbef-0b8f967bab49')) OR (id='8d13b6a3-5a09-4f29-b040-590e016befbf')) OR (id='10f7ee22-2888-415a-8248-7745433bfcb8')) OR (id='5ef76c74-faa1-4420-a42f-f8de999c3cdb')) OR (id='9399ea7b-6a7f-43ec-93d8-87d13ac53020')) OR (id='24311b19-dc7b-4b98-a97e-4beac1e75ced')) OR (id='d5257471-f44c-4d4d-995e-a5b122fc92e1')) OR (id='dc566086-1eda-4799-a8fc-8f3314b2c2a7')) OR (id='ccb9e43c-cece-41d9-9375-7160d56122f5')) OR (id='9bcbf655-f413-4db4-9808-db2661ab4668')) OR (id='062b53e3-b387-458b-8889-bc0ed86b673b') 2019-07-29 18:04:47.419 UTC [614] LOG: duration: 0.714 ms statement: SELECT jsonb,id FROM supertenant_mod_inventory_storage.instance WHERE (((((((((((((((((((id='4e645dcb-4818-4331-bac0-9e6b7e10dcb8') OR (id='d42d072a-6180-4125-ae8c-374dd0ad7bab')) OR (id='945a641d-5d11-49a7-a870-a0a9819d8f42')) OR (id='78f696a1-8903-4f3c-95b4-5602607d9a0a')) OR (id='c7b05d46-d8d1-421c-8eb7-1bdd65e92fb6')) OR (id='617d3a1d-fbd7-4e93-892e-aa2419fa7d83')) OR (id='d4b2bbec-924b-440d-bcef-dd43e299a004')) OR (id='1702dbde-a46c-402f-9ed4-9d971764d86b')) OR (id='9b054ccb-1de4-4b18-a2e6-9ac58923255f')) OR (id='6bb66d2b-2e9d-47e6-bbef-0b8f967bab49')) OR (id='8d13b6a3-5a09-4f29-b040-590e016befbf')) OR (id='10f7ee22-2888-415a-8248-7745433bfcb8')) OR (id='5ef76c74-faa1-4420-a42f-f8de999c3cdb')) OR (id='9399ea7b-6a7f-43ec-93d8-87d13ac53020')) OR (id='24311b19-dc7b-4b98-a97e-4beac1e75ced')) OR (id='d5257471-f44c-4d4d-995e-a5b122fc92e1')) OR (id='dc566086-1eda-4799-a8fc-8f3314b2c2a7')) OR (id='ccb9e43c-cece-41d9-9375-7160d56122f5')) OR (id='9bcbf655-f413-4db4-9808-db2661ab4668')) OR (id='062b53e3-b387-458b-8889-bc0ed86b673b') LIMIT 20 OFFSET 0 |
| Comment by Jakub Skoczen [ 30/Jul/19 ] |
|
Hongwei Ji Any idea why the test is so incredibly slow in the perf env? Could we be looking at an index mismatch due to unaccent/lower? |
| Comment by Jakub Skoczen [ 30/Jul/19 ] |
|
Hongwei Ji Oh – I see that the slow test is part of the Perf_Setup phase, so maybe it's so slow because the indexes are cold? Can we add this test also to the regular phase to compare? |
| Comment by Hongwei Ji [ 30/Jul/19 ] |
Item table has following indexes on status.name attribute "item_status_name_idx" btree (lower(f_unaccent((jsonb -> 'status'::text) ->> 'name'::text))) "item_status_name_idx_gin" gin (lower(f_unaccent((jsonb -> 'status'::text) ->> 'name'::text)) gin_trgm_ops) When query for available items, following SQL was generated and it takes about 7 seconds. SELECT COUNT(*) FROM supertenant_mod_inventory_storage.item WHERE lower(f_unaccent(item.jsonb->'status'->>'name')) LIKE lower(f_unaccent('Available')) status | count -------------+--------- Available | 2837576 Checked out | 71070 (2 rows) folio=# explain analyze SELECT COUNT(*) FROM supertenant_mod_inventory_storage.item WHERE lower(f_unaccent(item.jsonb->'status'->>'name')) LIKE lower(f_unaccent('Available')); QUERY PLAN ------------------------------------------------------------------------------------------------------------------------- Aggregate (cost=1056857.03..1056857.04 rows=1 width=8) (actual time=6928.481..6928.481 rows=1 loops=1) -> Seq Scan on item (cost=0.00..1049763.28 rows=2837499 width=0) (actual time=0.059..6677.623 rows=2837576 loops=1) Filter: (lower(f_unaccent(((jsonb -> 'status'::text) ->> 'name'::text))) ~~ 'available'::text) Rows Removed by Filter: 71070 Planning time: 0.233 ms Execution time: 6928.502 ms (6 rows) folio=# explain analyze SELECT COUNT(*) FROM supertenant_mod_inventory_storage.item WHERE lower(f_unaccent(item.jsonb->'status'->>'name')) = lower(f_unaccent('Available')); QUERY PLAN ----------------------------------------------------------------------------------------------------------------------------------------------------- Aggregate (cost=430982.13..430982.14 rows=1 width=8) (actual time=1459.968..1459.968 rows=1 loops=1) -> Index Scan using item_status_name_idx on item (cost=0.43..423888.38 rows=2837499 width=0) (actual time=0.411..1275.004 rows=2837576 loops=1) Index Cond: (lower(f_unaccent(((jsonb -> 'status'::text) ->> 'name'::text))) = 'available'::text) Planning time: 0.160 ms Execution time: 1459.991 ms (5 rows) |
| Comment by Hongwei Ji [ 30/Jul/19 ] |
|
We will add a test for this query |
| Comment by Jakub Skoczen [ 31/Jul/19 ] |
|
Hongwei Ji as discussed during the stand-up:
According to the Postgres manual "If pattern does not contain percent signs or underscores, then the pattern only represents the string itself; in that case LIKE acts like the equals operator". https://www.postgresql.org/docs/current/functions-matching.html If the performance is indeed different we will need to update the CQL alogorithm to convert all exact string matching without wildcards to '='. If the performance is non-deterministic it might be related to the lack of statistics for JSON fields in Postgres. In this case it might make sense to consider the workaround Julian Ladisch implemented for FT queries in
|
| Comment by Hongwei Ji [ 31/Jul/19 ] |
|
First the test has been added. See Perf - GET inventory_items?query=(status.name=="Available") on https://jenkins-aws.indexdata.com/job/Automation/job/folio-perf-platform/209/performance/ Second I ran the query explain multiple times and see consistent result. See below summary and detailed execution plans: 1) with just b-tree index: "item_status_name_idx" btree (lower(f_unaccent((jsonb -> 'status'::text) ->> 'name'::text))) folio=# vacuum analyze supertenant_mod_inventory_storage.item; VACUUM folio=# explain analyze SELECT COUNT(1) FROM supertenant_mod_inventory_storage.item WHERE lower(f_unaccent(item.jsonb->'status'->>'name')) LIKE lower(f_unaccent('Available')); QUERY PLAN ------------------------------------------------------------------------------------------------------------------------- Aggregate (cost=1056834.36..1056834.38 rows=1 width=8) (actual time=7326.753..7326.753 rows=1 loops=1) -> Seq Scan on item (cost=0.00..1049759.31 rows=2830022 width=0) (actual time=0.054..7060.456 rows=2837576 loops=1) Filter: (lower(f_unaccent(((jsonb -> 'status'::text) ->> 'name'::text))) ~~ 'available'::text) Rows Removed by Filter: 71070 Planning time: 0.215 ms Execution time: 7326.774 ms (6 rows) folio=# explain analyze SELECT COUNT(1) FROM supertenant_mod_inventory_storage.item WHERE lower(f_unaccent(item.jsonb->'status'->>'name')) LIKE lower(f_unaccent('Checked out')); QUERY PLAN ----------------------------------------------------------------------------------------------------------------------------------------------- Aggregate (cost=58888.39..58888.40 rows=1 width=8) (actual time=469.995..469.996 rows=1 loops=1) -> Index Scan using item_status_name_idx on item (cost=0.43..58691.81 rows=78631 width=0) (actual time=0.445..461.876 rows=71070 loops=1) Index Cond: (lower(f_unaccent(((jsonb -> 'status'::text) ->> 'name'::text))) = 'checked out'::text) Filter: (lower(f_unaccent(((jsonb -> 'status'::text) ->> 'name'::text))) ~~ 'checked out'::text) Planning time: 0.158 ms Execution time: 470.019 ms (6 rows) folio=# explain analyze SELECT COUNT(1) FROM supertenant_mod_inventory_storage.item WHERE lower(f_unaccent(item.jsonb->'status'->>'name')) = lower(f_unaccent('Available')); QUERY PLAN ----------------------------------------------------------------------------------------------------------------------------------------------------- Aggregate (cost=443045.82..443045.83 rows=1 width=8) (actual time=1465.292..1465.292 rows=1 loops=1) -> Index Scan using item_status_name_idx on item (cost=0.43..435970.76 rows=2830022 width=0) (actual time=0.063..1263.410 rows=2837576 loops=1) Index Cond: (lower(f_unaccent(((jsonb -> 'status'::text) ->> 'name'::text))) = 'available'::text) Planning time: 0.154 ms Execution time: 1465.317 ms (5 rows) folio=# explain analyze SELECT COUNT(1) FROM supertenant_mod_inventory_storage.item WHERE lower(f_unaccent(item.jsonb->'status'->>'name')) = lower(f_unaccent('Checked out')); QUERY PLAN ----------------------------------------------------------------------------------------------------------------------------------------------- Aggregate (cost=38444.33..38444.34 rows=1 width=8) (actual time=291.678..291.679 rows=1 loops=1) -> Index Scan using item_status_name_idx on item (cost=0.43..38247.75 rows=78631 width=0) (actual time=0.094..285.701 rows=71070 loops=1) Index Cond: (lower(f_unaccent(((jsonb -> 'status'::text) ->> 'name'::text))) = 'checked out'::text) Planning time: 0.154 ms Execution time: 291.704 ms (5 rows) 2) With just gin index: "item_status_name_idx_gin" gin (lower(f_unaccent((jsonb -> 'status'::text) ->> 'name'::text)) gin_trgm_ops) folio=# vacuum analyze supertenant_mod_inventory_storage.item; VACUUM folio=# explain analyze SELECT COUNT(1) FROM supertenant_mod_inventory_storage.item WHERE lower(f_unaccent(item.jsonb->'status'->>'name')) LIKE lower(f_unaccent('Available')); QUERY PLAN ------------------------------------------------------------------------------------------------------------------------- Aggregate (cost=1056851.82..1056851.83 rows=1 width=8) (actual time=7149.606..7149.606 rows=1 loops=1) -> Seq Scan on item (cost=0.00..1049759.31 rows=2837003 width=0) (actual time=0.053..6895.869 rows=2837576 loops=1) Filter: (lower(f_unaccent(((jsonb -> 'status'::text) ->> 'name'::text))) ~~ 'available'::text) Rows Removed by Filter: 71070 Planning time: 0.202 ms Execution time: 7149.625 ms (6 rows) folio=# explain analyze SELECT COUNT(1) FROM supertenant_mod_inventory_storage.item WHERE lower(f_unaccent(item.jsonb->'status'->>'name')) LIKE lower(f_unaccent('Checked out')); QUERY PLAN ---------------------------------------------------------------------------------------------------------------------------------------------------- Aggregate (cost=189376.56..189376.57 rows=1 width=8) (actual time=1305.208..1305.208 rows=1 loops=1) -> Bitmap Heap Scan on item (cost=9923.29..189197.43 rows=71650 width=0) (actual time=43.358..1296.635 rows=71070 loops=1) Recheck Cond: (lower(f_unaccent(((jsonb -> 'status'::text) ->> 'name'::text))) ~~ 'checked out'::text) Rows Removed by Index Recheck: 337220 Heap Blocks: exact=37348 lossy=33722 -> Bitmap Index Scan on item_status_name_idx_gin (cost=0.00..9905.37 rows=71650 width=0) (actual time=37.155..37.155 rows=71070 loops=1) Index Cond: (lower(f_unaccent(((jsonb -> 'status'::text) ->> 'name'::text))) ~~ 'checked out'::text) Planning time: 0.161 ms Execution time: 1305.239 ms (9 rows) folio=# explain analyze SELECT COUNT(1) FROM supertenant_mod_inventory_storage.item WHERE lower(f_unaccent(item.jsonb->'status'->>'name')) = lower(f_unaccent('Available')); QUERY PLAN ------------------------------------------------------------------------------------------------------------------------- Aggregate (cost=1056851.82..1056851.83 rows=1 width=8) (actual time=7151.198..7151.198 rows=1 loops=1) -> Seq Scan on item (cost=0.00..1049759.31 rows=2837003 width=0) (actual time=0.063..6896.387 rows=2837576 loops=1) Filter: (lower(f_unaccent(((jsonb -> 'status'::text) ->> 'name'::text))) = 'available'::text) Rows Removed by Filter: 71070 Planning time: 0.146 ms Execution time: 7151.217 ms (6 rows) folio=# explain analyze SELECT COUNT(1) FROM supertenant_mod_inventory_storage.item WHERE lower(f_unaccent(item.jsonb->'status'->>'name')) = lower(f_unaccent('Checked out')); QUERY PLAN --------------------------------------------------------------------------------------------------------------------- Aggregate (cost=1049938.44..1049938.45 rows=1 width=8) (actual time=6624.144..6624.144 rows=1 loops=1) -> Seq Scan on item (cost=0.00..1049759.31 rows=71650 width=0) (actual time=0.431..6615.394 rows=71070 loops=1) Filter: (lower(f_unaccent(((jsonb -> 'status'::text) ->> 'name'::text))) = 'checked out'::text) Rows Removed by Filter: 2837576 Planning time: 0.142 ms Execution time: 6624.164 ms (6 rows) |
| Comment by Hongwei Ji [ 31/Jul/19 ] |
|
Created
|
| Comment by Jakub Skoczen [ 01/Aug/19 ] |
|
Hongwei Ji Julian Ladisch Guys, what I still don't understand is why there is no LIMIT applied to the query? If 97% of entries have status=available Postgres seems to be making the right decision to go for a sequential scan and this would be fast if there was a LIMIT. |
| Comment by Hongwei Ji [ 01/Aug/19 ] |
|
The sql without limit was generated to get the total number of records. There are multiple queries generated. See the first comment above. |
| Comment by Julian Ladisch [ 02/Aug/19 ] |
|
Counting most (97%) or all record of a table is always slow: |
| Comment by Marc Johnson [ 02/Aug/19 ] |
|
Julian Ladisch Thank you for the information and link.
With the way that the collection response schema are defined and how we handle filtering/searching using CQL on collection endpoints, we need this information on any query the client might construct, in order to populate the totalRecords property. Are you suggesting that is not possible to do in a performant way, in many circumstances? |
| Comment by Julian Ladisch [ 03/Aug/19 ] |
|
If the number of totalRecords is small (less than 20000) this is fast. |
| Comment by Jakub Skoczen [ 05/Aug/19 ] |
|
Julian Ladisch you say "RMB uses PostgreSQL's result count estimation". Why doesn't this happen in this case? |
| Comment by Jakub Skoczen [ 05/Aug/19 ] |
|
Julian Ladisch Hongwei Ji Adam Dickmeiss Guys, I am filing a bug for this beyond
|
| Comment by Hongwei Ji [ 05/Aug/19 ] |
|
Jakub Skoczen, just want to be sure we are on the same page. This query was initially used to set up the performance test. Find some available items so they can be used by following tests. It was set up to run just once but it was very slow (minutes) because the index was not warmed yet. Jakub Skoczen suggested we add the same query as a regular test so we can monitor its performance. It is still a bit slow because of the reason stated in
|