Content-Type: multipart/alternative;
 boundary="------------7XpVslWD6FQ1s5vuuMg09bsv"
Message-ID: <41b8c2d3-b86c-45f5-a198-4889c22665e0@gmail.com>
Date: Sun, 26 Apr 2026 18:00:00 +0300
MIME-Version: 1.0
User-Agent: Mozilla Thunderbird
Subject: Re: Yet another way for pg_ctl stop to fail on Windows
To: Noah Misch <noah@leadboat.com>
Cc: pgsql-hackers <pgsql-hackers@postgresql.org>
References: <ba498e06-d22a-5bfb-389b-031f8db62d7d@gmail.com>
 <20240907181143.11.nmisch@google.com>
 <da4f9ec1-a272-bd2d-4ca1-6eb58d6dc79a@gmail.com>
 <20240908165355.93.nmisch@google.com>
Content-Language: en-US
From: Alexander Lakhin <exclusion@gmail.com>
In-Reply-To: <20240908165355.93.nmisch@google.com>
Archived-At: 
 <https://www.postgresql.org/message-id/41b8c2d3-b86c-45f5-a198-4889c22665e0%40gmail.com>
Precedence: bulk

This is a multi-part message in MIME format.
--------------7XpVslWD6FQ1s5vuuMg09bsv
Content-Type: text/plain; charset=UTF-8; format=flowed
Content-Transfer-Encoding: 8bit

Hello Noah,

08.09.2024 19:53, Noah Misch wrote:
> I see Microsoft suggests WaitNamedPipeA() as opposed to just polling.
> WaitNamedPipeA() should be more responsive.  Given how rare this has been, it
> likely doesn't matter whether we use WaitNamedPipeA() or polling.  I'd lean
> toward whichever makes the code simpler, probably polling.
>
>> So if we aim to not only fix "pg_ctl stop", but to make pgkill() robust,
>> it's the way to go, IMHO. I'm not sure about an infinite loop they show,
>> I'd vote for a loop with the same characteristics as in
>> pgwin32_open_handle().
> I agree with bounding the total time of each kill(), like
> pgwin32_open_handle() does for open().

While investigating a recent buildfarm failure [1] (which also happened
before: [2]):
# # --- C:/prog/bf/root/HEAD/pgsql/src/test/regress/expected/misc_functions.out 2026-04-08 01:57:31.191354200 +0000
# # +++ C:/prog/bf/root/HEAD/pgsql.build/testrun/pg_upgrade/002_pg_upgrade/data/results/misc_functions.out 2026-04-24 
02:45:42.446717500 +0000
# # @@ -316,9 +316,10 @@
# #  -- permissions are set properly.
# #  --
# #  SELECT pg_log_backend_memory_contexts(pg_backend_pid());
# # +WARNING:  could not send signal to process 3940: Invalid argument
# #   pg_log_backend_memory_contexts
# #  --------------------------------
# # - t
# # + f
# #  (1 row)
# #
# #  SELECT pg_log_backend_memory_contexts(pid) FROM pg_stat_activity
# # @@ -347,9 +348,10 @@
# #
# #  SET ROLE regress_log_memory;
# #  SELECT pg_log_backend_memory_contexts(pg_backend_pid());
# # +WARNING:  could not send signal to process 3940: Invalid argument
# #   pg_log_backend_memory_contexts
# #  --------------------------------
# # - t
# # + f
# #  (1 row)
# #
# #  RESET ROLE;
# # 1 of 248 tests failed.
# # The differences that caused some tests to fail can be viewed in the file 
"C:/prog/bf/root/HEAD/pgsql.build/testrun/pg_upgrade/002_pg_upgrade/data/regression.diffs".
# # A copy of the test summary that you see above is saved in the file 
"C:/prog/bf/root/HEAD/pgsql.build/testrun/pg_upgrade/002_pg_upgrade/data/regression.out".
# ------------------------------------
# Looks like you failed 1 test of 20.

I've managed to reproduced it locally, by running five
pg_upgrade/002_pg_upgrade tests (with
"SELECT pg_log_backend_memory_contexts(pg_backend_pid());" x100 in
misc_functions.sql) concurrently on one-core VM:
iteration 3
1/5 postgresql:pg_upgrade_5 / pg_upgrade_5/002_pg_upgrade OK              184.42s   5 subtests passed
2/5 postgresql:pg_upgrade_1 / pg_upgrade_1/002_pg_upgrade ERROR           184.79s   exit status 1

pg_upgrade_1\002_pg_upgrade\log\002_pg_upgrade_old_node.log:
2026-04-26 13:13:44.238 UTC client backend[688] pg_regress/misc_functions WARNING:  could not send signal to process 
688: Invalid argument

With the logging added inside pgkill():
@@ -89,6 +93,9 @@ pgkill(int pid, int sig)
                         errno = EPERM;
                         return -1;
                 default:
+#ifndef FRONTEND
+elog(LOG, "!!!pgkill| CallNamedPipe() returned %d", GetLastError());
+#endif
                         errno = EINVAL;         /* unexpected */
                         return -1;
         }

and backtrace_functions = 'pgkill', I could see
2026-04-26 13:13:44.237 UTC client backend[688] pg_regress/misc_functions LOG:  !!!pgkill| CallNamedPipe() returned 231
2026-04-26 13:13:44.237 UTC client backend[688] pg_regress/misc_functions BACKTRACE:
     pgkill+0x15f [0x7ff6c05279ef] [C:\src\postgresql\src\port\kill.c:103]
     SendProcSignal+0xb1 [0x7ff6c03202e1] [C:\src\postgresql\src\backend\storage\ipc\procsignal.c:341]
     pg_log_backend_memory_contexts+0x7b [0x7ff6c040df1b] [C:\src\postgresql\src\backend\utils\adt\mcxtfuncs.c:301]
     ExecInterpExpr+0x684 [0x7ff6c00ec264] [C:\src\postgresql\src\backend\executor\execExprInterp.c:630]
...

That is, pg_log_backend_memory_contexts(() fails due to the same
ERROR_PIPE_BUSY.

Moreover, I can see other instances of this error in the log, which go
unnoticed:
2026-04-26 13:12:19.049 UTC client backend[2948] pg_regress/subselect LOG:  !!!pgkill| CallNamedPipe() returned 231
2026-04-26 13:12:19.049 UTC client backend[2948] pg_regress/subselect BACKTRACE:
     pgkill+0x15f [0x7ff6c05279ef] [C:\src\postgresql\src\port\kill.c:103]
     SendProcSignal+0xb1 [0x7ff6c03202e1] [C:\src\postgresql\src\backend\storage\ipc\procsignal.c:341]
     SICleanupQueue+0x1e1 [0x7ff6c03252b1] [C:\src\postgresql\src\backend\storage\ipc\sinvaladt.c:677]
     SIInsertDataEntries+0x91 [0x7ff6c0325511] [C:\src\postgresql\src\backend\storage\ipc\sinvaladt.c:411]
     AtEOXact_Inval+0x86 [0x7ff6c04b0636] [C:\src\postgresql\src\backend\utils\cache\inval.c:1225]
     CommitTransaction+0x2b4 [0x7ff6bffa5604] [C:\src\postgresql\src\backend\access\transam\xact.c:2477]
     CommitTransactionCommandInternal+0x8e [0x7ff6bffa588e] [C:\src\postgresql\src\backend\access\transam\xact.c:3253]
     CommitTransactionCommand+0x9 [0x7ff6bffa57e9] [C:\src\postgresql\src\backend\access\transam\xact.c:3213]
     RemoveTempRelationsCallback+0x6a [0x7ff6bfff51fa] [C:\src\postgresql\src\backend\catalog\namespace.c:4710]
     proc_exit_prepare+0xc6 [0x7ff6c03178d6] [C:\src\postgresql\src\backend\storage\ipc\ipc.c:199]
     proc_exit+0x56 [0x7ff6c03177c6] [C:\src\postgresql\src\backend\storage\ipc\ipc.c:155]
     PostgresMain+0xd9a [0x7ff6c034e2ea] [C:\src\postgresql\src\backend\tcop\postgres.c:5091]
     BackendMain+0xd5 [0x7ff6c034acb5] [C:\src\postgresql\src\backend\tcop\backend_startup.c:124]
...
2026-04-26 13:12:45.010 UTC client backend[8104] pg_regress/replica_identity LOG:  !!!pgkill| CallNamedPipe() returned 231
2026-04-26 13:12:45.010 UTC client backend[8104] pg_regress/replica_identity BACKTRACE:
     pgkill+0x15f [0x7ff6c05279ef] [C:\src\postgresql\src\port\kill.c:103]
     SendProcSignal+0xb1 [0x7ff6c03202e1] [C:\src\postgresql\src\backend\storage\ipc\procsignal.c:341]
     SICleanupQueue+0x1e1 [0x7ff6c03252b1] [C:\src\postgresql\src\backend\storage\ipc\sinvaladt.c:677]
     SIInsertDataEntries+0x91 [0x7ff6c0325511] [C:\src\postgresql\src\backend\storage\ipc\sinvaladt.c:411]
     AtInplace_Inval+0x67 [0x7ff6c04b0727] [C:\src\postgresql\src\backend\utils\cache\inval.c:1270]
     heap_inplace_update_and_unlock+0x266 [0x7ff6bff2a366] [C:\src\postgresql\src\backend\access\heap\heapam.c:6591]
     systable_inplace_update_finish+0x20 [0x7ff6bff4c160] [C:\src\postgresql\src\backend\access\index\genam.c:904]
     index_update_stats+0x21e [0x7ff6bffefefe] [C:\src\postgresql\src\backend\catalog\index.c:2982]
     index_build+0x2fc [0x7ff6bffed2fc] [C:\src\postgresql\src\backend\catalog\index.c:3180]
     index_create+0xc05 [0x7ff6bffef035] [C:\src\postgresql\src\backend\catalog\index.c:1291]
     DefineIndex+0x12fc [0x7ff6c006544c] [C:\src\postgresql\src\backend\commands\indexcmds.c:1265]
     ProcessUtilitySlow+0x924 [0x7ff6c0358524] [C:\src\postgresql\src\backend\tcop\utility.c:1566]
     standard_ProcessUtility+0x9f0 [0x7ff6c0359ec0] [C:\src\postgresql\src\backend\tcop\utility.c:1078]
     ProcessUtility+0x70 [0x7ff6c0357aa0] [C:\src\postgresql\src\backend\tcop\utility.c:531]
     ProcessUtilitySlow+0x3a0 [0x7ff6c0357fa0] [C:\src\postgresql\src\backend\tcop\utility.c:1262]
     standard_ProcessUtility+0x9f0 [0x7ff6c0359ec0] [C:\src\postgresql\src\backend\tcop\utility.c:1078]
     ProcessUtility+0x70 [0x7ff6c0357aa0] [C:\src\postgresql\src\backend\tcop\utility.c:531]


[1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=drongo&dt=2026-04-24%2001%3A26%3A26
[2] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=drongo&dt=2025-09-26%2018%3A15%3A06

Best regards,
Alexander
--------------7XpVslWD6FQ1s5vuuMg09bsv
Content-Type: text/html; charset=UTF-8
Content-Transfer-Encoding: 8bit

<!DOCTYPE html>
<html>
  <head>
    <meta http-equiv="Content-Type" content="text/html; charset=UTF-8">
  </head>
  <body>
    <div class="moz-cite-prefix">Hello Noah,<br>
      <br>
      08.09.2024 19:53, Noah Misch wrote:<br>
    </div>
    <blockquote type="cite"
      cite="mid:20240908165355.93.nmisch@google.com">
      <pre wrap="" class="moz-quote-pre">I see Microsoft suggests WaitNamedPipeA() as opposed to just polling.
WaitNamedPipeA() should be more responsive.  Given how rare this has been, it
likely doesn't matter whether we use WaitNamedPipeA() or polling.  I'd lean
toward whichever makes the code simpler, probably polling.

</pre>
      <blockquote type="cite">
        <pre wrap="" class="moz-quote-pre">So if we aim to not only fix "pg_ctl stop", but to make pgkill() robust,
it's the way to go, IMHO. I'm not sure about an infinite loop they show,
I'd vote for a loop with the same characteristics as in
pgwin32_open_handle().
</pre>
      </blockquote>
      <pre wrap="" class="moz-quote-pre">
I agree with bounding the total time of each kill(), like
pgwin32_open_handle() does for open().
</pre>
    </blockquote>
    <br>
    While investigating a recent buildfarm failure [1] (which also
    happened<br>
    before: [2]):<br>
    # # ---
C:/prog/bf/root/HEAD/pgsql/src/test/regress/expected/misc_functions.out   
    2026-04-08 01:57:31.191354200 +0000<br>
    # # +++
C:/prog/bf/root/HEAD/pgsql.build/testrun/pg_upgrade/002_pg_upgrade/data/results/misc_functions.out   
    2026-04-24 02:45:42.446717500 +0000<br>
    # # @@ -316,9 +316,10 @@<br>
    # #  -- permissions are set properly.<br>
    # #  --<br>
    # #  SELECT pg_log_backend_memory_contexts(pg_backend_pid());<br>
    # # +WARNING:  could not send signal to process 3940: Invalid
    argument<br>
    # #   pg_log_backend_memory_contexts <br>
    # #  --------------------------------<br>
    # # - t<br>
    # # + f<br>
    # #  (1 row)<br>
    # #  <br>
    # #  SELECT pg_log_backend_memory_contexts(pid) FROM
    pg_stat_activity<br>
    # # @@ -347,9 +348,10 @@<br>
    # #  <br>
    # #  SET ROLE regress_log_memory;<br>
    # #  SELECT pg_log_backend_memory_contexts(pg_backend_pid());<br>
    # # +WARNING:  could not send signal to process 3940: Invalid
    argument<br>
    # #   pg_log_backend_memory_contexts <br>
    # #  --------------------------------<br>
    # # - t<br>
    # # + f<br>
    # #  (1 row)<br>
    # #  <br>
    # #  RESET ROLE;<br>
    # # 1 of 248 tests failed.<br>
    # # The differences that caused some tests to fail can be viewed in
    the file
"C:/prog/bf/root/HEAD/pgsql.build/testrun/pg_upgrade/002_pg_upgrade/data/regression.diffs".<br>
    # # A copy of the test summary that you see above is saved in the
    file
"C:/prog/bf/root/HEAD/pgsql.build/testrun/pg_upgrade/002_pg_upgrade/data/regression.out".<br>
    # ------------------------------------<br>
    # Looks like you failed 1 test of 20.<br>
    <br>
    I've managed to reproduced it locally, by running five<br>
    pg_upgrade/002_pg_upgrade tests (with<br>
    "SELECT pg_log_backend_memory_contexts(pg_backend_pid());" x100 in<br>
    misc_functions.sql) concurrently on one-core VM:<br>
    iteration 3<br>
    1/5 postgresql:pg_upgrade_5 / pg_upgrade_5/002_pg_upgrade       
    OK              184.42s   5 subtests passed<br>
    2/5 postgresql:pg_upgrade_1 / pg_upgrade_1/002_pg_upgrade       
    ERROR           184.79s   exit status 1<br>
    <br>
    pg_upgrade_1\002_pg_upgrade\log\002_pg_upgrade_old_node.log:<br>
    2026-04-26 13:13:44.238 UTC client backend[688]
    pg_regress/misc_functions WARNING:  could not send signal to process
    688: Invalid argument<br>
    <br>
    With the logging added inside pgkill():<br>
    @@ -89,6 +93,9 @@ pgkill(int pid, int sig)<br>
                            errno = EPERM;<br>
                            return -1;<br>
                    default:<br>
    +#ifndef FRONTEND<br>
    +elog(LOG, "!!!pgkill| CallNamedPipe() returned %d",
    GetLastError());<br>
    +#endif<br>
                            errno = EINVAL;         /* unexpected */<br>
                            return -1;<br>
            }<br>
    <br>
    and backtrace_functions = 'pgkill', I could see<br>
    2026-04-26 13:13:44.237 UTC client backend[688]
    pg_regress/misc_functions LOG:  !!!pgkill| CallNamedPipe() returned
    231<br>
    2026-04-26 13:13:44.237 UTC client backend[688]
    pg_regress/misc_functions BACKTRACE:  <br>
        pgkill+0x15f [0x7ff6c05279ef]
    [C:\src\postgresql\src\port\kill.c:103]<br>
        SendProcSignal+0xb1 [0x7ff6c03202e1]
    [C:\src\postgresql\src\backend\storage\ipc\procsignal.c:341]<br>
        pg_log_backend_memory_contexts+0x7b [0x7ff6c040df1b]
    [C:\src\postgresql\src\backend\utils\adt\mcxtfuncs.c:301]<br>
        ExecInterpExpr+0x684 [0x7ff6c00ec264]
    [C:\src\postgresql\src\backend\executor\execExprInterp.c:630]<br>
    ...<br>
    <br>
    That is, pg_log_backend_memory_contexts(() fails due to the same<br>
    ERROR_PIPE_BUSY.<br>
    <br>
    Moreover, I can see other instances of this error in the log, which
    go<br>
    unnoticed:<br>
    2026-04-26 13:12:19.049 UTC client backend[2948]
    pg_regress/subselect LOG:  !!!pgkill| CallNamedPipe() returned 231<br>
    2026-04-26 13:12:19.049 UTC client backend[2948]
    pg_regress/subselect BACKTRACE:  <br>
        pgkill+0x15f [0x7ff6c05279ef]
    [C:\src\postgresql\src\port\kill.c:103]<br>
        SendProcSignal+0xb1 [0x7ff6c03202e1]
    [C:\src\postgresql\src\backend\storage\ipc\procsignal.c:341]<br>
        SICleanupQueue+0x1e1 [0x7ff6c03252b1]
    [C:\src\postgresql\src\backend\storage\ipc\sinvaladt.c:677]<br>
        SIInsertDataEntries+0x91 [0x7ff6c0325511]
    [C:\src\postgresql\src\backend\storage\ipc\sinvaladt.c:411]<br>
        AtEOXact_Inval+0x86 [0x7ff6c04b0636]
    [C:\src\postgresql\src\backend\utils\cache\inval.c:1225]<br>
        CommitTransaction+0x2b4 [0x7ff6bffa5604]
    [C:\src\postgresql\src\backend\access\transam\xact.c:2477]<br>
        CommitTransactionCommandInternal+0x8e [0x7ff6bffa588e]
    [C:\src\postgresql\src\backend\access\transam\xact.c:3253]<br>
        CommitTransactionCommand+0x9 [0x7ff6bffa57e9]
    [C:\src\postgresql\src\backend\access\transam\xact.c:3213]<br>
        RemoveTempRelationsCallback+0x6a [0x7ff6bfff51fa]
    [C:\src\postgresql\src\backend\catalog\namespace.c:4710]<br>
        proc_exit_prepare+0xc6 [0x7ff6c03178d6]
    [C:\src\postgresql\src\backend\storage\ipc\ipc.c:199]<br>
        proc_exit+0x56 [0x7ff6c03177c6]
    [C:\src\postgresql\src\backend\storage\ipc\ipc.c:155]<br>
        PostgresMain+0xd9a [0x7ff6c034e2ea]
    [C:\src\postgresql\src\backend\tcop\postgres.c:5091]<br>
        BackendMain+0xd5 [0x7ff6c034acb5]
    [C:\src\postgresql\src\backend\tcop\backend_startup.c:124]<br>
    ...<br>
    2026-04-26 13:12:45.010 UTC client backend[8104]
    pg_regress/replica_identity LOG:  !!!pgkill| CallNamedPipe()
    returned 231<br>
    2026-04-26 13:12:45.010 UTC client backend[8104]
    pg_regress/replica_identity BACKTRACE:  <br>
        pgkill+0x15f [0x7ff6c05279ef]
    [C:\src\postgresql\src\port\kill.c:103]<br>
        SendProcSignal+0xb1 [0x7ff6c03202e1]
    [C:\src\postgresql\src\backend\storage\ipc\procsignal.c:341]<br>
        SICleanupQueue+0x1e1 [0x7ff6c03252b1]
    [C:\src\postgresql\src\backend\storage\ipc\sinvaladt.c:677]<br>
        SIInsertDataEntries+0x91 [0x7ff6c0325511]
    [C:\src\postgresql\src\backend\storage\ipc\sinvaladt.c:411]<br>
        AtInplace_Inval+0x67 [0x7ff6c04b0727]
    [C:\src\postgresql\src\backend\utils\cache\inval.c:1270]<br>
        heap_inplace_update_and_unlock+0x266 [0x7ff6bff2a366]
    [C:\src\postgresql\src\backend\access\heap\heapam.c:6591]<br>
        systable_inplace_update_finish+0x20 [0x7ff6bff4c160]
    [C:\src\postgresql\src\backend\access\index\genam.c:904]<br>
        index_update_stats+0x21e [0x7ff6bffefefe]
    [C:\src\postgresql\src\backend\catalog\index.c:2982]<br>
        index_build+0x2fc [0x7ff6bffed2fc]
    [C:\src\postgresql\src\backend\catalog\index.c:3180]<br>
        index_create+0xc05 [0x7ff6bffef035]
    [C:\src\postgresql\src\backend\catalog\index.c:1291]<br>
        DefineIndex+0x12fc [0x7ff6c006544c]
    [C:\src\postgresql\src\backend\commands\indexcmds.c:1265]<br>
        ProcessUtilitySlow+0x924 [0x7ff6c0358524]
    [C:\src\postgresql\src\backend\tcop\utility.c:1566]<br>
        standard_ProcessUtility+0x9f0 [0x7ff6c0359ec0]
    [C:\src\postgresql\src\backend\tcop\utility.c:1078]<br>
        ProcessUtility+0x70 [0x7ff6c0357aa0]
    [C:\src\postgresql\src\backend\tcop\utility.c:531]<br>
        ProcessUtilitySlow+0x3a0 [0x7ff6c0357fa0]
    [C:\src\postgresql\src\backend\tcop\utility.c:1262]<br>
        standard_ProcessUtility+0x9f0 [0x7ff6c0359ec0]
    [C:\src\postgresql\src\backend\tcop\utility.c:1078]<br>
        ProcessUtility+0x70 [0x7ff6c0357aa0]
    [C:\src\postgresql\src\backend\tcop\utility.c:531]<br>
    <br>
    <br>
    [1]
<a class="moz-txt-link-freetext" href="https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=drongo&amp;dt=2026-04-24%2001%3A26%3A26">https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=drongo&amp;dt=2026-04-24%2001%3A26%3A26</a><br>
    [2]
<a class="moz-txt-link-freetext" href="https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=drongo&amp;dt=2025-09-26%2018%3A15%3A06">https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=drongo&amp;dt=2025-09-26%2018%3A15%3A06</a><br>
    <br>
    Best regards,<br>
    Alexander<br>
  </body>
</html>

--------------7XpVslWD6FQ1s5vuuMg09bsv--