Message-ID: <04adb164-6df3-51c2-edf9-909a1e977976@gmail.com>
Date: Wed, 28 Aug 2024 12:00:00 +0300
MIME-Version: 1.0
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101
 Thunderbird/102.4.2
Subject: Re: Streaming read-ready sequential scan code
Content-Language: en-US
To: Thomas Munro <thomas.munro@gmail.com>
Cc: Melanie Plageman <melanieplageman@gmail.com>,
 Andres Freund <andres@anarazel.de>, David Rowley <dgrowleyml@gmail.com>,
 Heikki Linnakangas <hlinnaka@iki.fi>,
 Pg Hackers <pgsql-hackers@postgresql.org>
References: <CA+hUKG+wWKJ=mEXj0Xg06zQop6foV6dsirFYf2o7wMzbn_OKeA@mail.gmail.com>
 <CAAKRu_b1BfikoH8GGGubDnY4-eXZE4PoVEkxwppMTmiW2_NrWQ@mail.gmail.com>
 <CA+hUKG+h8Whpv0YsJqjMVkjYX+80fTVc6oi-V+zxJvykLpLHYQ@mail.gmail.com>
 <CAAKRu_aU60EFTLnB86FY9NUT1KqjzjLC2u+DqBtBLWi_ZooFpQ@mail.gmail.com>
 <CA+hUKGJDdbmJGCm6CsnkuRKe24jGE1L22eBS3eAG=POXM7cxxA@mail.gmail.com>
 <20240407221229.upgvhyf2gzflcawi@awork3.anarazel.de>
 <63a63690-dd92-c809-0b47-af05459e95d1@gmail.com>
 <CA+hUKGLHNNMbGntNyNGpVq+bA=ann=zC7Y+9a_P99dGmgXS9VQ@mail.gmail.com>
 <CA+hUKG+D8n8_YhezY6VEKcy3PjZ-=G0oNfye3HWFBbdKDoz=Ww@mail.gmail.com>
 <CA+hUKGKpw8KBL_V4yhCMAbi6jf5rLyFz-K2MrwuDTHTcUytSVw@mail.gmail.com>
 <CAAKRu_b=foYLPVvxL0YHb5ZSGvasvK2EH1ia9Eg8knk_cVgAtQ@mail.gmail.com>
 <CA+hUKGLdvzXDMiLeyBd6u25AwNpPFdWTgER2-_JMU6QPNnxjrw@mail.gmail.com>
 <CA+hUKGKHpN7Gg7x_0ALz1e2ZguS1CjrPioDLB0CHjjv7zpiWeg@mail.gmail.com>
 <7e090ca5-1d3d-b4f3-9060-8ec88f444c6c@gmail.com>
 <CA+hUKG+5tfGCaurEmOyvL1E7-A96cxtsVx_+NS+jdgnZkCvXjQ@mail.gmail.com>
From: Alexander Lakhin <exclusion@gmail.com>
In-Reply-To: <CA+hUKG+5tfGCaurEmOyvL1E7-A96cxtsVx_+NS+jdgnZkCvXjQ@mail.gmail.com>
Content-Type: text/plain; charset=UTF-8; format=flowed
Content-Transfer-Encoding: 8bit
Archived-At: <https://www.postgresql.org/message-id/04adb164-6df3-51c2-edf9-909a1e977976%40gmail.com>
Precedence: bulk

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