I have trouble understanding the following query plan (anonyized). There seems to be a gap in how much time the actual parts of the query took and a part is missing.
The relevant part:
-> Sort (cost=306952.44..307710.96 rows=303409 width=40) (actual time=4222.122..4400.534 rows=582081 loops=1)
Sort Key: table1.column3, table1.column2
Sort Method: quicksort Memory: 71708kB
Buffers: shared hit=38058
-> Index Scan using myindex on table1 (cost=0.56..279325.68 rows=303409 width=40) (actual time=0.056..339.565 rows=582081 loops=1)
Index Cond: (((column1)::text = 'xxx1'::text) AND ((column2)::text > 'xxx2'::text) AND ((column2)::text < 'xxx3'::text))
Buffers: shared hit=38058
What happened between the index scan (up until 339.565
) and starting to sort the result (4222.122
)?
And the full plan (just in case):
GroupAggregate (cost=344290.95..348368.01 rows=30341 width=65) (actual time=4933.739..4933.806 rows=11 loops=1)
Group Key: t.column1, t.current_value, t.previous_value
Buffers: shared hit=38058
-> Sort (cost=344290.95..345045.68 rows=301892 width=72) (actual time=4933.712..4933.719 rows=58 loops=1)
Sort Key: t.column1, t.current_value, t.previous_value
Sort Method: quicksort Memory: 32kB
Buffers: shared hit=38058
-> Subquery Scan on t (cost=306952.44..316813.23 rows=301892 width=72) (actual time=4573.523..4933.607 rows=58 loops=1)
Filter: ((t.current_value)::text <> (t.previous_value)::text)
Rows Removed by Filter: 582023
Buffers: shared hit=38058
-> WindowAgg (cost=306952.44..313020.62 rows=303409 width=72) (actual time=4222.144..4859.579 rows=582081 loops=1)
Buffers: shared hit=38058
-> Sort (cost=306952.44..307710.96 rows=303409 width=40) (actual time=4222.122..4400.534 rows=582081 loops=1)
Sort Key: table1.column3, table1.column2
Sort Method: quicksort Memory: 71708kB
Buffers: shared hit=38058
-> Index Scan using myindex on table1 (cost=0.56..279325.68 rows=303409 width=40) (actual time=0.056..339.565 rows=582081 loops=1)
Index Cond: (((column1)::text = 'xxx1'::text) AND ((column2)::text > 'xxx2'::text) AND ((column2)::text < 'xxx3'::text))
Buffers: shared hit=38058
Planning Time: 0.405 ms
Execution Time: 4941.003 ms
Both cost
and actual time
data are shown as two numbers in these plans. The first is the setup time. Sloppily described, it's the time the query step takes to deliver its first row. See this. The second is the completion time, or time to last row.
actual time=setup...completion
The setup on a sort step includes the time required to retrieve the result set needing sorting and to actually perform the sort: shuffle the rows around in RAM or hopefully not, on disk. (Because quicksort is generally O(n log(n)) in complexity, that can be long for big result sets. You knew that.)
In your plan, the inner sort handles almost 600K rows that came from an index scan. It's the step where the sort takes time. It used 71,708 kilobytes of RAM.
As far as I can tell, there's nothing anomalous in your plan. How to speed up that sort? You might try shorter or fixed-length column2
and column3
data types, but that's all guesswork without seeing your query and table definitions.