Log_statement behaviour a little misleading?
This caught me today :
I switched on "log_statement=true" whilst examining a possible foreign
key concurrency problem. I noticed that the generated foreign key check
"SELECT 1 FROM ONLY ... WHERE id = ...FOR UPDATE..."
on the parent table seemed to be only appearing every now and again.
This caused some scratching of the head :-)
Finally light dawned (ok - after reading ri_triggers.c and querying
pg_locks) - that the backend saves the execution plan for the generated
statement, so it is only planned once...and I guess log_statement is
triggered in the plan stage somewhere...
So setting "log_statement=true" does all *statements* - but not all
*executions* of each statement. Is this the intention?
(BTW - I am using 7.4.1)
best wishes
Mark
Mark Kirkwood <markir@paradise.net.nz> writes:
So setting "log_statement=true" does all *statements* - but not all
*executions* of each statement. Is this the intention?
AFAIK this is an implementation artifact that's never really been
discussed. Another aspect of the artifact is that SQL commands
appearing in plpgsql functions will be logged only on first execution
in a session.
I think you could make a fair argument that "log_statement" ought to log
only commands received from the client application. There would be real
value in being able to trace execution of plpgsql functions, but such a
feature would have very little to do with log_statement as it now
stands. The fact that RI triggers issue SQL commands is an artifact of
their implementation (and one that I believe Stephan and Jan would like
to get rid of); they shouldn't be cluttering the log at all.
At least that's what it seems like to me after a few moments'
reflection. Other opinions out there?
regards, tom lane
Tom Lane wrote:
The fact that RI triggers issue SQL commands is an artifact of
their implementation (and one that I believe Stephan and Jan would like
to get rid of); they shouldn't be cluttering the log at all.
I am glad you mentioned that - I did find myself wondering why it was
necessary to go through the whole parse->plan->etc business, when the
backend "knows" that an access via the (required) primary key is going
to be available...
cheers
Mark
Tom Lane wrote:
Mark Kirkwood <markir@paradise.net.nz> writes:
So setting "log_statement=true" does all *statements* - but not all
*executions* of each statement. Is this the intention?AFAIK this is an implementation artifact that's never really been
discussed. Another aspect of the artifact is that SQL commands
appearing in plpgsql functions will be logged only on first execution
in a session.I think you could make a fair argument that "log_statement" ought to log
only commands received from the client application. There would be real
value in being able to trace execution of plpgsql functions, but such a
feature would have very little to do with log_statement as it now
stands. The fact that RI triggers issue SQL commands is an artifact of
their implementation (and one that I believe Stephan and Jan would like
to get rid of); they shouldn't be cluttering the log at all.At least that's what it seems like to me after a few moments'
reflection. Other opinions out there?
I checked prepared queries and it looks like this:
LOG: statement: prepare xx as select 1;
LOG: statement: execute xx;
which seems OK by me. I have updated the docs to mention the behavior
mentioned above for PREPARE and PL/pgSQL.
--
Bruce Momjian | http://candle.pha.pa.us
pgman@candle.pha.pa.us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073