28.08.2024 07:45, Thomas Munro wrote:
Huh. I can reproduce what I showed with pretty low variance, on my
FreeBSD, Linux and macOS systems. I included
parallel_leader_participation=off so that the workers would hopefully
start as closely together in time as possible, and hopefully allow
only a block or so of variation in the outcome. If I do:
create or replace function f(i int) returns int language plpgsql
parallel safe as $$
begin
raise notice '% pid %', clock_timestamp(), pg_backend_pid();
return i;
end;
$$;
then
postgres=# explain (analyze) select f(i) from t limit 1;
NOTICE: 2024-08-28 16:41:32.845747+12 pid 47019
NOTICE: 2024-08-28 16:41:32.845746+12 pid 47018
shows start times differ by only a few microseconds at most, often 0.
I wonder if your system is more variable at beginning execution?
Maybe you're on a multi-socket system and forking/startup times vary
in some way I can't see on small systems or something like that?
I use a single-socket system with AMD Ryzen 5900X, running Ubuntu 20.04.
With no active background tasks running, I'm seeing:
NOTICE: 2024-08-28 08:17:36.917162+00 pid 320103
NOTICE: 2024-08-28 08:17:36.917163+00 pid 320102
NOTICE: 2024-08-28 08:17:40.592333+00 pid 320143
NOTICE: 2024-08-28 08:17:40.592645+00 pid 320144
With log_min_messages = DEBUG3, I get:
NOTICE: 2024-08-28 08:41:59.309364+00 pid 338263
NOTICE: 2024-08-28 08:41:59.310079+00 pid 338264
And the following messages in the server.log:
2024-08-28 08:41:59.304 UTC [338251] DEBUG: starting background worker process
"parallel worker for PID 338262"
2024-08-28 08:41:59.304 UTC [338251] DEBUG: starting background worker process
"parallel worker for PID 338262"
2024-08-28 08:41:59.305 UTC [338263] DEBUG: InitPostgres
2024-08-28 08:41:59.305 UTC [338264] DEBUG: InitPostgres
2024-08-28 08:41:59.309 UTC [338263] NOTICE: 2024-08-28 08:41:59.309364+00 pid
338263
2024-08-28 08:41:59.309 UTC [338263] CONTEXT: PL/pgSQL function f(integer)
line 3 at RAISE
2024-08-28 08:41:59.309 UTC [338262] NOTICE: 2024-08-28 08:41:59.309364+00 pid
338263
2024-08-28 08:41:59.309 UTC [338262] CONTEXT: PL/pgSQL function f(integer)
line 3 at RAISE
parallel worker
2024-08-28 08:41:59.309 UTC [338263] DEBUG: shmem_exit(0): 5 before_shmem_exit
callbacks to make
2024-08-28 08:41:59.309 UTC [338263] DEBUG: shmem_exit(0): 6 on_shmem_exit
callbacks to make
2024-08-28 08:41:59.309 UTC [338263] DEBUG: proc_exit(0): 1 callbacks to make
2024-08-28 08:41:59.309 UTC [338263] DEBUG: exit(0)
2024-08-28 08:41:59.309 UTC [338263] DEBUG: shmem_exit(-1): 0
before_shmem_exit callbacks to make
2024-08-28 08:41:59.309 UTC [338263] DEBUG: shmem_exit(-1): 0 on_shmem_exit
callbacks to make
2024-08-28 08:41:59.309 UTC [338263] DEBUG: proc_exit(-1): 0 callbacks to make
2024-08-28 08:41:59.310 UTC [338264] NOTICE: 2024-08-28 08:41:59.310079+00 pid
338264
2024-08-28 08:41:59.310 UTC [338264] CONTEXT: PL/pgSQL function f(integer)
line 3 at RAISE
It looks like the two parallel workers were started simultaneously, but
then the second one lagged behind...
Best regards,
Alexander
