Re: [HACKERS] Logging statements and parameter values

Our development group needs to have the option of logging all SQL
statements including substituted parameter values. Getting output in the
form:
... WHERE contact.login_con = $1 AND company.login_co = $2

was no problem, but nothing that I tried turning on in the config file
yielded values for $1 and $2.

Digging into the source for 8.1.1 brought me to this code in
.../backend/tcop/postgres.c (lines 1449+)

/* We need to output the parameter values someday */
if (log_statement == LOGSTMT_ALL)
ereport(LOG,
(errmsg("statement: <BIND> %s", portal_name)));

/*
* Fetch parameters, if any, and store in the portal's memory context.
*/
if (numParams > 0)

It seems to me that a point near the bottom of the loop over parameters
(1564+)
params[i].kind = PARAM_NUM;
params[i].id = i + 1;
params[i].ptype = ptype;
params[i].isnull = isNull;

i++;
}

(params[i].value is set in a couple of places higher up in the loop)
would be a good place to log each parameter, but...

Has this not been done simply because nobody has gotten around to it, or
are there pitfalls? Although I've been using PostgreSQL for several years,
this is my first venture into its source code beyond watching it build.

Also, the Datum params[i].value, does it necessarily hold displayable
text, even when its content is the output of a binary input converter?
Is there a utility log routine somewhere that I can simply feed a
Datum to?

--
Ted Powell <ted(at)psg(dot)com> http://psg.com/~ted/
GPL code ... It's the difference between
owning your own home and just renting. --PJ

Ted Powell <ted(at)theplace(dot)enposte(dot)net> writes:
> Has this not been done simply because nobody has gotten around to it, or
> are there pitfalls?

What are you going to do with binary parameter values? Calling the
type's output converter is possible but not very pleasant.

> Also, the Datum params[i].value, does it necessarily hold displayable
> text, even when its content is the output of a binary input converter?

Datums are guaranteed *not* to be displayable text.

regards, tom lane

I assume it is this TODO:

* Allow protocol-level BIND parameter values to be logged

---------------------------------------------------------------------------

Ted Powell wrote:
> Our development group needs to have the option of logging all SQL
> statements including substituted parameter values. Getting output in the
> form:
> ... WHERE contact.login_con = $1 AND company.login_co = $2
>
> was no problem, but nothing that I tried turning on in the config file
> yielded values for $1 and $2.
>
> Digging into the source for 8.1.1 brought me to this code in
> .../backend/tcop/postgres.c (lines 1449+)
>
> /* We need to output the parameter values someday */
> if (log_statement == LOGSTMT_ALL)
> ereport(LOG,
> (errmsg("statement: <BIND> %s", portal_name)));
>
> /*
> * Fetch parameters, if any, and store in the portal's memory context.
> */
> if (numParams > 0)
>
> It seems to me that a point near the bottom of the loop over parameters
> (1564+)
> params[i].kind = PARAM_NUM;
> params[i].id = i + 1;
> params[i].ptype = ptype;
> params[i].isnull = isNull;
>
> i++;
> }
>
> (params[i].value is set in a couple of places higher up in the loop)
> would be a good place to log each parameter, but...
>
> Has this not been done simply because nobody has gotten around to it, or
> are there pitfalls? Although I've been using PostgreSQL for several years,
> this is my first venture into its source code beyond watching it build.
>
> Also, the Datum params[i].value, does it necessarily hold displayable
> text, even when its content is the output of a binary input converter?
> Is there a utility log routine somewhere that I can simply feed a
> Datum to?
>
>
> --
> Ted Powell <ted(at)psg(dot)com> http://psg.com/~ted/
> GPL code ... It's the difference between
> owning your own home and just renting. --PJ
>
> ---------------------------(end of broadcast)---------------------------
> TIP 1: if posting/reading through Usenet, please send an appropriate
> subscribe-nomail command to majordomo(at)postgresql(dot)org so that your
> message can get through to the mailing list cleanly
>

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

On Mon, Jan 30, 2006 at 04:31:29PM -0500, Bruce Momjian wrote:
>
> I assume it is this TODO:
>
> * Allow protocol-level BIND parameter values to be logged
>
>
> ---------------------------------------------------------------------------
>
> Ted Powell wrote:
> > Our development group needs to have the option of logging all SQL
> > statements including substituted parameter values. [...]

That's it! (I should have thought to look in the TODO.)

Has any design work been done on this?

--
Ted Powell <ted(at)psg(dot)com> http://psg.com/~ted/
GPL code ... It's the difference between
owning your own home and just renting. --PJ

Ted Powell wrote:
> On Mon, Jan 30, 2006 at 04:31:29PM -0500, Bruce Momjian wrote:
> >
> > I assume it is this TODO:
> >
> > * Allow protocol-level BIND parameter values to be logged
> >
> >
> > ---------------------------------------------------------------------------
> >
> > Ted Powell wrote:
> > > Our development group needs to have the option of logging all SQL
> > > statements including substituted parameter values. [...]
>
> That's it! (I should have thought to look in the TODO.)
>
> Has any design work been done on this?

No. I am with Simon Riggs today at my house and I asked him, hoping he
can get it done for 8.2. I don't think it is very hard.

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

On Mon, Jan 30, 2006 at 05:19:23PM -0500, Bruce Momjian wrote:
> [...]
> > > * Allow protocol-level BIND parameter values to be logged
> [...]
> > That's it! (I should have thought to look in the TODO.)
> >
> > Has any design work been done on this?
>
> No. I am with Simon Riggs today at my house and I asked him, hoping he
> can get it done for 8.2. I don't think it is very hard.

Various things have been pushed on my stack since I posted about this.
When it gets near the top again, I'll check back. Thanks for the response.

--
Ted Powell <ted(at)psg(dot)com> http://psg.com/~ted/
GPL code ... It's the difference between
owning your own home and just renting. --PJ

On Mon, 2006-01-30 at 17:19 -0500, Bruce Momjian wrote:
> Ted Powell wrote:
> > On Mon, Jan 30, 2006 at 04:31:29PM -0500, Bruce Momjian wrote:
> > >
> > > I assume it is this TODO:
> > >
> > > * Allow protocol-level BIND parameter values to be logged
> > >
> > >
> > > ---------------------------------------------------------------------------
> > >
> > > Ted Powell wrote:
> > > > Our development group needs to have the option of logging all SQL
> > > > statements including substituted parameter values. [...]
> >
> > That's it! (I should have thought to look in the TODO.)
> >
> > Has any design work been done on this?
>
> No. I am with Simon Riggs today at my house and I asked him, hoping he
> can get it done for 8.2. I don't think it is very hard.

Some more detailed thoughts:

1. Do we want to log parameters at Bind time or at Execution time? Bind
is easier and more correct, but might look a little strange in the log
since the parameters would be logged before the execution appears. IMHO
Bind time is more correct. That would mean we have a separate line for
logged parameters, e.g.
parameters: p1=111 p2=hshssh p3=47000.5

2. Should we save them until end of execution, so we can output them on
the same line as log_min_duration_statement queries? Sounds easier but
the meaning might be more confused.

3. Do we want to log parameters that are used for planning, but no
others? Sometimes yes, sometimes no, I think.

Sounds like we need:
- a log_parameters GUC with settings of: "none", "plan" and "all".
- output log messages at Bind time on a separate log line, which would
replace the existing "statement: [protocol] <BIND>" message with
"(portalname) parameters: p1=111 p2=hshssh p3=47000.5"
- portalname would be blank if we aren't using named portals

While we're discussing logging, I also want to be able to set
log_min_duration_statement on a user by user basis (i,e, for individual
applications). We set this to superuser-only for valid security reasons,
but I'd like to have the ability for the superuser to relax that
restriction for short periods, or even permanently on development
servers. That sounds like another GUC: log_security = on
which would enforce SUSET/USERSET control (and would need to be a SIGHUP
parameter).

Best Regards, Simon Riggs

Simon,

For me the usage pattern would be: log all params, bind time values, on
the same log line as "log_min_duration" entries. That's what I need to
know which are the non-performant queries, and it also helps on
occasions to identify application problems.

In any case all your plans sound very good, can't wait to have it
working :-)

Thanks,
Csaba.

On Mon, 2006-02-06 at 12:43, Simon Riggs wrote:
> On Mon, 2006-01-30 at 17:19 -0500, Bruce Momjian wrote:
> > Ted Powell wrote:
> > > On Mon, Jan 30, 2006 at 04:31:29PM -0500, Bruce Momjian wrote:
> > > >
> > > > I assume it is this TODO:
> > > >
> > > > * Allow protocol-level BIND parameter values to be logged
> > > >
> > > >
> > > > ---------------------------------------------------------------------------
> > > >
> > > > Ted Powell wrote:
> > > > > Our development group needs to have the option of logging all SQL
> > > > > statements including substituted parameter values. [...]
> > >
> > > That's it! (I should have thought to look in the TODO.)
> > >
> > > Has any design work been done on this?
> >
> > No. I am with Simon Riggs today at my house and I asked him, hoping he
> > can get it done for 8.2. I don't think it is very hard.
>
> Some more detailed thoughts:
>
> 1. Do we want to log parameters at Bind time or at Execution time? Bind
> is easier and more correct, but might look a little strange in the log
> since the parameters would be logged before the execution appears. IMHO
> Bind time is more correct. That would mean we have a separate line for
> logged parameters, e.g.
> parameters: p1=111 p2=hshssh p3=47000.5
>
> 2. Should we save them until end of execution, so we can output them on
> the same line as log_min_duration_statement queries? Sounds easier but
> the meaning might be more confused.
>
> 3. Do we want to log parameters that are used for planning, but no
> others? Sometimes yes, sometimes no, I think.
>
> Sounds like we need:
> - a log_parameters GUC with settings of: "none", "plan" and "all".
> - output log messages at Bind time on a separate log line, which would
> replace the existing "statement: [protocol] <BIND>" message with
> "(portalname) parameters: p1=111 p2=hshssh p3=47000.5"
> - portalname would be blank if we aren't using named portals
>
> While we're discussing logging, I also want to be able to set
> log_min_duration_statement on a user by user basis (i,e, for individual
> applications). We set this to superuser-only for valid security reasons,
> but I'd like to have the ability for the superuser to relax that
> restriction for short periods, or even permanently on development
> servers. That sounds like another GUC: log_security = on
> which would enforce SUSET/USERSET control (and would need to be a SIGHUP
> parameter).
>
> Best Regards, Simon Riggs
>
>
> ---------------------------(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

On Mon, 2006-02-06 at 13:28 +0100, Csaba Nagy wrote:

> For me the usage pattern would be: log all params, bind time values, on
> the same log line as "log_min_duration" entries. That's what I need to
> know which are the non-performant queries, and it also helps on
> occasions to identify application problems.

You remind me that two sets of parameters could be logged

Trouble is, you need to know both
- parameters that were used to plan the query
- parameters used for this execution of the query
since very often it is the combination that is the problem. i.e. it was
a good query at plan time and if re-planned would also be a good query,
but running the earlier plan with the later set of parameters is bad.

Perhaps it would be useful to store the parameters that were used to
plan the query with the portal, so we could have an option to say "and
with what parameters was this query planned". That would then sensibly
appear on the log_min_messages log line, as you suggest. This is
important for diagnosing many run-time issues accurately.

Maybe we should expand the list to
log_parameters = none | bind | plan | exec | all

bind = log parameters directly at bind time, using a separate log line;
do not store them. Useful mainly as an interface debugging aid.

plan = store parameters used for planning with portal, then output them
with the statement at log_min_message time
e.g. (plan parms: p1= p2= ...) - which is very similar to what we do now
with spitting out the SQL statement since that is not resent for each
execution

exec = store the parameters used at bind time and output them with the
statement e.g. (exec parms: p1= p2=)

all = store the parameters used at bind time and output them with the
statement, as well as the exec parms e.g. (plan parms: p1= p2= ...)(exec
parms: p1= p2=)

none = nada, not even the current log lines for bind

Sounds too much, but you don't really want all of that all of the time.

Best Regards, Simon Riggs