Performance Evaluation of Result Cache by using TPC-DS
Hello,
Recently, the result cache feature was committed to PostgreSQL. I
tested its performance by executing TPC-DS. As a result, I found that
there were some regressions in the query performance.
I used the TPC-DS scale factor 100 in the evaluation. I executed all
of the 99 queries in the TPC-DS, and the result cache worked in the 21
queries of them. However, some queries took too much time, so I
skipped their execution. I set work_mem to 256MB, and
max_parallel_workers_per_gather to 0.
Evaluation results are as follows. The negative speedup ratio
indicates that the execution time increased by the result cache.
Query No | Execution time with result cache | Execution time
without result cache | Speedup ratio
7 142.1 142.2 0.03%
8 144.0 142.8 -0.82%
13 164.6 162.0 -1.65%
27 138.9 138.7 -0.16%
34 135.7 137.1 1.02%
43 209.5 207.2 -1.10%
48 181.5 170.7 -6.32%
55 130.6 123.8 -5.48%
61 0.014 0.037 62.06%
62 66.7 59.9 -11.36%
68 131.3 127.2 -3.17%
72 567.0 563.4 -0.65%
73 130.1 129.8 -0.29%
88 1044.5 1048.7 0.40%
91 1.2 1.1 -7.93%
96 132.2 131.7 -0.37%
As you can see from these results, many queries have a negative
speedup ratio, which means that there are negative impacts on the
query performance. In query 62, the execution time increased by
11.36%. I guess these regressions are due to the misestimation of the
cost in the planner. I attached the execution plan of query 62.
The result cache is currently enabled by default. However, if this
kind of performance regression is common, we have to change its
default behavior.
Best regards,
Yuya Watari
On Tue, 13 Apr 2021 at 21:29, Yuya Watari <watari.yuya@gmail.com> wrote:
I used the TPC-DS scale factor 100 in the evaluation. I executed all
of the 99 queries in the TPC-DS, and the result cache worked in the 21
queries of them. However, some queries took too much time, so I
skipped their execution. I set work_mem to 256MB, and
max_parallel_workers_per_gather to 0.
Many thanks for testing this.
As you can see from these results, many queries have a negative
speedup ratio, which means that there are negative impacts on the
query performance. In query 62, the execution time increased by
11.36%. I guess these regressions are due to the misestimation of the
cost in the planner. I attached the execution plan of query 62.
Can you share if these times were to run EXPLAIN ANALYZE or if they
were just the queries being executed normally?
The times in the two files you attached do look very similar to the
times in your table, so I suspect either TIMING ON is not that high an
overhead on your machine, or the results are that of EXPLAIN ANALYZE.
It would be really great if you could show the EXPLAIN (ANALYZE,
TIMING OFF) for query 62. There's a chance that the slowdown comes
from the additional EXPLAIN ANALYZE timing overhead with the Result
Cache version.
The result cache is currently enabled by default. However, if this
kind of performance regression is common, we have to change its
default behavior.
Yes, the feedback we get during the beta period will help drive that
decision or if the costing needs to be adjusted.
David
Hello David,
Thank you for your reply.
Can you share if these times were to run EXPLAIN ANALYZE or if they
were just the queries being executed normally?
These times were to run EXPLAIN ANALYZE. I executed each query twice,
and the **average** execution time was shown in the table of the last
e-mail. Therefore, the result of the table is not simply equal to that
of the attached file. I'm sorry for the insufficient explanation.
It would be really great if you could show the EXPLAIN (ANALYZE,
TIMING OFF) for query 62. There's a chance that the slowdown comes
from the additional EXPLAIN ANALYZE timing overhead with the Result
Cache version.
I ran query 62 by "EXPLAIN (ANALYZE, TIMING OFF)" and normally. I
attached these execution results to this e-mail. At this time, I
executed each query only once (not twice). The results are as follows.
Method | Execution time with result cache (s) | Execution time
without result cache (s) | Speedup ratio
EXPLAIN (ANALYZE, TIMING ON) 67.161 59.615 -12.66%
EXPLAIN (ANALYZE, TIMING OFF) 66.142 60.660 -9.04%
Normal 66.611 60.955 -9.28%
Although there is variation in the execution time, the speedup ratio
is around -10%. So, the result cache has a 10% regression in query 62.
The overhead of EXPLAIN ANALYZE and TIMING ON do not seem to be high.
Best regards,
Yuya Watari
Show quoted text
On Tue, Apr 13, 2021 at 7:13 PM David Rowley <dgrowleyml@gmail.com> wrote:
On Tue, 13 Apr 2021 at 21:29, Yuya Watari <watari.yuya@gmail.com> wrote:
I used the TPC-DS scale factor 100 in the evaluation. I executed all
of the 99 queries in the TPC-DS, and the result cache worked in the 21
queries of them. However, some queries took too much time, so I
skipped their execution. I set work_mem to 256MB, and
max_parallel_workers_per_gather to 0.Many thanks for testing this.
As you can see from these results, many queries have a negative
speedup ratio, which means that there are negative impacts on the
query performance. In query 62, the execution time increased by
11.36%. I guess these regressions are due to the misestimation of the
cost in the planner. I attached the execution plan of query 62.Can you share if these times were to run EXPLAIN ANALYZE or if they
were just the queries being executed normally?The times in the two files you attached do look very similar to the
times in your table, so I suspect either TIMING ON is not that high an
overhead on your machine, or the results are that of EXPLAIN ANALYZE.It would be really great if you could show the EXPLAIN (ANALYZE,
TIMING OFF) for query 62. There's a chance that the slowdown comes
from the additional EXPLAIN ANALYZE timing overhead with the Result
Cache version.The result cache is currently enabled by default. However, if this
kind of performance regression is common, we have to change its
default behavior.Yes, the feedback we get during the beta period will help drive that
decision or if the costing needs to be adjusted.David
Attachments:
On Wed, 14 Apr 2021 at 17:11, Yuya Watari <watari.yuya@gmail.com> wrote:
I ran query 62 by "EXPLAIN (ANALYZE, TIMING OFF)" and normally. I
attached these execution results to this e-mail. At this time, I
executed each query only once (not twice). The results are as follows.
Thanks for running that again. I see from the EXPLAIN ANALYZE output
that the planner did cost the Result Cache plan slightly more
expensive than the Hash Join plan. It's likely that add_path() did
not consider the Hash Join plan to be worth keeping because it was not
more than 1% better than the Result Cache plan. STD_FUZZ_FACTOR is set
so new paths need to be at least 1% better than existing paths for
them to be kept. That's pretty unfortunate and that alone does not
mean the costs are incorrect. It would be good to know if that's the
case for the other queries too.
To test that, I've set up TPC-DS locally, however, it would be good if
you could send me the list of indexes that you've created. I see the
tool from the transaction processing council for TPC-DS only comes
with the list of tables.
Can you share the output of:
select pg_get_indexdef(indexrelid) from pg_index where indrelid::regclass in (
'call_center',
'catalog_page',
'catalog_returns',
'catalog_sales',
'customer',
'customer_address',
'customer_demographics',
'date_dim',
'dbgen_version',
'household_demographics',
'income_band',
'inventory',
'item',
'promotion',
'reason',
'ship_mode',
'store',
'store_returns',
'store_sales',
'time_dim')
order by indrelid;
from your TPC-DS database?
David
Hello David,
Thank you for your reply.
Thanks for running that again. I see from the EXPLAIN ANALYZE output
that the planner did cost the Result Cache plan slightly more
expensive than the Hash Join plan. It's likely that add_path() did
not consider the Hash Join plan to be worth keeping because it was not
more than 1% better than the Result Cache plan. STD_FUZZ_FACTOR is set
so new paths need to be at least 1% better than existing paths for
them to be kept. That's pretty unfortunate and that alone does not
mean the costs are incorrect. It would be good to know if that's the
case for the other queries too.
Thanks for your analysis. I understood why HashJoin was not selected
in this query plan.
To test that, I've set up TPC-DS locally, however, it would be good if
you could send me the list of indexes that you've created. I see the
tool from the transaction processing council for TPC-DS only comes
with the list of tables.Can you share the output of:
I listed all indexes on my machine by executing your query. I attached
the result to this e-mail. I hope it will help you.
Best regards,
Yuya Watari
Attachments:
On Tue, 20 Apr 2021 at 16:43, Yuya Watari <watari.yuya@gmail.com> wrote:
I listed all indexes on my machine by executing your query. I attached
the result to this e-mail. I hope it will help you.
Thanks for sending that.
I've now run some benchmarks of TPC-DS both with enable_resultcache on
and off. I think I've used the same scale of test as you did. -SCALE
10.
tpcds=# \l+ tpcds
List of databases
Name | Owner | Encoding | Collate | Ctype | Access
privileges | Size | Tablespace | Description
-------+---------+----------+-------------+-------------+-------------------+-------+------------+-------------
tpcds | drowley | UTF8 | en_NZ.UTF-8 | en_NZ.UTF-8 |
| 28 GB | pg_default |
(1 row)
The following settings were non-standard:
tpcds=# select name,setting from pg_Settings where setting <> boot_val;
name | setting
----------------------------------+--------------------
application_name | psql
archive_command | (disabled)
client_encoding | UTF8
data_directory_mode | 0700
DateStyle | ISO, DMY
default_text_search_config | pg_catalog.english
enable_resultcache | off
fsync | off
jit | off
lc_collate | en_NZ.UTF-8
lc_ctype | en_NZ.UTF-8
lc_messages | en_NZ.UTF-8
lc_monetary | en_NZ.UTF-8
lc_numeric | en_NZ.UTF-8
lc_time | en_NZ.UTF-8
log_file_mode | 0600
log_timezone | Pacific/Auckland
max_parallel_maintenance_workers | 10
max_parallel_workers_per_gather | 0
max_stack_depth | 2048
server_encoding | UTF8
shared_buffers | 2621440
TimeZone | Pacific/Auckland
unix_socket_permissions | 0777
wal_buffers | 2048
work_mem | 262144
(26 rows)
This is an AMD 3990x CPU with 64GB of RAM.
I didn't run all of the queries. To reduce the benchmark times and to
make the analysis easier, I just ran the queries where EXPLAIN shows
at least 1 Result Cache node.
The queries in question are: 1 2 6 7 15 16 21 23 24 27 34 43 44 45 66
69 73 79 88 89 91 94 99.
The one exception here is query 58. It did use a Result Cache node
when enable_resultcache=on, but the query took more than 6 hours to
run. This slowness is not due to Result Cache. It's due to the
following correlated subquery.
and i.i_current_price > 1.2 *
(select avg(j.i_current_price)
from item j
where j.i_category = i.i_category)
That results in:
SubPlan 2
-> Aggregate
(cost=8264.44..8264.45 rows=1 width=32) (actual time=87.592..87.592
rows=1 loops=255774)
87.592 * 255774 is 6.22 hours. So 6.22 hours of executing that
subplan. The query took 6.23 hours in total. (A Result Cache on the
subplan would help here! :-) there are only 10 distinct categories)
Results
======
Out of the 23 queries that used Result Cache, only 7 executed more
quickly than with enable_resultcache = off. However, with 15 of the
23 queries, the Result Cache plan was not cheaper. This means the
planner rejected some other join method that would have made a cheaper
plan in 15 out of 23 queries. This is likely due to the add_path()
fuzziness not keeping the cheaper plan.
In only 5 of 23 queries, the Result Cache plan was both cheaper and
slower to execute. These are queries 1, 6, 27, 88 and 99. These cost
0.55%, 0.04%, 0.25%, 0.25% and 0.01% more than the plan that was
picked when enable_resultcache=off. None of those costs seem
significantly cheaper than the alternative plan.
So, in summary, I'd say there are two separate problems here:
1. The planner does not always pick the cheapest plan due to add_path
fuzziness. (15 of 23 queries have this problem, however, 4 of these
15 queries were faster with result cache, despite costing more)
2. Sometimes the Result Cache plan is cheaper and slower than the plan
that is picked with enable_resultcache = off. (5 of 23 queries have
this problem)
Overall with result cache enabled, the benchmark ran 1.15% faster.
This is mostly due to query 69 which ran over 40 seconds more quickly
with result cache enabled. Unfortunately, 16 of the 23 queries became
slower due to result cache with only the remaining 7 becoming faster.
That's not a good track record. I never expected that we'd use a
Result Cache node correctly in every planning problem we ever try to
solve, but only getting that right 30.4% of the time is not quite as
close to that 100% mark as I'd have liked. However, maybe that's
overly harsh on the Result Cache code as it was only 5 queries that we
costed cheaper and were slower. So 18 of 23 seem to have more
realistic costs, which is 78% of queries.
What can be done?
===============
I'm not quite sure. The biggest problem is add_path's fuzziness. I
could go and add some penalty cost to Result Cache paths so that
they're picked less often. If I make that penalty more than 1% of the
cost, then that should get around add_path rejecting the other join
method that is not fuzzily good enough. Adding some sort of penalty
might also help the 5 of 23 queries that were cheaper and slower than
the alternative.
I've attached a spreadsheet with all of the results and also the
EXPLAIN / EXPLAIN ANALYZE and times from both runs.
The query times in the spreadsheet are to run the query once with
pgbench (i.e -t 1). Not the EXPLAIN ANALYZE time.
I've also zipped the entire benchmark results and attached as results.tar.bz2.
David
Attachments:
results.tar.bz2application/octet-stream; name=results.tar.bz2Download
BZh91AY&SY�v
��������������������l����*R��S��`����)�x�>�
��,�eQ%����<M�%�� *��j $
�����t}a��w�>� <�R���{s`c/B�4�����u�Y�v�@#�����G�=��*�����@�y�
_F�@���
��q<��{��#Td=>z�"��eR�*$�"^�� Hv�������rQXN��\�#iN�@���k���^����[��vKj�CT����4wh�N�5d�2�UY�5�L�{�v�1fJ=n��6� "���,n�r����ltQ�;n��
����m��;`J��d������dZjl�P#��h��n���Y
V�P0u�C*{b�J#F�U�RL�%@P P�)�:<@t{��W��=����$
����BTDP�� @
��D� �Q�)PP
�IJ��B�T���4D�&E@i��24z��2�� ��405� ��=A���mF��mA������5#I�&�� �3@ M0 `&!�C �$��=F�i�4� �� dh � %=$M!B � � �� &