please see attached
sorry, some unintended changes sneaked in, please see the corrected patch
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index f64402a..924a76c 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -6270,6 +6270,23 @@ log_line_prefix = '%m [%p] %q%u@%d/%a ' </listitem> </varlistentry> + <varlistentry id="guc-log-parameters" xreflabel="log_parameters"> + <term><varname>log_parameters</varname> (<type>boolean</type>) + <indexterm> + <primary><varname>log_parameters</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 de41588..195e3c5 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 0c0891b..1f81fba 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; @@ -183,7 +189,7 @@ static void forbidden_in_wal_sender(char firstchar); static List *pg_rewrite_query(Query *query); static bool check_log_statement(List *stmt_list); static int errdetail_execute(List *raw_parsetree_list); -static int errdetail_params(ParamListInfo params); +static int errdetail_params(Portal portal); static int errdetail_abort(void); static int errdetail_recovery_conflict(void); static void start_xact_command(void); @@ -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; + 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); @@ -1936,13 +2000,14 @@ exec_bind_message(StringInfo input_message) *portal_name ? portal_name : "", psrc->query_string), errhidestmt(true), - errdetail_params(params))); + errdetail_params(portal))); break; } if (save_log_statement_stats) ShowUsage("BIND MESSAGE STATISTICS"); + current_top_portal = NULL; debug_query_string = NULL; } @@ -1961,7 +2026,6 @@ exec_execute_message(const char *portal_name, long max_rows) char completionTag[COMPLETION_TAG_BUFSIZE]; const char *sourceText; const char *prepStmtName; - ParamListInfo portalParams; bool save_log_statement_stats = log_statement_stats; bool is_xact_command; bool execute_is_fetch; @@ -1978,7 +2042,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. @@ -2005,21 +2068,22 @@ exec_execute_message(const char *portal_name, long max_rows) 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; + sourceText = portal->sourceText; if (portal->prepStmtName) prepStmtName = portal->prepStmtName; else prepStmtName = "<unnamed>"; - portalParams = portal->portalParams; } /* @@ -2071,7 +2135,7 @@ exec_execute_message(const char *portal_name, long max_rows) *portal_name ? portal_name : "", sourceText), errhidestmt(true), - errdetail_params(portalParams))); + errdetail_params(portal))); was_logged = true; } @@ -2160,13 +2224,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))); break; } if (save_log_statement_stats) ShowUsage("EXECUTE MESSAGE STATISTICS"); + current_top_portal = NULL; debug_query_string = NULL; } @@ -2304,63 +2369,20 @@ errdetail_execute(List *raw_parsetree_list) * Add an errdetail() line showing bind-parameter data, if available. */ static int -errdetail_params(ParamListInfo params) +errdetail_params(Portal portal) { - /* 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); - - 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); + /* Make sure any trash is generated in MessageContext */ + MemoryContext oldcontext = MemoryContextSwitchTo(MessageContext); + char *params_message = get_portal_bind_parameters(portal); - MemoryContextSwitchTo(oldcontext); + if (params_message) + { + errdetail("parameters: %s", params_message); + pfree(params_message); } + MemoryContextSwitchTo(oldcontext); + return 0; } @@ -2678,6 +2700,94 @@ 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(Portal portal) +{ + ParamListInfo params; + StringInfoData param_str; + + /* Fail if no current portal */ + if (!PortalIsValid(portal)) + return NULL; + + params = portal->portalParams; + + /* No parameters to format */ + if (!params || params->numParams == 0) + return NULL; + + /* + * 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 +4141,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..6f4ab5a 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,16 @@ write_csvlog(ErrorData *edata) if (print_stmt && edata->cursorpos > 0) appendStringInfo(&buf, "%d", edata->cursorpos); appendStringInfoChar(&buf, ','); + if (print_stmt) + { + char *param_values = get_portal_bind_parameters(current_top_portal); + if (param_values != NULL) + { + appendCSVLiteral(&buf, param_values); + pfree(param_values); + } + } + appendStringInfoChar(&buf, ','); /* file error location */ if (Log_error_verbosity >= PGERROR_VERBOSE) @@ -2944,6 +2956,17 @@ send_message_to_server_log(ErrorData *edata) appendStringInfoString(&buf, _("STATEMENT: ")); append_with_tabs(&buf, debug_query_string); appendStringInfoChar(&buf, '\n'); + + if (log_parameters) + { + char *param_values = get_portal_bind_parameters(current_top_portal); + 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 7eda7fd..f072741 100644 --- a/src/backend/utils/misc/guc.c +++ b/src/backend/utils/misc/guc.c @@ -464,6 +464,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 = false; bool Debug_print_plan = false; bool Debug_print_parse = false; bool Debug_print_rewritten = false; @@ -1235,6 +1236,15 @@ static struct config_bool ConfigureNamesBool[] = NULL, NULL, NULL }, { + {"log_parameters", PGC_SUSET, LOGGING_WHAT, + gettext_noop("Logs bind parameters of the logged statements where possible."), + NULL + }, + &log_parameters, + 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 f7c1dee..6d8bdc0 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 = off # 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..c96ea32 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(Portal portal); 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..82e9a04 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; extern bool Debug_print_plan; extern bool Debug_print_parse; extern bool Debug_print_rewritten;