Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1nvjaQ-0004ep-QW for pgsql-bugs@arkaria.postgresql.org; Mon, 30 May 2022 17:53:50 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1nvjaO-0002Bi-LR for pgsql-bugs@arkaria.postgresql.org; Mon, 30 May 2022 17:53:48 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1nvjaO-0002BX-Br for pgsql-bugs@lists.postgresql.org; Mon, 30 May 2022 17:53:48 +0000 Received: from sfr-1.cri.mines-paristech.fr ([77.158.180.225] helo=smtp.cri.ensmp.fr) by magus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1nvjaL-0007Fw-Nc for pgsql-bugs@lists.postgresql.org; Mon, 30 May 2022 17:53:47 +0000 Received: from pseudo (185.141.6.84.rev.sfr.net [84.6.141.185]) by smtp.cri.ensmp.fr (Postfix) with ESMTPSA id 416C3C005F; Mon, 30 May 2022 19:57:26 +0200 (CEST) Date: Mon, 30 May 2022 19:53:33 +0200 (CEST) From: Fabien COELHO X-X-Sender: fabien@pseudo Reply-To: Fabien COELHO To: Tom Lane cc: Alastair McKinley , PostgreSQL Bugs , Peter Eisentraut Subject: Re: psql 15beta1 does not print notices on the console until transaction completes In-Reply-To: Message-ID: References: <3662994.1653856025@sss.pgh.pa.us> User-Agent: Alpine 2.22 (DEB 394 2020-01-19) MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="2056645051-963880089-1653933223=:1376708" List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk This message is in MIME format. The first part should be readable text, while the remaining parts are likely unreadable without MIME-aware tools. --2056645051-963880089-1653933223=:1376708 Content-Type: text/plain; charset=UTF-8; format=flowed Content-Transfer-Encoding: 8BIT 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. --2056645051-963880089-1653933223=:1376708 Content-Type: text/x-diff; name=psql-notices-1.patch Content-Transfer-Encoding: BASE64 Content-ID: Content-Description: Content-Disposition: attachment; filename=psql-notices-1.patch ZGlmZiAtLWdpdCBhL3NyYy9iaW4vcHNxbC9jb21tb24uYyBiL3NyYy9iaW4v cHNxbC9jb21tb24uYw0KaW5kZXggMDNlNmQ5Y2U4Zi4uOTc0OTU5YzU5NSAx MDA2NDQNCi0tLSBhL3NyYy9iaW4vcHNxbC9jb21tb24uYw0KKysrIGIvc3Jj L2Jpbi9wc3FsL2NvbW1vbi5jDQpAQCAtMTA2MSw0NCArMTA2MSw2IEBAIFBy aW50UXVlcnlSZXN1bHQoUEdyZXN1bHQgKnJlc3VsdCwgYm9vbCBsYXN0LCBi b29sIGlzX3dhdGNoLCBjb25zdCBwcmludFF1ZXJ5T3B0DQogCXJldHVybiBz dWNjZXNzOw0KIH0NCiANCi0vKg0KLSAqIERhdGEgc3RydWN0dXJlIGFuZCBm dW5jdGlvbnMgdG8gcmVjb3JkIG5vdGljZXMgd2hpbGUgdGhleSBhcmUNCi0g KiBlbWl0dGVkLCBzbyB0aGF0IHRoZXkgY2FuIGJlIHNob3duIGxhdGVyLg0K LSAqDQotICogV2UgbmVlZCB0byBrbm93IHdoaWNoIHJlc3VsdCBpcyBsYXN0 LCB3aGljaCByZXF1aXJlcyB0byBleHRyYWN0DQotICogb25lIHJlc3VsdCBp biBhZHZhbmNlLCBoZW5jZSB0d28gYnVmZmVycyBhcmUgbmVlZGVkLg0KLSAq Lw0KLXN0cnVjdCB0X25vdGljZV9tZXNzYWdlcw0KLXsNCi0JUFFFeHBCdWZm ZXJEYXRhIG1lc3NhZ2VzWzJdOw0KLQlpbnQJCQljdXJyZW50Ow0KLX07DQot DQotLyoNCi0gKiBTdG9yZSBub3RpY2VzIGluIGFwcHJvcHJpYXRlIGJ1ZmZl ciwgZm9yIGxhdGVyIGRpc3BsYXkuDQotICovDQotc3RhdGljIHZvaWQNCi1B cHBlbmROb3RpY2VNZXNzYWdlKHZvaWQgKmFyZywgY29uc3QgY2hhciAqbXNn KQ0KLXsNCi0Jc3RydWN0IHRfbm90aWNlX21lc3NhZ2VzICpub3RpY2VzID0g YXJnOw0KLQ0KLQlhcHBlbmRQUUV4cEJ1ZmZlclN0cigmbm90aWNlcy0+bWVz c2FnZXNbbm90aWNlcy0+Y3VycmVudF0sIG1zZyk7DQotfQ0KLQ0KLS8qDQot ICogU2hvdyBub3RpY2VzIHN0b3JlZCBpbiBidWZmZXIsIHdoaWNoIGlzIHRo ZW4gcmVzZXQuDQotICovDQotc3RhdGljIHZvaWQNCi1TaG93Tm90aWNlTWVz c2FnZShzdHJ1Y3QgdF9ub3RpY2VfbWVzc2FnZXMgKm5vdGljZXMpDQotew0K LQlQUUV4cEJ1ZmZlckRhdGEgKmN1cnJlbnQgPSAmbm90aWNlcy0+bWVzc2Fn ZXNbbm90aWNlcy0+Y3VycmVudF07DQotDQotCWlmICgqY3VycmVudC0+ZGF0 YSAhPSAnXDAnKQ0KLQkJcGdfbG9nX2luZm8oIiVzIiwgY3VycmVudC0+ZGF0 YSk7DQotCXJlc2V0UFFFeHBCdWZmZXIoY3VycmVudCk7DQotfQ0KLQ0KLQ0K IC8qDQogICogU2VuZFF1ZXJ5OiBzZW5kIHRoZSBxdWVyeSBzdHJpbmcgdG8g dGhlIGJhY2tlbmQNCiAgKiAoYW5kIHByaW50IG91dCByZXN1bHQpDQpAQCAt MTQ4Myw3ICsxNDQ1LDYgQEAgRXhlY1F1ZXJ5QW5kUHJvY2Vzc1Jlc3VsdHMo Y29uc3QgY2hhciAqcXVlcnksIGRvdWJsZSAqZWxhcHNlZF9tc2VjLCBib29s ICpzdnB0X2cNCiAJaW5zdHJfdGltZQliZWZvcmUsDQogCQkJCWFmdGVyOw0K IAlQR3Jlc3VsdCAgICpyZXN1bHQ7DQotCXN0cnVjdCB0X25vdGljZV9tZXNz YWdlcyBub3RpY2VzOw0KIA0KIAlpZiAodGltaW5nKQ0KIAkJSU5TVFJfVElN RV9TRVRfQ1VSUkVOVChiZWZvcmUpOw0KQEAgLTE1MTMsMTIgKzE0NzQsNiBA QCBFeGVjUXVlcnlBbmRQcm9jZXNzUmVzdWx0cyhjb25zdCBjaGFyICpxdWVy eSwgZG91YmxlICplbGFwc2VkX21zZWMsIGJvb2wgKnN2cHRfZw0KIAkJcmV0 dXJuIDA7DQogCX0NCiANCi0JLyogaW50ZXJjZXB0IG5vdGljZXMgKi8NCi0J bm90aWNlcy5jdXJyZW50ID0gMDsNCi0JaW5pdFBRRXhwQnVmZmVyKCZub3Rp Y2VzLm1lc3NhZ2VzWzBdKTsNCi0JaW5pdFBRRXhwQnVmZmVyKCZub3RpY2Vz Lm1lc3NhZ2VzWzFdKTsNCi0JUFFzZXROb3RpY2VQcm9jZXNzb3IocHNldC5k YiwgQXBwZW5kTm90aWNlTWVzc2FnZSwgJm5vdGljZXMpOw0KLQ0KIAkvKiBm aXJzdCByZXN1bHQgKi8NCiAJcmVzdWx0ID0gUFFnZXRSZXN1bHQocHNldC5k Yik7DQogDQpAQCAtMTUzNiw3ICsxNDkxLDYgQEAgRXhlY1F1ZXJ5QW5kUHJv Y2Vzc1Jlc3VsdHMoY29uc3QgY2hhciAqcXVlcnksIGRvdWJsZSAqZWxhcHNl ZF9tc2VjLCBib29sICpzdnB0X2cNCiAJCQkgKi8NCiAJCQljb25zdCBjaGFy ICplcnJvciA9IFBRcmVzdWx0RXJyb3JNZXNzYWdlKHJlc3VsdCk7DQogDQot CQkJU2hvd05vdGljZU1lc3NhZ2UoJm5vdGljZXMpOw0KIAkJCWlmIChzdHJs ZW4oZXJyb3IpKQ0KIAkJCQlwZ19sb2dfaW5mbygiJXMiLCBlcnJvcik7DQog DQpAQCAtMTYwMSw4ICsxNTU1LDYgQEAgRXhlY1F1ZXJ5QW5kUHJvY2Vzc1Jl c3VsdHMoY29uc3QgY2hhciAqcXVlcnksIGRvdWJsZSAqZWxhcHNlZF9tc2Vj LCBib29sICpzdnB0X2cNCiAJCWlmIChyZXN1bHRfc3RhdHVzID09IFBHUkVT X0NPUFlfSU4gfHwNCiAJCQlyZXN1bHRfc3RhdHVzID09IFBHUkVTX0NPUFlf T1VUKQ0KIAkJew0KLQkJCVNob3dOb3RpY2VNZXNzYWdlKCZub3RpY2VzKTsN Ci0NCiAJCQlpZiAoaXNfd2F0Y2gpDQogCQkJew0KIAkJCQlDbGVhck9yU2F2 ZUFsbFJlc3VsdHMoKTsNCkBAIC0xNjEwLDEyICsxNTYyLDcgQEAgRXhlY1F1 ZXJ5QW5kUHJvY2Vzc1Jlc3VsdHMoY29uc3QgY2hhciAqcXVlcnksIGRvdWJs ZSAqZWxhcHNlZF9tc2VjLCBib29sICpzdnB0X2cNCiAJCQkJcmV0dXJuIC0x Ow0KIAkJCX0NCiANCi0JCQkvKiB1c2Ugbm9ybWFsIG5vdGljZSBwcm9jZXNz b3IgZHVyaW5nIENPUFkgKi8NCi0JCQlQUXNldE5vdGljZVByb2Nlc3Nvcihw c2V0LmRiLCBOb3RpY2VQcm9jZXNzb3IsIE5VTEwpOw0KLQ0KIAkJCXN1Y2Nl c3MgJj0gSGFuZGxlQ29weVJlc3VsdCgmcmVzdWx0KTsNCi0NCi0JCQlQUXNl dE5vdGljZVByb2Nlc3Nvcihwc2V0LmRiLCBBcHBlbmROb3RpY2VNZXNzYWdl LCAmbm90aWNlcyk7DQogCQl9DQogDQogCQkvKg0KQEAgLTE2MjMsOSArMTU3 MCw3IEBAIEV4ZWNRdWVyeUFuZFByb2Nlc3NSZXN1bHRzKGNvbnN0IGNoYXIg KnF1ZXJ5LCBkb3VibGUgKmVsYXBzZWRfbXNlYywgYm9vbCAqc3ZwdF9nDQog CQkgKiBzdHJpbmcsIGl0IHdpbGwgcmV0dXJuIE5VTEwuICBPdGhlcndpc2Us IHdlJ2xsIGhhdmUgb3RoZXIgcmVzdWx0cw0KIAkJICogdG8gcHJvY2Vzcy4g IFdlIG5lZWQgdG8gZG8gdGhhdCB0byBjaGVjayB3aGV0aGVyIHRoaXMgaXMg dGhlIGxhc3QuDQogCQkgKi8NCi0JCW5vdGljZXMuY3VycmVudCBePSAxOw0K IAkJbmV4dF9yZXN1bHQgPSBQUWdldFJlc3VsdChwc2V0LmRiKTsNCi0JCW5v dGljZXMuY3VycmVudCBePSAxOw0KIAkJbGFzdCA9IChuZXh0X3Jlc3VsdCA9 PSBOVUxMKTsNCiANCiAJCS8qDQpAQCAtMTY0Nyw5ICsxNTkyLDYgQEAgRXhl Y1F1ZXJ5QW5kUHJvY2Vzc1Jlc3VsdHMoY29uc3QgY2hhciAqcXVlcnksIGRv dWJsZSAqZWxhcHNlZF9tc2VjLCBib29sICpzdnB0X2cNCiAJCQkqZWxhcHNl ZF9tc2VjID0gSU5TVFJfVElNRV9HRVRfTUlMTElTRUMoYWZ0ZXIpOw0KIAkJ fQ0KIA0KLQkJLyogbm90aWNlcyBhbHJlYWR5IHNob3duIGFib3ZlIGZvciBj b3B5ICovDQotCQlTaG93Tm90aWNlTWVzc2FnZSgmbm90aWNlcyk7DQotDQog CQkvKiB0aGlzIG1heSBvciBtYXkgbm90IHByaW50IHNvbWV0aGluZyBkZXBl bmRpbmcgb24gc2V0dGluZ3MgKi8NCiAJCWlmIChyZXN1bHQgIT0gTlVMTCkN CiAJCQlzdWNjZXNzICY9IFByaW50UXVlcnlSZXN1bHQocmVzdWx0LCBsYXN0 LCBmYWxzZSwgb3B0LCBwcmludFF1ZXJ5Rm91dCk7DQpAQCAtMTY1OSw3ICsx NjAxLDYgQEAgRXhlY1F1ZXJ5QW5kUHJvY2Vzc1Jlc3VsdHMoY29uc3QgY2hh ciAqcXVlcnksIGRvdWJsZSAqZWxhcHNlZF9tc2VjLCBib29sICpzdnB0X2cN CiAJCQlTZXRSZXN1bHRWYXJpYWJsZXMocmVzdWx0LCB0cnVlKTsNCiANCiAJ CUNsZWFyT3JTYXZlUmVzdWx0KHJlc3VsdCk7DQotCQlub3RpY2VzLmN1cnJl bnQgXj0gMTsNCiAJCXJlc3VsdCA9IG5leHRfcmVzdWx0Ow0KIA0KIAkJaWYg KGNhbmNlbF9wcmVzc2VkKQ0KQEAgLTE2NjksMTEgKzE2MTAsNiBAQCBFeGVj UXVlcnlBbmRQcm9jZXNzUmVzdWx0cyhjb25zdCBjaGFyICpxdWVyeSwgZG91 YmxlICplbGFwc2VkX21zZWMsIGJvb2wgKnN2cHRfZw0KIAkJfQ0KIAl9DQog DQotCS8qIHJlc2V0IG5vdGljZSBob29rICovDQotCVBRc2V0Tm90aWNlUHJv Y2Vzc29yKHBzZXQuZGIsIE5vdGljZVByb2Nlc3NvciwgTlVMTCk7DQotCXRl cm1QUUV4cEJ1ZmZlcigmbm90aWNlcy5tZXNzYWdlc1swXSk7DQotCXRlcm1Q UUV4cEJ1ZmZlcigmbm90aWNlcy5tZXNzYWdlc1sxXSk7DQotDQogCS8qIG1h eSBuZWVkIHRoaXMgdG8gcmVjb3ZlciBmcm9tIGNvbm4gbG9zcyBkdXJpbmcg Q09QWSAqLw0KIAlpZiAoIUNoZWNrQ29ubmVjdGlvbigpKQ0KIAkJcmV0dXJu IC0xOw0K --2056645051-963880089-1653933223=:1376708--