pg.ddx.io pgsql-hackers@postgresql.org mailing list archive help / color / mirror / Atom feed From: Justin Pryzby <pryzby@telsasoft.com>
To: Alvaro Herrera <alvherre@2ndquadrant.com>
Cc: Arthur Zakirov <a.zakirov@postgrespro.ru>
Cc: pgsql-hackers@postgresql.org
Subject: Re: query logging of prepared statements
Date: Thu, 4 Apr 2019 16:26:13 -0500
Message-ID: <20190404212613.GA16096@telsasoft.com> (raw )
In-Reply-To: <20190404182630.GA4305@alvherre.pgsql > <20190404180704.GA31569@alvherre.pgsql >
On Thu, Apr 04, 2019 at 03:07:04PM -0300, Alvaro Herrera wrote:
> which does not look good -- the statement is nowhere to be seen. The commit
> message quotes this as desirable output:
Good catch.
Unnamed statements sent behind the scenes by pqExecParams weren't being logged.
I specifically handled unnamed statements in my v1 patch, and tested that in
20190215145704.GW30291@telsasoft.com, but for some reason dropped that logic in
v2, which was intended to only remove behavior conditional on
log_error_verbosity.
Previous patches also never logged pqPrepare with named prepared statements
(unnamed prepared statements were handled in v1 and SQL PREPARE was handled as
a simple statement).
On Thu, Apr 04, 2019 at 03:26:30PM -0300, Alvaro Herrera wrote:
> With this patch (pretty much equivalent to reinstanting the
> errdetail_execute for that line),
That means the text of the prepared statement is duplicated for each execute,
which is what we're trying to avoid, no ?
Attached patch promotes message to LOG in exec_parse_message. Parse is a
protocol-layer message, and I think it's used by (only) pqPrepare and
pqExecParams.
testlibpq3 now shows:
|LOG: parse <unnamed>: SELECT * FROM test1 WHERE t = $1
|LOG: execute <unnamed>
|DETAIL: parameters: $1 = 'joe''s place'
|LOG: parse <unnamed>: SELECT * FROM test1 WHERE i = $1::int4
|LOG: execute <unnamed>
|DETAIL: parameters: $1 = '2'
Compare unpatched v11.2 , the text of the prepared statement was shown in
"parse" phase rather than in each execute:
|LOG: execute <unnamed>: SELECT * FROM test1 WHERE t = $1
|DETAIL: parameters: $1 = 'joe''s place'
|LOG: execute <unnamed>: SELECT * FROM test1 WHERE i = $1::int4
|DETAIL: parameters: $1 = '2'
Justin
Attachments:
v4-0001-Avoid-repetitive-log-of-PREPARE-during-EXECUTE-of.patch (text/x-diff, 5.2K) download
From 0826f7f90eb8f169244140a22db0bbbcb0d2b269 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <justin@telsasoft.com>
Date: Sat, 9 Feb 2019 19:20:43 -0500
Subject: [PATCH v4] Avoid repetitive log of PREPARE during EXECUTE of prepared
statements
---
src/backend/tcop/postgres.c | 70 ++++++++++++---------------------------------
1 file changed, 18 insertions(+), 52 deletions(-)
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 44a59e1..348343c 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -182,7 +182,6 @@ static int ReadCommand(StringInfo inBuf);
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_abort(void);
static int errdetail_recovery_conflict(void);
@@ -1041,8 +1040,7 @@ exec_simple_query(const char *query_string)
{
ereport(LOG,
(errmsg("statement: %s", query_string),
- errhidestmt(true),
- errdetail_execute(parsetree_list)));
+ errhidestmt(true)));
was_logged = true;
}
@@ -1292,8 +1290,7 @@ exec_simple_query(const char *query_string)
ereport(LOG,
(errmsg("duration: %s ms statement: %s",
msec_str, query_string),
- errhidestmt(true),
- errdetail_execute(parsetree_list)));
+ errhidestmt(true)));
break;
}
@@ -1326,6 +1323,7 @@ exec_parse_message(const char *query_string, /* string to execute */
bool is_named;
bool save_log_statement_stats = log_statement_stats;
char msec_str[32];
+ bool was_logged = false;
/*
* Report query to various monitoring facilities.
@@ -1339,11 +1337,6 @@ exec_parse_message(const char *query_string, /* string to execute */
if (save_log_statement_stats)
ResetUsage();
- ereport(DEBUG2,
- (errmsg("parse %s: %s",
- *stmt_name ? stmt_name : "<unnamed>",
- query_string)));
-
/*
* Start up a transaction command so we can run parse analysis etc. (Note
* that this will normally change current memory context.) Nothing happens
@@ -1404,6 +1397,14 @@ exec_parse_message(const char *query_string, /* string to execute */
Query *query;
bool snapshot_set = false;
+ if (check_log_statement(parsetree_list)) {
+ ereport( LOG, // else log as DEBUG2 ?
+ (errmsg("parse %s: %s",
+ *stmt_name ? stmt_name : "<unnamed>",
+ query_string)));
+ was_logged = true;
+ }
+
raw_parse_tree = linitial_node(RawStmt, parsetree_list);
/*
@@ -1544,7 +1545,7 @@ exec_parse_message(const char *query_string, /* string to execute */
/*
* Emit duration logging if appropriate.
*/
- switch (check_log_duration(msec_str, false))
+ switch (check_log_duration(msec_str, was_logged))
{
case 1:
ereport(LOG,
@@ -1920,12 +1921,11 @@ exec_bind_message(StringInfo input_message)
break;
case 2:
ereport(LOG,
- (errmsg("duration: %s ms bind %s%s%s: %s",
+ (errmsg("duration: %s ms bind %s%s%s",
msec_str,
*stmt_name ? stmt_name : "<unnamed>",
*portal_name ? "/" : "",
- *portal_name ? portal_name : "",
- psrc->query_string),
+ *portal_name ? portal_name : ""),
errhidestmt(true),
errdetail_params(params)));
break;
@@ -2053,14 +2053,13 @@ exec_execute_message(const char *portal_name, long max_rows)
if (check_log_statement(portal->stmts))
{
ereport(LOG,
- (errmsg("%s %s%s%s: %s",
+ (errmsg("%s %s%s%s",
execute_is_fetch ?
_("execute fetch from") :
_("execute"),
prepStmtName,
*portal_name ? "/" : "",
- *portal_name ? portal_name : "",
- sourceText),
+ *portal_name ? portal_name : ""),
errhidestmt(true),
errdetail_params(portalParams)));
was_logged = true;
@@ -2141,15 +2140,14 @@ exec_execute_message(const char *portal_name, long max_rows)
break;
case 2:
ereport(LOG,
- (errmsg("duration: %s ms %s %s%s%s: %s",
+ (errmsg("duration: %s ms %s %s%s%s",
msec_str,
execute_is_fetch ?
_("execute fetch from") :
_("execute"),
prepStmtName,
*portal_name ? "/" : "",
- *portal_name ? portal_name : "",
- sourceText),
+ *portal_name ? portal_name : ""),
errhidestmt(true),
errdetail_params(portalParams)));
break;
@@ -2260,38 +2258,6 @@ check_log_duration(char *msec_str, bool was_logged)
}
/*
- * errdetail_execute
- *
- * Add an errdetail() line showing the query referenced by an EXECUTE, if any.
- * The argument is the raw parsetree list.
- */
-static int
-errdetail_execute(List *raw_parsetree_list)
-{
- ListCell *parsetree_item;
-
- foreach(parsetree_item, raw_parsetree_list)
- {
- RawStmt *parsetree = lfirst_node(RawStmt, parsetree_item);
-
- if (IsA(parsetree->stmt, ExecuteStmt))
- {
- ExecuteStmt *stmt = (ExecuteStmt *) parsetree->stmt;
- PreparedStatement *pstmt;
-
- pstmt = FetchPreparedStatement(stmt->name, false);
- if (pstmt)
- {
- errdetail("prepare: %s", pstmt->plansource->query_string);
- return 0;
- }
- }
- }
-
- return 0;
-}
-
-/*
* errdetail_params
*
* Add an errdetail() line showing bind-parameter data, if available.
--
2.1.4
view thread (16+ messages) latest in thread
Message-ID: <20190404212613.GA16096@telsasoft.com>
Permalink: ../20190404212613.GA16096@telsasoft.com/
Also on: postgresql.org/message-id/20190404212613.GA16096@telsasoft.com
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: pryzby@telsasoft.com, alvherre@2ndquadrant.com, a.zakirov@postgrespro.ru
Subject: Re: query logging of prepared statements
In-Reply-To: <20190404212613.GA16096@telsasoft.com>
* 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