Обсуждение: Re: [GENERAL] Logging statements and parameter values
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