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?
