4

I look on a Postgres query plan and I noticed that the upper step start time is not overlap with the lower step end time, so I wonder where the gap time is spent?

fields name were edited for this query.

As you can see below the query executer has 2 steps. The lower step 'Index Scan' end at 5730.776 (actual time), but the root step begin on 19199.316 (actual time). My question is what was happened between 5730.776 to 19199.316 ?

postgres 9.1

explain analyze select a_id,b_id,c_id,d_id,e_id,mydate, f,sum(used) used
from report A where mydate >= '2013-05-01' and mydate  <= '2013-08-30'
group by a_id,b_id,c_id,d_id,e_id,date,f;
                                                                                                      QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 HashAggregate  (cost=412378.59..418074.28 rows=569569 width=70) (actual time=**19199.316**..25518.672 rows=4935988 loops=1)
   ->  Index Scan using report_dateonly_idx on report a  (cost=0.00..298464.83 rows=5695688 width=70) (actual time=0.033..**5730.776** rows=5816028 loops=1)
         Index Cond: ((date >= '2013-05-01 00:00:00'::timestamp without time zone) AND (date <= '2013-08-30 00:00:00'::timestamp without time zone))
 Total runtime: 29148.500 ms
4

2 回答 2

4

You might be interested in this series of blog posts on understanding query plans.

In your case, you are misinterpreting what the two numbers in each cost/timing represent. They are not the start and end of the operation, but (roughly) the cost/time before the first row, and the cost/time including all rows.

Depesz gives the example of a sort operation having "cost=22.88..23.61" - the cost to prepare the data is high, because you have to sort everything before you can return any of it; the cost of actually returning it is much lower, because it's just spooling through your sorted list.

So in your example the 19199.316 doesn't mean that the HashAggregate doesn't start running until t=19199.316, it means that until t=19199.316 no data will come out of the HashAggregate because it is still preparing stuff.

In fact, the HashAggregate will start processing data as soon as the Index Scan starts returning it, which is at t=0.033; by t=5730.776, the Index Scan has found all the relevant rows, but the HashAggregate is still processing them. At t=19199.316, the HashAggregate is ready to start returning data to its parent (which in this case is the final result), and at t=25518.672, it's finished returning them.

Depezs also has a tool which interprets query plans into a table form; here's your plan. Note that the HashAggregate shows an "exclusive time" of 19787.896 - that's how long it took to do the hashing, ignoring where the input data came from.

于 2013-09-22T13:15:13.610 回答
1

The reason for the observed behaviour: your statistics are wrong:

HashAggregate  (cost=412378.59..418074.28 rows=569569 width=70) (actual time=**19199.316**..25518.672 rows=4935988 loops=1)
 [expected] -----------------------------------^^^^^^       [actual rows found] > ------------------------ ^^^^^^^

This is off by a factor nine, and causes the planner to choose a hash-table based aggregation, since it thinks that the result will fit into work_mem. It is initially undersized, needs to be resized a few times and if does not fit into workmem it even has to be spilt to disk.

BTW: I was unable to recreate this kind of plan. I keep getting bitmap index scans.

于 2013-09-22T21:00:39.047 回答