From: Fabien COELHO <coelho@cri.ensmp.fr>
To: Tom Lane <tgl@sss.pgh.pa.us>
Cc: Alastair McKinley <a.mckinley@analyticsengines.com>
Cc: PostgreSQL Bugs <pgsql-bugs@lists.postgresql.org>
Cc: Peter Eisentraut <peter.eisentraut@enterprisedb.com>
Subject: Re: psql 15beta1 does not print notices on the console until transaction completes
Date: Tue, 31 May 2022 13:51:07 +0200 (CEST)
Message-ID: <alpine.DEB.2.22.394.2205311331140.1672363@pseudo> (raw)
In-Reply-To: <alpine.DEB.2.22.394.2205301921520.1376708@pseudo>
References: <PAXPR02MB760039506C87A2083AD85575E3DA9@PAXPR02MB7600.eurprd02.prod.outlook.com>
<3662994.1653856025@sss.pgh.pa.us>
<alpine.DEB.2.22.394.2205300849090.1166441@pseudo>
<alpine.DEB.2.22.394.2205301921520.1376708@pseudo>
>>>> 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.
Attachments:psql-notices-2.patch (text/x-diff, 5.1K) downloaddiff --git a/src/bin/psql/common.c b/src/bin/psql/common.cindex 03e6d9ce8f..71b33e2c34 100644--- a/src/bin/psql/common.c+++ b/src/bin/psql/common.c@@ -1061,44 +1061,6 @@ PrintQueryResult(PGresult *result, bool last, bool is_watch, const printQueryOpt
return success;
}
-/*- * Data structure and functions to record notices while they are- * emitted, so that they can be shown later.- *- * We need to know which result is last, which requires to extract- * one result in advance, hence two buffers are needed.- */-struct t_notice_messages-{- PQExpBufferData messages[2];- int current;-};--/*- * Store notices in appropriate buffer, for later display.- */-static void-AppendNoticeMessage(void *arg, const char *msg)-{- struct t_notice_messages *notices = arg;-- appendPQExpBufferStr(¬ices->messages[notices->current], msg);-}--/*- * Show notices stored in buffer, which is then reset.- */-static void-ShowNoticeMessage(struct t_notice_messages *notices)-{- PQExpBufferData *current = ¬ices->messages[notices->current];-- if (*current->data != '\0')- pg_log_info("%s", current->data);- resetPQExpBuffer(current);-}--
/*
* SendQuery: send the query string to the backend
* (and print out result)
@@ -1483,7 +1445,7 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
instr_time before,
after;
PGresult *result;
- struct t_notice_messages notices;+ bool need_last = pset.gset_prefix || pset.gexec_flag || pset.crosstab_flag || !pset.show_all_results;
if (timing)
INSTR_TIME_SET_CURRENT(before);
@@ -1513,12 +1475,6 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
return 0;
}
- /* intercept notices */- notices.current = 0;- initPQExpBuffer(¬ices.messages[0]);- initPQExpBuffer(¬ices.messages[1]);- PQsetNoticeProcessor(pset.db, AppendNoticeMessage, ¬ices);-
/* first result */
result = PQgetResult(pset.db);
@@ -1536,7 +1492,6 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
*/
const char *error = PQresultErrorMessage(result);
- ShowNoticeMessage(¬ices);
if (strlen(error))
pg_log_info("%s", error);
@@ -1601,8 +1556,6 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
if (result_status == PGRES_COPY_IN ||
result_status == PGRES_COPY_OUT)
{
- ShowNoticeMessage(¬ices);-
if (is_watch)
{
ClearOrSaveAllResults();
@@ -1610,12 +1563,7 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
return -1;
}
- /* use normal notice processor during COPY */- PQsetNoticeProcessor(pset.db, NoticeProcessor, NULL);-
success &= HandleCopyResult(&result);
-- PQsetNoticeProcessor(pset.db, AppendNoticeMessage, ¬ices);
}
/*
@@ -1623,9 +1571,7 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
* string, it will return NULL. Otherwise, we'll have other results
* to process. We need to do that to check whether this is the last.
*/
- notices.current ^= 1;- next_result = PQgetResult(pset.db);- notices.current ^= 1;+ next_result = need_last ? PQgetResult(pset.db) : NULL;
last = (next_result == NULL);
/*
@@ -1647,9 +1593,6 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
*elapsed_msec = INSTR_TIME_GET_MILLISEC(after);
}
- /* notices already shown above for copy */- ShowNoticeMessage(¬ices);-
/* this may or may not print something depending on settings */
if (result != NULL)
success &= PrintQueryResult(result, last, false, opt, printQueryFout);
@@ -1659,8 +1602,7 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
SetResultVariables(result, true);
ClearOrSaveResult(result);
- notices.current ^= 1;- result = next_result;+ result = need_last ? next_result : PQgetResult(pset.db);
if (cancel_pressed)
{
@@ -1669,11 +1611,6 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
}
}
- /* reset notice hook */- PQsetNoticeProcessor(pset.db, NoticeProcessor, NULL);- termPQExpBuffer(¬ices.messages[0]);- termPQExpBuffer(¬ices.messages[1]);-
/* may need this to recover from conn loss during COPY */
if (!CheckConnection())
return -1;
diff --git a/src/test/regress/expected/psql.out b/src/test/regress/expected/psql.outindex 2a38a93a3b..baedf04ba5 100644--- a/src/test/regress/expected/psql.out+++ b/src/test/regress/expected/psql.out@@ -5335,13 +5335,13 @@ CONTEXT: PL/pgSQL function warn(text) line 2 at RAISE
-- \gset applies to last query only
SELECT 3 AS three \; SELECT warn('3.5') \; SELECT 4 AS four \gset
+NOTICE: warn 3.5+CONTEXT: PL/pgSQL function warn(text) line 2 at RAISE
three
-------
3
(1 row)
-NOTICE: warn 3.5-CONTEXT: PL/pgSQL function warn(text) line 2 at RAISE
warn
------
t
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-bugs@postgresql.org
Cc: coelho@cri.ensmp.fr, tgl@sss.pgh.pa.us, a.mckinley@analyticsengines.com, pgsql-bugs@lists.postgresql.org, peter.eisentraut@enterprisedb.com
Subject: Re: psql 15beta1 does not print notices on the console until transaction completes
In-Reply-To: <alpine.DEB.2.22.394.2205311331140.1672363@pseudo>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox