Re: Erratically behaving query needs optimization
I wonder how I missed that... probabily because of the "WHERE" clause
in what I already had.
I indexed by scheduler_task_executions.device_id and the new plan is
as follows: https://explain.depesz.com/s/cQRq
Can it be further improved?
Limit (cost=138511.45..138519.36 rows=2 width=54) (actual
time=598.703..618.524 rows=2 loops=1)
Buffers: shared hit=242389 read=44098
-> Unique (cost=138511.45..138527.26 rows=4 width=54) (actual
time=598.701..598.878 rows=2 loops=1)
Buffers: shared hit=242389 read=44098
-> Sort (cost=138511.45..138519.36 rows=3162 width=54)
(actual time=598.699..598.767 rows=2052 loops=1)
Sort Key: results.attribute_id, results."timestamp" DESC
Sort Method: quicksort Memory: 641kB
Buffers: shared hit=242389 read=44098
-> Gather (cost=44082.11..138327.64 rows=3162
width=54) (actual time=117.548..616.456 rows=4102 loops=1)
Workers Planned: 2
Workers Launched: 2
Buffers: shared hit=242389 read=44098
-> Nested Loop (cost=43082.11..137011.44
rows=1318 width=54) (actual time=47.436..525.664 rows=1367 loops=3)
Buffers: shared hit=242389 read=44098
-> Parallel Hash Join
(cost=43081.68..124545.34 rows=24085 width=4) (actual
time=33.099..469.958 rows=19756 loops=3)
Hash Cond:
(scheduler_operation_executions.task_execution_id =
scheduler_task_executions.id)
Buffers: shared hit=32518 read=44098
-> Parallel Seq Scan on
scheduler_operation_executions (cost=0.00..74945.82 rows=2482982
width=8) (actual time=8.493..245.190 rows=1986887 loops=3)
Buffers: shared hit=6018 read=44098
-> Parallel Hash
(cost=42881.33..42881.33 rows=16028 width=4) (actual
time=23.272..23.272 rows=13558 loops=3)
Buckets: 65536 Batches: 1
Memory Usage: 2112kB
Buffers: shared hit=26416
-> Parallel Bitmap Heap Scan on
scheduler_task_executions (cost=722.55..42881.33 rows=16028 width=4)
(actual time=27.290..61.563 rows=40675 loops=1)
Recheck Cond: (device_id = 97)
Heap Blocks: exact=26302
Buffers: shared hit=26416
-> Bitmap Index Scan on
scheduler_task_executions_device_id_idx (cost=0.00..712.93 rows=38467
width=0) (actual time=17.087..17.087 rows=40675 loops=1)
Index Cond: (device_id = 97)
Buffers: shared hit=114
-> Index Scan using
index_operation_execution_id_asc on results (cost=0.43..0.51 rows=1
width=58) (actual time=0.003..0.003 rows=0 loops=59269)
Index Cond: (operation_execution_id =
scheduler_operation_executions.id)
Filter: ((data IS NOT NULL) AND (data
<> ''::text) AND (attribute_id = ANY ('{4,5}'::integer[]))
AND (object_id = 1955) AND (data_access_result = 'SUCCESS'::text))
Rows Removed by Filter: 0
Buffers: shared hit=209871
Planning Time: 2.327 ms
Execution Time: 618.935 ms
On Tue, Aug 20, 2019 at 5:54 PM Luís Roberto Weck
wrote:
>
> Em 20/08/2019 10:54, Barbu Paul - Gheorghe escreveu:
> > Hello,
> > I'm running "PostgreSQL 11.2, compiled by Visual C++ build 1914,
> > 64-bit" and I have a query that runs several times per user action
> > (9-10 times).
> > The query takes a long time to execute, specially at first, due to
> > cold caches I think, but the performance varies greatly during a run
> > of the application (while applying the said action by the user several
> > times).
> >
> > My tables are only getting bigger with time, not much DELETEs and even
> > less UPDATEs as far as I can tell.
> >
> > Problematic query:
> >
> > EXPLAIN (ANALYZE,BUFFERS)
> > SELECT DISTINCT ON (results.attribute_id) results.timestamp,
> > results.data FROM results
> > JOIN scheduler_operation_executions ON
> > scheduler_operation_executions.id = results.operation_execution_id
> > JOIN scheduler_task_executions ON scheduler_task_executions.id =
> > scheduler_operation_executions.task_execution_id
> > WHERE scheduler_task_executions.device_id = 97
> > AND results.data <> ''
> > AND results.data IS NOT NULL
> > AND results.object_id = 1955
> > AND results.attribute_id IN (4, 5) -- possibly a longer list here
> > AND results.data_access_result = 'SUCCESS'
> > ORDER BY results.attribute_id, results.timestamp DESC
> > LIMIT 2 -- limit by the length of the attributes list
> >
> > In w
Re: Erratically behaving query needs optimization
Em 21/08/2019 04:30, Barbu Paul - Gheorghe escreveu:
I wonder how I missed that... probabily because of the "WHERE" clause
in what I already had.
I indexed by scheduler_task_executions.device_id and the new plan is
as follows: https://explain.depesz.com/s/cQRq
Can it be further improved?
Limit (cost=138511.45..138519.36 rows=2 width=54) (actual
time=598.703..618.524 rows=2 loops=1)
Buffers: shared hit=242389 read=44098
-> Unique (cost=138511.45..138527.26 rows=4 width=54) (actual
time=598.701..598.878 rows=2 loops=1)
Buffers: shared hit=242389 read=44098
-> Sort (cost=138511.45..138519.36 rows=3162 width=54)
(actual time=598.699..598.767 rows=2052 loops=1)
Sort Key: results.attribute_id, results."timestamp" DESC
Sort Method: quicksort Memory: 641kB
Buffers: shared hit=242389 read=44098
-> Gather (cost=44082.11..138327.64 rows=3162
width=54) (actual time=117.548..616.456 rows=4102 loops=1)
Workers Planned: 2
Workers Launched: 2
Buffers: shared hit=242389 read=44098
-> Nested Loop (cost=43082.11..137011.44
rows=1318 width=54) (actual time=47.436..525.664 rows=1367 loops=3)
Buffers: shared hit=242389 read=44098
-> Parallel Hash Join
(cost=43081.68..124545.34 rows=24085 width=4) (actual
time=33.099..469.958 rows=19756 loops=3)
Hash Cond:
(scheduler_operation_executions.task_execution_id =
scheduler_task_executions.id)
Buffers: shared hit=32518 read=44098
-> Parallel Seq Scan on
scheduler_operation_executions (cost=0.00..74945.82 rows=2482982
width=8) (actual time=8.493..245.190 rows=1986887 loops=3)
Buffers: shared hit=6018 read=44098
-> Parallel Hash
(cost=42881.33..42881.33 rows=16028 width=4) (actual
time=23.272..23.272 rows=13558 loops=3)
Buckets: 65536 Batches: 1
Memory Usage: 2112kB
Buffers: shared hit=26416
-> Parallel Bitmap Heap Scan on
scheduler_task_executions (cost=722.55..42881.33 rows=16028 width=4)
(actual time=27.290..61.563 rows=40675 loops=1)
Recheck Cond: (device_id = 97)
Heap Blocks: exact=26302
Buffers: shared hit=26416
-> Bitmap Index Scan on
scheduler_task_executions_device_id_idx (cost=0.00..712.93 rows=38467
width=0) (actual time=17.087..17.087 rows=40675 loops=1)
Index Cond: (device_id = 97)
Buffers: shared hit=114
-> Index Scan using
index_operation_execution_id_asc on results (cost=0.43..0.51 rows=1
width=58) (actual time=0.003..0.003 rows=0 loops=59269)
Index Cond: (operation_execution_id =
scheduler_operation_executions.id)
Filter: ((data IS NOT NULL) AND (data
<> ''::text) AND (attribute_id = ANY ('{4,5}'::integer[]))
AND (object_id = 1955) AND (data_access_result = 'SUCCESS'::text))
Rows Removed by Filter: 0
Buffers: shared hit=209871
Planning Time: 2.327 ms
Execution Time: 618.935 ms
On Tue, Aug 20, 2019 at 5:54 PM Luís Roberto Weck
wrote:
Em 20/08/2019 10:54, Barbu Paul - Gheorghe escreveu:
Hello,
I'm running "PostgreSQL 11.2, compiled by Visual C++ build 1914,
64-bit" and I have a query that runs several times per user action
(9-10 times).
The query takes a long time to execute, specially at first, due to
cold caches I think, but the performance varies greatly during a run
of the application (while applying the said action by the user several
times).
My tables are only getting bigger with time, not much DELETEs and even
less UPDATEs as far as I can tell.
Problematic query:
EXPLAIN (ANALYZE,BUFFERS)
SELECT DISTINCT ON (results.attribute_id) results.timestamp,
results.data FROM results
JOIN scheduler_operation_executions ON
scheduler_operation_executions.id = results.operation_execution_id
JOIN scheduler_task_executions ON scheduler_task_executions.id =
scheduler_operation_executions.task_execution_id
WHERE scheduler_task_executions.device_id = 97
AND results.data <> ''
AND results.data IS NOT NULL
AND results.object_id = 1955
AND results.attribute_id IN (4, 5) -- possibly a longer list here
AND results.data_access_result = 'SUCCESS'
ORDER BY results.attribute_id, results.timestamp DESC
LIMIT 2 -- limit by the length of the attributes list
In words: I want the latest (OR
Re: Extremely slow HashAggregate in simple UNION query
On Tue, Aug 20, 2019 at 11:12 AM Felix Geisendörfer
wrote:
...
> [1] My actual query had bad estimates for other reasons (GIN Index), but
> that's another story. The query above was of course deliberately designed
> to have bad estimates.
>
As noted elsewhere, v12 thwarts your attempts to deliberately design the
bad estimates. You can still get them, you just have to work a bit harder
at it:
CREATE FUNCTION j (bigint, bigint) returns setof bigint as $$ select
generate_series($1,$2) $$ rows 1000 language sql;
EXPLAIN ANALYZE
SELECT * FROM j(1, 1) a, j(1, 1) b
UNION
SELECT * FROM j(1, 1) a, j(1, 1) b;
QUERY PLAN
--
HashAggregate (cost=80021.00..100021.00 rows=200 width=16) (actual
time=11.332..13.241 rows=1 loops=1)
Group Key: a.a, b.b
-> Append (cost=0.50..70021.00 rows=200 width=16) (actual
time=0.118..0.163 rows=2 loops=1)
-> Nested Loop (cost=0.50..20010.50 rows=100 width=16)
(actual time=0.117..0.118 rows=1 loops=1)
-> Function Scan on j a (cost=0.25..10.25 rows=1000
width=8) (actual time=0.087..0.088 rows=1 loops=1)
-> Function Scan on j b (cost=0.25..10.25 rows=1000
width=8) (actual time=0.027..0.027 rows=1 loops=1)
-> Nested Loop (cost=0.50..20010.50 rows=100 width=16)
(actual time=0.044..0.044 rows=1 loops=1)
-> Function Scan on j a_1 (cost=0.25..10.25 rows=1000
width=8) (actual time=0.022..0.022 rows=1 loops=1)
-> Function Scan on j b_1 (cost=0.25..10.25 rows=1000
width=8) (actual time=0.020..0.021 rows=1 loops=1)
Planning Time: 0.085 ms
Execution Time: 69.277 ms
(11 rows)
But the same advance in v12 which makes it harder to fool with your test
case also opens the possibility of fixing your real case.
I've made an extension which has a function which always returns true, but
lies about how often it is expected to return true. See the attachment.
With that, you can fine-tune the planner.
CREATE EXTENSION pg_selectivities ;
EXPLAIN ANALYZE
SELECT * FROM j(1, 1) a, j(1, 1) b where pg_always(0.1)
UNION
SELECT * FROM j(1, 1) a, j(1, 1) b where pg_always(0.1);
QUERY PLAN
--
HashAggregate (cost=45021.40..45021.60 rows=20 width=16) (actual
time=0.226..0.227 rows=1 loops=1)
Group Key: a.a, b.b
-> Append (cost=0.50..45021.30 rows=20 width=16) (actual
time=0.105..0.220 rows=2 loops=1)
-> Nested Loop (cost=0.50..22510.50 rows=10 width=16) (actual
time=0.104..0.105 rows=1 loops=1)
Join Filter: pg_always('1e-05'::double precision)
-> Function Scan on j a (cost=0.25..10.25 rows=1000
width=8) (actual time=0.066..0.066 rows=1 loops=1)
-> Function Scan on j b (cost=0.25..10.25 rows=1000
width=8) (actual time=0.035..0.035 rows=1 loops=1)
-> Nested Loop (cost=0.50..22510.50 rows=10 width=16) (actual
time=0.112..0.113 rows=1 loops=1)
Join Filter: pg_always('1e-05'::double precision)
-> Function Scan on j a_1 (cost=0.25..10.25 rows=1000
width=8) (actual time=0.077..0.077 rows=1 loops=1)
-> Function Scan on j b_1 (cost=0.25..10.25 rows=1000
width=8) (actual time=0.034..0.034 rows=1 loops=1)
Planning Time: 0.139 ms
Execution Time: 0.281 ms
Cheers,
Jeff
pg_selectivities.patch
Description: Binary data
Re: Extremely slow HashAggregate in simple UNION query
čt 22. 8. 2019 v 3:11 odesílatel Jeff Janes napsal:
> On Tue, Aug 20, 2019 at 11:12 AM Felix Geisendörfer
> wrote:
> ...
>
>
>> [1] My actual query had bad estimates for other reasons (GIN Index), but
>> that's another story. The query above was of course deliberately designed
>> to have bad estimates.
>>
>
> As noted elsewhere, v12 thwarts your attempts to deliberately design the
> bad estimates. You can still get them, you just have to work a bit harder
> at it:
>
> CREATE FUNCTION j (bigint, bigint) returns setof bigint as $$ select
> generate_series($1,$2) $$ rows 1000 language sql;
>
> EXPLAIN ANALYZE
> SELECT * FROM j(1, 1) a, j(1, 1) b
> UNION
> SELECT * FROM j(1, 1) a, j(1, 1) b;
> QUERY PLAN
>
>
> --
> HashAggregate (cost=80021.00..100021.00 rows=200 width=16) (actual
> time=11.332..13.241 rows=1 loops=1)
>Group Key: a.a, b.b
>-> Append (cost=0.50..70021.00 rows=200 width=16) (actual
> time=0.118..0.163 rows=2 loops=1)
> -> Nested Loop (cost=0.50..20010.50 rows=100 width=16)
> (actual time=0.117..0.118 rows=1 loops=1)
>-> Function Scan on j a (cost=0.25..10.25 rows=1000
> width=8) (actual time=0.087..0.088 rows=1 loops=1)
>-> Function Scan on j b (cost=0.25..10.25 rows=1000
> width=8) (actual time=0.027..0.027 rows=1 loops=1)
> -> Nested Loop (cost=0.50..20010.50 rows=100 width=16)
> (actual time=0.044..0.044 rows=1 loops=1)
>-> Function Scan on j a_1 (cost=0.25..10.25 rows=1000
> width=8) (actual time=0.022..0.022 rows=1 loops=1)
>-> Function Scan on j b_1 (cost=0.25..10.25 rows=1000
> width=8) (actual time=0.020..0.021 rows=1 loops=1)
> Planning Time: 0.085 ms
> Execution Time: 69.277 ms
> (11 rows)
>
> But the same advance in v12 which makes it harder to fool with your test
> case also opens the possibility of fixing your real case.
>
I think so much more interesting should be long time after query processing
- last row was processed in 13ms, but Execution Time was 69ms .. so some
cleaning is 56ms - that is pretty long.
> I've made an extension which has a function which always returns true, but
> lies about how often it is expected to return true. See the attachment.
> With that, you can fine-tune the planner.
>
> CREATE EXTENSION pg_selectivities ;
>
> EXPLAIN ANALYZE
> SELECT * FROM j(1, 1) a, j(1, 1) b where pg_always(0.1)
> UNION
> SELECT * FROM j(1, 1) a, j(1, 1) b where pg_always(0.1);
> QUERY PLAN
>
>
> --
> HashAggregate (cost=45021.40..45021.60 rows=20 width=16) (actual
> time=0.226..0.227 rows=1 loops=1)
>Group Key: a.a, b.b
>-> Append (cost=0.50..45021.30 rows=20 width=16) (actual
> time=0.105..0.220 rows=2 loops=1)
> -> Nested Loop (cost=0.50..22510.50 rows=10 width=16) (actual
> time=0.104..0.105 rows=1 loops=1)
>Join Filter: pg_always('1e-05'::double precision)
>-> Function Scan on j a (cost=0.25..10.25 rows=1000
> width=8) (actual time=0.066..0.066 rows=1 loops=1)
>-> Function Scan on j b (cost=0.25..10.25 rows=1000
> width=8) (actual time=0.035..0.035 rows=1 loops=1)
> -> Nested Loop (cost=0.50..22510.50 rows=10 width=16) (actual
> time=0.112..0.113 rows=1 loops=1)
>Join Filter: pg_always('1e-05'::double precision)
>-> Function Scan on j a_1 (cost=0.25..10.25 rows=1000
> width=8) (actual time=0.077..0.077 rows=1 loops=1)
>-> Function Scan on j b_1 (cost=0.25..10.25 rows=1000
> width=8) (actual time=0.034..0.034 rows=1 loops=1)
> Planning Time: 0.139 ms
> Execution Time: 0.281 ms
>
> Cheers,
>
> Jeff
>
>
