Thread: 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
Index: doc/src/sgml/runtime.sgml
===================================================================
RCS file: /cvsroot/pgsql-server/doc/src/sgml/runtime.sgml,v
retrieving revision 1.232
diff -c -c -r1.232 runtime.sgml
*** doc/src/sgml/runtime.sgml    23 Jan 2004 23:54:20 -0000    1.232
--- doc/src/sgml/runtime.sgml    25 Jan 2004 00:32:55 -0000
***************
*** 1822,1829 ****
        <listitem>
         <para>
          Causes each SQL statement to be logged. The default is off.
!         Only superusers can turn off this option if it is enabled by
!         the administrator.
         </para>
        </listitem>
       </varlistentry>
--- 1822,1832 ----
        <listitem>
         <para>
          Causes each SQL statement to be logged. The default is off.
!         <command>EXECUTE</> only displays the plan name, not the
!         prepared query. Server-side languages like
!         <application>PL/pgSQL</> that store functions in a cache only
!         display their queries on first function call. superusers can
!         turn off this option if it is enabled by the administrator.
         </para>
        </listitem>
       </varlistentry>