Search code examples
postgresqlexplain

Postgresql explain analyze actual time not adding up

I have query's that when run on my postgresql database will constantly increase the execution time as their numbers increase. During high load I ran the same query manually from Dbeaver using explain analyze and it took ~9seconds for the planning time and 1 seconds for the execution time. But if I add up all the actual times in the resulted query I don't get nowhere near 9 seconds.

I also don't have multiple loops. Below is the explain analyze result:

Nested Loop Left Join  (cost=26304.72..35480113.45 rows=624544385412 width=1843) (actual time=0.277..0.284 rows=1 loops=1)
  ->  Nested Loop  (cost=26304.15..907648.85 rows=320874 width=1495) (actual time=0.215..0.218 rows=1 loops=1)
        ->  Index Scan using idx_info_part_13_test_id on test_part_13 "Model"  (cost=0.69..8.71 rows=1 width=976) (actual time=0.140..0.142 rows=1 loops=1)
              Index Cond: ((test_id)::text = 'sjbvas6dsad4sad7asda7sd567as5f7dsdf75sdfsdf6sdf5sfas78d6fdsdsada'::text)
        ->  Bitmap Heap Scan on outputs_p_33 "Model"  (cost=26303.46..904431.40 rows=320874 width=519) (actual time=0.060..0.061 rows=1 loops=1)
              Recheck Cond: ((test_id)::text = 'sjbvas6dsad4sad7asda7sd567as5f7dsdf75sdfsdf6sdf5sfas78d6fdsdsada'::text)
              Heap Blocks: exact=1
              ->  Bitmap Index Scan on pk_test_p_33  (cost=0.00..26223.24 rows=320874 width=0) (actual time=0.055..0.055 rows=1 loops=1)
                    Index Cond: ((test_id)::text = 'sjbvas6dsad4sad7asda7sd567as5f7dsdf75sdfsdf6sdf5sfas78d6fdsdsada'::text)
  ->  Append  (cost=0.56..107.54 rows=20 width=348) (actual time=0.046..0.049 rows=1 loops=1)
        ->  Index Scan using addresses_part_0_address_id_idx on addresses_part_0 "ModelType"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_1_address_id_idx on addresses_part_1 "ModelType_1"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_2_address_id_idx on addresses_part_2 "ModelType_2"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_3_address_id_idx on addresses_part_3 "ModelType_3"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_4_address_id_idx on addresses_part_4 "ModelType_4"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_5_address_id_idx on addresses_part_5 "ModelType_5"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_6_address_id_idx on addresses_part_6 "ModelType_6"  (cost=0.56..5.37 rows=1 width=348) (actual time=0.042..0.042 rows=1 loops=1)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_7_address_id_idx on addresses_part_7 "ModelType_7"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_8_address_id_idx on addresses_part_8 "ModelType_8"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_9_address_id_idx on addresses_part_9 "ModelType_9"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_10_address_id_idx on addresses_part_10 "ModelType_10"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_11_address_id_idx on addresses_part_11 "ModelType_11"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_12_address_id_idx on addresses_part_12 "ModelType_12"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_13_address_id_idx on addresses_part_13 "ModelType_13"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_14_address_id_idx on addresses_part_14 "ModelType_14"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_15_address_id_idx on addresses_part_15 "ModelType_15"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_16_address_id_idx on addresses_part_16 "ModelType_16"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_17_address_id_idx on addresses_part_17 "ModelType_17"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_18_address_id_idx on addresses_part_18 "ModelType_18"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_19_address_id_idx on addresses_part_19 "ModelType_19"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
Planning Time: 9127.562 ms
Execution Time: 1.090 ms

Shouldn't I get the same number of seconds if I add the "actual time" from the result? Why is it that big of a difference?

Solution
    1. Use this to inspect your execution plans.
    2. These don't add up because they don't have to. From Using EXPLAIN in the doc:

      The Planning time shown by EXPLAIN ANALYZE is the time it took to generate the query plan from the parsed query and optimize it. It does not include parsing or rewriting.

      The Execution time shown by EXPLAIN ANALYZE includes executor start-up and shut-down time, as well as the time to run any triggers that are fired

    3. The doc explains what those measurements are exactly:

      In [nested-loop plan], the loops value reports the total number of executions of the node, and the actual time and rows values shown are averages per-execution

    4. There's auto_explain you can use to automatically catch, log and explain the slow queries. It's useful if you're trying to track down why something's slow and for some reason, when you run and inspect it individually, it suddenly isn't slow. Auto_explain should reflect why it was slow when it was, and what exactly held it up.

    Typically if you're experiencing increasing query times in response to increased traffic, you might want to see if you're not

    • locking something, causing concurrent sessions to have to wait in a queue waiting for the current one to finish,
    • running out of CPU/memory
    • approaching the bandwidth limit if you transfer a lot of data in each request/response
    • trying to read-write too much at once, stress-testing your underlying storage, which could be unable to keep up with the IO demand

    The list is far from exhaustive. Server config, schema, full query, data set characteristics and traffic profile would be required to look into it.