Re: [HACKERS] Inconsistency in extended-query-protocol logging
"Guillaume Smet" <[EMAIL PROTECTED]> writes:
> On 9/13/06, Tom Lane <[EMAIL PROTECTED]> wrote:
>> statement: querystring Simple Query
>> parse : querystring Parse
>> bind /: querystring Bind
>> execute /: querystringExecute
> I agree with that.
OK, Bruce hasn't said anything so I went ahead and changed it,
as per attached patch.
> Hmmm, AFAICS, you changed "/" to " to
> " in your last commit. Or did I misunderstand?
Yeah, that seemed like a good idea at the time ... but on reflection
it's probably better to be consistent with the way the execute message
is logged.
>> Also, the current code distinguishes a "fetch" from an
>> already-partially-executed portal ... do you care about that?
> I don't really understand what is a portal - I must admit I don't use
> libpq directly. I never saw a log file with fetch. Do you have an
> example? Should I consider an execute from fetch differently?
Well, the point is that if you see
execute : select ...
followed by
execute fetch from : select ...
the latter is a continuation of the same command not a newly entered
command. For resource-analysis purposes you can likely treat them the
same, but if you were trying to debug an application you might need to
know the difference.
regards, tom lane
*** src/backend/tcop/postgres.c.origFri Sep 8 11:55:53 2006
--- src/backend/tcop/postgres.c Wed Sep 13 17:51:35 2006
***
*** 1610,1619
break;
case 2:
ereport(LOG,
! (errmsg("duration: %s ms bind %s to
%s: %s",
msec_str,
- *portal_name ?
portal_name : "",
*stmt_name ? stmt_name
: "",
pstmt->query_string ?
pstmt->query_string : ""),
errdetail_params(params)));
break;
--- 1610,1620
break;
case 2:
ereport(LOG,
! (errmsg("duration: %s ms bind %s%s%s:
%s",
msec_str,
*stmt_name ? stmt_name
: "",
+ *portal_name ? "/" : "",
+ *portal_name ?
portal_name : "",
pstmt->query_string ?
pstmt->query_string : ""),
errdetail_params(params)));
break;
***
*** 1740,1747
ereport(LOG,
(errmsg("%s %s%s%s%s%s",
execute_is_fetch ?
! _("statement: execute fetch
from") :
! _("statement: execute"),
prepStmtName,
*portal_name ? "/" : "",
*portal_name ? portal_name : "",
--- 1741,1748
ereport(LOG,
(errmsg("%s %s%s%s%s%s",
execute_is_fetch ?
! _("execute fetch from") :
! _("execute"),
prepStmtName,
*portal_name ? "/" : "",
*portal_name ? portal_name : "",
---(end of broadcast)---
TIP 9: In versions below 8.0, the planner will ignore your desire to
choose an index scan if your joining column's datatypes do not
match
Re: [HACKERS] Inconsistency in extended-query-protocol logging
On 9/13/06, Tom Lane <[EMAIL PROTECTED]> wrote: statement: querystring Simple Query parse : querystring Parse bind /: querystring Bind execute /: querystringExecute I agree with that. Hmmm, AFAICS, you changed "/" to " to " in your last commit. Or did I misunderstand? or these prefixed with "duration: xxx", as appropriate. Bruce was pretty hot about having statement: in there, so the hard part might be to convince him. Bruce, any opinion? I really think the extended query protocol is not a statement stricly speaking. Also, the current code distinguishes a "fetch" from an already-partially-executed portal ... do you care about that? I don't really understand what is a portal - I must admit I don't use libpq directly. I never saw a log file with fetch. Do you have an example? Should I consider an execute from fetch differently? -- Guillaume ---(end of broadcast)--- TIP 4: Have you searched our list archives? http://archives.postgresql.org
Re: [HACKERS] Inconsistency in extended-query-protocol logging
"Guillaume Smet" <[EMAIL PROTECTED]> writes: > IMHO, it's more logical to remove it as the text after statement: is > not a statement in the extended query protocol case. Well, I was never particularly enamored of the idea that we should put statement: into everything generated by log_statement. My proposal would be to generate statement: querystring Simple Query parse : querystring Parse bind /: querystring Bind execute /: querystringExecute or these prefixed with "duration: xxx", as appropriate. Bruce was pretty hot about having statement: in there, so the hard part might be to convince him. Also, the current code distinguishes a "fetch" from an already-partially-executed portal ... do you care about that? regards, tom lane ---(end of broadcast)--- TIP 3: Have you checked our extensive FAQ? http://www.postgresql.org/docs/faq
Re: [HACKERS] Inconsistency in extended-query-protocol logging
On 9/13/06, Tom Lane <[EMAIL PROTECTED]> wrote: "Guillaume Smet" <[EMAIL PROTECTED]> writes: > I attached a patch to improve the consistency. It adds statement: for > every case. Isn't that just bloating the log? And weren't you the one complaining about log volumes to begin with? As I told you, I don't care if we remove it or if we add it but having: statement: query -> duration: duration statement: query in one case and statement: query -> duration: duration query in the other case is not consistent. Either we remove statement: for extended protocol or we add it but I don't think it's a good idea to have a different behaviour between log_duration and log_min_duration_statement. As for bloating the log, it's already the case currently with regular queries so it won't change that much. At least in the cases we have here, it's negligible compared to the query text. IMHO, it's not an argument to choose either solution. IMHO, it's more logical to remove it as the text after statement: is not a statement in the extended query protocol case. I chose the other solution to be consistent with the choices Bruce made before. Regards, -- Guillaume ---(end of broadcast)--- TIP 1: if posting/reading through Usenet, please send an appropriate subscribe-nomail command to [EMAIL PROTECTED] so that your message can get through to the mailing list cleanly
Re: [HACKERS] Inconsistency in extended-query-protocol logging
"Guillaume Smet" <[EMAIL PROTECTED]> writes: > I attached a patch to improve the consistency. It adds statement: for > every case. Isn't that just bloating the log? And weren't you the one complaining about log volumes to begin with? The reason it is why it is is that Bruce wanted the wording to reflect why you are getting the log message: anything starting "statement:" is being logged because of log_statement, anything starting "duration:" is being logged because of one of the log_duration variables. Your proposed patch blurs that distinction and doesn't buy anything much that I can see. regards, tom lane ---(end of broadcast)--- TIP 3: Have you checked our extensive FAQ? http://www.postgresql.org/docs/faq
[HACKERS] Inconsistency in extended-query-protocol logging
Tom,
I'm currently resyncing my parser with the changes you made to
prepared statement logging. Everything is OK apart from an
inconsistency between log_duration and log_min_duration_statement.
* With log_duration, we have:
protocol : LOG: statement: execute my_query: SELECT * FROM shop WHERE $1 = $2
query : LOG: statement: EXECUTE test1('lop1', 'lop2')
* With log_min_duration_statement, we have:
protocol: LOG: duration: 235.345 ms execute insert_query: INSERT
INTO shop (name) VALUES($1)
query: LOG: duration: 0.187 ms statement: EXECUTE test1('lop1', 'lop2')
As you can see, in the log_duration case, we always have the
"statement: " part but we don't have it in log_min_duration_statement
case when using protocol.
I attached a patch to improve the consistency. It adds statement: for
every case. Note that statement was not there in the first version of
Bruce and he added it after so I keep it in this patch. I don't really
care if we have statement: or not but I'd really like a consistent
behaviour between both configuration.
Thanks,
--
Guillaume
Index: src/backend/tcop/postgres.c
===
RCS file: /projects/cvsroot/pgsql/src/backend/tcop/postgres.c,v
retrieving revision 1.508
diff -c -r1.508 postgres.c
*** src/backend/tcop/postgres.c 8 Sep 2006 15:55:53 - 1.508
--- src/backend/tcop/postgres.c 13 Sep 2006 12:44:16 -
***
*** 1256,1262
break;
case 2:
ereport(LOG,
! (errmsg("duration: %s ms parse %s: %s",
msec_str,
*stmt_name ? stmt_name : "",
query_string)));
--- 1256,1262
break;
case 2:
ereport(LOG,
! (errmsg("duration: %s ms statement: parse %s: %s",
msec_str,
*stmt_name ? stmt_name : "",
query_string)));
***
*** 1610,1616
break;
case 2:
ereport(LOG,
! (errmsg("duration: %s ms bind %s to %s: %s",
msec_str,
*portal_name ? portal_name : "",
*stmt_name ? stmt_name : "",
--- 1610,1616
break;
case 2:
ereport(LOG,
! (errmsg("duration: %s ms statement: bind %s to %s: %s",
msec_str,
*portal_name ? portal_name : "",
*stmt_name ? stmt_name : "",
***
*** 1819,1825
break;
case 2:
ereport(LOG,
! (errmsg("duration: %s ms %s %s%s%s%s%s",
msec_str,
execute_is_fetch ?
_("execute fetch from") :
--- 1819,1825
break;
case 2:
ereport(LOG,
! (errmsg("duration: %s ms statement: %s %s%s%s%s%s",
msec_str,
execute_is_fetch ?
_("execute fetch from") :
---(end of broadcast)---
TIP 3: Have you checked our extensive FAQ?
http://www.postgresql.org/docs/faq
