0

Update on 2022-05-15

After running vacuum analyze, the query plans are below.

For A query

Nested Loop Left Join  (cost=45913.11..496597.16 rows=10 width=128) (actual time=115.205..3068.596 rows=10 loops=1)
  Join Filter: (project.uuid = project_2.uuid)
  Rows Removed by Join Filter: 1106
  ->  Nested Loop Left Join  (cost=45756.05..45816.92 rows=10 width=96) (actual time=54.480..55.484 rows=10 loops=1)
"        Join Filter: (project.uuid = sub.""projectUuid"")"
        Rows Removed by Join Filter: 773
        ->  Limit  (cost=16719.78..16719.81 rows=10 width=64) (actual time=11.850..11.861 rows=10 loops=1)
              ->  Sort  (cost=16719.78..16720.24 rows=182 width=64) (actual time=11.849..11.856 rows=10 loops=1)
"                    Sort Key: (COALESCE(sum(token_transaction_history.price_in_klay), '0'::numeric)) DESC"
                    Sort Method: top-N heapsort  Memory: 26kB
                    ->  GroupAggregate  (cost=16710.74..16715.85 rows=182 width=64) (actual time=11.605..11.804 rows=183 loops=1)
                          Group Key: project.uuid
                          ->  Sort  (cost=16710.74..16711.69 rows=378 width=35) (actual time=11.597..11.639 rows=856 loops=1)
                                Sort Key: project.uuid
                                Sort Method: quicksort  Memory: 92kB
                                ->  Hash Right Join  (cost=47.62..16694.56 rows=378 width=35) (actual time=10.438..11.397 rows=856 loops=1)
                                      Hash Cond: (token_transaction_history.project_uuid = project.uuid)
"                                      ->  Index Scan using ""IDX_25c65868e779c6c3ff8eb492f5"" on token_transaction_history  (cost=0.43..16646.29 rows=399 width=19) (actual time=3.620..10.891 rows=753 loops=1)"
"                                            Index Cond: (type = 'sale'::token_transaction_history_type_enum)"
"                                            Filter: ((transaction_timestamp <= now()) AND (transaction_timestamp >= (now() - '7 days'::interval)))"
                                            Rows Removed by Filter: 17562
                                      ->  Hash  (cost=44.92..44.92 rows=182 width=32) (actual time=0.198..0.199 rows=183 loops=1)
                                            Buckets: 1024  Batches: 1  Memory Usage: 20kB
                                            ->  Seq Scan on project  (cost=0.00..44.92 rows=182 width=32) (actual time=0.006..0.170 rows=183 loops=1)
                                                  Filter: (is_valid AND is_visible)
                                                  Rows Removed by Filter: 9
        ->  Materialize  (cost=29036.27..29068.69 rows=192 width=48) (actual time=4.262..4.356 rows=78 loops=10)
              ->  Subquery Scan on sub  (cost=29036.27..29067.73 rows=192 width=48) (actual time=42.620..43.489 rows=116 loops=1)
                    ->  GroupAggregate  (cost=29036.27..29065.81 rows=192 width=48) (actual time=42.619..43.474 rows=116 loops=1)
                          Group Key: project_1.uuid
                          ->  Sort  (cost=29036.27..29045.48 rows=3683 width=22) (actual time=42.603..42.940 rows=3361 loops=1)
                                Sort Key: project_1.uuid
                                Sort Method: quicksort  Memory: 399kB
                                ->  Hash Join  (cost=13.85..28818.11 rows=3683 width=22) (actual time=0.084..40.345 rows=3869 loops=1)
                                      Hash Cond: (token.project_uuid = project_1.uuid)
                                      ->  Nested Loop  (cost=0.43..28794.81 rows=3683 width=22) (actual time=0.035..39.029 rows=3869 loops=1)
                                            ->  Seq Scan on token_listed  (cost=0.00..923.88 rows=3683 width=22) (actual time=0.012..4.727 rows=3869 loops=1)
                                                  Filter: ((NOT is_cancelled) AND (expiration_block_number > 90119997))
                                                  Rows Removed by Filter: 37001
"                                            ->  Index Scan using ""PK_a9a66098c2fb758dff713f8d838"" on token  (cost=0.43..7.57 rows=1 width=32) (actual time=0.008..0.008 rows=1 loops=3869)"
                                                  Index Cond: (uuid = token_listed.token_uuid)
                                      ->  Hash  (cost=11.03..11.03 rows=192 width=16) (actual time=0.042..0.043 rows=192 loops=1)
                                            Buckets: 1024  Batches: 1  Memory Usage: 17kB
"                                            ->  Index Only Scan using ""PK_bcbc9244374131f3ccb908aa616"" on project project_1  (cost=0.14..11.03 rows=192 width=16) (actual time=0.009..0.023 rows=192 loops=1)"
                                                  Heap Fetches: 0
  ->  Materialize  (cost=157.06..450751.91 rows=192 width=32) (actual time=0.524..301.293 rows=112 loops=10)
        ->  GroupAggregate  (cost=157.06..450749.03 rows=192 width=32) (actual time=5.236..3012.647 rows=167 loops=1)
              Group Key: project_2.uuid
              ->  Nested Loop  (cost=157.06..441951.84 rows=1172703 width=686) (actual time=0.250..2737.133 rows=1023186 loops=1)
"                    ->  Index Only Scan using ""PK_bcbc9244374131f3ccb908aa616"" on project project_2  (cost=0.14..11.03 rows=192 width=16) (actual time=0.010..0.244 rows=168 loops=1)"
                          Heap Fetches: 0
                    ->  Bitmap Heap Scan on token token_1  (cost=156.91..2239.73 rows=6205 width=686) (actual time=1.413..15.695 rows=6090 loops=168)
                          Recheck Cond: (project_uuid = project_2.uuid)
                          Heap Blocks: exact=431451
"                          ->  Bitmap Index Scan on ""UQ_274fa8346ca77abaa6452a4c8ac""  (cost=0.00..155.36 rows=6205 width=0) (actual time=1.101..1.101 rows=6150 loops=168)"
                                Index Cond: (project_uuid = project_2.uuid)
Planning Time: 1.237 ms
Execution Time: 3068.694 ms

For B query

GroupAggregate  (cost=71293.52..72477.88 rows=1820 width=199) (actual time=1026.028..3167.650 rows=10 loops=1)
"  Group Key: (COALESCE(sum(token_transaction_history.price_in_klay), '0'::numeric)), project.contract_address, project.logo_path, project.name"
  ->  Sort  (cost=71293.52..71439.29 rows=58308 width=823) (actual time=1017.967..1200.920 rows=280429 loops=1)
"        Sort Key: (COALESCE(sum(token_transaction_history.price_in_klay), '0'::numeric)) DESC, project.contract_address, project.logo_path, project.name"
        Sort Method: external merge  Disk: 175752kB
        ->  Hash Left Join  (cost=20154.55..45552.04 rows=58308 width=823) (actual time=16.184..406.375 rows=280429 loops=1)
              Hash Cond: (token.uuid = token_listed.token_uuid)
              Join Filter: token.is_valid
              ->  Nested Loop  (cost=19184.12..40789.75 rows=58308 width=834) (actual time=11.025..344.971 rows=280429 loops=1)
                    ->  Nested Loop  (cost=19025.43..19071.08 rows=9 width=183) (actual time=10.660..10.784 rows=10 loops=1)
                          ->  Limit  (cost=19025.28..19025.31 rows=10 width=48) (actual time=10.650..10.667 rows=10 loops=1)
                                ->  Sort  (cost=19025.28..19025.74 rows=182 width=48) (actual time=10.649..10.659 rows=10 loops=1)
"                                      Sort Key: (COALESCE(sum(token_transaction_history.price_in_klay), '0'::numeric)) DESC"
                                      Sort Method: top-N heapsort  Memory: 26kB
                                      ->  GroupAggregate  (cost=19015.61..19021.35 rows=182 width=48) (actual time=10.423..10.616 rows=183 loops=1)
                                            Group Key: project_1.uuid
                                            ->  Sort  (cost=19015.61..19016.77 rows=461 width=19) (actual time=10.418..10.462 rows=856 loops=1)
                                                  Sort Key: project_1.uuid
                                                  Sort Method: quicksort  Memory: 87kB
                                                  ->  Hash Right Join  (cost=47.62..18995.22 rows=461 width=19) (actual time=9.340..10.244 rows=856 loops=1)
                                                        Hash Cond: (token_transaction_history.project_uuid = project_1.uuid)
"                                                        ->  Index Scan using ""IDX_25c65868e779c6c3ff8eb492f5"" on token_transaction_history  (cost=0.43..18946.71 rows=486 width=19) (actual time=3.314..9.766 rows=753 loops=1)"
"                                                              Index Cond: (type = 'sale'::token_transaction_history_type_enum)"
"                                                              Filter: (transaction_timestamp > (now() - '7 days'::interval))"
                                                              Rows Removed by Filter: 17562
                                                        ->  Hash  (cost=44.92..44.92 rows=182 width=16) (actual time=0.162..0.163 rows=183 loops=1)
                                                              Buckets: 1024  Batches: 1  Memory Usage: 17kB
                                                              ->  Seq Scan on project project_1  (cost=0.00..44.92 rows=182 width=16) (actual time=0.006..0.141 rows=183 loops=1)
                                                                    Filter: (is_visible AND is_valid)
                                                                    Rows Removed by Filter: 9
"                          ->  Index Scan using ""PK_bcbc9244374131f3ccb908aa616"" on project  (cost=0.14..4.56 rows=1 width=135) (actual time=0.008..0.008 rows=1 loops=10)"
                                Index Cond: (uuid = project_1.uuid)
                                Filter: (is_visible AND is_valid)
                    ->  Bitmap Heap Scan on token  (cost=158.70..2351.36 rows=6183 width=699) (actual time=3.901..30.552 rows=28043 loops=10)
                          Recheck Cond: (project_uuid = project.uuid)
                          Heap Blocks: exact=97999
"                          ->  Bitmap Index Scan on ""UQ_274fa8346ca77abaa6452a4c8ac""  (cost=0.00..157.15 rows=6183 width=0) (actual time=2.549..2.549 rows=28043 loops=10)"
                                Index Cond: (project_uuid = project.uuid)
              ->  Hash  (cost=923.89..923.89 rows=3723 width=22) (actual time=5.148..5.149 rows=3870 loops=1)
                    Buckets: 4096  Batches: 1  Memory Usage: 236kB
                    ->  Seq Scan on token_listed  (cost=0.00..923.89 rows=3723 width=22) (actual time=0.007..4.630 rows=3870 loops=1)
                          Filter: ((NOT is_cancelled) AND (expiration_block_number > 90119997))
                          Rows Removed by Filter: 37001
Planning Time: 1.177 ms
Execution Time: 3191.467 ms

==================================================================

I've tested two queries(A, B) with postgresql which returns same results. The thing is that the A query has higher cost but runs faster than B. Anyone could explain why?

The result of explain analysis A is

Sort  (cost=471787.01..471787.03 rows=10 width=128) (actual time=132.236..132.243 rows=10 loops=1)
"  Sort Key: (COALESCE(sum(token_transaction_history.price_in_klay), '0'::numeric)) DESC"
  Sort Method: quicksort  Memory: 26kB
  ->  Merge Left Join  (cost=29549.67..471786.84 rows=10 width=128) (actual time=69.820..132.218 rows=10 loops=1)
        Merge Cond: (project.uuid = project_2.uuid)
        ->  Merge Left Join  (cost=29392.37..30394.29 rows=10 width=96) (actual time=34.773..35.754 rows=10 loops=1)
              Merge Cond: (project.uuid = project_1.uuid)
              ->  Limit  (cost=0.57..970.10 rows=10 width=64) (actual time=10.820..11.730 rows=10 loops=1)
                    ->  GroupAggregate  (cost=0.57..17064.24 rows=176 width=64) (actual time=10.819..11.725 rows=10 loops=1)
                          Group Key: project.uuid
                          ->  Nested Loop Left Join  (cost=0.57..17060.31 rows=347 width=35) (actual time=10.808..11.687 rows=33 loops=1)
                                Join Filter: (token_transaction_history.project_uuid = project.uuid)
                                Rows Removed by Join Filter: 8311
"                                ->  Index Scan using ""PK_bcbc9244374131f3ccb908aa616"" on project  (cost=0.14..178.27 rows=176 width=32) (actual time=0.009..0.042 rows=11 loops=1)"
                                      Filter: (is_valid AND is_visible)
                                      Rows Removed by Filter: 1
                                ->  Materialize  (cost=0.43..15929.90 rows=361 width=19) (actual time=0.872..1.010 rows=758 loops=11)
"                                      ->  Index Scan using ""IDX_25c65868e779c6c3ff8eb492f5"" on token_transaction_history  (cost=0.43..15928.10 rows=361 width=19) (actual time=9.590..10.536 rows=801 loops=1)"
"                                            Index Cond: (type = 'sale'::token_transaction_history_type_enum)"
"                                            Filter: ((transaction_timestamp <= now()) AND (transaction_timestamp >= (now() - '7 days'::interval)))"
                                            Rows Removed by Filter: 16897
              ->  GroupAggregate  (cost=29391.80..29421.68 rows=183 width=48) (actual time=23.949..24.005 rows=8 loops=1)
                    Group Key: project_1.uuid
                    ->  Sort  (cost=29391.80..29401.15 rows=3740 width=22) (actual time=23.931..23.954 rows=153 loops=1)
                          Sort Key: project_1.uuid
                          Sort Method: quicksort  Memory: 409kB
                          ->  Hash Join  (cost=25.57..29169.85 rows=3740 width=22) (actual time=0.076..22.451 rows=3995 loops=1)
                                Hash Cond: (token.project_uuid = project_1.uuid)
                                ->  Nested Loop  (cost=0.43..29134.66 rows=3740 width=22) (actual time=0.025..20.812 rows=3995 loops=1)
                                      ->  Seq Scan on token_listed  (cost=0.00..874.36 rows=3740 width=22) (actual time=0.012..4.589 rows=3995 loops=1)
                                            Filter: ((NOT is_cancelled) AND (expiration_block_number > 90119997))
                                            Rows Removed by Filter: 34932
"                                      ->  Index Scan using ""PK_a9a66098c2fb758dff713f8d838"" on token  (cost=0.43..7.56 rows=1 width=32) (actual time=0.004..0.004 rows=1 loops=3995)"
                                            Index Cond: (uuid = token_listed.token_uuid)
                                ->  Hash  (cost=22.86..22.86 rows=183 width=16) (actual time=0.045..0.046 rows=183 loops=1)
                                      Buckets: 1024  Batches: 1  Memory Usage: 17kB
"                                      ->  Index Only Scan using ""PK_bcbc9244374131f3ccb908aa616"" on project project_1  (cost=0.14..22.86 rows=183 width=16) (actual time=0.008..0.025 rows=183 loops=1)"
                                            Heap Fetches: 6
        ->  GroupAggregate  (cost=157.30..441390.14 rows=183 width=32) (actual time=5.995..96.440 rows=11 loops=1)
              Group Key: project_2.uuid
              ->  Nested Loop  (cost=157.30..432893.21 rows=1132680 width=688) (actual time=0.186..81.324 rows=62761 loops=1)
"                    ->  Index Only Scan using ""PK_bcbc9244374131f3ccb908aa616"" on project project_2  (cost=0.14..22.86 rows=183 width=16) (actual time=0.012..0.024 rows=12 loops=1)"
                          Heap Fetches: 0
                    ->  Bitmap Heap Scan on token token_1  (cost=157.15..2302.48 rows=6293 width=688) (actual time=0.775..6.281 rows=5230 loops=12)
                          Recheck Cond: (project_uuid = project_2.uuid)
                          Heap Blocks: exact=26937
"                          ->  Bitmap Index Scan on ""UQ_274fa8346ca77abaa6452a4c8ac""  (cost=0.00..155.58 rows=6293 width=0) (actual time=0.469..0.469 rows=5419 loops=12)"
                                Index Cond: (project_uuid = project_2.uuid)
Planning Time: 0.814 ms
Execution Time: 132.327 ms

The result of explain analyze B is

GroupAggregate  (cost=71645.69..72853.83 rows=1760 width=199) (actual time=1195.984..3383.887 rows=10 loops=1)
"  Group Key: (COALESCE(sum(token_transaction_history.price_in_klay), '0'::numeric)), project.contract_address, project.logo_path, project.name"
  ->  Sort  (cost=71645.69..71794.51 rows=59527 width=829) (actual time=1186.935..1359.517 rows=284530 loops=1)
"        Sort Key: (COALESCE(sum(token_transaction_history.price_in_klay), '0'::numeric)) DESC, project.contract_address, project.logo_path, project.name"
        Sort Method: external merge  Disk: 184832kB
        ->  Hash Left Join  (cost=16992.95..45151.32 rows=59527 width=829) (actual time=14.918..472.148 rows=284530 loops=1)
              Hash Cond: (token.uuid = token_listed.token_uuid)
              Join Filter: token.is_valid
              ->  Nested Loop  (cost=16071.84..40433.40 rows=59527 width=840) (actual time=10.261..404.012 rows=284530 loops=1)
                    ->  Nested Loop  (cost=15913.25..15958.91 rows=10 width=183) (actual time=10.019..10.154 rows=10 loops=1)
                          ->  Limit  (cost=15913.11..15913.13 rows=10 width=48) (actual time=10.009..10.028 rows=10 loops=1)
                                ->  Sort  (cost=15913.11..15913.55 rows=176 width=48) (actual time=10.008..10.020 rows=10 loops=1)
"                                      Sort Key: (COALESCE(sum(token_transaction_history.price_in_klay), '0'::numeric)) DESC"
                                      Sort Method: top-N heapsort  Memory: 25kB
                                      ->  GroupAggregate  (cost=15904.50..15909.31 rows=176 width=48) (actual time=9.774..9.977 rows=177 loops=1)
                                            Group Key: project_1.uuid
                                            ->  Sort  (cost=15904.50..15905.37 rows=348 width=19) (actual time=9.767..9.812 rows=933 loops=1)
                                                  Sort Key: project_1.uuid
                                                  Sort Method: quicksort  Memory: 93kB
                                                  ->  Hash Right Join  (cost=46.46..15889.80 rows=348 width=19) (actual time=8.682..9.597 rows=933 loops=1)
                                                        Hash Cond: (token_transaction_history.project_uuid = project_1.uuid)
"                                                        ->  Index Scan using ""IDX_25c65868e779c6c3ff8eb492f5"" on token_transaction_history  (cost=0.43..15842.80 rows=362 width=19) (actual time=8.498..9.108 rows=801 loops=1)"
"                                                              Index Cond: (type = 'sale'::token_transaction_history_type_enum)"
"                                                              Filter: (transaction_timestamp > (now() - '7 days'::interval))"
                                                              Rows Removed by Filter: 16897
                                                        ->  Hash  (cost=43.83..43.83 rows=176 width=16) (actual time=0.176..0.177 rows=177 loops=1)
                                                              Buckets: 1024  Batches: 1  Memory Usage: 17kB
                                                              ->  Seq Scan on project project_1  (cost=0.00..43.83 rows=176 width=16) (actual time=0.005..0.155 rows=177 loops=1)
                                                                    Filter: (is_visible AND is_valid)
                                                                    Rows Removed by Filter: 6
"                          ->  Index Scan using ""PK_bcbc9244374131f3ccb908aa616"" on project  (cost=0.14..4.56 rows=1 width=135) (actual time=0.008..0.008 rows=1 loops=10)"
                                Index Cond: (uuid = project_1.uuid)
                                Filter: (is_visible AND is_valid)
                    ->  Bitmap Heap Scan on token  (cost=158.58..2384.52 rows=6293 width=705) (actual time=4.216..35.949 rows=28453 loops=10)
                          Recheck Cond: (project_uuid = project.uuid)
                          Heap Blocks: exact=99284
"                          ->  Bitmap Index Scan on ""UQ_274fa8346ca77abaa6452a4c8ac""  (cost=0.00..157.01 rows=6293 width=0) (actual time=2.708..2.708 rows=29860 loops=10)"
                                Index Cond: (project_uuid = project.uuid)
              ->  Hash  (cost=874.36..874.36 rows=3740 width=22) (actual time=4.645..4.646 rows=3995 loops=1)
                    Buckets: 4096  Batches: 1  Memory Usage: 243kB
                    ->  Seq Scan on token_listed  (cost=0.00..874.36 rows=3740 width=22) (actual time=0.010..4.128 rows=3995 loops=1)
                          Filter: ((NOT is_cancelled) AND (expiration_block_number > 90119997))
                          Rows Removed by Filter: 34932
Planning Time: 0.637 ms
Execution Time: 3414.067 ms

I think the actual time diff comes from the GroupAggregate on first line of query plan of B(used group by with aggregated value, "COALESCE(sum(token_transaction_history.price_in_klay), 0)") but I don't know why the costs is not reasonable in terms of actual time.

Any references would be really appreciated! Thanks in advance!

pjr
  • 37
  • 9
  • VACUUM ANALYZE all involved tables first. Then if the issue still exists, update the question's plans with the new ones. – jjanes May 09 '22 at 22:58
  • Also, what is the version? – jjanes May 09 '22 at 23:32
  • Your are correct that the top group aggregate from B is much slower than the planner thinks it will be. It actually takes 60% of the time while it is 2% of the cost estimate. But without seeing the query, or least the VERBOSE version of the plan, there is no hope at coming up with a reasonable explanation for that. – jjanes May 09 '22 at 23:48
  • @jjanes Thanks! I updated the query plan after running `vacuum analyze` and the postgres version is 13. – pjr May 15 '22 at 12:15

1 Answers1

1

A Merge Left Join gets to stop once its left child runs out of rows. That is what happens pretty early in the top merge of your plan A. It's right child gets to stop after producing only 11 out of an expected 183 rows, while the planner seems to have thought it would run to near completion (otherwise it would have deweighted the cost estimate of 441390.14 for the GroupAggregate). The next Merge Left Join down also has the same issue, though the numbers are less dramatic in absolute terms.

The LIMIT farther down also does the same thing, but there the planner gets it correct, deweighting the cost of 17064.24 down to 970.10 due to the early stopping.

The planner doesn't understand that the rows returned by the left child of each of the Merge Left Joins will be biased to the front of the distribution, and there is likely nothing you can (currently) do to make it understand that.

jjanes
  • 37,812
  • 5
  • 27
  • 34