Re: I don't understand that EXPLAIN PLAN timings
Hello David, Thanks for your answer. Le 23/01/2024 à 11:41, David Rowley a écrit : 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
Re: I don't understand that EXPLAIN PLAN timings
On Fri, 26 Jan 2024 at 02:31, Jean-Christophe Boggio wrote: > 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_ ? 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 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)? 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) 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) ; RESET enable_memoize; SET enable_hashjoin=0; EXPLAIN (SUMMARY ON) ; 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
Re: I don't understand that EXPLAIN PLAN timings
David Rowley 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
Re: I don't understand that EXPLAIN PLAN timings
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) 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
Re: I don't understand that EXPLAIN PLAN timings
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
Re: I don't understand that EXPLAIN PLAN timings
On Fri, 26 Jan 2024 at 17:23, Jean-Christophe Boggio 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
