Log query parameters for terminated execute
Hello all
We already have feature to logging query parameters. If we use log_statement = 'all' we write parameters before execution and all is fine here. If we use log_min_duration_statement statement is logged obviously after execution, but currently we have no parameters if query was terminated by statement_timeout, lock_timeout or by pg_terminate_backend.
I would like have parameters in logs at least for such three cases.
Simple way achieve this is just add errdetail_params to such ereport as in attached patch.
Another way is add something like printing global variable debug_query_string in send_message_to_server_log (src/backend/utils/error/elog.c). But i have no good idea how print ParamListInfo correctly. We can not use OidOutputFunctionCall in all cases, right?
Another small question is why errdetail_params uses errdetail instead errdetail_log? We assume that the user wants to get their own parameters back (if he set client_min_messages to LOG)?
Any feedback is strongly appreciated. Thank you!
regards, Sergei
Attachments:
naive_log_execute_parameters.patchtext/x-diff; name=naive_log_execute_parameters.patchDownload
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index f413395..ef6877e 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -171,6 +171,9 @@ static ProcSignalReason RecoveryConflictReason;
static MemoryContext row_description_context = NULL;
static StringInfoData row_description_buf;
+/* current portal parameters */
+static ParamListInfo debug_query_params = NULL;
+
/* ----------------------------------------------------------------
* decls for routines only used in this file
* ----------------------------------------------------------------
@@ -183,7 +186,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_log_params(ParamListInfo params);
static int errdetail_abort(void);
static int errdetail_recovery_conflict(void);
static void start_xact_command(void);
@@ -1850,7 +1853,7 @@ exec_bind_message(StringInfo input_message)
*portal_name ? portal_name : "",
psrc->query_string),
errhidestmt(true),
- errdetail_params(params)));
+ errdetail_log_params(params)));
break;
}
@@ -1934,6 +1937,7 @@ exec_execute_message(const char *portal_name, long max_rows)
else
prepStmtName = "<unnamed>";
portalParams = portal->portalParams;
+ debug_query_params = portalParams;
}
/*
@@ -1985,7 +1989,7 @@ exec_execute_message(const char *portal_name, long max_rows)
*portal_name ? portal_name : "",
sourceText),
errhidestmt(true),
- errdetail_params(portalParams)));
+ errdetail_log_params(portalParams)));
was_logged = true;
}
@@ -2074,7 +2078,7 @@ exec_execute_message(const char *portal_name, long max_rows)
*portal_name ? portal_name : "",
sourceText),
errhidestmt(true),
- errdetail_params(portalParams)));
+ errdetail_log_params(portalParams)));
break;
}
@@ -2082,6 +2086,7 @@ exec_execute_message(const char *portal_name, long max_rows)
ShowUsage("EXECUTE MESSAGE STATISTICS");
debug_query_string = NULL;
+ debug_query_params = NULL;
}
/*
@@ -2200,12 +2205,12 @@ errdetail_execute(List *raw_parsetree_list)
}
/*
- * errdetail_params
+ * errdetail_log_params
*
- * Add an errdetail() line showing bind-parameter data, if available.
+ * Add an errdetail_log() line showing bind-parameter data, if available.
*/
static int
-errdetail_params(ParamListInfo params)
+errdetail_log_params(ParamListInfo params)
{
/* We mustn't call user-defined I/O functions when in an aborted xact */
if (params && params->numParams > 0 && !IsAbortedTransactionBlockState())
@@ -2256,7 +2261,7 @@ errdetail_params(ParamListInfo params)
pfree(pstring);
}
- errdetail("parameters: %s", param_str.data);
+ errdetail_log("parameters: %s", param_str.data);
pfree(param_str.data);
@@ -2925,7 +2930,8 @@ ProcessInterrupts(void)
else
ereport(FATAL,
(errcode(ERRCODE_ADMIN_SHUTDOWN),
- errmsg("terminating connection due to administrator command")));
+ errmsg("terminating connection due to administrator command"),
+ errdetail_log_params(debug_query_params)));
}
if (ClientConnectionLost)
{
@@ -3001,14 +3007,16 @@ ProcessInterrupts(void)
LockErrorCleanup();
ereport(ERROR,
(errcode(ERRCODE_LOCK_NOT_AVAILABLE),
- errmsg("canceling statement due to lock timeout")));
+ errmsg("canceling statement due to lock timeout"),
+ errdetail_log_params(debug_query_params)));
}
if (stmt_timeout_occurred)
{
LockErrorCleanup();
ereport(ERROR,
(errcode(ERRCODE_QUERY_CANCELED),
- errmsg("canceling statement due to statement timeout")));
+ errmsg("canceling statement due to statement timeout"),
+ errdetail_log_params(debug_query_params)));
}
if (IsAutoVacuumWorkerProcess())
{
@@ -3932,6 +3940,7 @@ PostgresMain(int argc, char *argv[],
* the storage it points at.
*/
debug_query_string = NULL;
+ debug_query_params = NULL;
/*
* Abort the current transaction in order to recover.
2018-06-23 21:54 GMT+02:00 Sergei Kornilov <sk@zsrv.org>:
Hello all
We already have feature to logging query parameters. If we use
log_statement = 'all' we write parameters before execution and all is fine
here. If we use log_min_duration_statement statement is logged obviously
after execution, but currently we have no parameters if query was
terminated by statement_timeout, lock_timeout or by pg_terminate_backend.I would like have parameters in logs at least for such three cases.
It is good idea - more times I would to see these values
Regards
Pavel
Show quoted text
Simple way achieve this is just add errdetail_params to such ereport as in
attached patch.
Another way is add something like printing global variable
debug_query_string in send_message_to_server_log
(src/backend/utils/error/elog.c). But i have no good idea how print
ParamListInfo correctly. We can not use OidOutputFunctionCall in all cases,
right?Another small question is why errdetail_params uses errdetail instead
errdetail_log? We assume that the user wants to get their own parameters
back (if he set client_min_messages to LOG)?Any feedback is strongly appreciated. Thank you!
regards, Sergei
On Sun, Jun 24, 2018 at 1:08 AM, Pavel Stehule <pavel.stehule@gmail.com>
wrote:
2018-06-23 21:54 GMT+02:00 Sergei Kornilov <sk@zsrv.org>:
Hello all
We already have feature to logging query parameters. If we use
log_statement = 'all' we write parameters before execution and all is fine
here. If we use log_min_duration_statement statement is logged obviously
after execution, but currently we have no parameters if query was
terminated by statement_timeout, lock_timeout or by pg_terminate_backend.I would like have parameters in logs at least for such three cases.
It is good idea - more times I would to see these values
Regards
Pavel
Simple way achieve this is just add errdetail_params to such ereport as
in attached patch.
Another way is add something like printing global variable
debug_query_string in send_message_to_server_log
(src/backend/utils/error/elog.c). But i have no good idea how print
ParamListInfo correctly. We can not use OidOutputFunctionCall in all cases,
right?Another small question is why errdetail_params uses errdetail instead
errdetail_log? We assume that the user wants to get their own parameters
back (if he set client_min_messages to LOG)?Any feedback is strongly appreciated. Thank you!
regards, Sergei
I have reviewed and tested the patch here are my findings about the patch.
Patch applied successfully on master branch
"04269320aed30d3e37c10ae77775954eae234d45". There is no compilation issue
with the patch.
statement_timeout: For this I wrote a simple LibPq program to insert into
table. The results are random, some times it logs the param and some time
does not; with the same program. After digging a bit I found that if you
execute just after starting the server it does not log the param and start
logging after subsequent calls. Here is the log
2018-07-23 14:12:13.530 PKT [29165] ERROR: canceling statement due to
statement timeout
2018-07-23 14:12:13.530 PKT [29165] DETAIL: parameters: $1 = '16777216',
$2 = 'Foobar'
2018-07-23 14:12:13.530 PKT [29165] STATEMENT: INSERT INTO tbl_libpq_test
(id, name) VALUES ($1::integer, $2::varchar)
...
2018-07-23 14:13:38.483 PKT [29169] LOG: shutting down
...
2018-07-23 14:13:38.616 PKT [29901] LOG: database system is ready to
accept connections
2018-07-23 14:13:39.848 PKT [29910] ERROR: canceling statement due to
statement timeout
2018-07-23 14:13:39.848 PKT [29910] STATEMENT: INSERT INTO tbl_libpq_test
(id, name) VALUES ($1::integer, $2::varchar)
lock_timeout: For this I a use the same program to insert into table. I
lock the table in other session and try to execute the program. It does not
log any params at all here is the log.
2018-07-23 14:21:19.165 PKT [30006] ERROR: canceling statement due to lock
timeout at character 13
2018-07-23 14:21:19.165 PKT [30006] STATEMENT: INSERT INTO tbl_libpq_test
(id, name) VALUES ($1::integer, $2::varchar)
--
Ibrar Ahmed
Hello
Thank you for review!
Well, i can miss some cases. I'm not sure about overall design of this patch. Is acceptable add errdetail_params to statement_timeout ereport in such way?
After shutdown signal we must be in aborted state, so we mustn't call user-defined I/O functions. (quotation from comment to errdetail_params in src/backend/tcop/postgres.c ). It seems i can not fix it with current design.
ERROR: canceling statement due to lock timeout at character 13
Hm, "at character"? How can we get this message? I found only "canceling statement due to lock timeout" (without "at character") ereport in src/backend/tcop/postgres.c
Maybe try .. catch in parse state, not in execute?
regards, Sergei
On Mon, Jul 23, 2018 at 3:05 PM, Sergei Kornilov <sk@zsrv.org> wrote:
Hello
Thank you for review!
Well, i can miss some cases. I'm not sure about overall design of this
patch. Is acceptable add errdetail_params to statement_timeout ereport in
such way?After shutdown signal we must be in aborted state, so we mustn't call
user-defined I/O functions. (quotation from comment to errdetail_params in
src/backend/tcop/postgres.c ). It seems i can not fix it with current
design.
No its not about calling the function after abort/shutdown. Just start the
server and try to run the program, most of the time you will not get
params.
ERROR: canceling statement due to lock timeout at character 13
Hm, "at character"? How can we get this message? I found only "canceling
statement due to lock timeout" (without "at character") ereport in
src/backend/tcop/postgres.c
Maybe try .. catch in parse state, not in execute?
Its really easy to reproduce, just lock the table form another session and
run a "c" program to insert row in the same table.
regards, Sergei
--
Ibrar Ahmed
The following review has been posted through the commitfest application:
make installcheck-world: not tested
Implements feature: not tested
Spec compliant: not tested
Documentation: not tested
Review submitted
The new status of this patch is: Waiting on Author
Hello!
After shutdown signal we must be in aborted state, so we mustn't call user-defined I/O functions. (quotation from comment to errdetail_params in src/backend/tcop/postgres.c ). It seems i can not fix it with current design.
No its not about calling the function after abort/shutdown. Just start the server and try to run the program, most of the time you will not get params.
ERROR: canceling statement due to lock timeout at character 13
Hm, "at character"? How can we get this message? I found only "canceling statement due to lock timeout" (without "at character") ereport in src/backend/tcop/postgres.c
Maybe try .. catch in parse state, not in execute?Its really easy to reproduce, just lock the table form another session and run a "c" program to insert row in the same table.
So, I was right. We can got "canceling statement due to lock timeout at character 13" only in PARSE state. In parse state we have completely no parameters, we receive parameters only later in BIND message. I can not log data from future.
And initially i did change only EXECUTE. Attached patch with similar change in BIND message, if this design is acceptable.
Please test with logging command tag %i in log_line_prefix. Extended protocol has three different messages, each can be canceled by timeout. But here is completely no parameters in PARSE and i did not change BIND in first patch.
regards, Sergei
Attachments:
log_prepared_stmt_parameters_v2.patchtext/x-diff; name=log_prepared_stmt_parameters_v2.patchDownload
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index f413395..c6a7cb2 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -171,6 +171,9 @@ static ProcSignalReason RecoveryConflictReason;
static MemoryContext row_description_context = NULL;
static StringInfoData row_description_buf;
+/* current portal parameters */
+static ParamListInfo debug_query_params = NULL;
+
/* ----------------------------------------------------------------
* decls for routines only used in this file
* ----------------------------------------------------------------
@@ -183,7 +186,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_log_params(ParamListInfo params);
static int errdetail_abort(void);
static int errdetail_recovery_conflict(void);
static void start_xact_command(void);
@@ -1771,6 +1774,7 @@ exec_bind_message(StringInfo input_message)
params->params[paramno].pflags = PARAM_FLAG_CONST;
params->params[paramno].ptype = ptype;
}
+ debug_query_params = params;
}
else
params = NULL;
@@ -1850,7 +1854,7 @@ exec_bind_message(StringInfo input_message)
*portal_name ? portal_name : "",
psrc->query_string),
errhidestmt(true),
- errdetail_params(params)));
+ errdetail_log_params(params)));
break;
}
@@ -1858,6 +1862,7 @@ exec_bind_message(StringInfo input_message)
ShowUsage("BIND MESSAGE STATISTICS");
debug_query_string = NULL;
+ debug_query_params = NULL;
}
/*
@@ -1934,6 +1939,7 @@ exec_execute_message(const char *portal_name, long max_rows)
else
prepStmtName = "<unnamed>";
portalParams = portal->portalParams;
+ debug_query_params = portalParams;
}
/*
@@ -1985,7 +1991,7 @@ exec_execute_message(const char *portal_name, long max_rows)
*portal_name ? portal_name : "",
sourceText),
errhidestmt(true),
- errdetail_params(portalParams)));
+ errdetail_log_params(portalParams)));
was_logged = true;
}
@@ -2074,7 +2080,7 @@ exec_execute_message(const char *portal_name, long max_rows)
*portal_name ? portal_name : "",
sourceText),
errhidestmt(true),
- errdetail_params(portalParams)));
+ errdetail_log_params(portalParams)));
break;
}
@@ -2082,6 +2088,7 @@ exec_execute_message(const char *portal_name, long max_rows)
ShowUsage("EXECUTE MESSAGE STATISTICS");
debug_query_string = NULL;
+ debug_query_params = NULL;
}
/*
@@ -2200,12 +2207,12 @@ errdetail_execute(List *raw_parsetree_list)
}
/*
- * errdetail_params
+ * errdetail_log_params
*
- * Add an errdetail() line showing bind-parameter data, if available.
+ * Add an errdetail_log() line showing bind-parameter data, if available.
*/
static int
-errdetail_params(ParamListInfo params)
+errdetail_log_params(ParamListInfo params)
{
/* We mustn't call user-defined I/O functions when in an aborted xact */
if (params && params->numParams > 0 && !IsAbortedTransactionBlockState())
@@ -2256,7 +2263,7 @@ errdetail_params(ParamListInfo params)
pfree(pstring);
}
- errdetail("parameters: %s", param_str.data);
+ errdetail_log("parameters: %s", param_str.data);
pfree(param_str.data);
@@ -2925,7 +2932,8 @@ ProcessInterrupts(void)
else
ereport(FATAL,
(errcode(ERRCODE_ADMIN_SHUTDOWN),
- errmsg("terminating connection due to administrator command")));
+ errmsg("terminating connection due to administrator command"),
+ errdetail_log_params(debug_query_params)));
}
if (ClientConnectionLost)
{
@@ -3001,14 +3009,16 @@ ProcessInterrupts(void)
LockErrorCleanup();
ereport(ERROR,
(errcode(ERRCODE_LOCK_NOT_AVAILABLE),
- errmsg("canceling statement due to lock timeout")));
+ errmsg("canceling statement due to lock timeout"),
+ errdetail_log_params(debug_query_params)));
}
if (stmt_timeout_occurred)
{
LockErrorCleanup();
ereport(ERROR,
(errcode(ERRCODE_QUERY_CANCELED),
- errmsg("canceling statement due to statement timeout")));
+ errmsg("canceling statement due to statement timeout"),
+ errdetail_log_params(debug_query_params)));
}
if (IsAutoVacuumWorkerProcess())
{
@@ -3932,6 +3942,7 @@ PostgresMain(int argc, char *argv[],
* the storage it points at.
*/
debug_query_string = NULL;
+ debug_query_params = NULL;
/*
* Abort the current transaction in order to recover.
Sergei Kornilov <sk@zsrv.org> writes:
Please test with logging command tag %i in log_line_prefix. Extended protocol has three different messages, each can be canceled by timeout. But here is completely no parameters in PARSE and i did not change BIND in first patch.
This patch scares me to death. It risks calling user-defined I/O
functions in all sorts of weird places, particularly outside transactions,
or in already-failed transactions, or with no ActiveSnapshot.
Separately from that concern: it appears to result in a substantial
degradation of existing functionality in the places where you did
s/errdetail/errdetail_log/. What was the reason for that?
regards, tom lane
Hello
23.07.2018, 17:08, "Tom Lane" <tgl@sss.pgh.pa.us>:
Sergei Kornilov <sk@zsrv.org> writes:
Please test with logging command tag %i in log_line_prefix. Extended protocol has three different messages, each can be canceled by timeout. But here is completely no parameters in PARSE and i did not change BIND in first patch.
This patch scares me to death. It risks calling user-defined I/O
functions in all sorts of weird places, particularly outside transactions,
or in already-failed transactions, or with no ActiveSnapshot.
This is reason why i start thread with question how do it right way
As i wrote in beginning:
i have no good idea how print ParamListInfo correctly. We can not use OidOutputFunctionCall in all cases, right?
Attached patch is just simple enough to illustrate one possible way.
I can further work with proper design, but i need idea how it should look.
Separately from that concern: it appears to result in a substantial
degradation of existing functionality in the places where you did
s/errdetail/errdetail_log/. What was the reason for that?
This is my second question at thread beginning. Why used errdetail? We assume that the user wants to get their own parameters back (if he set client_min_messages to LOG)?
regards, Sergei