Gap in the execution-time parts in the query plan

Question

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

the reported time is at the **end** of the sorting operation — JGH, Jan 12 '22 at 16:05
@JGH My understanding was that `4222.122..4400.534` means the sorting started `4222.122` and lasted until `4400.534`. Which means the index-scan finished at `339.565` and the sorting started at `4400.534`. Is this not correct? — valenterry, Jan 12 '22 at 20:30
no, the 1st reported time is not the "start" time but the step initialization duration. See this [post](https://dba.stackexchange.com/questions/193508/postgresql-execution-plan-actual-time-meaning) and the [example](https://www.postgresql.org/docs/current/using-explain.html) in the doc (search for `EXPLAIN ANALYZE UPDATE tenk1 SET hundred = hundred + 1 WHERE unique1 < 100;`) — JGH, Jan 12 '22 at 21:00

score 2 · Accepted Answer · answered Jan 13 '22 at 12:29

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.

Gap in the execution-time parts in the query plan

1 Answers1