pg.ddx.io pgsql-hackers@postgresql.org mailing list archive help / color / mirror / Atom feed From: Justin Pryzby <pryzby@telsasoft.com>
To: Arthur Zakirov <a.zakirov@postgrespro.ru>
Cc: pgsql-hackers@postgresql.org
Subject: Re: query logging of prepared statements
Date: Mon, 4 Mar 2019 12:31:50 -0600
Message-ID: <20190304183150.GK29584@telsasoft.com> (raw )
In-Reply-To: <70868e0d-2a29-36c8-e3e2-f54a56804bc4@postgrespro.ru >
References: <20190208132953.GF29720@telsasoft.com >
<20190215145704.GW30291@telsasoft.com >
<20190227180653.GF28750@telsasoft.com >
<70868e0d-2a29-36c8-e3e2-f54a56804bc4@postgrespro.ru >
On Mon, Mar 04, 2019 at 06:53:31PM +0300, Arthur Zakirov wrote:
> Hello Justin,
>
> On 27.02.2019 21:06, Justin Pryzby wrote:
> >I'm attaching a v2 patch which avoids repeated logging of PREPARE, rather than
> >making such logs conditional on log_error_verbosity=VERBOSE, since
> >log_error_verbosity is documented to control whether these are output:
> >DETAIL/HINT/QUERY/CONTEXT/SQLSTATE.
> I looked the patch. I got interesting result with different parameters.
>
> But with log_statement='none' and log_min_duration_statement='0' I get:
>
> =# execute test_ins(3);
> LOG: duration: 8.439 ms statement: execute test_ins(3);
> DETAIL: prepare: prepare test_ins (int) as
> insert into test values ($1);
>
> Is it intended? In the second result I got the query details.
It wasn't intentional. Find attached v3 patch which handles that case,
by removing the 2nd call to errdetail_execute() ; since it's otherwise unused,
so remove that function entirely.
|postgres=# execute test_ins(3);
|2019-03-04 11:56:15.997 EST [4044] LOG: duration: 0.637 ms statement: execute test_ins(3);
I also fixed a 2nd behavior using library call pqExecPrepared with
log_min_duration_statement=0.
It was logging:
|LOG: duration: 0.264 ms statement: SELECT 1; PREPARE q AS SELECT $1
|LOG: duration: 0.027 ms bind q: SELECT 1; PREPARE q AS SELECT $1
|DETAIL: parameters: $1 = '1'
|LOG: duration: 0.006 ms execute q: SELECT 1; PREPARE q AS SELECT $1
|DETAIL: parameters: $1 = '1'
But now logs:
PGPORT=5679 PGHOST=/tmp PYTHONPATH=../PyGreSQL/build/lib.linux-x86_64-2.7/ python2.7 -c "import pg; d=pg.DB('postgres'); d.query('SET client_min_messages=error; SET log_error_verbosity=default; SET log_min_duration_statement=0; SET log_statement=\"none\"'); d.query('SELECT 1; PREPARE q AS SELECT \$1'); d.query_prepared('q',[1])"
|LOG: duration: 0.479 ms statement: SELECT 1; PREPARE q AS SELECT $1
|LOG: duration: 0.045 ms bind q
|DETAIL: parameters: $1 = '1'
|LOG: duration: 0.008 ms execute q
|DETAIL: parameters: $1 = '1'
Thanks for reviewing. I'm also interested in discussion about whether this
change is undesirable for someone else for some reason ? For me, the existing
output seems duplicative and "denormalized". :)
Justin
Attachments:
v3-0001-Avoid-repetitive-log-of-PREPARE-during-EXECUTE-of.patch (text/x-diff, 3.8K) download
From c04f2fe815a55babe6a9bdd53421d74fc283094b Mon Sep 17 00:00:00 2001
From: Justin Pryzby <justin@telsasoft.com>
Date: Sat, 9 Feb 2019 19:20:43 -0500
Subject: [PATCH v3] Avoid repetitive log of PREPARE during EXECUTE of prepared
statements
---
src/backend/tcop/postgres.c | 54 +++++++--------------------------------------
1 file changed, 8 insertions(+), 46 deletions(-)
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 8b4d94c9a1..f348475ea3 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;
}
@@ -1929,12 +1926,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;
@@ -2062,14 +2058,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;
@@ -2150,15 +2145,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;
@@ -2267,38 +2261,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.12.2
view thread (16+ messages) latest in thread
Message-ID: <20190304183150.GK29584@telsasoft.com>
Permalink: ../20190304183150.GK29584@telsasoft.com/
Also on: postgresql.org/message-id/20190304183150.GK29584@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, a.zakirov@postgrespro.ru
Subject: Re: query logging of prepared statements
In-Reply-To: <20190304183150.GK29584@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