Thread: I don't understand that EXPLAIN PLAN timings
Hello, This EXPLAIN ANALYZE tells me the actual time was 11.xxx ms but the final Execution time says 493.xxx ms (this last one is true : about 1/2 second). I would like to optimize this query but with this inconsistency, it will be difficult. This query is really a function so I added the "params" CTE to do the tests. Thanks for your help, JC PS: PostgreSQL 14.10 (Ubuntu 14.10-1.pgdg23.10+1) on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 13.2.0-4ubuntu3) 13.2.0, 64-bit and JIT is disabled Nested Loop Left Join (cost=36411048684.11..36411051002.22 rows=54228 width=116) (actual time=11.609..11.620 rows=0 loops=1) Join Filter: (u_g_internalvalidation.idinternalvalidation IS NOT NULL) CTE params -> Result (cost=0.00..0.01 rows=1 width=41) (actual time=0.001..0.001 rows=1 loops=1) CTE u -> Nested Loop (cost=0.25..12.77 rows=250 width=368) (never executed) -> CTE Scan on params (cost=0.00..0.02 rows=1 width=41) (never executed) -> Function Scan on get_user (cost=0.25..10.25 rows=250 width=327) (never executed) Filter: ((NOT isgroup) AND (NOT istemplate)) CTE internalvalidation -> Hash Join (cost=13988.95..14336.16 rows=436 width=42) (actual time=11.601..11.606 rows=0 loops=1) Hash Cond: (files.idfile = i_1.idfile) -> HashAggregate (cost=13929.87..14039.58 rows=10971 width=4) (actual time=11.480..11.527 rows=243 loops=1) Group Key: files.idfile Batches: 1 Memory Usage: 417kB -> Append (cost=0.00..13902.45 rows=10971 width=4) (actual time=6.593..11.423 rows=243 loops=1) -> Nested Loop (cost=0.00..10139.01 rows=10766 width=4) (actual time=5.143..5.145 rows=0 loops=1) Join Filter: ((files.idfile = (unnest(params_2.fn_idfile))) OR ((params_1.fn_idrealm = files.idrealminitial) AND params_1.fn_canseesubfiles)) -> Seq Scan on files (cost=0.00..2985.74 rows=40874 width=8) (actual time=0.002..2.396 rows=40766 loops=1) -> Materialize (cost=0.00..0.35 rows=10 width=9) (actual time=0.000..0.000 rows=0 loops=40766) -> Nested Loop (cost=0.00..0.30 rows=10 width=9) (actual time=0.003..0.003 rows=0 loops=1) -> CTE Scan on params params_1 (cost=0.00..0.02 rows=1 width=5) (actual time=0.002..0.003 rows=0 loops=1) Filter: (fn_idfile IS NOT NULL) Rows Removed by Filter: 1 -> ProjectSet (cost=0.00..0.08 rows=10 width=4) (never executed) -> CTE Scan on params params_2 (cost=0.00..0.02 rows=1 width=32) (never executed) -> Nested Loop (cost=0.00..3598.87 rows=205 width=4) (actual time=1.448..6.267 rows=243 loops=1) Join Filter: (((params_3.fn_idfile IS NULL) AND (files_1.idrealm = params_3.fn_idrealm)) OR ((files_1.idrealminitial = params_3.fn_idrealm) AND params_3.fn_canseesubfiles)) Rows Removed by Join Filter: 40523 -> CTE Scan on params params_3 (cost=0.00..0.02 rows=1 width=37) (actual time=0.001..0.001 rows=1 loops=1) Filter: ((fn_idfile IS NULL) OR fn_canseesubfiles) -> Seq Scan on files files_1 (cost=0.00..2985.74 rows=40874 width=12) (actual time=0.002..1.946 rows=40766 loops=1) -> Hash (cost=58.94..58.94 rows=11 width=42) (actual time=0.059..0.060 rows=6 loops=1) Buckets: 1024 Batches: 1 Memory Usage: 9kB -> Nested Loop Left Join (cost=0.29..58.94 rows=11 width=42) (actual time=0.031..0.055 rows=6 loops=1) -> Seq Scan on internalvalidations i_1 (cost=0.00..9.81 rows=11 width=26) (actual time=0.012..0.033 rows=6 loops=1) Filter: isvisible Rows Removed by Filter: 453 -> Memoize (cost=0.29..7.58 rows=1 width=20) (actual time=0.003..0.003 rows=1 loops=6) Cache Key: i_1.idclaimer Cache Mode: logical Hits: 5 Misses: 1 Evictions: 0 Overflows: 0 Memory Usage: 1kB -> Index Scan using users_pkey on users users_1 (cost=0.28..7.57 rows=1 width=20) (actual time=0.012..0.013 rows=1 loops=1) Index Cond: (iduser = i_1.idclaimer) CTE u_g_internalvalidation_without_u_status -> Recursive Union (cost=23.65..7914563.16 rows=220606936 width=19) (never executed) -> Nested Loop (cost=23.65..9280.10 rows=1936 width=19) (never executed) Join Filter: (uhi.iduser = gu.iduser) -> Nested Loop (cost=23.40..80.70 rows=733 width=15) (never executed) -> Hash Join (cost=23.11..42.43 rows=733 width=10) (never executed) Hash Cond: (internalvalidation.idinternalvalidation = uhi.idinternalvalidation) -> CTE Scan on internalvalidation (cost=0.00..8.72 rows=436 width=4) (never executed) -> Hash (cost=13.05..13.05 rows=805 width=10) (never executed) -> Seq Scan on users_has_internalvalidations uhi (cost=0.00..13.05 rows=805 width=10) (never executed) -> Memoize (cost=0.29..1.67 rows=1 width=5) (never executed) Cache Key: uhi.iduser Cache Mode: logical -> Index Scan using users_pkey on users v (cost=0.28..1.66 rows=1 width=5) (never executed) Index Cond: (iduser = uhi.iduser) -> Function Scan on get_user gu (cost=0.25..12.75 rows=4 width=5) (never executed) Filter: ((canvalidate OR v.isgroup) AND (v.iduser = iduser)) -> Nested Loop (cost=750.89..349314.43 rows=22060500 width=19) (never executed) -> Merge Join (cost=750.63..1200.96 rows=29414 width=18) (never executed) Merge Cond: (uhg.idgroup = ugiwus.idusergroup) -> Sort (cost=126.96..131.52 rows=1823 width=8) (never executed) Sort Key: uhg.idgroup -> Seq Scan on users_has_groups uhg (cost=0.00..28.23 rows=1823 width=8) (never executed) -> Sort (cost=623.67..631.74 rows=3227 width=18) (never executed) Sort Key: ugiwus.idusergroup -> WorkTable Scan on u_g_internalvalidation_without_u_status ugiwus (cost=0.00..435.60 rows=3227 width=18) (never executed) Filter: (isgroup AND (level < 25)) -> Memoize (cost=0.26..10.26 rows=750 width=5) (never executed) Cache Key: uhg.iduser Cache Mode: binary -> Function Scan on get_user gu_1 (cost=0.25..10.25 rows=750 width=5) (never executed) Filter: (canvalidate OR isgroup) -> Hash Join (cost=36403119772.02..36403120996.38 rows=436 width=120) (actual time=11.609..11.611 rows=0 loops=1) Hash Cond: (ug1.idinternalvalidation = i.idinternalvalidation) -> Merge Left Join (cost=36403119757.85..36403120966.35 rows=200 width=75) (never executed) Merge Cond: (ug1.idinternalvalidation = u_g_internalvalidation.idinternalvalidation) -> GroupAggregate (cost=36397604572.80..36397605775.80 rows=200 width=70) (never executed) Group Key: ug1.idinternalvalidation -> Sort (cost=36397604572.80..36397604772.80 rows=80000 width=27) (never executed) Sort Key: ug1.idinternalvalidation -> Hash Left Join (cost=36397596247.48..36397598057.72 rows=80000 width=27) (never executed) Hash Cond: (ug1.idusergroup = users.iduser) -> HashAggregate (cost=36397595908.85..36397596708.85 rows=80000 width=43) (never executed) Group Key: ug1.idinternalvalidation, ug1.idusergroup, ug1.atleastonemustvalidate -> Merge Left Join (cost=77330317.34..21265069958.96 rows=1210602075991 width=13) (never executed) Merge Cond: ((ug1.idinternalvalidation = ug2.idinternalvalidation) AND (ug1.iduser = ug2.iduser)) -> Sort (cost=38754984.35..39306501.69 rows=220606936 width=15) (never executed) Sort Key: ug1.idinternalvalidation, ug1.iduser -> CTE Scan on u_g_internalvalidation_without_u_status ug1 (cost=0.00..4412138.72 rows=220606936 width=15) (never executed) -> Materialize (cost=38575332.99..39672852.50 rows=219503901 width=10) (never executed) -> Sort (cost=38575332.99..39124092.74 rows=219503901 width=10) (never executed) Sort Key: ug2.idinternalvalidation, ug2.iduser -> CTE Scan on u_g_internalvalidation_without_u_status ug2 (cost=0.00..4412138.72 rows=219503901 width=10) (never executed) Filter: (hasvalidate IS NOT NULL) -> Hash (cost=289.95..289.95 rows=3895 width=20) (never executed) -> Seq Scan on users (cost=0.00..289.95 rows=3895 width=20) (never executed) -> Sort (cost=5515185.04..5515185.54 rows=200 width=5) (never executed) Sort Key: u_g_internalvalidation.idinternalvalidation -> Subquery Scan on u_g_internalvalidation (cost=5515173.40..5515177.40 rows=200 width=5) (never executed) -> HashAggregate (cost=5515173.40..5515175.40 rows=200 width=5) (never executed) Group Key: ugi.idinternalvalidation -> CTE Scan on u_g_internalvalidation_without_u_status ugi (cost=0.00..4412138.72 rows=220606936 width=5) (never executed) -> Hash (cost=8.72..8.72 rows=436 width=49) (actual time=11.603..11.603 rows=0 loops=1) Buckets: 1024 Batches: 1 Memory Usage: 8kB -> CTE Scan on internalvalidation i (cost=0.00..8.72 rows=436 width=49) (actual time=11.603..11.603 rows=0 loops=1) -> CTE Scan on u (cost=0.00..5.00 rows=125 width=4) (never executed) Filter: canvalidate Planning Time: 1.037 ms Execution Time: 493.815 ms And here is the query in case it can help : explain analyze WITH RECURSIVE params AS ( SELECT 4 AS fn_iduser , 1 AS fn_idrealm , NULL::INT[] AS fn_idfile , TRUE AS fn_canseesubfiles ), r AS ( SELECT realms.* FROM realms CROSS JOIN params WHERE idrealm=fn_idrealm ) ,u AS ( SELECT * FROM PARAMS CROSS JOIN get_user(fn_iduser) WHERE NOT isgroup AND NOT istemplate ) ,allfiles AS ( SELECT files.idfile --idfile devrait suffire FROM params CROSS JOIN ( SELECT UNNEST(fn_idfile) as idfile FROM params ) AS unnestedfiles JOIN files ON files.idfile = unnestedfiles.idfile OR ( -- see sub files fn_idrealm = files.idrealminitial AND fn_canseesubfiles ) WHERE fn_idfile IS NOT NULL UNION SELECT files.idfile --idfile devrait suffire FROM files CROSS JOIN params WHERE fn_idfile IS NULL AND files.idrealm = fn_idrealm OR ( files.idrealminitial = fn_idrealm AND fn_canseesubfiles ) ) ,internalvalidation as ( SELECT i.*, users.name FROM allfiles pfu JOIN internalvalidations i ON i.idfile = pfu.idfile AND i.isvisible LEFT JOIN users ON users.iduser = i.idclaimer ) ,u_g_internalvalidation_without_u_status AS ( SELECT uhi.idinternalvalidation ,uhi.iduser as idusergroup ,uhi.hasvalidate ,uhi.atleastonemustvalidate ,v.iduser ,v.isgroup , 0 level FROM internalvalidation JOIN users_has_internalvalidations uhi ON uhi.idinternalvalidation = internalvalidation.idinternalvalidation JOIN users v on uhi.iduser = v.iduser JOIN get_user(v.iduser) gu ON gu.iduser = v.iduser AND ( gu.canvalidate OR v.isgroup ) UNION SELECT ugiwus.idinternalvalidation ,ugiwus.iduser as idusergroup ,ugiwus.hasvalidate ,ugiwus.atleastonemustvalidate ,gu.iduser ,gu.isgroup , ugiwus.level + 1 FROM u_g_internalvalidation_without_u_status ugiwus JOIN users_has_groups uhg ON uhg.idgroup = ugiwus.idusergroup AND ugiwus.isgroup JOIN get_user(uhg.iduser) gu ON ( gu.canvalidate OR gu.isgroup ) WHERE ugiwus.level < 25 ) -- SELECT * FROM u_g_internalvalidation_without_u_status; ,u_g_internalvalidation AS ( SELECT ugi.idinternalvalidation, bool_or(COALESCE(ugi.hasvalidate,false)) currentuserhasvalidate--, bool_or( ugi.iduser = u.iduser ) /* à quoi sert ce champ ? */ FROM u_g_internalvalidation_without_u_status ugi -- CROSS JOIN u /* et donc à quoi sert cette table ? */ -- WHERE u.iduser = ugi.iduser GROUP BY ugi.idinternalvalidation ) ,regroup_users as ( SELECT -- regroup users by group etc ... ug1.idinternalvalidation ,ug1.idusergroup ,BOOL_OR( COALESCE( ug2.hasvalidate, ug1.hasvalidate,false)) FILTER ( WHERE NOT ug1.isgroup OR ug2.isgroup ) AS atleastoneuserhasvalidate ,BOOL_AND( COALESCE( ug2.hasvalidate, ug1.hasvalidate,false)) FILTER ( WHERE NOT ug1.isgroup OR ug2.isgroup ) AS everyuserhasvalidate ,ARRAY_AGG( DISTINCT ug1.iduser) AS iduser ,ug1.atleastonemustvalidate FROM u_g_internalvalidation_without_u_status ug1 LEFT JOIN u_g_internalvalidation_without_u_status ug2 ON ug2.idinternalvalidation = ug1.idinternalvalidation AND ug2.iduser = ug1.iduser AND ug2.hasvalidate IS NOT NULL GROUP BY ug1.idinternalvalidation,ug1.idusergroup,ug1.atleastonemustvalidate ) ,regroup_internvalvalidations AS ( SELECT r.idinternalvalidation ,ARRAY_AGG(r.idusergroup) AS iduser ,ARRAY_AGG(users.name) AS name ,BOOL_OR(v.validate) AS atleastoneuserhasvalidate ,BOOL_AND(v.validate) AS everyusershasvalidate FROM regroup_users r LEFT JOIN users ON users.iduser = r.idusergroup CROSS JOIN LATERAL ( SELECT CASE WHEN r.atleastonemustvalidate THEN r.atleastoneuserhasvalidate ELSE r.everyuserhasvalidate END AS validate ) AS v GROUP BY r.idinternalvalidation ) SELECT ri.idinternalvalidation ,ri.iduser ,ri.name ,ri.atleastoneuserhasvalidate ,ri.everyusershasvalidate ,i.ttl ,i.idfile ,i.idclaimer ,i.name AS claimername ,CASE WHEN i.atleastonemustvalidate THEN ri.atleastoneuserhasvalidate ELSE ri.everyusershasvalidate END AS internalvalidationisdone ,CASE WHEN u.iduser IS NULL THEN NULL::BOOLEAN ELSE u_g_internalvalidation.currentuserhasvalidate END AS currentuserhasvalidate FROM regroup_internvalvalidations ri JOIN internalvalidation i ON i.idinternalvalidation = ri.idinternalvalidation LEFT JOIN u_g_internalvalidation ON u_g_internalvalidation.idinternalvalidation = ri.idinternalvalidation LEFT JOIN u ON u_g_internalvalidation.idinternalvalidation IS NOT NULL AND u.canvalidate
Hello,
No answer to my previous email, here is a simpler query with the same problem: explain says actual time between 1.093→1.388 but final execution time says 132.880ms?!?
Thanks for your help,
explain analyze
WITH RECURSIVE u AS (
SELECT idrealm, canseesubrealm
FROM get_user(256)
)
,realm_list as (
-- get the tree view of all visible realms by the user
SELECT u.idrealm, 0 AS level
FROM u
UNION
SELECT realms.idrealm, rl.level+1
FROM realms
JOIN realm_list rl ON rl.idrealm = realms.idrealmparent
CROSS JOIN u
WHERE u.canseesubrealm
AND rl.level < 20
)
SELECT
r.idrealm
,r.idrealmparent
,r.name
,r.istemplate
,r.mustvalidate
,r.filesdirectory
,r.dbname
,r.iconrealm
,r.dbhost
,r.email
,r.urlrealm
,r.dbport
,r.dbpassword
,r.dbloginname
,r.dbowner
,rl.level
,r.pricetag
FROM realm_list rl
JOIN realms r ON r.idrealm=rl.idrealm;
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------
Hash Join (cost=520303.68..854752.18 rows=13123940 width=258) (actual time=1.093..1.388 rows=167 loops=1)
Hash Cond: (rl.idrealm = r.idrealm)
CTE u
-> Function Scan on get_user (cost=0.25..10.25 rows=1000 width=5) (actual time=0.996..0.997 rows=1 loops=1)
CTE realm_list
-> Recursive Union (cost=0.00..520273.42 rows=14746000 width=8) (actual time=1.000..1.228 rows=167 loops=1)
-> CTE Scan on u (cost=0.00..20.00 rows=1000 width=8) (actual time=0.998..0.999 rows=1 loops=1)
-> Nested Loop (cost=266.66..22533.34 rows=1474500 width=8) (actual time=0.014..0.038 rows=42 loops=4)
-> CTE Scan on u u_1 (cost=0.00..20.00 rows=500 width=0) (actual time=0.000..0.001 rows=1 loops=4)
Filter: canseesubrealm
-> Materialize (cost=266.66..403.22 rows=2949 width=8) (actual time=0.012..0.034 rows=42 loops=4)
-> Hash Join (cost=266.66..388.47 rows=2949 width=8) (actual time=0.012..0.026 rows=42 loops=4)
Hash Cond: (realms.idrealmparent = rl_1.idrealm)
-> Seq Scan on realms (cost=0.00..17.78 rows=178 width=8) (actual time=0.000..0.009 rows=167 loops=4)
-> Hash (cost=225.00..225.00 rows=3333 width=8) (actual time=0.006..0.006 rows=42 loops=4)
Buckets: 4096 Batches: 1 Memory Usage: 38kB
-> WorkTable Scan on realm_list rl_1 (cost=0.00..225.00 rows=3333 width=8) (actual time=0.000..0.003 rows=42 loops=4)
Filter: (level < 20)
-> CTE Scan on realm_list rl (cost=0.00..294920.00 rows=14746000 width=8) (actual time=1.001..1.254 rows=167 loops=1)
-> Hash (cost=17.78..17.78 rows=178 width=254) (actual time=0.085..0.085 rows=167 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 30kB
-> Seq Scan on realms r (cost=0.00..17.78 rows=178 width=254) (actual time=0.006..0.043 rows=167 loops=1)
Planning Time: 0.457 ms
Execution Time: 132.880 ms
(24 lignes)
Temps : 134,292 ms
# select version();
version
-------------------------------------------------------------------------------------------------------------------------------
PostgreSQL 14.10 (Ubuntu 14.10-1.pgdg23.10+1) on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 13.2.0-4ubuntu3) 13.2.0, 64-bit
On Tue, 23 Jan 2024 at 20:45, Jean-Christophe Boggio <postgresql@thefreecat.org> wrote: > explain says actual time between 1.093→1.388 but final execution time says 132.880ms?!? The 1.388 indicates the total time spent in that node starting from just before the node was executed for the first time up until the node returned no more tuples. The 132.88 ms is the total time spent to start up the plan, which includes doing things like obtaining locks (if not already obtained during planning), opening files and allocating memory for various things needed for the plan. After the top-level node returns NULL it then will print out the plan before shutting the plan down. This shutdown time is also included in the 132.88 ms. I don't know where exactly the extra time is spent with your query, but it must be in one of the operations that I mentioned which takes place either before the top node is first executed or after the top node returns NULL. If you're using psql, if you do \timing on, how long does EXPLAIN take without ANALYZE? That also goes through executor startup and shutdown. It just skips the running the executor part. David
Hello David,
Thanks for your answer.
If you're using psql, if you do \timing on, how long does EXPLAIN take without ANALYZE? That also goes through executor startup and shutdown.
You are absolutely correct : the EXPLAIN without ANALYZE gives about the same results. Also, minimizing the amount of workmem in postgresql.conf changes drastically the timings. So that means memory allocation is eating up a lot of time _PER_QUERY_ ?
Since we have quite some RAM on our machines, I dedicated as much as possible to workmem (initially I was allocating 1GB) but this looks quite counterproductive (I didn't think that memory was allocated every time, I thought it was "available" for the current query but not necessarily used). Is this an issue specific to that version of PostgreSQL? (I guess no) Or can this be hardware-related? Or OS-related (both systems on which I have done tests are running Ubuntu, I will try on Debian)?
Thanks again for your inputs.
Best,
JC
On Fri, 26 Jan 2024 at 02:31, Jean-Christophe Boggio <postgresql@thefreecat.org> wrote: > You are absolutely correct : the EXPLAIN without ANALYZE gives about the same results. Also, minimizing the amount of workmemin postgresql.conf changes drastically the timings. So that means memory allocation is eating up a lot of time _PER_QUERY_? We do reuse pallocs to create memory context, but only for I believe 1k and 8k blocks. That likely allows most small allocations in the executor to be done without malloc. Speaking in vague terms as I don't have the exact numbers to hand, but larger allocations will go directly to malloc. There was a bug fixed in [1] that did cause behaviour like this, but you seem to be on 14.10 which will have that fix. Also, the 2nd plan you sent has no Memoize nodes. I do wonder now if it was a bad idea to make Memoize build the hash table on plan startup rather than delaying that until we fetch the first tuple. I see Hash Join only builds its table during executor run. > Since we have quite some RAM on our machines, I dedicated as much as possible to workmem (initially I was allocating 1GB)but this looks quite counterproductive (I didn't think that memory was allocated every time, I thought it was "available"for the current query but not necessarily used). Is this an issue specific to that version of PostgreSQL? (I guessno) Or can this be hardware-related? Or OS-related (both systems on which I have done tests are running Ubuntu, I willtry on Debian)? It would be good to narrow down which plan node is causing this. Can you try disabling various planner enable_* GUCs before running EXPLAIN (SUMMARY ON) <your query> with \timing on and see if you can find which enable_* GUC causes the EXPLAIN to run more quickly? Just watch out for variations in the timing of "Planning Time:". You're still looking for a large portion of time not accounted for by planning time. I'd start with: SET enable_memoize=0; EXPLAIN (SUMMARY ON) <your query>; RESET enable_memoize; SET enable_hashjoin=0; EXPLAIN (SUMMARY ON) <your query>; RESET enable_hashjoin; The following will show others that you could try. select name,setting from pg_settings where name like 'enable%'; David [1] https://git.postgresql.org/gitweb/?p=postgresql.git;a=commit;h=1e731ed12aa
David Rowley <dgrowleyml@gmail.com> writes:
> I do wonder now if it was a bad idea to make Memoize build the hash
> table on plan startup rather than delaying that until we fetch the
> first tuple. I see Hash Join only builds its table during executor
> run.
Ouch! If it really does that, yes it's a bad idea.
regards, tom lane
David, > It would be good to narrow down which plan node is causing this. Can > you try disabling various planner enable_* GUCs before running EXPLAIN > (SUMMARY ON) <your query> with \timing on and see if you can find > which enable_* GUC causes the EXPLAIN to run more quickly? Just watch > out for variations in the timing of "Planning Time:". You're still > looking for a large portion of time not accounted for by planning > time. I put the original values for work_mem and temp_buffers back to 1GB (don't know if that made a difference in the results). Execution time is consistent at ~135ms Here are the results for planning time, disabling each planner method : enable_async_append 0.454ms *slowest enable_bitmapscan 0.221ms enable_gathermerge 0.176ms enable_hashagg 0.229ms enable_hashjoin 0.127ms enable_incremental_sort 0.143ms enable_indexonlyscan 0.147ms enable_indexscan 0.200ms enable_material 0.138ms enable_memoize 0.152ms enable_mergejoin 0.122ms*fastest enable_nestloop 0.136ms enable_parallel_append 0.147ms enable_parallel_hash 0.245ms enable_partition_pruning 0.162ms enable_seqscan 0.137ms enable_sort 0.143ms enable_tidscan 0.164ms Hope this helps. Thanks, JC
Hello, In case it might be useful, I made some more tests. On my dev computer (a notebook) I installed: PostgreSQL 15.5 (Ubuntu 15.5-1.pgdg23.10+1) on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 13.2.0-4ubuntu3) 13.2.0, 64-bit and PostgreSQL 16.1 (Ubuntu 16.1-1.pgdg23.10+1) on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 13.2.0-4ubuntu3) 13.2.0, 64-bit I adjusted work_mem to 1GB and disabled JIT, restored the same DB, did VACUUM ANALYZE and ran the query several times to lower I/O interference. Execution time is about the same on PG 14, 15 and 16, around ~120ms I noticed that planning time, whatever the version, is very variable between executions (ranging from 0.120ms to 0.400ms), probably due to other programs activity and <1ms measurements imprecision. So the results I gave you in my previous email are probably irrelevant. On our production server, which is running PG 14.10 on Debian 11, same work_mem, execution time is ~45ms but planning time is much more consistent at ~0.110ms Interestingly though, lowering work_mem to 32MB gives 22ms execution time but planning time rises consistently at ~0.7ms On my notebook with work_mem=32MB, execution time is also 22ms but planning time is lower at ~0.4ms (?!?) Let me know if I can do anything to provide you with more useful benchmark. The DB is still very small so it is easy to do tests. JC
On Fri, 26 Jan 2024 at 17:23, Jean-Christophe Boggio <postgresql@thefreecat.org> wrote: > Let me know if I can do anything to provide you with more useful > benchmark. The DB is still very small so it is easy to do tests. What I was looking to find out was if there was some enable_* GUC that you could turn off that would make the unaccounted time that you were complaining about go away. Because it seems when you reduce work_mem this unaccounted for time goes away, it makes me think that some executor node is allocating a load of memory during executor startup. I was hoping to find out which node is the offending one by the process of elimination. Are you still seeing this unaccounted for time with your notebook? i.e. the relatively high "Execution Time" reported by EXPLAIN ANALYZE and low total actual execution time on the plan's top-level node. I probably didn't need to mention the planning time as it seems unlikely that disabling an enable* GUC would result in increased planning time. However, it does not seem impossible that that *could* happen. David