Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix performance regression on crate search #1746

Merged
merged 1 commit into from May 19, 2019

Conversation

Projects
None yet
3 participants
@sgrif
Copy link
Contributor

commented May 14, 2019

A major performance regression was introduced by #1560, as it didn't
introduce the appropriate index and the query is now falling back to a
sequential scan. This has caused the query to increase from 12ms on
average to 756ms on average. This introduces the appropriate index,
bringing performance back to its previous levels.

Original Query

                                                                                            QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=180.26..180.26 rows=1 width=881) (actual time=0.509..0.509 rows=0 loops=1)
   ->  WindowAgg  (cost=180.26..180.26 rows=1 width=881) (actual time=0.508..0.508 rows=0 loops=1)
         ->  Sort  (cost=180.26..180.26 rows=1 width=873) (actual time=0.506..0.506 rows=0 loops=1)
               Sort Key: ((replace(lower((crates.name)::text), '-'::text, '_'::text) = 'crates_io_test'::text)) DESC, crates.name
               Sort Method: quicksort  Memory: 25kB
               ->  Nested Loop Left Join  (cost=174.19..180.25 rows=1 width=873) (actual time=0.502..0.502 rows=0 loops=1)
                     ->  Bitmap Heap Scan on crates  (cost=174.13..176.19 rows=1 width=864) (actual time=0.502..0.502 rows=0 loops=1)
                           Recheck Cond: ((plainto_tsquery('crates-io-test'::text) @@ textsearchable_index_col) OR (replace(lower((name)::text), '-'::text, '_'::text) = 'crates_io_test'::text))
                           ->  BitmapOr  (cost=174.13..174.13 rows=1 width=0) (actual time=0.500..0.500 rows=0 loops=1)
                                 ->  Bitmap Index Scan on index_crates_name_search  (cost=0.00..172.05 rows=1 width=0) (actual time=0.475..0.475 rows=0 loops=1)
                                       Index Cond: (plainto_tsquery('crates-io-test'::text) @@ textsearchable_index_col)
                                 ->  Bitmap Index Scan on index_crates_name  (cost=0.00..2.08 rows=1 width=0) (actual time=0.025..0.025 rows=0 loops=1)
                                       Index Cond: (replace(lower((name)::text), '-'::text, '_'::text) = 'crates_io_test'::text)
                     ->  Index Scan using recent_crate_downloads_crate_id on recent_crate_downloads  (cost=0.06..4.06 rows=1 width=12) (never executed)
                           Index Cond: (crate_id = crates.id)
 Planning Time: 0.658 ms
 Execution Time: 0.565 ms

New Query w/o this commit

                                                                                         QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=4614.84..4614.86 rows=3 width=881) (actual time=225.720..225.720 rows=0 loops=1)
   ->  WindowAgg  (cost=4614.84..4614.86 rows=3 width=881) (actual time=225.719..225.719 rows=0 loops=1)
         ->  Sort  (cost=4614.84..4614.84 rows=3 width=873) (actual time=225.717..225.717 rows=0 loops=1)
               Sort Key: ((replace(lower((crates.name)::text), '-'::text, '_'::text) = 'crates_io_test'::text)) DESC, crates.name
               Sort Method: quicksort  Memory: 25kB
               ->  Nested Loop Left Join  (cost=0.06..4614.84 rows=3 width=873) (actual time=225.710..225.711 rows=0 loops=1)
                     ->  Seq Scan on crates  (cost=0.00..4602.65 rows=3 width=864) (actual time=225.709..225.709 rows=0 loops=1)
                           Filter: ((plainto_tsquery('crates-io-test'::text) @@ textsearchable_index_col) OR (replace(lower((name)::text), '-'::text, '_'::text) ~~ 'crates_io_test'::text))
                           Rows Removed by Filter: 25739
                     ->  Index Scan using recent_crate_downloads_crate_id on recent_crate_downloads  (cost=0.06..4.06 rows=1 width=12) (never executed)
                           Index Cond: (crate_id = crates.id)
 Planning Time: 0.536 ms
 Execution Time: 225.774 ms

New Query after this commit

                                                                                            QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=80.32..80.34 rows=3 width=881) (actual time=0.466..0.466 rows=0 loops=1)
   ->  WindowAgg  (cost=80.32..80.34 rows=3 width=881) (actual time=0.465..0.465 rows=0 loops=1)
         ->  Sort  (cost=80.32..80.32 rows=3 width=873) (actual time=0.464..0.464 rows=0 loops=1)
               Sort Key: ((replace(lower((crates.name)::text), '-'::text, '_'::text) = 'crates_io_test'::text)) DESC, crates.name
               Sort Method: quicksort  Memory: 25kB
               ->  Nested Loop Left Join  (cost=62.11..80.32 rows=3 width=873) (actual time=0.459..0.459 rows=0 loops=1)
                     ->  Bitmap Heap Scan on crates  (cost=62.05..68.13 rows=3 width=864) (actual time=0.458..0.458 rows=0 loops=1)
                           Recheck Cond: ((plainto_tsquery('crates-io-test'::text) @@ textsearchable_index_col) OR (replace(lower((name)::text), '-'::text, '_'::text) ~~ 'crates_io_test'::text))
                           Rows Removed by Index Recheck: 22
                           Heap Blocks: exact=21
                           ->  BitmapOr  (cost=62.05..62.05 rows=3 width=0) (actual time=0.255..0.255 rows=0 loops=1)
                                 ->  Bitmap Index Scan on index_crates_name_search  (cost=0.00..28.05 rows=1 width=0) (actual time=0.103..0.103 rows=0 loops=1)
                                       Index Cond: (plainto_tsquery('crates-io-test'::text) @@ textsearchable_index_col)
                                 ->  Bitmap Index Scan on sgrif_testing  (cost=0.00..34.00 rows=3 width=0) (actual time=0.151..0.151 rows=22 loops=1)
                                       Index Cond: (replace(lower((name)::text), '-'::text, '_'::text) ~~ 'crates_io_test'::text)
                     ->  Index Scan using recent_crate_downloads_crate_id on recent_crate_downloads  (cost=0.06..4.06 rows=1 width=12) (never executed)
                           Index Cond: (crate_id = crates.id)
 Planning Time: 0.476 ms
 Execution Time: 0.528 ms
Fix performance regression on crate search
A major performance regression was introduced by #1560, as it didn't
introduce the appropriate index and the query is now falling back to a
sequential scan. This has caused the query to increase from 12ms on
average to 756ms on average. This introduces the appropriate index,
bringing performance back to its previous levels.

Original Query
---

```
                                                                                            QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=180.26..180.26 rows=1 width=881) (actual time=0.509..0.509 rows=0 loops=1)
   ->  WindowAgg  (cost=180.26..180.26 rows=1 width=881) (actual time=0.508..0.508 rows=0 loops=1)
         ->  Sort  (cost=180.26..180.26 rows=1 width=873) (actual time=0.506..0.506 rows=0 loops=1)
               Sort Key: ((replace(lower((crates.name)::text), '-'::text, '_'::text) = 'crates_io_test'::text)) DESC, crates.name
               Sort Method: quicksort  Memory: 25kB
               ->  Nested Loop Left Join  (cost=174.19..180.25 rows=1 width=873) (actual time=0.502..0.502 rows=0 loops=1)
                     ->  Bitmap Heap Scan on crates  (cost=174.13..176.19 rows=1 width=864) (actual time=0.502..0.502 rows=0 loops=1)
                           Recheck Cond: ((plainto_tsquery('crates-io-test'::text) @@ textsearchable_index_col) OR (replace(lower((name)::text), '-'::text, '_'::text) = 'crates_io_test'::text))
                           ->  BitmapOr  (cost=174.13..174.13 rows=1 width=0) (actual time=0.500..0.500 rows=0 loops=1)
                                 ->  Bitmap Index Scan on index_crates_name_search  (cost=0.00..172.05 rows=1 width=0) (actual time=0.475..0.475 rows=0 loops=1)
                                       Index Cond: (plainto_tsquery('crates-io-test'::text) @@ textsearchable_index_col)
                                 ->  Bitmap Index Scan on index_crates_name  (cost=0.00..2.08 rows=1 width=0) (actual time=0.025..0.025 rows=0 loops=1)
                                       Index Cond: (replace(lower((name)::text), '-'::text, '_'::text) = 'crates_io_test'::text)
                     ->  Index Scan using recent_crate_downloads_crate_id on recent_crate_downloads  (cost=0.06..4.06 rows=1 width=12) (never executed)
                           Index Cond: (crate_id = crates.id)
 Planning Time: 0.658 ms
 Execution Time: 0.565 ms
```

New Query w/o this commit
---

```
                                                                                         QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=4614.84..4614.86 rows=3 width=881) (actual time=225.720..225.720 rows=0 loops=1)
   ->  WindowAgg  (cost=4614.84..4614.86 rows=3 width=881) (actual time=225.719..225.719 rows=0 loops=1)
         ->  Sort  (cost=4614.84..4614.84 rows=3 width=873) (actual time=225.717..225.717 rows=0 loops=1)
               Sort Key: ((replace(lower((crates.name)::text), '-'::text, '_'::text) = 'crates_io_test'::text)) DESC, crates.name
               Sort Method: quicksort  Memory: 25kB
               ->  Nested Loop Left Join  (cost=0.06..4614.84 rows=3 width=873) (actual time=225.710..225.711 rows=0 loops=1)
                     ->  Seq Scan on crates  (cost=0.00..4602.65 rows=3 width=864) (actual time=225.709..225.709 rows=0 loops=1)
                           Filter: ((plainto_tsquery('crates-io-test'::text) @@ textsearchable_index_col) OR (replace(lower((name)::text), '-'::text, '_'::text) ~~ 'crates_io_test'::text))
                           Rows Removed by Filter: 25739
                     ->  Index Scan using recent_crate_downloads_crate_id on recent_crate_downloads  (cost=0.06..4.06 rows=1 width=12) (never executed)
                           Index Cond: (crate_id = crates.id)
 Planning Time: 0.536 ms
 Execution Time: 225.774 ms
```

New Query after this commit

```
                                                                                            QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=80.32..80.34 rows=3 width=881) (actual time=0.466..0.466 rows=0 loops=1)
   ->  WindowAgg  (cost=80.32..80.34 rows=3 width=881) (actual time=0.465..0.465 rows=0 loops=1)
         ->  Sort  (cost=80.32..80.32 rows=3 width=873) (actual time=0.464..0.464 rows=0 loops=1)
               Sort Key: ((replace(lower((crates.name)::text), '-'::text, '_'::text) = 'crates_io_test'::text)) DESC, crates.name
               Sort Method: quicksort  Memory: 25kB
               ->  Nested Loop Left Join  (cost=62.11..80.32 rows=3 width=873) (actual time=0.459..0.459 rows=0 loops=1)
                     ->  Bitmap Heap Scan on crates  (cost=62.05..68.13 rows=3 width=864) (actual time=0.458..0.458 rows=0 loops=1)
                           Recheck Cond: ((plainto_tsquery('crates-io-test'::text) @@ textsearchable_index_col) OR (replace(lower((name)::text), '-'::text, '_'::text) ~~ 'crates_io_test'::text))
                           Rows Removed by Index Recheck: 22
                           Heap Blocks: exact=21
                           ->  BitmapOr  (cost=62.05..62.05 rows=3 width=0) (actual time=0.255..0.255 rows=0 loops=1)
                                 ->  Bitmap Index Scan on index_crates_name_search  (cost=0.00..28.05 rows=1 width=0) (actual time=0.103..0.103 rows=0 loops=1)
                                       Index Cond: (plainto_tsquery('crates-io-test'::text) @@ textsearchable_index_col)
                                 ->  Bitmap Index Scan on sgrif_testing  (cost=0.00..34.00 rows=3 width=0) (actual time=0.151..0.151 rows=22 loops=1)
                                       Index Cond: (replace(lower((name)::text), '-'::text, '_'::text) ~~ 'crates_io_test'::text)
                     ->  Index Scan using recent_crate_downloads_crate_id on recent_crate_downloads  (cost=0.06..4.06 rows=1 width=12) (never executed)
                           Index Cond: (crate_id = crates.id)
 Planning Time: 0.476 ms
 Execution Time: 0.528 ms
```
@jtgeibel

This comment has been minimized.

Copy link
Member

commented May 19, 2019

LGTM!

@bors r+

@bors

This comment has been minimized.

Copy link
Contributor

commented May 19, 2019

📌 Commit eccc699 has been approved by jtgeibel

@bors

This comment has been minimized.

Copy link
Contributor

commented May 19, 2019

⌛️ Testing commit eccc699 with merge 638f37a...

bors added a commit that referenced this pull request May 19, 2019

Auto merge of #1746 - sgrif:sg-index-crate-name, r=jtgeibel
Fix performance regression on crate search

A major performance regression was introduced by #1560, as it didn't
introduce the appropriate index and the query is now falling back to a
sequential scan. This has caused the query to increase from 12ms on
average to 756ms on average. This introduces the appropriate index,
bringing performance back to its previous levels.

Original Query
---

```
                                                                                            QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=180.26..180.26 rows=1 width=881) (actual time=0.509..0.509 rows=0 loops=1)
   ->  WindowAgg  (cost=180.26..180.26 rows=1 width=881) (actual time=0.508..0.508 rows=0 loops=1)
         ->  Sort  (cost=180.26..180.26 rows=1 width=873) (actual time=0.506..0.506 rows=0 loops=1)
               Sort Key: ((replace(lower((crates.name)::text), '-'::text, '_'::text) = 'crates_io_test'::text)) DESC, crates.name
               Sort Method: quicksort  Memory: 25kB
               ->  Nested Loop Left Join  (cost=174.19..180.25 rows=1 width=873) (actual time=0.502..0.502 rows=0 loops=1)
                     ->  Bitmap Heap Scan on crates  (cost=174.13..176.19 rows=1 width=864) (actual time=0.502..0.502 rows=0 loops=1)
                           Recheck Cond: ((plainto_tsquery('crates-io-test'::text) @@ textsearchable_index_col) OR (replace(lower((name)::text), '-'::text, '_'::text) = 'crates_io_test'::text))
                           ->  BitmapOr  (cost=174.13..174.13 rows=1 width=0) (actual time=0.500..0.500 rows=0 loops=1)
                                 ->  Bitmap Index Scan on index_crates_name_search  (cost=0.00..172.05 rows=1 width=0) (actual time=0.475..0.475 rows=0 loops=1)
                                       Index Cond: (plainto_tsquery('crates-io-test'::text) @@ textsearchable_index_col)
                                 ->  Bitmap Index Scan on index_crates_name  (cost=0.00..2.08 rows=1 width=0) (actual time=0.025..0.025 rows=0 loops=1)
                                       Index Cond: (replace(lower((name)::text), '-'::text, '_'::text) = 'crates_io_test'::text)
                     ->  Index Scan using recent_crate_downloads_crate_id on recent_crate_downloads  (cost=0.06..4.06 rows=1 width=12) (never executed)
                           Index Cond: (crate_id = crates.id)
 Planning Time: 0.658 ms
 Execution Time: 0.565 ms
```

New Query w/o this commit
---

```
                                                                                         QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=4614.84..4614.86 rows=3 width=881) (actual time=225.720..225.720 rows=0 loops=1)
   ->  WindowAgg  (cost=4614.84..4614.86 rows=3 width=881) (actual time=225.719..225.719 rows=0 loops=1)
         ->  Sort  (cost=4614.84..4614.84 rows=3 width=873) (actual time=225.717..225.717 rows=0 loops=1)
               Sort Key: ((replace(lower((crates.name)::text), '-'::text, '_'::text) = 'crates_io_test'::text)) DESC, crates.name
               Sort Method: quicksort  Memory: 25kB
               ->  Nested Loop Left Join  (cost=0.06..4614.84 rows=3 width=873) (actual time=225.710..225.711 rows=0 loops=1)
                     ->  Seq Scan on crates  (cost=0.00..4602.65 rows=3 width=864) (actual time=225.709..225.709 rows=0 loops=1)
                           Filter: ((plainto_tsquery('crates-io-test'::text) @@ textsearchable_index_col) OR (replace(lower((name)::text), '-'::text, '_'::text) ~~ 'crates_io_test'::text))
                           Rows Removed by Filter: 25739
                     ->  Index Scan using recent_crate_downloads_crate_id on recent_crate_downloads  (cost=0.06..4.06 rows=1 width=12) (never executed)
                           Index Cond: (crate_id = crates.id)
 Planning Time: 0.536 ms
 Execution Time: 225.774 ms
```

New Query after this commit

```
                                                                                            QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=80.32..80.34 rows=3 width=881) (actual time=0.466..0.466 rows=0 loops=1)
   ->  WindowAgg  (cost=80.32..80.34 rows=3 width=881) (actual time=0.465..0.465 rows=0 loops=1)
         ->  Sort  (cost=80.32..80.32 rows=3 width=873) (actual time=0.464..0.464 rows=0 loops=1)
               Sort Key: ((replace(lower((crates.name)::text), '-'::text, '_'::text) = 'crates_io_test'::text)) DESC, crates.name
               Sort Method: quicksort  Memory: 25kB
               ->  Nested Loop Left Join  (cost=62.11..80.32 rows=3 width=873) (actual time=0.459..0.459 rows=0 loops=1)
                     ->  Bitmap Heap Scan on crates  (cost=62.05..68.13 rows=3 width=864) (actual time=0.458..0.458 rows=0 loops=1)
                           Recheck Cond: ((plainto_tsquery('crates-io-test'::text) @@ textsearchable_index_col) OR (replace(lower((name)::text), '-'::text, '_'::text) ~~ 'crates_io_test'::text))
                           Rows Removed by Index Recheck: 22
                           Heap Blocks: exact=21
                           ->  BitmapOr  (cost=62.05..62.05 rows=3 width=0) (actual time=0.255..0.255 rows=0 loops=1)
                                 ->  Bitmap Index Scan on index_crates_name_search  (cost=0.00..28.05 rows=1 width=0) (actual time=0.103..0.103 rows=0 loops=1)
                                       Index Cond: (plainto_tsquery('crates-io-test'::text) @@ textsearchable_index_col)
                                 ->  Bitmap Index Scan on sgrif_testing  (cost=0.00..34.00 rows=3 width=0) (actual time=0.151..0.151 rows=22 loops=1)
                                       Index Cond: (replace(lower((name)::text), '-'::text, '_'::text) ~~ 'crates_io_test'::text)
                     ->  Index Scan using recent_crate_downloads_crate_id on recent_crate_downloads  (cost=0.06..4.06 rows=1 width=12) (never executed)
                           Index Cond: (crate_id = crates.id)
 Planning Time: 0.476 ms
 Execution Time: 0.528 ms
```
@bors

This comment has been minimized.

Copy link
Contributor

commented May 19, 2019

☀️ Test successful - checks-travis
Approved by: jtgeibel
Pushing 638f37a to master...

@bors bors merged commit eccc699 into rust-lang:master May 19, 2019

3 checks passed

Travis CI - Pull Request Build Passed
Details
homu Test successful
Details
percy/crates.io Visual review automatically approved, no visual changes found.
Details

sgrif added a commit to sgrif/crates.io that referenced this pull request May 20, 2019

Further address performance regression in search
Even after rust-lang#1746, we're still seeing a performance issue with search in
production. Now it's limited to searches that are a single letter, or
short 2 letter words like 'do'. It's caused by any search that would
cause PG to warn that the query contains only stopwords. It appears the
code path taken when `plainto_tsquery` returns an empty query is
substantially slower than it would be otherwise, even if the query
contains stopwords.

The reason this has started causing problems now is that rust-lang#1560 caused
the query to change from performing a nested loop join to a hash join.
Due to what appears to be a bug in PG, `plainto_tsquery` is getting
called once per row when a hash join is performed. When the query is
passed as the only argument, the function is declared as `STABLE`,
meaning that within a single statement it will always return the same
result for the same arguments, so PG should only be calling it once (or
at least only a handful of times).

There's a second form available where you explicitly pass the language
as an argument. This form is marked as `IMMUTABLE`, so the query planner
will just replace the call to the function with its results.

Unfortunately, PG is picky about how we pass the language. It doesn't
consider a cast from `text` to `regconfig` to be `IMMUTABLE`, only
`STABLE` (which is valid, since it's based on a `pg_catalog` lookup --
The fact that it accepts a string literal as `IMMUTABLE` actually seems
wrong). The actual value is the OID of the row in `pg_ts_config`, which
is *not* stable. Since `regconfig('english'::text)` is not considered
`IMMUTABLE`, we just need to embed it as a string literal instead.

bors added a commit that referenced this pull request May 21, 2019

Auto merge of #1749 - sgrif:sg-fix-slow-query-more, r=pietroalbini
Further address performance regression in search

Even after #1746, we're still seeing a performance issue with search in
production. Now it's limited to searches that are a single letter, or
short 2 letter words like 'do'. It's caused by any search that would
cause PG to warn that the query contains only stopwords. It appears the
code path taken when `plainto_tsquery` returns an empty query is
substantially slower than it would be otherwise, even if the query
contains stopwords.

The reason this has started causing problems now is that #1560 caused
the query to change from performing a nested loop join to a hash join.
Due to what appears to be a bug in PG, `plainto_tsquery` is getting
called once per row when a hash join is performed. When the query is
passed as the only argument, the function is declared as `STABLE`,
meaning that within a single statement it will always return the same
result for the same arguments, so PG should only be calling it once (or
at least only a handful of times).

There's a second form available where you explicitly pass the language
as an argument. This form is marked as `IMMUTABLE`, so the query planner
will just replace the call to the function with its results.

Unfortunately, PG is picky about how we pass the language. It doesn't
consider a cast from `text` to `regconfig` to be `IMMUTABLE`, only
`STABLE` (which is valid, since it's based on a `pg_catalog` lookup --
The fact that it accepts a string literal as `IMMUTABLE` actually seems
wrong). The actual value is the OID of the row in `pg_ts_config`, which
is *not* stable. Since `regconfig('english'::text)` is not considered
`IMMUTABLE`, we just need to embed it as a string literal instead.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.