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: Mon, 30 May 2022 19:53:33 +0200 (CEST)
Message-ID: <alpine.DEB.2.22.394.2205301921520.1376708@pseudo> (raw)
In-Reply-To: <alpine.DEB.2.22.394.2205300849090.1166441@pseudo>
References: <PAXPR02MB760039506C87A2083AD85575E3DA9@PAXPR02MB7600.eurprd02.prod.outlook.com>
<3662994.1653856025@sss.pgh.pa.us>
<alpine.DEB.2.22.394.2205300849090.1166441@pseudo>
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.
Attachments:psql-notices-1.patch (text/x-diff, 4.2K) downloaddiff --git a/src/bin/psql/common.c b/src/bin/psql/common.cindex 03e6d9ce8f..974959c595 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,6 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
instr_time before,
after;
PGresult *result;
- struct t_notice_messages notices;
if (timing)
INSTR_TIME_SET_CURRENT(before);
@@ -1513,12 +1474,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 +1491,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 +1555,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 +1562,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 +1570,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;
last = (next_result == NULL);
/*
@@ -1647,9 +1592,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,7 +1601,6 @@ ExecQueryAndProcessResults(const char *query, double *elapsed_msec, bool *svpt_g
SetResultVariables(result, true);
ClearOrSaveResult(result);
- notices.current ^= 1;
result = next_result;
if (cancel_pressed)
@@ -1669,11 +1610,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;
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.2205301921520.1376708@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