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@xxxxxxxxxxxxxxx> 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
