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
<> '<NullData/>'::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
<luisroberto(at)siscobra(dot)com(dot)br> 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 <> '<NullData/>'
> > 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 (ORDER BY results.timestamp DESC) results
> > of a device (scheduler_task_executions.device_id = 97 - hence the
> > joins results -> scheduler_operation_executions ->
> > scheduler_task_executions)
> > for a given object and attributes with some additional constraints on
> > the data column. But I only want the latest attributes for which we
> > have results, hence the DISTINCT ON (results.attribute_id) and LIMIT.
> >
> > First run: https://explain.depesz.com/s/qh4C
> > Limit (cost=157282.39..157290.29 rows=2 width=54) (actual
> > time=44068.166..44086.970 rows=2 loops=1)
> > Buffers: shared hit=215928 read=85139
> > -> Unique (cost=157282.39..157298.20 rows=4 width=54) (actual
> > time=44068.164..44069.301 rows=2 loops=1)
> > Buffers: shared hit=215928 read=85139
> > -> Sort (cost=157282.39..157290.29 rows=3162 width=54)
> > (actual time=44068.161..44068.464 rows=2052 loops=1)
> > Sort Key: results.attribute_id, results."timestamp" DESC
> > Sort Method: quicksort Memory: 641kB
> > Buffers: shared hit=215928 read=85139
> > -> Gather (cost=62853.04..157098.57 rows=3162
> > width=54) (actual time=23518.745..44076.385 rows=4102 loops=1)
> > Workers Planned: 2
> > Workers Launched: 2
> > Buffers: shared hit=215928 read=85139
> > -> Nested Loop (cost=61853.04..155782.37
> > rows=1318 width=54) (actual time=23290.514..43832.223 rows=1367
> > loops=3)
> > Buffers: shared hit=215928 read=85139
> > -> Parallel Hash Join
> > (cost=61852.61..143316.27 rows=24085 width=4) (actual
> > time=23271.275..40018.451 rows=19756 loops=3)
> > Hash Cond:
> > (scheduler_operation_executions.task_execution_id =
> > scheduler_task_executions.id)
> > Buffers: shared hit=6057 read=85139
> > -> Parallel Seq Scan on
> > scheduler_operation_executions (cost=0.00..74945.82 rows=2482982
> > width=8) (actual time=7.575..15694.435 rows=1986887 loops=3)
> > Buffers: shared hit=2996 read=47120
> > -> Parallel Hash
> > (cost=61652.25..61652.25 rows=16029 width=4) (actual
> > time=23253.337..23253.337 rows=13558 loops=3)
> > Buckets: 65536 Batches: 1
> > Memory Usage: 2144kB
> > Buffers: shared hit=2977 read=38019
> > -> Parallel Seq Scan on
> > scheduler_task_executions (cost=0.00..61652.25 rows=16029 width=4)
> > (actual time=25.939..23222.174 rows=13558 loops=3)
> > Filter: (device_id = 97)
> > Rows Removed by Filter: 1308337
> > Buffers: shared hit=2977 read=38019
> > -> Index Scan using
> > index_operation_execution_id_asc on results (cost=0.43..0.51 rows=1
> > width=58) (actual time=0.191..0.191 rows=0 loops=59269)
> > Index Cond: (operation_execution_id =
> > scheduler_operation_executions.id)
> > Filter: ((data IS NOT NULL) AND (data
> > <> '<NullData/>'::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: 29.295 ms
> > Execution Time: 44087.365 ms
> >
> >
> > Second run: https://explain.depesz.com/s/uy9f
> > Limit (cost=157282.39..157290.29 rows=2 width=54) (actual
> > time=789.363..810.440 rows=2 loops=1)
> > Buffers: shared hit=216312 read=84755
> > -> Unique (cost=157282.39..157298.20 rows=4 width=54) (actual
> > time=789.361..789.535 rows=2 loops=1)
> > Buffers: shared hit=216312 read=84755
> > -> Sort (cost=157282.39..157290.29 rows=3162 width=54)
> > (actual time=789.361..789.418 rows=2052 loops=1)
> > Sort Key: results.attribute_id, results."timestamp" DESC
> > Sort Method: quicksort Memory: 641kB
> > Buffers: shared hit=216312 read=84755
> > -> Gather (cost=62853.04..157098.57 rows=3162
> > width=54) (actual time=290.356..808.454 rows=4102 loops=1)
> > Workers Planned: 2
> > Workers Launched: 2
> > Buffers: shared hit=216312 read=84755
> > -> Nested Loop (cost=61853.04..155782.37
> > rows=1318 width=54) (actual time=238.313..735.472 rows=1367 loops=3)
> > Buffers: shared hit=216312 read=84755
> > -> Parallel Hash Join
> > (cost=61852.61..143316.27 rows=24085 width=4) (actual
> > time=237.966..677.975 rows=19756 loops=3)
> > Hash Cond:
> > (scheduler_operation_executions.task_execution_id =
> > scheduler_task_executions.id)
> > Buffers: shared hit=6441 read=84755
> > -> Parallel Seq Scan on
> > scheduler_operation_executions (cost=0.00..74945.82 rows=2482982
> > width=8) (actual time=0.117..234.279 rows=1986887 loops=3)
> > Buffers: shared hit=3188 read=46928
> > -> Parallel Hash
> > (cost=61652.25..61652.25 rows=16029 width=4) (actual
> > time=236.631..236.631 rows=13558 loops=3)
> > Buckets: 65536 Batches: 1
> > Memory Usage: 2144kB
> > Buffers: shared hit=3169 read=37827
> > -> Parallel Seq Scan on
> > scheduler_task_executions (cost=0.00..61652.25 rows=16029 width=4)
> > (actual time=0.132..232.758 rows=13558 loops=3)
> > Filter: (device_id = 97)
> > Rows Removed by Filter: 1308337
> > Buffers: shared hit=3169 read=37827
> > -> 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
> > <> '<NullData/>'::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: 1.787 ms
> > Execution Time: 810.634 ms
> >
> > You can see that the second run takes less than one second to run...
> > which is 43 seconds better than the first try, just by re-running the
> > query.
> > Other runs take maybe 1s, 3s, still a long time.
> >
> > How can I improve it to be consistently fast (is it possible to get to
> > several milliseconds?)?
> > What I don't really understand is why the nested loop has 3 loops
> > (three joined tables)?
> > And why does the first index scan indicate ~60k loops? And does it
> > really work? It doesn't seem to filter out any rows.
> >
> > Should I add an index only on (attribute_id, object_id)? And maybe
> > data_access_result?
> > Does it make sens to add it on a text column (results.data)?
> >
> > My tables:
> > https://gist.githubusercontent.com/paulbarbu/0d36271d710349d8fb6102d9a466bb54/raw/7a6946ba7c2adec5b87ed90f343f1aff37432d21/gistfile1.txt
> >
> > As you can see from the gist the foreign keys are indexed. Other
> > indices were added to speed up other queries.
> > Other relevant information (my tables have 3+ millions of rows, not
> > very big I think?), additional info with regards to size also included
> > below.
> > This query has poor performance on two PCs (both running off of HDDs)
> > so I think it has more to do with my indices and query than Postgres
> > config & hardware, will post those if necessary.
> >
> >
> > Size info:
> > SELECT relname, relpages, reltuples, relallvisible, relkind, relnatts,
> > relhassubclass, reloptions, pg_table_size(oid) FROM pg_class WHERE
> > relname IN ('results', 'scheduler_operation_executions',
> > 'scheduler_task_executions');
> > -[ RECORD 1 ]--+-------------------------------
> > relname | results
> > relpages | 65922
> > reltuples | 3.17104e+06
> > relallvisible | 65922
> > relkind | r
> > relnatts | 9
> > relhassubclass | f
> > reloptions |
> > pg_table_size | 588791808
> > -[ RECORD 2 ]--+-------------------------------
> > relname | scheduler_operation_executions
> > relpages | 50116
> > reltuples | 5.95916e+06
> > relallvisible | 50116
> > relkind | r
> > relnatts | 8
> > relhassubclass | f
> > reloptions |
> > pg_table_size | 410697728
> > -[ RECORD 3 ]--+-------------------------------
> > relname | scheduler_task_executions
> > relpages | 40996
> > reltuples | 3.966e+06
> > relallvisible | 40996
> > relkind | r
> > relnatts | 12
> > relhassubclass | f
> > reloptions |
> > pg_table_size | 335970304
> >
> > Thanks for your time!
> >
> > --
> > Barbu Paul - Gheorghe
> >
> Can you create an index on scheduler_task_executions.device_id and run
> it again?

--

Barbu Paul - Gheorghe