PostgreSQL – Time Difference Between Actual Total Time and Execution Time in EXPLAIN ANALYZE

explainpostgresqlpostgresql-11

I have the following output of EXPLAIN ANALYZE query on PostgreSQL 11.5

EXPLAIN (ANALYZE, VERBOSE, BUFFERS) 
SELECT actor.actor_id, actor.first_name, act.num 
FROM actor 
  INNER JOIN ( 
    SELECT  actor_id, COUNT(DISTINCT film_category.category_id) as num 
    FROM film_actor 
      INNER JOIN film_category ON film_actor.film_id = film_category.film_id   
    GROUP BY actor_id 
  ) act ON act.actor_id = actor.actor_id 
ORDER BY actor.actor_id ASC; 

Merge Join  (cost=527.43..591.41 rows=200 width=18) (actual time=320.130..324.861 rows=200 loops=1)
  Output: actor.actor_id, actor.first_name, (count(DISTINCT film_category.category_id))
  Inner Unique: true
  Merge Cond: (actor.actor_id = film_actor.actor_id)
  Buffers: shared hit=9 read=35
  ->  Index Scan using actor_pkey on public.actor  (cost=0.14..16.16 rows=200 width=10) (actual time=77.146..77.272 rows=200 loops=1)
        Output: actor.actor_id, actor.first_name, actor.last_name, actor.last_update
        Buffers: shared hit=2 read=3
  ->  GroupAggregate  (cost=527.28..570.25 rows=200 width=10) (actual time=242.973..247.346 rows=200 loops=1)
        Output: film_actor.actor_id, count(DISTINCT film_category.category_id)
        Group Key: film_actor.actor_id
        Buffers: shared hit=7 read=32
        ->  Sort  (cost=527.28..540.94 rows=5462 width=4) (actual time=242.932..243.781 rows=5462 loops=1)
              Output: film_actor.actor_id, film_category.category_id
              Sort Key: film_actor.actor_id
              Sort Method: quicksort  Memory: 449kB
              Buffers: shared hit=7 read=32
              ->  Hash Join  (cost=28.50..188.22 rows=5462 width=4) (actual time=17.034..216.640 rows=5462 loops=1)
                    Output: film_actor.actor_id, film_category.category_id
                    Hash Cond: (film_actor.film_id = film_category.film_id)
                    Buffers: shared hit=4 read=32
                    ->  Seq Scan on public.film_actor  (cost=0.00..84.62 rows=5462 width=4) (actual time=0.019..195.884 rows=5462 loops=1)
                          Output: film_actor.actor_id, film_actor.film_id, film_actor.last_update
                          Buffers: shared hit=2 read=28
                    ->  Hash  (cost=16.00..16.00 rows=1000 width=4) (actual time=16.964..16.965 rows=1000 loops=1)
                          Output: film_category.category_id, film_category.film_id
                          Buckets: 1024  Batches: 1  Memory Usage: 44kB
                          Buffers: shared hit=2 read=4
                          ->  Seq Scan on public.film_category  (cost=0.00..16.00 rows=1000 width=4) (actual time=0.017..16.431 rows=1000 loops=1)
                                Output: film_category.category_id, film_category.film_id
                                Buffers: shared hit=2 read=4
Planning Time: 966.447 ms
Execution Time: 436.348 ms

On the first line, the actual total time is 324.861 ms but on the last line the execution time is 436.348 ms. What are the causes of this differences?

Best Answer

The source of EXPLAIN has:

    /* Create textual dump of plan tree */
    ExplainPrintPlan(es, queryDesc);

    if (es->summary && planduration)
    {
            double          plantime = INSTR_TIME_GET_DOUBLE(*planduration);

            ExplainPropertyFloat("Planning Time", "ms", 1000.0 * plantime, 3, es);
    }

    ...

    /*
     * Close down the query and free resources.  Include time for this in the
     * total execution time (although it should be pretty minimal).
     */
    INSTR_TIME_SET_CURRENT(starttime);

    ExecutorEnd(queryDesc);

    FreeQueryDesc(queryDesc);

    PopActiveSnapshot();

    /* We need a CCI just in case query expanded to multiple plans */
    if (es->analyze)
            CommandCounterIncrement();

    totaltime += elapsed_time(&starttime);

    /*
     * We only report execution time if we actually ran the query (that is,
     * the user specified ANALYZE), and if summary reporting is enabled (the
     * user can set SUMMARY OFF to not have the timing information included in
     * the output).  By default, ANALYZE sets SUMMARY to true.
     */
    if (es->summary && es->analyze)
            ExplainPropertyFloat("Execution Time", "ms", 1000.0 * totaltime, 3,
                                                     es);

Perhaps freeing of the query resources (tearing down the executor infrastructure, freeing the snapshot) takes an inordinate time. Hard to say.

Is that a one-time occurrence or do you see that result consistently?

If the latter, is there anything unusual about this query?

Related Question