Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1gnuar-0006Hx-TG for pgsql-hackers@arkaria.postgresql.org; Mon, 28 Jan 2019 00:16:06 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.89) (envelope-from ) id 1gnuap-00045J-Jh for pgsql-hackers@arkaria.postgresql.org; Mon, 28 Jan 2019 00:16:03 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1gnuan-00041E-I5 for pgsql-hackers@lists.postgresql.org; Mon, 28 Jan 2019 00:16:03 +0000 Received: from out5-smtp.messagingengine.com ([66.111.4.29]) by magus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1gnuai-0002UM-SM for pgsql-hackers@postgresql.org; Mon, 28 Jan 2019 00:16:01 +0000 Received: from compute2.internal (compute2.nyi.internal [10.202.2.42]) by mailout.nyi.internal (Postfix) with ESMTP id E600120DB2; Sun, 27 Jan 2019 19:15:54 -0500 (EST) Received: from mailfrontend1 ([10.202.2.162]) by compute2.internal (MEProxy); Sun, 27 Jan 2019 19:15:54 -0500 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=imap.cc; h= subject:to:references:from:message-id:date:mime-version :in-reply-to:content-type; s=fm2; bh=YRWxgb4wjGKLCPf6xXhh/WGs1dT Z4w5VdrU+3XhA8wo=; b=c+ry/fwLgLrRX2AAyHs4qLRTFsNEaqUS/jsVUV6bhb2 XqLqBxDxCtwtix1DSpaqIE/H9Hp25p5/j2pqg6q70jWdxItOWKqw+fS3vOXLp68A kcXBa/iHIdS3XTC6U1flD2AkGSQg5gdhnBJsc1hL2xtDOwqVtpse4MY2GJGJxK7y GPxan/9btbcnwhLTFbnfD7WWyk5TtZW2NZLlxmqtv0s3KiMwDqdR+FHLkiUCigBX ZbCtx8hcdQMRkbr3NOhi7YMKtbZzqOPbQIna48RoLJn510EUSFEj5aQ0yM+5J4XI GLZfB1ptpy/L4BNB5rPZZHyw4tqaoxFNbD8tnu7svMA== DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d= messagingengine.com; h=content-type:date:from:in-reply-to :message-id:mime-version:references:subject:to:x-me-proxy :x-me-proxy:x-me-sender:x-me-sender:x-sasl-enc; s=fm1; bh=YRWxgb 4wjGKLCPf6xXhh/WGs1dTZ4w5VdrU+3XhA8wo=; b=ZCPy4Mx671m9o2ZwW/FVsR so2QZWzpYt/MXBbj+BJi2lne3gIy43zGcLOzFWblcZEBpsQHTXj319hATw7ZJbME hk/Q4satzHy2Nitnh6vrsn19AWeak136pW9BoCjtVzZw6XgiVHjtAIwSwMufKWhB X7UpjDwwpKYJGlo0BaxsM2g0aOJ71iXv1eYvkS9C1opyxNIbsq8AEPaRlepR6AzS JAufCtw6pFwadF5t5eTpkdmIRxHnASQ3Bkel093maKO0QrbySqAKjPee8FQU0JbG RQqPOC59aXBnV3HMSnSzouiMlxvQHpLC1rarTFlBnejqEAoYObtk1n4vqE5GE/VQ == X-ME-Sender: X-ME-Proxy-Cause: gggruggvucftvghtrhhoucdtuddrgedtledrieelgddvudcutefuodetggdotefrodftvf curfhrohhfihhlvgemucfhrghsthforghilhdpqfhuthenuceurghilhhouhhtmecufedt tdenucesvcftvggtihhpihgvnhhtshculddquddttddmnegfrhhlucfvnfffucdlfedtmd enucfjughrpefuvfhfhffkffgfgggjtgesmhdtreertdefjeenucfhrhhomheptehlvgig vgihuceurghshhhtrghnohhvuceosggrshhhthgrnhhovhesihhmrghprdgttgeqnecukf hppeekiedrvddtrdeffedrudehudenucfrrghrrghmpehmrghilhhfrhhomhepsggrshhh thgrnhhovhesihhmrghprdgttgenucevlhhushhtvghrufhiiigvpedt X-ME-Proxy: Received: from [192.168.1.242] (cpc83287-brig21-2-0-cust406.3-3.cable.virginm.net [86.20.33.151]) by mail.messagingengine.com (Postfix) with ESMTPA id 5E279E40D1; Sun, 27 Jan 2019 19:15:53 -0500 (EST) Subject: Re: log bind parameter values on error To: Peter Eisentraut , PostgreSQL Hackers References: <0146a67b-a22a-0519-9082-bc29756b93a2@imap.cc> <896ac2ed-7735-1f24-d877-3249b38bb6fe@2ndquadrant.com> <8efd95fe-3886-61f0-0faa-6c661cd2f874@imap.cc> <084a044f-9d77-b931-0658-5d871df8a2f8@imap.cc> <96007f6e-1e42-e454-9db4-e7842e137508@2ndquadrant.com> From: Alexey Bashtanov Message-ID: Date: Mon, 28 Jan 2019 00:15:51 +0000 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:60.0) Gecko/20100101 Thunderbird/60.2.1 MIME-Version: 1.0 In-Reply-To: <96007f6e-1e42-e454-9db4-e7842e137508@2ndquadrant.com> Content-Type: multipart/mixed; boundary="------------E93AB7656B27F670EFACCBF7" Content-Language: en-US List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Precedence: bulk This is a multi-part message in MIME format. --------------E93AB7656B27F670EFACCBF7 Content-Type: text/plain; charset=utf-8; format=flowed Content-Transfer-Encoding: 8bit Hi Peter, > With your patch, with log_statement=all and log_parameters=on, you get > the same, but with log_statement=all and log_parameters=off you get > > LOG: execute : SELECT abalance FROM pgbench_accounts WHERE aid > = $1; > DETAIL: parameters: $1 = UNKNOWN TYPE Thanks for spotting this, I've fixed it, see the new patch attached. > This also raises the question of the new parameter name. Parameters are > already logged. So the name should perhaps be more like > log_parameters_on_error. Done > Some API notes on your patch: I think you can change > get_portal_bind_parameters() to take a ParamListInfo, since you're not > doing anything with the Portal other than grab the parameters. And that > would allow you to keep the signature of errdetail_params() unchanged. Done > I did some performance tests using the commands shown above and didn't > find any problems. Obviously the default pgbench stuff isn't very > parameter-intensive. Do you have tests with more and larger parameter > values? > I've done some tests, but they are not very reproducible: the difference between runs is more than the difference between master vs feature branch and log_parameters_on_error on vs off. I was using a small java app, it tested the speed using only a single connection. See its code and the results attached. I'm sorry for the delay, feel free to move it to next commitfest if needed. Best,   Alex --------------E93AB7656B27F670EFACCBF7 Content-Type: text/x-java; name="JDBCTest.java" Content-Transfer-Encoding: 7bit Content-Disposition: attachment; filename="JDBCTest.java" import java.sql.ResultSet; import java.util.Arrays; import java.util.Collections; import java.util.List; import com.zaxxer.hikari.HikariDataSource; import org.springframework.jdbc.core.JdbcTemplate; import org.springframework.jdbc.core.RowMapper; public class JDBCTest { public static void main(String[] argv) throws Exception { Class.forName("org.postgresql.Driver"); HikariDataSource dataSource = new HikariDataSource(); dataSource.setPoolName("foo"); dataSource.setJdbcUrl("jdbc:postgresql://127.0.0.1:5432/alexey?prepareThreshold=1"); dataSource.setUsername("alexey"); dataSource.setPassword(""); dataSource.setMinimumIdle(0); dataSource.setMaximumPoolSize(1); dataSource.setIdleTimeout(10000 * 1000L); dataSource.setMaxLifetime(10000 * 1000L); JdbcTemplate jt = new JdbcTemplate(dataSource); int[][] paramsets = new int[][]{ {100000, 0, 0}, {1000, 10000, 1}, {1000, 1000, 1000}, {1000, 100, 10000}, {1000, 10, 100000}, {1000, 1, 1000000}, {10, 1, 100000000} }; for(int[] paramset: paramsets) { int nruns = paramset[0]; int nparams = paramset[1]; int paramLength = paramset[2]; String sql = "select coalesce('' " + String.join("", Collections.nCopies(nparams, ", ?")) + ")"; String p = String.join("", Collections.nCopies(paramLength, "z")); Object[] pp = new Object[nparams]; Arrays.fill(pp, p); RowMapper rm = (ResultSet resultSet, int i) -> resultSet.getString(1); long startTime = System.nanoTime(); for (int i = 0; i < nruns; i++) { List result = jt.query(sql, pp, rm); } long endTime = System.nanoTime(); long duration = (endTime - startTime); System.out.println(String.format("NPARAMS=%d PARAM_LENGTH=%d NRUNS=%d TIME=%fs", nparams, paramLength, nruns, duration / 1000000. / 1000)); } System.exit(0); } } --------------E93AB7656B27F670EFACCBF7 Content-Type: text/plain; charset=UTF-8; name="params_benchmark.txt" Content-Transfer-Encoding: base64 Content-Disposition: attachment; filename="params_benchmark.txt" bG9nX21pbl9kdXJhdGlvbl9zdGF0ZW1lbnQ9LTE6CgpmZWF0dXJlIGJyYW5jaCwgbG9nX3Bh cmFtZXRlcnNfb25fZXJyb3I9b2ZmOgpOUEFSQU1TPTAgUEFSQU1fTEVOR1RIPTAgTlJVTlM9 MTAwMDAwIFRJTUU9NS40NTU5NTBzCk5QQVJBTVM9MTAwMDAgUEFSQU1fTEVOR1RIPTEgTlJV TlM9MTAwMCBUSU1FPTguNzA4OTExcwpOUEFSQU1TPTEwMDAgUEFSQU1fTEVOR1RIPTEwMDAg TlJVTlM9MTAwMCBUSU1FPTkuMjY2NDI4cwpOUEFSQU1TPTEwMCBQQVJBTV9MRU5HVEg9MTAw MDAgTlJVTlM9MTAwMCBUSU1FPTUuOTQ5MTA5cwpOUEFSQU1TPTEwIFBBUkFNX0xFTkdUSD0x MDAwMDAgTlJVTlM9MTAwMCBUSU1FPTUuMDg2MzgxcwpOUEFSQU1TPTEgUEFSQU1fTEVOR1RI PTEwMDAwMDAgTlJVTlM9MTAwMCBUSU1FPTUuMzAxNzgwcwpOUEFSQU1TPTEgUEFSQU1fTEVO R1RIPTEwMDAwMDAwMCBOUlVOUz0xMCBUSU1FPTYuNzYzODgzcwoKZmVhdHVyZSBicmFuY2gs IGxvZ19wYXJhbWV0ZXJzX29uX2Vycm9yPW9uOgpOUEFSQU1TPTAgUEFSQU1fTEVOR1RIPTAg TlJVTlM9MTAwMDAwIFRJTUU9NS4yMzg2NzRzCk5QQVJBTVM9MTAwMDAgUEFSQU1fTEVOR1RI PTEgTlJVTlM9MTAwMCBUSU1FPTguOTI3ODE4cwpOUEFSQU1TPTEwMDAgUEFSQU1fTEVOR1RI PTEwMDAgTlJVTlM9MTAwMCBUSU1FPTcuOTYwNTY5cwpOUEFSQU1TPTEwMCBQQVJBTV9MRU5H VEg9MTAwMDAgTlJVTlM9MTAwMCBUSU1FPTYuMzk4MzQzcwpOUEFSQU1TPTEwIFBBUkFNX0xF TkdUSD0xMDAwMDAgTlJVTlM9MTAwMCBUSU1FPTUuMjkzOTYycwpOUEFSQU1TPTEgUEFSQU1f TEVOR1RIPTEwMDAwMDAgTlJVTlM9MTAwMCBUSU1FPTUuNTE5NjA3cwpOUEFSQU1TPTEgUEFS QU1fTEVOR1RIPTEwMDAwMDAwMCBOUlVOUz0xMCBUSU1FPTcuMjM2MDE0cwoKbWFzdGVyOgpO UEFSQU1TPTAgUEFSQU1fTEVOR1RIPTAgTlJVTlM9MTAwMDAwIFRJTUU9NS42MDA3MzVzCk5Q QVJBTVM9MTAwMDAgUEFSQU1fTEVOR1RIPTEgTlJVTlM9MTAwMCBUSU1FPTExLjQ3ODQwNnMK TlBBUkFNUz0xMDAwIFBBUkFNX0xFTkdUSD0xMDAwIE5SVU5TPTEwMDAgVElNRT05LjcwMTA1 NHMKTlBBUkFNUz0xMDAgUEFSQU1fTEVOR1RIPTEwMDAwIE5SVU5TPTEwMDAgVElNRT02LjM1 Mjk2MXMKTlBBUkFNUz0xMCBQQVJBTV9MRU5HVEg9MTAwMDAwIE5SVU5TPTEwMDAgVElNRT01 LjE1MzMwM3MKTlBBUkFNUz0xIFBBUkFNX0xFTkdUSD0xMDAwMDAwIE5SVU5TPTEwMDAgVElN RT01LjQ1Njk2NHMKTlBBUkFNUz0xIFBBUkFNX0xFTkdUSD0xMDAwMDAwMDAgTlJVTlM9MTAg VElNRT04Ljg4Nzc5MnMKCgpsb2dfbWluX2R1cmF0aW9uX3N0YXRlbWVudD0wOgoKZmVhdHVy ZSBicmFuY2gsIGxvZ19wYXJhbWV0ZXJzX29uX2Vycm9yPW9mZjoKTlBBUkFNUz0wIFBBUkFN X0xFTkdUSD0wIE5SVU5TPTEwMDAwMCBUSU1FPTcuMTQ3MDU3cwpOUEFSQU1TPTEwMDAwIFBB UkFNX0xFTkdUSD0xIE5SVU5TPTEwMDAgVElNRT0xOC43MDcwNzdzCk5QQVJBTVM9MTAwMCBQ QVJBTV9MRU5HVEg9MTAwMCBOUlVOUz0xMDAwIFRJTUU9MjkuOTA2NTEzcwpOUEFSQU1TPTEw MCBQQVJBTV9MRU5HVEg9MTAwMDAgTlJVTlM9MTAwMCBUSU1FPTI3LjM1MjQ4OXMKTlBBUkFN Uz0xMCBQQVJBTV9MRU5HVEg9MTAwMDAwIE5SVU5TPTEwMDAgVElNRT0yNS45NTA3ODBzCk5Q QVJBTVM9MSBQQVJBTV9MRU5HVEg9MTAwMDAwMCBOUlVOUz0xMDAwIFRJTUU9MjcuMTgzMDE5 cwpOUEFSQU1TPTEgUEFSQU1fTEVOR1RIPTEwMDAwMDAwMCBOUlVOUz0xMCBUSU1FPTM1LjA4 ODQyM3MKCmZlYXR1cmUgYnJhbmNoLCBsb2dfcGFyYW1ldGVyc19vbl9lcnJvcj1vbjoKTlBB UkFNUz0wIFBBUkFNX0xFTkdUSD0wIE5SVU5TPTEwMDAwMCBUSU1FPTYuNDIyMDQxcwpOUEFS QU1TPTEwMDAwIFBBUkFNX0xFTkdUSD0xIE5SVU5TPTEwMDAgVElNRT0xNC42NTM5NTRzCk5Q QVJBTVM9MTAwMCBQQVJBTV9MRU5HVEg9MTAwMCBOUlVOUz0xMDAwIFRJTUU9MjguNDc4MDEy cwpOUEFSQU1TPTEwMCBQQVJBTV9MRU5HVEg9MTAwMDAgTlJVTlM9MTAwMCBUSU1FPTI2LjI5 NzM2OHMKTlBBUkFNUz0xMCBQQVJBTV9MRU5HVEg9MTAwMDAwIE5SVU5TPTEwMDAgVElNRT0y Ni4xMjg5NjRzCk5QQVJBTVM9MSBQQVJBTV9MRU5HVEg9MTAwMDAwMCBOUlVOUz0xMDAwIFRJ TUU9MjYuNTAzODQ0cwpOUEFSQU1TPTEgUEFSQU1fTEVOR1RIPTEwMDAwMDAwMCBOUlVOUz0x MCBUSU1FPTM1LjkwMzU0MHMKCm1hc3RlcjoKTlBBUkFNUz0wIFBBUkFNX0xFTkdUSD0wIE5S VU5TPTEwMDAwMCBUSU1FPTcuMjIyMzg3cwpOUEFSQU1TPTEwMDAwIFBBUkFNX0xFTkdUSD0x IE5SVU5TPTEwMDAgVElNRT0xOC43Nzg4MTBzCk5QQVJBTVM9MTAwMCBQQVJBTV9MRU5HVEg9 MTAwMCBOUlVOUz0xMDAwIFRJTUU9MjkuMzcyMDI1cwpOUEFSQU1TPTEwMCBQQVJBTV9MRU5H VEg9MTAwMDAgTlJVTlM9MTAwMCBUSU1FPTI3Ljk5MTU4NnMKTlBBUkFNUz0xMCBQQVJBTV9M RU5HVEg9MTAwMDAwIE5SVU5TPTEwMDAgVElNRT0yNi4wMTE1MDZzCk5QQVJBTVM9MSBQQVJB TV9MRU5HVEg9MTAwMDAwMCBOUlVOUz0xMDAwIFRJTUU9MjYuMjI5Mzc2cwpOUEFSQU1TPTEg UEFSQU1fTEVOR1RIPTEwMDAwMDAwMCBOUlVOUz0xMCBUSU1FPTM2LjQ3NjIxNXMK --------------E93AB7656B27F670EFACCBF7 Content-Type: text/x-patch; name="log_parameters_v005.patch" Content-Transfer-Encoding: 7bit Content-Disposition: attachment; filename="log_parameters_v005.patch" diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index b6f5822..997e6e8 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -6274,6 +6274,23 @@ log_line_prefix = '%m [%p] %q%u@%d/%a ' + + log_parameters_on_error (boolean) + + log_parameters_on_error configuration parameter + + + + + Controls whether the statement is logged with bind parameter values. + It adds some overhead, as postgres will cache textual + representations of parameter values in memory for all statements, + even if they eventually do not get logged. The default is + off. Only superusers can change this setting. + + + + log_statement (enum) diff --git a/src/backend/commands/prepare.c b/src/backend/commands/prepare.c index a98c836..9ee3954 100644 --- a/src/backend/commands/prepare.c +++ b/src/backend/commands/prepare.c @@ -404,6 +404,7 @@ EvaluateParams(PreparedStatement *pstmt, List *params, paramLI->parserSetup = NULL; paramLI->parserSetupArg = NULL; paramLI->numParams = num_params; + paramLI->hasTextValues = false; i = 0; foreach(l, exprstates) diff --git a/src/backend/executor/functions.c b/src/backend/executor/functions.c index c6b7203..e107fa3 100644 --- a/src/backend/executor/functions.c +++ b/src/backend/executor/functions.c @@ -921,6 +921,7 @@ postquel_sub_params(SQLFunctionCachePtr fcache, paramLI->parserSetup = NULL; paramLI->parserSetupArg = NULL; paramLI->numParams = nargs; + paramLI->hasTextValues = false; fcache->paramLI = paramLI; } else diff --git a/src/backend/executor/spi.c b/src/backend/executor/spi.c index 94a53e0..398f0e3 100644 --- a/src/backend/executor/spi.c +++ b/src/backend/executor/spi.c @@ -2399,6 +2399,7 @@ _SPI_convert_params(int nargs, Oid *argtypes, paramLI->parserSetup = NULL; paramLI->parserSetupArg = NULL; paramLI->numParams = nargs; + paramLI->hasTextValues = false; for (i = 0; i < nargs; i++) { diff --git a/src/backend/nodes/params.c b/src/backend/nodes/params.c index a89a25e..5aebd428 100644 --- a/src/backend/nodes/params.c +++ b/src/backend/nodes/params.c @@ -31,6 +31,8 @@ * set of parameter values. If dynamic parameter hooks are present, we * intentionally do not copy them into the result. Rather, we forcibly * instantiate all available parameter values and copy the datum values. + * + * We don't copy textual representations here. */ ParamListInfo copyParamList(ParamListInfo from) @@ -53,6 +55,7 @@ copyParamList(ParamListInfo from) retval->parserSetup = NULL; retval->parserSetupArg = NULL; retval->numParams = from->numParams; + retval->hasTextValues = false; for (i = 0; i < from->numParams; i++) { @@ -229,6 +232,7 @@ RestoreParamList(char **start_address) paramLI->parserSetup = NULL; paramLI->parserSetupArg = NULL; paramLI->numParams = nparams; + paramLI->hasTextValues = false; for (i = 0; i < nparams; i++) { diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c index e773f20..69fa610 100644 --- a/src/backend/tcop/postgres.c +++ b/src/backend/tcop/postgres.c @@ -86,6 +86,12 @@ */ const char *debug_query_string; /* client-supplied query string */ +/* + * The top-level portal that the client is immediately working with: + * creating, binding, executing, or all at one using simple protocol + */ +Portal current_top_portal = NULL; + /* Note: whereToSendOutput is initialized for the bootstrap/standalone case */ CommandDest whereToSendOutput = DestDebug; @@ -1694,6 +1700,9 @@ exec_bind_message(StringInfo input_message) else portal = CreatePortal(portal_name, false, false); + Assert(current_top_portal == NULL); + current_top_portal = portal; + /* * Prepare to copy stuff into the portal's memory context. We do all this * copying first, because it could possibly fail (out-of-memory) and we @@ -1731,6 +1740,9 @@ exec_bind_message(StringInfo input_message) */ if (numParams > 0) { + /* GUC value can change, so we remember its state to be consistent */ + bool need_text_values = log_parameters_on_error; + params = (ParamListInfo) palloc(offsetof(ParamListInfoData, params) + numParams * sizeof(ParamExternData)); /* we have static list of params, so no hooks needed */ @@ -1741,6 +1753,8 @@ exec_bind_message(StringInfo input_message) params->parserSetup = NULL; params->parserSetupArg = NULL; params->numParams = numParams; + /* mark as not having text values before we have populated them all */ + params->hasTextValues = false; for (int paramno = 0; paramno < numParams; paramno++) { @@ -1807,9 +1821,31 @@ exec_bind_message(StringInfo input_message) pval = OidInputFunctionCall(typinput, pstring, typioparam, -1); - /* Free result of encoding conversion, if any */ - if (pstring && pstring != pbuf.data) - pfree(pstring); + if (pstring) + { + if (need_text_values) + { + if (pstring == pbuf.data) + { + /* + * Copy textual representation to portal context. + */ + params->params[paramno].textValue = + pstrdup(pstring); + } + else + { + /* Reuse the result of encoding conversion for it */ + params->params[paramno].textValue = pstring; + } + } + else + { + /* Free result of encoding conversion */ + if (pstring != pbuf.data) + pfree(pstring); + } + } } else if (pformat == 1) /* binary mode */ { @@ -1835,6 +1871,22 @@ exec_bind_message(StringInfo input_message) (errcode(ERRCODE_INVALID_BINARY_REPRESENTATION), errmsg("incorrect binary data format in bind parameter %d", paramno + 1))); + + /* + * Compute textual representation for further logging. We waste + * some time and memory here, maybe one day we could skip + * certain types like built-in primitives, which are safe to get + * it calculated later in an aborted xact. + */ + if (!isNull && need_text_values) + { + Oid typoutput; + bool typisvarlena; + + getTypeOutputInfo(ptype, &typoutput, &typisvarlena); + params->params[paramno].textValue = + OidOutputFunctionCall(typoutput, pval); + } } else { @@ -1859,10 +1911,22 @@ exec_bind_message(StringInfo input_message) params->params[paramno].pflags = PARAM_FLAG_CONST; params->params[paramno].ptype = ptype; } + + /* + * now we can safely set it, as we have textValue populated + * for all non-null parameters + */ + params->hasTextValues = need_text_values; } else params = NULL; + /* + * Set portal parameters early for them to get logged if an error happens + * on planning stage + */ + portal->portalParams = params; + /* Done storing stuff in portal's context */ MemoryContextSwitchTo(oldContext); @@ -1943,6 +2007,7 @@ exec_bind_message(StringInfo input_message) if (save_log_statement_stats) ShowUsage("BIND MESSAGE STATISTICS"); + current_top_portal = NULL; debug_query_string = NULL; } @@ -1978,7 +2043,6 @@ exec_execute_message(const char *portal_name, long max_rows) ereport(ERROR, (errcode(ERRCODE_UNDEFINED_CURSOR), errmsg("portal \"%s\" does not exist", portal_name))); - /* * If the original query was a null string, just return * EmptyQueryResponse. @@ -2000,26 +2064,30 @@ exec_execute_message(const char *portal_name, long max_rows) */ if (is_xact_command) { + portalParams = portal->portalParams; + sourceText = pstrdup(portal->sourceText); if (portal->prepStmtName) prepStmtName = pstrdup(portal->prepStmtName); else prepStmtName = ""; - - /* - * An xact command shouldn't have any parameters, which is a good - * thing because they wouldn't be around after finish_xact_command. - */ - portalParams = NULL; } else { + /* + * We do it for non-xact commands only, as an xact command + * 1) shouldn't have any parameters to log; + * 2) may have the portal dropped early. + */ + Assert(current_top_portal == NULL); + current_top_portal = portal; + portalParams = NULL; + sourceText = portal->sourceText; if (portal->prepStmtName) prepStmtName = portal->prepStmtName; else prepStmtName = ""; - portalParams = portal->portalParams; } /* @@ -2160,13 +2228,14 @@ exec_execute_message(const char *portal_name, long max_rows) *portal_name ? portal_name : "", sourceText), errhidestmt(true), - errdetail_params(portalParams))); + errdetail_params(current_top_portal->portalParams))); break; } if (save_log_statement_stats) ShowUsage("EXECUTE MESSAGE STATISTICS"); + current_top_portal = NULL; debug_query_string = NULL; } @@ -2306,61 +2375,18 @@ errdetail_execute(List *raw_parsetree_list) static int errdetail_params(ParamListInfo params) { - /* We mustn't call user-defined I/O functions when in an aborted xact */ - if (params && params->numParams > 0 && !IsAbortedTransactionBlockState()) - { - StringInfoData param_str; - MemoryContext oldcontext; - - /* This code doesn't support dynamic param lists */ - Assert(params->paramFetch == NULL); - - /* Make sure any trash is generated in MessageContext */ - oldcontext = MemoryContextSwitchTo(MessageContext); - - initStringInfo(¶m_str); - - for (int paramno = 0; paramno < params->numParams; paramno++) - { - ParamExternData *prm = ¶ms->params[paramno]; - Oid typoutput; - bool typisvarlena; - char *pstring; - char *p; - - appendStringInfo(¶m_str, "%s$%d = ", - paramno > 0 ? ", " : "", - paramno + 1); - - if (prm->isnull || !OidIsValid(prm->ptype)) - { - appendStringInfoString(¶m_str, "NULL"); - continue; - } - - getTypeOutputInfo(prm->ptype, &typoutput, &typisvarlena); - - pstring = OidOutputFunctionCall(typoutput, prm->value); + /* Make sure any trash is generated in MessageContext */ + MemoryContext oldcontext = MemoryContextSwitchTo(MessageContext); + char *params_message = get_portal_bind_parameters(params); - appendStringInfoCharMacro(¶m_str, '\''); - for (p = pstring; *p; p++) - { - if (*p == '\'') /* double single quotes */ - appendStringInfoCharMacro(¶m_str, *p); - appendStringInfoCharMacro(¶m_str, *p); - } - appendStringInfoCharMacro(¶m_str, '\''); - - pfree(pstring); - } - - errdetail("parameters: %s", param_str.data); - - pfree(param_str.data); - - MemoryContextSwitchTo(oldcontext); + if (params_message) + { + errdetail("parameters: %s", params_message); + pfree(params_message); } + MemoryContextSwitchTo(oldcontext); + return 0; } @@ -2678,6 +2704,89 @@ drop_unnamed_stmt(void) } } +/* + * get_portal_bind_parameters + * Get the string containing parameters data, is used for logging. + * + * Can return NULL if there are no parameters in the portal + * or the portal is not valid, or the text representations of the parameters are + * not available. If returning a non-NULL value, it allocates memory + * for the returned string in the current context, and it's the caller's + * responsibility to pfree() it if needed. + */ +char * +get_portal_bind_parameters(ParamListInfo params) +{ + StringInfoData param_str; + + /* No parameters to format */ + if (!params || params->numParams == 0) + return NULL; + + elog(WARNING, "params->hasTextValues=%d, IsAbortedTransactionBlockState()=%d", + params->hasTextValues && IsAbortedTransactionBlockState()); + /* + * We either need textual representation of parameters pre-calcualted, + * or call potentially user-defined I/O functions to convert internal + * representation into text, which cannot be done in an aborted xact + */ + if (!params->hasTextValues && IsAbortedTransactionBlockState()) + return NULL; + + initStringInfo(¶m_str); + + /* This code doesn't support dynamic param lists */ + Assert(params->paramFetch == NULL); + + for (int paramno = 0; paramno < params->numParams; paramno++) + { + ParamExternData *prm = ¶ms->params[paramno]; + char *pstring; + char *p; + + appendStringInfo(¶m_str, "%s$%d = ", + paramno > 0 ? ", " : "", + paramno + 1); + + if (prm->isnull) + { + appendStringInfoString(¶m_str, "NULL"); + continue; + } + + if (params->hasTextValues) + pstring = prm->textValue; + else + { + Oid typoutput; + bool typisvarlena; + + if (!OidIsValid(prm->ptype)) + { + appendStringInfoString(¶m_str, "UNKNOWN TYPE"); + continue; + } + + getTypeOutputInfo(prm->ptype, &typoutput, &typisvarlena); + pstring = OidOutputFunctionCall(typoutput, prm->value); + } + + appendStringInfoCharMacro(¶m_str, '\''); + for (p = pstring; *p; p++) + { + if (*p == '\'') /* double single quotes */ + appendStringInfoCharMacro(¶m_str, *p); + appendStringInfoCharMacro(¶m_str, *p); + } + appendStringInfoCharMacro(¶m_str, '\''); + + if (!params->hasTextValues) + pfree(pstring); + } + + return param_str.data; +} + /* -------------------------------- * signal handler routines used in PostgresMain() @@ -4031,10 +4140,11 @@ PostgresMain(int argc, char *argv[], EmitErrorReport(); /* - * Make sure debug_query_string gets reset before we possibly clobber - * the storage it points at. + * Make sure these get reset before we possibly clobber + * the storages they point at. */ debug_query_string = NULL; + current_top_portal = NULL; /* * Abort the current transaction in order to recover. diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c index 8b4720e..e18d9e5 100644 --- a/src/backend/utils/error/elog.c +++ b/src/backend/utils/error/elog.c @@ -76,6 +76,7 @@ #include "tcop/tcopprot.h" #include "utils/guc.h" #include "utils/memutils.h" +#include "utils/portal.h" #include "utils/ps_status.h" @@ -344,6 +345,7 @@ errstart(int elevel, const char *filename, int lineno, { error_context_stack = NULL; debug_query_string = NULL; + current_top_portal = NULL; } } if (++errordata_stack_depth >= ERRORDATA_STACK_SIZE) @@ -2788,6 +2790,18 @@ write_csvlog(ErrorData *edata) if (print_stmt && edata->cursorpos > 0) appendStringInfo(&buf, "%d", edata->cursorpos); appendStringInfoChar(&buf, ','); + if (print_stmt && log_parameters_on_error + && PortalIsValid(current_top_portal)) + { + char *param_values = + get_portal_bind_parameters(current_top_portal->portalParams); + if (param_values != NULL) + { + appendCSVLiteral(&buf, param_values); + pfree(param_values); + } + } + appendStringInfoChar(&buf, ','); /* file error location */ if (Log_error_verbosity >= PGERROR_VERBOSE) @@ -2944,6 +2958,18 @@ send_message_to_server_log(ErrorData *edata) appendStringInfoString(&buf, _("STATEMENT: ")); append_with_tabs(&buf, debug_query_string); appendStringInfoChar(&buf, '\n'); + + if (log_parameters_on_error && PortalIsValid(current_top_portal)) + { + char *param_values = + get_portal_bind_parameters(current_top_portal->portalParams); + if (param_values != NULL) + { + log_line_prefix(&buf, edata); + appendStringInfo(&buf, _("PARAMETERS: %s\n"), param_values); + pfree(param_values); + } + } } #ifdef HAVE_SYSLOG diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c index c216ed0..892ca77 100644 --- a/src/backend/utils/misc/guc.c +++ b/src/backend/utils/misc/guc.c @@ -465,6 +465,7 @@ extern const struct config_enum_entry dynamic_shared_memory_options[]; * GUC option variables that are exported from this module */ bool log_duration = false; +bool log_parameters_on_error = false; bool Debug_print_plan = false; bool Debug_print_parse = false; bool Debug_print_rewritten = false; @@ -1242,6 +1243,15 @@ static struct config_bool ConfigureNamesBool[] = NULL, NULL, NULL }, { + {"log_parameters_on_error", PGC_SUSET, LOGGING_WHAT, + gettext_noop("Logs bind parameters of the logged statements where possible."), + NULL + }, + &log_parameters_on_error, + false, + NULL, NULL, NULL + }, + { {"debug_print_parse", PGC_USERSET, LOGGING_WHAT, gettext_noop("Logs each query's parse tree."), NULL diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample index a21865a..b2865d8 100644 --- a/src/backend/utils/misc/postgresql.conf.sample +++ b/src/backend/utils/misc/postgresql.conf.sample @@ -526,6 +526,7 @@ # e.g. '<%u%%%d> ' #log_lock_waits = off # log lock waits >= deadlock_timeout #log_statement = 'none' # none, ddl, mod, all +#log_parameters_on_error = off # on error log statements with bind parameters #log_replication_commands = off #log_temp_files = -1 # log temporary files equal or larger # than the specified size in kilobytes; diff --git a/src/include/nodes/params.h b/src/include/nodes/params.h index ded3b3a..3b850a4 100644 --- a/src/include/nodes/params.h +++ b/src/include/nodes/params.h @@ -93,6 +93,7 @@ typedef struct ParamExternData bool isnull; /* is it NULL? */ uint16 pflags; /* flag bits, see above */ Oid ptype; /* parameter's datatype, or 0 */ + char *textValue; /* textual representation for debug purposes */ } ParamExternData; typedef struct ParamListInfoData *ParamListInfo; @@ -116,6 +117,8 @@ typedef struct ParamListInfoData ParserSetupHook parserSetup; /* parser setup hook */ void *parserSetupArg; int numParams; /* nominal/maximum # of Params represented */ + bool hasTextValues; /* whether textValue for all non-null + params is populated */ /* * params[] may be of length zero if paramFetch is supplied; otherwise it diff --git a/src/include/tcop/tcopprot.h b/src/include/tcop/tcopprot.h index b367838..2cfa2ac 100644 --- a/src/include/tcop/tcopprot.h +++ b/src/include/tcop/tcopprot.h @@ -24,6 +24,7 @@ #include "nodes/plannodes.h" #include "storage/procsignal.h" #include "utils/guc.h" +#include "utils/portal.h" #include "utils/queryenvironment.h" @@ -32,6 +33,8 @@ extern CommandDest whereToSendOutput; extern PGDLLIMPORT const char *debug_query_string; +extern PGDLLIMPORT Portal current_top_portal; + extern int max_stack_depth; extern int PostAuthDelay; @@ -83,6 +86,7 @@ extern long get_stack_depth_rlimit(void); extern void ResetUsage(void); extern void ShowUsage(const char *title); extern int check_log_duration(char *msec_str, bool was_logged); +extern char *get_portal_bind_parameters(ParamListInfo params); extern void set_debug_options(int debug_flag, GucContext context, GucSource source); extern bool set_plan_disabling_options(const char *arg, diff --git a/src/include/utils/guc.h b/src/include/utils/guc.h index c07e7b9..1034fc2 100644 --- a/src/include/utils/guc.h +++ b/src/include/utils/guc.h @@ -232,6 +232,7 @@ typedef enum /* GUC vars that are actually declared in guc.c, rather than elsewhere */ extern bool log_duration; +extern bool log_parameters_on_error; extern bool Debug_print_plan; extern bool Debug_print_parse; extern bool Debug_print_rewritten; --------------E93AB7656B27F670EFACCBF7--