psql 15beta1 does not print notices on the console until transaction completes

[ redirecting to -bugs ]

Alastair McKinley <a.mckinley@analyticsengines.com> writes:

Using this test function:

create or replace function test_notice() returns void as
$$
begin
raise notice 'hello';
perform pg_sleep(10);
end; $$ language plpgsql;

In psql 15beta1, the "hello" message only appears on the console when the transaction completes.
in psql 14.3, it appears immediately as I would have expected.

A quick cross-check confirms that this is a psql, not server,
behavior change. I didn't bisect, but I'm betting this is a
side-effect of 7844c9918 (Show all query results by default).

I agree it's pretty undesirable, so I'm adding it as an open issue.

regards, tom lane

On 5/29/22 13:11, Alastair McKinley wrote:

Hi all,

I notice this change in behaviour with psql in 15beta1 when testing an existing codebase.

I didn't see any mention of this change in the release notes and it surprised me.

Using this test function:

    create or replace function test_notice() returns void as
    $$
    begin
        raise notice 'hello';
        perform pg_sleep(10);
    end; $$ language plpgsql;

In psql 15beta1, the "hello" message only appears on the console when the transaction completes.

I am not seeing that.

Can you provide more information about how you are running test_notice()?

in psql 14.3, it appears immediately as I would have expected.

Is there a way to change psql behaviour to display notices immediately as in versions < 15?

Best regards,

Alastair

--
Adrian Klaver
adrian.klaver@aklaver.com

From: Adrian Klaver <adrian.klaver@aklaver.com>
Sent: 29 May 2022 21:47To: Alastair McKinley <a.mckinley@analyticsengines.com>; pgsql-general@lists.postgresql.org <pgsql-general@lists.postgresql.org>Subject: Re: psql 15beta1 does not print notices on the console until transaction completes

On 5/29/22 13:11, Alastair McKinley wrote:

Hi all,

I notice this change in behaviour with psql in 15beta1 when testing an existing codebase.

I didn't see any mention of this change in the release notes and it surprised me.

Using this test function:

create or replace function test_notice() returns void as
$$
begin
raise notice 'hello';
perform pg_sleep(10);
end; $$ language plpgsql;

In psql 15beta1, the "hello" message only appears on the console when the transaction completes.

I am not seeing that.

Can you provide more information about how you are running test_notice()?

Hi Adrian,

I am running the function "select test_notice();" from the psql console with psql/server versions 15beta1.

In psql 15beta1, the notice appears only after the function returns/transaction completes.

If I execute the same function from psql 14.3 and server 15beta1, the notice appears on the psql console immediately as expected, before the pg_sleep() completes.

It's reproducible for me, I just double checked it.

I think Tom was able to reproduce this by the sounds of his response?

Best regards,

Alastair

On 5/29/22 13:47, Adrian Klaver wrote:

On 5/29/22 13:11, Alastair McKinley wrote:

Hi all,

In psql 15beta1, the "hello" message only appears on the console when
the transaction completes.

I am not seeing that.

I take that back, I was using psql 14.3 to connect to the 15 instance.
When I changed to psql 15 I saw the same thing.

Best regards,

Alastair

--
Adrian Klaver
adrian.klaver@aklaver.com

On 5/29/22 13:59, Alastair McKinley wrote:

From: Adrian Klaver <adrian.klaver@aklaver.com>
Sent: 29 May 2022 21:47To: Alastair McKinley

Hi Adrian,

I am running the function "select test_notice();" from the psql console
with psql/server versions 15beta1.

In psql 15beta1, the notice appears only after the function
returns/transaction completes.

If I execute the same function from psql 14.3 and server 15beta1, the
notice appears on the psql console immediately as expected, before the
pg_sleep() completes.

It's reproducible for me, I just double checked it.

Yeah, I see the same thing after using the new psql.

I think Tom was able to reproduce this by the sounds of his response?

I have not received that post yet. I do see it in the archives. I had
already tried:

\set SHOW_ALL_RESULTS off

which is supposed to restore to previous behavior, but it did not lead
to the 14.3 result.

Best regards,

Alastair

--
Adrian Klaver
adrian.klaver@aklaver.com

Adrian Klaver <adrian.klaver@aklaver.com> writes:

On 5/29/22 13:59, Alastair McKinley wrote:

I think Tom was able to reproduce this by the sounds of his response?

I have not received that post yet. I do see it in the archives.

I re-addressed it to pgsql-bugs, maybe you are not subscribed to that?

regards, tom lane

On 5/29/22 15:03, Tom Lane wrote:

Adrian Klaver <adrian.klaver@aklaver.com> writes:

On 5/29/22 13:59, Alastair McKinley wrote:

I think Tom was able to reproduce this by the sounds of his response?

I have not received that post yet. I do see it in the archives.

I re-addressed it to pgsql-bugs, maybe you are not subscribed to that?

I am not, still I see it here:

https://www.postgresql.org/list/pgsql-general/since/202205290000/

And when I click on the message:

/messages/by-id/3662994.1653856025@sss.pgh.pa.us

Lists: pgsql-bugs pgsql-general

I will admit that the mailing list software is a mystery to me, so it is
entirely possible I am misreading the above.

regards, tom lane

--
Adrian Klaver
adrian.klaver@aklaver.com

On 5/29/22 18:00, Adrian Klaver wrote:

On 5/29/22 15:03, Tom Lane wrote:

Adrian Klaver <adrian.klaver@aklaver.com> writes:

On 5/29/22 13:59, Alastair McKinley wrote:

I think Tom was able to reproduce this by the sounds of his response?

I have not received that post yet. I do see it in the archives.

I re-addressed it to pgsql-bugs, maybe you are not subscribed to that?

I am not, still I see it here:

https://www.postgresql.org/list/pgsql-general/since/202205290000/

And when I click on the message:

/messages/by-id/3662994.1653856025@sss.pgh.pa.us

Lists:     pgsql-bugs pgsql-general

I will admit that the mailing list software is a mystery to me, so it
is entirely possible I am misreading the above.

FWIW, I didn't see Tom's first (bugs) post either.  Nor am I subscribed
to bugs

Alastair McKinley <a.mckinley@analyticsengines.com> writes:

Using this test function:

create or replace function test_notice() returns void as
$$
begin
raise notice 'hello';
perform pg_sleep(10);
end; $$ language plpgsql;

In psql 15beta1, the "hello" message only appears on the console when the transaction completes.
in psql 14.3, it appears immediately as I would have expected.

A quick cross-check confirms that this is a psql, not server,
behavior change. I didn't bisect, but I'm betting this is a
side-effect of 7844c9918 (Show all query results by default).

Yep, that is indeed possible, there is some hocus-pocus around notices
there because they arrive somehow in any order.

I agree it's pretty undesirable, so I'm adding it as an open issue.

Ok.

--
Fabien.

Hello Tom,

create or replace function test_notice() returns void as
$$
begin
raise notice 'hello';
perform pg_sleep(10);
end; $$ language plpgsql;

In psql 15beta1, the "hello" message only appears on the console when the
transaction completes.
in psql 14.3, it appears immediately as I would have expected.

A quick cross-check confirms that this is a psql, not server,
behavior change. I didn't bisect, but I'm betting this is a
side-effect of 7844c9918 (Show all query results by default).

Yep, that is indeed possible, there is some hocus-pocus around notices there
because they arrive somehow in any order.

I agree it's pretty undesirable, so I'm adding it as an open issue.

Ok.

I've looked into it. This behavior is triggered by the fact that "psql" is
trying to keep notices and results in some logical order.

The issue did not arise before because intermediate results where coldly
discarded, so it did not show whether they were discarded before of after
some notice was already shown:-)

If notices are to be shown "right away", it means that some notice may be
shown *before* the previous result has been shown, just because psql may
not have had time to process it and they are just sent through the
protocol and arriving for the next result, as shown with the attached
patch on non-regression tests:

   SELECT 1 AS one \; SELECT warn('1.5') \; SELECT 2 AS two ;
  +NOTICE:  warn 1.5
  +CONTEXT:  PL/pgSQL function warn(text) line 2 at RAISE
    one
   -----
      1
   (1 row)

-NOTICE: warn 1.5
-CONTEXT: PL/pgSQL function warn(text) line 2 at RAISE
warn
------
t

Now the second statement warning is shown before the first statement
output. I'm pretty sure that the initial order shoul show up from time to
time, just because of the underlying race condition.

Would this be okay? It simplifies the code significantly, but introduces
possible race conditions in the output, which could be hidden from the non
regression tests by removing the tests…

If notices are to be shown "right away" when processing a result, but not
quite "right away" when the previous result is not yet finished, this is
probably achievable but would require some effort and not so clear code.
Maybe psql could not get the next result when we do not need to know which
is last, but the execution would have somehow 2 different paths. I have to
try to see how terrible or not the resulting code would be.

Another approach could be do drop the "only show the last result"
compatibility, because then "psql" would not need to know that a result is
the last, which requires to trigger the next one before closing the
previous one, hence opening the race condition.

Thoughts?

--
Fabien.

create or replace function test_notice() returns void as
$$
begin
raise notice 'hello';
perform pg_sleep(10);
end; $$ language plpgsql;

In psql 15beta1, the "hello" message only appears on the console when
the transaction completes. in psql 14.3, it appears immediately as I
would have expected.

[...]

I've looked into it. This behavior is triggered by the fact that "psql" is
trying to keep notices and results in some logical order.

The issue did not arise before because intermediate results where coldly
discarded, so it did not show whether they were discarded before of after
some notice was already shown:-)

If notices are to be shown "right away", it means that some notice may be
shown *before* the previous result has been shown, just because psql may not
have had time to process it and they are just sent through the protocol and
arriving for the next result, as shown with the attached patch on
non-regression tests:

SELECT 1 AS one \; SELECT warn('1.5') \; SELECT 2 AS two ;
+NOTICE:  warn 1.5
+CONTEXT:  PL/pgSQL function warn(text) line 2 at RAISE
one
-----
1
(1 row)

-NOTICE: warn 1.5
-CONTEXT: PL/pgSQL function warn(text) line 2 at RAISE
warn
------
t

Now the second statement warning is shown before the first statement output.
I'm pretty sure that the initial order shoul show up from time to time, just
because of the underlying race condition.

Would this be okay? It simplifies the code significantly, but introduces
possible race conditions in the output, which could be hidden from the non
regression tests by removing the tests…

This would be the simplest solution.

If notices are to be shown "right away" when processing a result, but not
quite "right away" when the previous result is not yet finished, this is
probably achievable but would require some effort and not so clear code.

Maybe psql could not get the next result when we do not need to know which is
last, but the execution would have somehow 2 different paths. I have to try
to see how terrible or not the resulting code would be.

I've tried that (see v2 attached), but it does not work as I hoped: the
fact that a result has not yet been extracted does not preclude the server
from sending the notices relating to a statement, so delaying the
getResult does not fix the display order problem in anyway. I was quite
naïve.

Another approach could be do drop the "only show the last result"
compatibility, because then "psql" would not need to know that a result is
the last, which requires to trigger the next one before closing the previous
one, hence opening the race condition.

That would not work, either, for the reason stated above.

In order to have the best of both world, this requires more hopus-pocus:
accumulating the notices *but* displaying them as soon as dealing with a
statement is done *and* also while waiting for getResult. I see how I can
try to reduce a lot the out-of-order window… but not how to fully get rid
of it.

--
Fabien.

I've looked into it. This behavior is triggered by the fact that "psql" is
trying to keep notices and results in some logical order.

The issue did not arise before because intermediate results where coldly
discarded, so it did not show whether they were discarded before of after
some notice was already shown:-)

If notices are to be shown "right away", it means that some notice may be
shown *before* the previous result has been shown, just because psql may
not have had time to process it and they are just sent through the protocol
and arriving for the next result, as shown with the attached patch on
non-regression tests:

SELECT 1 AS one \; SELECT warn('1.5') \; SELECT 2 AS two ;
+NOTICE:  warn 1.5
+CONTEXT:  PL/pgSQL function warn(text) line 2 at RAISE
one
-----
1
(1 row)

-NOTICE: warn 1.5
-CONTEXT: PL/pgSQL function warn(text) line 2 at RAISE
warn
------
t

Now the second statement warning is shown before the first statement
output. I'm pretty sure that the initial order shoul show up from time to
time, just because of the underlying race condition.

Would this be okay? It simplifies the code significantly, but introduces
possible race conditions in the output, which could be hidden from the non
regression tests by removing the tests…

This would be the simplest solution.

If notices are to be shown "right away" when processing a result, but not
quite "right away" when the previous result is not yet finished, this is
probably achievable but would require some effort and not so clear code.

Maybe psql could not get the next result when we do not need to know which
is last, but the execution would have somehow 2 different paths. I have to
try to see how terrible or not the resulting code would be.

I've tried that (see v2 attached), but it does not work as I hoped: the fact
that a result has not yet been extracted does not preclude the server from
sending the notices relating to a statement, so delaying the getResult does
not fix the display order problem in anyway. I was quite naïve.

Another approach could be do drop the "only show the last result"
compatibility, because then "psql" would not need to know that a result is
the last, which requires to trigger the next one before closing the
previous one, hence opening the race condition.

That would not work, either, for the reason stated above.

In order to have the best of both world, this requires more hopus-pocus:
accumulating the notices *but* displaying them as soon as dealing with a
statement is done *and* also while waiting for getResult. I see how I can try
to reduce a lot the out-of-order window… but not how to fully get rid of it.

After more investigation and quite a few variants, the end result is that
you cannot have the best of both words in all cases, i.e. instantaneous
notices while keeping the order of results and their notices. The
underlying reason for that is that some cases (gexec and others,) need to
know which result is last because they need to to something special about
it, which always requires to wait for the next result before doing
anything with the previous one, so if the next one takes time, then the
previous one is somehow suspended.

In the previous setting, because intermediate results where coldly
skipped, the user could not see whether notices for one statement where
coming before or after some result, so all was well hidden, you just got
the notices as they were sent and the final result displayed. The
underlying truth was that it depended:-)

My short term recommendation is to remove the attempt at keeping the
notice/result order for a tradeoff of getting the notices as soon as they
are emitted, i.e. basically patch 1 and the acceptance of the diffs,
called 1-bis in the attached. Alternatively, the attached patch 3 keeps
the order in the simple case, but not in the gset case, at the price of
some complexity. I would not bet too much that these codes are immune to
race conditions.

--
Fabien.

On 03.06.22 20:25, Fabien COELHO wrote:

My short term recommendation is to remove the attempt at keeping the
notice/result order for a tradeoff of getting the notices as soon as
they are emitted, i.e. basically patch 1 and the acceptance of the
diffs, called 1-bis in the attached.

I agree with this solution. Do you want to keep the tests, do you think
they are going to be stable? I suppose we could try and find out.

My short term recommendation is to remove the attempt at keeping the
notice/result order for a tradeoff of getting the notices as soon as they
are emitted, i.e. basically patch 1 and the acceptance of the diffs, called
1-bis in the attached.

I agree with this solution. Do you want to keep the tests, do you think they
are going to be stable? I suppose we could try and find out.

I think that we should try to keep them, and remove them only if they are
proven unstable, which may happen. The buildfarm will tell.

--
Fabien.

On 08.06.22 12:16, Fabien COELHO wrote:

My short term recommendation is to remove the attempt at keeping the
notice/result order for a tradeoff of getting the notices as soon as
they are emitted, i.e. basically patch 1 and the acceptance of the
diffs, called 1-bis in the attached.

I agree with this solution.  Do you want to keep the tests, do you
think they are going to be stable?  I suppose we could try and find out.

I think that we should try to keep them, and remove them only if they
are proven unstable, which may happen. The buildfarm will tell.

Ok, committed as you submitted.