pg.ddx.io pgsql-hackers@postgresql.org mailing list archive help / color / mirror / Atom feed From: Alexey Bashtanov <bashtanov@imap.cc>
To: Peter Eisentraut <peter.eisentraut@2ndquadrant.com>
To: PostgreSQL Hackers <pgsql-hackers@postgresql.org>
Subject: Re: log bind parameter values on error
Date: Mon, 28 Jan 2019 00:15:51 +0000
Message-ID: <ce9cd06a-ebb4-7978-ef2e-52a4d94d4fc4@imap.cc> (raw )
In-Reply-To: <96007f6e-1e42-e454-9db4-e7842e137508@2ndquadrant.com >
References: <0146a67b-a22a-0519-9082-bc29756b93a2@imap.cc >
<c4891f99-8385-5c31-1aac-e226356ec964@2ndquadrant.com >
<ad08f6a3-e38c-f851-a5a2-0bf68d1d7f72@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 >
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 <unnamed>: 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
log_min_duration_statement=-1:
feature branch, log_parameters_on_error=off:
NPARAMS=0 PARAM_LENGTH=0 NRUNS=100000 TIME=5.455950s
NPARAMS=10000 PARAM_LENGTH=1 NRUNS=1000 TIME=8.708911s
NPARAMS=1000 PARAM_LENGTH=1000 NRUNS=1000 TIME=9.266428s
NPARAMS=100 PARAM_LENGTH=10000 NRUNS=1000 TIME=5.949109s
NPARAMS=10 PARAM_LENGTH=100000 NRUNS=1000 TIME=5.086381s
NPARAMS=1 PARAM_LENGTH=1000000 NRUNS=1000 TIME=5.301780s
NPARAMS=1 PARAM_LENGTH=100000000 NRUNS=10 TIME=6.763883s
feature branch, log_parameters_on_error=on:
NPARAMS=0 PARAM_LENGTH=0 NRUNS=100000 TIME=5.238674s
NPARAMS=10000 PARAM_LENGTH=1 NRUNS=1000 TIME=8.927818s
NPARAMS=1000 PARAM_LENGTH=1000 NRUNS=1000 TIME=7.960569s
NPARAMS=100 PARAM_LENGTH=10000 NRUNS=1000 TIME=6.398343s
NPARAMS=10 PARAM_LENGTH=100000 NRUNS=1000 TIME=5.293962s
NPARAMS=1 PARAM_LENGTH=1000000 NRUNS=1000 TIME=5.519607s
NPARAMS=1 PARAM_LENGTH=100000000 NRUNS=10 TIME=7.236014s
master:
NPARAMS=0 PARAM_LENGTH=0 NRUNS=100000 TIME=5.600735s
NPARAMS=10000 PARAM_LENGTH=1 NRUNS=1000 TIME=11.478406s
NPARAMS=1000 PARAM_LENGTH=1000 NRUNS=1000 TIME=9.701054s
NPARAMS=100 PARAM_LENGTH=10000 NRUNS=1000 TIME=6.352961s
NPARAMS=10 PARAM_LENGTH=100000 NRUNS=1000 TIME=5.153303s
NPARAMS=1 PARAM_LENGTH=1000000 NRUNS=1000 TIME=5.456964s
NPARAMS=1 PARAM_LENGTH=100000000 NRUNS=10 TIME=8.887792s
log_min_duration_statement=0:
feature branch, log_parameters_on_error=off:
NPARAMS=0 PARAM_LENGTH=0 NRUNS=100000 TIME=7.147057s
NPARAMS=10000 PARAM_LENGTH=1 NRUNS=1000 TIME=18.707077s
NPARAMS=1000 PARAM_LENGTH=1000 NRUNS=1000 TIME=29.906513s
NPARAMS=100 PARAM_LENGTH=10000 NRUNS=1000 TIME=27.352489s
NPARAMS=10 PARAM_LENGTH=100000 NRUNS=1000 TIME=25.950780s
NPARAMS=1 PARAM_LENGTH=1000000 NRUNS=1000 TIME=27.183019s
NPARAMS=1 PARAM_LENGTH=100000000 NRUNS=10 TIME=35.088423s
feature branch, log_parameters_on_error=on:
NPARAMS=0 PARAM_LENGTH=0 NRUNS=100000 TIME=6.422041s
NPARAMS=10000 PARAM_LENGTH=1 NRUNS=1000 TIME=14.653954s
NPARAMS=1000 PARAM_LENGTH=1000 NRUNS=1000 TIME=28.478012s
NPARAMS=100 PARAM_LENGTH=10000 NRUNS=1000 TIME=26.297368s
NPARAMS=10 PARAM_LENGTH=100000 NRUNS=1000 TIME=26.128964s
NPARAMS=1 PARAM_LENGTH=1000000 NRUNS=1000 TIME=26.503844s
NPARAMS=1 PARAM_LENGTH=100000000 NRUNS=10 TIME=35.903540s
master:
NPARAMS=0 PARAM_LENGTH=0 NRUNS=100000 TIME=7.222387s
NPARAMS=10000 PARAM_LENGTH=1 NRUNS=1000 TIME=18.778810s
NPARAMS=1000 PARAM_LENGTH=1000 NRUNS=1000 TIME=29.372025s
NPARAMS=100 PARAM_LENGTH=10000 NRUNS=1000 TIME=27.991586s
NPARAMS=10 PARAM_LENGTH=100000 NRUNS=1000 TIME=26.011506s
NPARAMS=1 PARAM_LENGTH=1000000 NRUNS=1000 TIME=26.229376s
NPARAMS=1 PARAM_LENGTH=100000000 NRUNS=10 TIME=36.476215s
Attachments:
[text/x-java] JDBCTest.java (2.3K, ../ce9cd06a-ebb4-7978-ef2e-52a4d94d4fc4@imap.cc/2-JDBCTest.java)
download | inline:
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<String> rm = (ResultSet resultSet, int i) -> resultSet.getString(1);
long startTime = System.nanoTime();
for (int i = 0; i < nruns; i++) {
List<String> 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);
}
}
[text/plain] params_benchmark.txt (2.6K, ../ce9cd06a-ebb4-7978-ef2e-52a4d94d4fc4@imap.cc/3-params_benchmark.txt)
download | inline:
log_min_duration_statement=-1:
feature branch, log_parameters_on_error=off:
NPARAMS=0 PARAM_LENGTH=0 NRUNS=100000 TIME=5.455950s
NPARAMS=10000 PARAM_LENGTH=1 NRUNS=1000 TIME=8.708911s
NPARAMS=1000 PARAM_LENGTH=1000 NRUNS=1000 TIME=9.266428s
NPARAMS=100 PARAM_LENGTH=10000 NRUNS=1000 TIME=5.949109s
NPARAMS=10 PARAM_LENGTH=100000 NRUNS=1000 TIME=5.086381s
NPARAMS=1 PARAM_LENGTH=1000000 NRUNS=1000 TIME=5.301780s
NPARAMS=1 PARAM_LENGTH=100000000 NRUNS=10 TIME=6.763883s
feature branch, log_parameters_on_error=on:
NPARAMS=0 PARAM_LENGTH=0 NRUNS=100000 TIME=5.238674s
NPARAMS=10000 PARAM_LENGTH=1 NRUNS=1000 TIME=8.927818s
NPARAMS=1000 PARAM_LENGTH=1000 NRUNS=1000 TIME=7.960569s
NPARAMS=100 PARAM_LENGTH=10000 NRUNS=1000 TIME=6.398343s
NPARAMS=10 PARAM_LENGTH=100000 NRUNS=1000 TIME=5.293962s
NPARAMS=1 PARAM_LENGTH=1000000 NRUNS=1000 TIME=5.519607s
NPARAMS=1 PARAM_LENGTH=100000000 NRUNS=10 TIME=7.236014s
master:
NPARAMS=0 PARAM_LENGTH=0 NRUNS=100000 TIME=5.600735s
NPARAMS=10000 PARAM_LENGTH=1 NRUNS=1000 TIME=11.478406s
NPARAMS=1000 PARAM_LENGTH=1000 NRUNS=1000 TIME=9.701054s
NPARAMS=100 PARAM_LENGTH=10000 NRUNS=1000 TIME=6.352961s
NPARAMS=10 PARAM_LENGTH=100000 NRUNS=1000 TIME=5.153303s
NPARAMS=1 PARAM_LENGTH=1000000 NRUNS=1000 TIME=5.456964s
NPARAMS=1 PARAM_LENGTH=100000000 NRUNS=10 TIME=8.887792s
log_min_duration_statement=0:
feature branch, log_parameters_on_error=off:
NPARAMS=0 PARAM_LENGTH=0 NRUNS=100000 TIME=7.147057s
NPARAMS=10000 PARAM_LENGTH=1 NRUNS=1000 TIME=18.707077s
NPARAMS=1000 PARAM_LENGTH=1000 NRUNS=1000 TIME=29.906513s
NPARAMS=100 PARAM_LENGTH=10000 NRUNS=1000 TIME=27.352489s
NPARAMS=10 PARAM_LENGTH=100000 NRUNS=1000 TIME=25.950780s
NPARAMS=1 PARAM_LENGTH=1000000 NRUNS=1000 TIME=27.183019s
NPARAMS=1 PARAM_LENGTH=100000000 NRUNS=10 TIME=35.088423s
feature branch, log_parameters_on_error=on:
NPARAMS=0 PARAM_LENGTH=0 NRUNS=100000 TIME=6.422041s
NPARAMS=10000 PARAM_LENGTH=1 NRUNS=1000 TIME=14.653954s
NPARAMS=1000 PARAM_LENGTH=1000 NRUNS=1000 TIME=28.478012s
NPARAMS=100 PARAM_LENGTH=10000 NRUNS=1000 TIME=26.297368s
NPARAMS=10 PARAM_LENGTH=100000 NRUNS=1000 TIME=26.128964s
NPARAMS=1 PARAM_LENGTH=1000000 NRUNS=1000 TIME=26.503844s
NPARAMS=1 PARAM_LENGTH=100000000 NRUNS=10 TIME=35.903540s
master:
NPARAMS=0 PARAM_LENGTH=0 NRUNS=100000 TIME=7.222387s
NPARAMS=10000 PARAM_LENGTH=1 NRUNS=1000 TIME=18.778810s
NPARAMS=1000 PARAM_LENGTH=1000 NRUNS=1000 TIME=29.372025s
NPARAMS=100 PARAM_LENGTH=10000 NRUNS=1000 TIME=27.991586s
NPARAMS=10 PARAM_LENGTH=100000 NRUNS=1000 TIME=26.011506s
NPARAMS=1 PARAM_LENGTH=1000000 NRUNS=1000 TIME=26.229376s
NPARAMS=1 PARAM_LENGTH=100000000 NRUNS=10 TIME=36.476215s
[text/x-patch] log_parameters_v005.patch (19.1K, ../ce9cd06a-ebb4-7978-ef2e-52a4d94d4fc4@imap.cc/4-log_parameters_v005.patch)
download | inline diff:
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 '
</listitem>
</varlistentry>
+ <varlistentry id="guc-log-parameters-on-error" xreflabel="log_parameters_on_error">
+ <term><varname>log_parameters_on_error</varname> (<type>boolean</type>)
+ <indexterm>
+ <primary><varname>log_parameters_on_error</varname> configuration parameter</primary>
+ </indexterm>
+ </term>
+ <listitem>
+ <para>
+ 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
+ <literal>off</literal>. Only superusers can change this setting.
+ </para>
+ </listitem>
+ </varlistentry>
+
<varlistentry id="guc-log-statement" xreflabel="log_statement">
<term><varname>log_statement</varname> (<type>enum</type>)
<indexterm>
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 = "<unnamed>";
-
- /*
- * 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 = "<unnamed>";
- 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;
view thread (70+ messages) latest in thread
Message-ID: <ce9cd06a-ebb4-7978-ef2e-52a4d94d4fc4@imap.cc>
Permalink: ../ce9cd06a-ebb4-7978-ef2e-52a4d94d4fc4@imap.cc/
Also on: postgresql.org/message-id/ce9cd06a-ebb4-7978-ef2e-52a4d94d4fc4@imap.cc
copy link · copy postgr.es · copy git am
reply 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-hackers@postgresql.org
Cc: bashtanov@imap.cc, peter.eisentraut@2ndquadrant.com
Subject: Re: log bind parameter values on error
In-Reply-To: <ce9cd06a-ebb4-7978-ef2e-52a4d94d4fc4@imap.cc>
* 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