主页 / dba / 问题 / 250996
Accepted
jrandiny
Asked: 2019-10-15 02:38:40 +0800 CST

EXPLAIN ANALYZE 中实际总时间与执行时间的时间差

  • 772

我在 PostgreSQL 11.5 上有以下 EXPLAIN ANALYZE 查询的输出

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

在第一行，实际总时间为 324.861 毫秒，但在最后一行，执行时间为 436.348 毫秒。造成这种差异的原因是什么？

postgresql explain

1 个回答

  1. Best Answer

    的来源EXPLAIN有：

        /* 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);

    或许释放查询资源（拆除执行器基础设施，释放快照）会花费过多的时间。很难说。

    这是一次性事件还是您始终看到该结果？

    如果是后者，这个查询有什么不寻常的地方吗？

    • 1

相关问题