Postgres EXPLAIN ANALYZE Total Time Appears to Exceed Sum of Parts

Question

I'm trying to identify some performance bottlenecks in my Postgres queries and ran an EXPLAIN ANALYZE on a query to get some insights. The output of the query analysis is below:

    Nested Loop  (cost=162.35..5361.39 rows=4385 width=33) (actual time=5.663..315.153 rows=2 loops=1)
  ->  Seq Scan on "User" p=u  (cost=0.00..1.02 rows=1 width=8) (actual time=0.009..0.011 rows=1 loops=1)
        Filter: ("ID" = 1)
        Rows Removed by Filter: 1
  ->  Nested Loop  (cost=162.35..5316.51 rows=4385 width=33) (actual time=5.646..315.130 rows=2 loops=1)
        ->  Nested Loop  (cost=161.93..1854.59 rows=6574 width=33) (actual time=5.567..106.350 rows=44342 loops=1)
              ->  Seq Scan on "Op" o  (cost=0.00..1.34 rows=1 width=8) (actual time=0.007..0.011 rows=1 loops=1)
                    Filter: ("Name" = 'write'::text)
                    Rows Removed by Filter: 26
              ->  Bitmap Heap Scan on "Account" a  (cost=161.93..1768.73 rows=8453 width=33) (actual time=5.551..45.435 rows=44342 loops=1)
                    Recheck Cond: ("OId" = o."ID")
                    Filter: ("UId" = 1)
                    Heap Blocks: exact=1480
                    ->  Bitmap Index Scan on "IX_Account_op_ID"  (cost=0.00..159.82 rows=8453 width=0) (actual time=5.138..5.139 rows=44342 loops=1)
                          Index Cond: ("OId" = o."ID")
        ->  Index Scan using "PK_Resource_ID" on "Resources" r  (cost=0.42..0.53 rows=1 width=8) (actual time=0.003..0.003 rows=0 loops=44342)
              Index Cond: ("ID" = a."ResourceId")
              Filter: ("Role" = ANY ('{r1,r2,r3,r4,r5}'::text[]))
              Rows Removed by Filter: 1
Planning Time: 0.777 ms
Execution Time: 315.220 ms

I haven't done much query analysis with pg explain before so I'm still trying to wrap my head around everything it's telling me here. One thing I am seeing that is causing me some confusion is I can see the outer execution:

Nested Loop  (cost=162.35..5361.39 rows=4385 width=33) (actual time=5.663..315.153 rows=2 loops=1)

says the actual time was 5.663...315 - ok, that makes sense since the total execution time was 315. Then, a little below that:

Nested Loop (cost=162.35..5316.51 rows=4385 width=33) (actual time=5.646..315.130 rows=2 loops=1)

Ok! This is telling me the bulk of the total execution time is going to be in this section. Under this I see:

    ->  Nested Loop  (cost=161.93..1854.59 rows=6574 width=33) (actual time=5.567..106.350 rows=44342 loops=1)
          ->  Seq Scan on "Op" o  (cost=0.00..1.34 rows=1 width=8) (actual time=0.007..0.011 rows=1 loops=1)
                Filter: ("Name" = 'write'::text)
                Rows Removed by Filter: 26
          ->  Bitmap Heap Scan on "Account" a  (cost=161.93..1768.73 rows=8453 width=33) (actual time=5.551..45.435 rows=44342 loops=1)
                Recheck Cond: ("OId" = o."ID")
                Filter: ("UId" = 1)
                Heap Blocks: exact=1480

Huh - so this is saying there was is a nested loop that took 106.35 ms , which looped once, and the contents of that loop were a sq scan that took .011ms and a bitmap heap scan that took 45.435ms.

All the loops have 1 loop but in both cases it looks to me like the total execution of these loops was higher than the sum of the loops contents. In the case of the inner loop it took 106ms to execute but if I add up the contents of that loop it looks like it should have only taken 45.446ms (.011ms + 45.435ms). In the case of the outer loop it took 315.13ms but again if I add up the contents it looks like it should have been 106.353ms (106.35ms + .003ms).

I'm looking at this and assuming that loops=1 means it only executed what was inside that loop once.. although the total times suggest that there was more than one execution. I'm not sure where I'm misinterpreting this. Could anyone shed some light on this for me? Any advice here would be appreciated, thanks much!

Just guessing, parallel processing of some of the branches of the plan? — wilx
– wilx, Commented Jun 2, 2019 at 12:06
Are you doing something in SELECTs, like for example math operations, function execition or something else that takes time? — Łukasz Kamiński
– Łukasz Kamiński, Commented Jun 3, 2019 at 9:42

Łukasz Kamiński · Accepted Answer · 2019-06-03 13:47:35Z

ANALYZE does not show how long it takes to perform tasks in SELECT tasks FROM [..]. Here pg_sleep(1) is taking 20000ms (20x1sec), but you only see it in Nested Loop section

explain (analyze, verbose)
select *, pg_sleep(1)
  from generate_series(1,5) AS w
  cross join generate_series(current_date,current_date+3,interval '1 day') AS v;

QUERY PLAN
Nested Loop  (cost=0.02..22510.02 rows=1000000 width=16) (actual time=1001.082..20021.134 rows=20 loops=1)
  Output: w.w, v.v, pg_sleep('1'::double precision)
  ->  Function Scan on pg_catalog.generate_series w  (cost=0.00..10.00 rows=1000 width=4) (actual time=0.006..0.008 rows=5 loops=1)
        Output: w.w
        Function Call: generate_series(1, 5)
  ->  Function Scan on pg_catalog.generate_series v  (cost=0.02..10.02 rows=1000 width=8) (actual time=0.005..0.010 rows=4 loops=5)
        Output: v.v
        Function Call: generate_series((('now'::cstring)::date)::timestamp with time zone, ((('now'::cstring)::date + 3))::timestamp with time zone, '1 day'::interval)
Planning time: 0.093 ms
Execution time: 20021.178 ms

It does not show how long it takes to JOIN data sets. Here getting data takes about 1000ms, but JOINing those sets takes 4x longer, because you see increase in time in Nested Loop section by about that much and it is the only thing it had to do and was not listed in detailed plan.

explain (analyze, verbose)
select *
  from generate_series(1,50000) AS w
  cross join generate_series(current_date,current_date+30,interval '1 day') AS v;

QUERY PLAN
Nested Loop  (cost=0.02..20010.02 rows=1000000 width=12) (actual time=3.237..3128.123 rows=1550000 loops=1)
  Output: w.w, v.v
  ->  Function Scan on pg_catalog.generate_series w  (cost=0.00..10.00 rows=1000 width=4) (actual time=3.210..35.472 rows=50000 loops=1)
        Output: w.w
        Function Call: generate_series(1, 50000)
  ->  Function Scan on pg_catalog.generate_series v  (cost=0.02..10.02 rows=1000 width=8) (actual time=0.001..0.021 rows=31 loops=50000)
        Output: v.v
        Function Call: generate_series((('now'::cstring)::date)::timestamp with time zone, ((('now'::cstring)::date + 30))::timestamp with time zone, '1 day'::interval)
Planning time: 0.046 ms
Execution time: 4103.113 ms

Collectives™ on Stack Overflow

Postgres EXPLAIN ANALYZE Total Time Appears to Exceed Sum of Parts

1 Answer 1

Comments

Your Answer

Hot Network Questions

Collectives™ on Stack Overflow

1 Answer 1

Comments

Your Answer

Sign up or log in

Post as a guest

Related