Re: 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

"Guillaume Smet" <guillaume(dot)smet(at)gmail(dot)com> 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

On 9/13/06, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> "Guillaume Smet" <guillaume(dot)smet(at)gmail(dot)com> 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

"Guillaume Smet" <guillaume(dot)smet(at)gmail(dot)com> 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 <stmt>: querystring Parse
bind <stmt>/<portal>: querystring Bind
execute <stmt>/<portal>: querystring Execute

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

On 9/13/06, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> statement: querystring Simple Query
> parse <stmt>: querystring Parse
> bind <stmt>/<portal>: querystring Bind
> execute <stmt>/<portal>: querystring Execute

I agree with that.
Hmmm, AFAICS, you changed "<stmt>/<portal>" to "<portal> to
<statement>" 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

"Guillaume Smet" <guillaume(dot)smet(at)gmail(dot)com> writes:
> On 9/13/06, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
>> statement: querystring Simple Query
>> parse <stmt>: querystring Parse
>> bind <stmt>/<portal>: querystring Bind
>> execute <stmt>/<portal>: querystring Execute

> 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 "<stmt>/<portal>" to "<portal> to
> <statement>" 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 <unnamed>: select ...
followed by
execute fetch from <unnamed>: 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.orig Fri 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 : "<unnamed>",
*stmt_name ? stmt_name : "<unnamed>",
pstmt->query_string ? pstmt->query_string : "<source not stored>"),
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 : "<unnamed>",
+ *portal_name ? "/" : "",
+ *portal_name ? portal_name : "",
pstmt->query_string ? pstmt->query_string : "<source not stored>"),
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 : "",

Tom Lane wrote:
> "Guillaume Smet" <guillaume(dot)smet(at)gmail(dot)com> writes:
> > On 9/13/06, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> >> statement: querystring Simple Query
> >> parse <stmt>: querystring Parse
> >> bind <stmt>/<portal>: querystring Bind
> >> execute <stmt>/<portal>: querystring Execute
>
> > I agree with that.
>
> OK, Bruce hasn't said anything so I went ahead and changed it,
> as per attached patch.

Sure, whatever people using it like.

--
Bruce Momjian bruce(at)momjian(dot)us
EnterpriseDB http://www.enterprisedb.com

+ If your life is a hard drive, Christ can be your backup. +