Thread: log_statement and PREPARE

log_statement and PREPARE

From
brian
Date:
The docs (8.1) say the following about log_statement:

-- snip --
... mod logs all ddl statements, plus INSERT, UPDATE, DELETE, TRUNCATE,
and COPY FROM. PREPARE and EXPLAIN ANALYZE statements are also logged if
their contained command is of an appropriate type.
-- snip --

Can someone please expain the meaning of, "if their contained command is
of an appropriate type"? I take it to mean that the prepared statement
will be logged if the it contains an INSERT (if 'mod' was chosen, of
course).

I ask because i've set log_statement to 'mod' but am not seeing any of
my prepared statements in the log. INSERT, UPDATE, and friends i do see.

FWIW, the app is PHP using MDB2. But checking its source doesn't give me
any reason to believe the issue lies there. Shouldn't i see these PREPAREs?

brian

Re: log_statement and PREPARE

From
Tom Lane
Date:
brian <brian@zijn-digital.com> writes:
> The docs (8.1) say the following about log_statement:
> -- snip --
> ... mod logs all ddl statements, plus INSERT, UPDATE, DELETE, TRUNCATE,
> and COPY FROM. PREPARE and EXPLAIN ANALYZE statements are also logged if
> their contained command is of an appropriate type.
> -- snip --

> Can someone please expain the meaning of, "if their contained command is
> of an appropriate type"? I take it to mean that the prepared statement
> will be logged if the it contains an INSERT (if 'mod' was chosen, of
> course).

I think you mis-parsed it.  The sentence about PREPARE et al is an
independent sentence applying to all the possible values of
log_statement.  That is, these commands will be logged if the contained
command is one that would have been logged, at the current log level.

> I ask because i've set log_statement to 'mod' but am not seeing any of
> my prepared statements in the log. INSERT, UPDATE, and friends i do see.

Ah.  Probably you are confusing PREPARE-the-SQL-command, which is what
this is speaking of, with the protocol-level prepared-statement
functionality.  8.1 is pretty bad about logging extended-query-protocol
operations.  If you can update to 8.2 you'll be happier.

            regards, tom lane

Re: log_statement and PREPARE

From
brian
Date:
Tom Lane wrote:
> brian <brian@zijn-digital.com> writes:
>
>> The docs (8.1) say the following about log_statement: -- snip --
>> ... mod logs all ddl statements, plus INSERT, UPDATE, DELETE,
>> TRUNCATE, and COPY FROM. PREPARE and EXPLAIN ANALYZE statements are
>> also logged if their contained command is of an appropriate type.
>> -- snip --
>
>> Can someone please expain the meaning of, "if their contained
>> command is of an appropriate type"? I take it to mean that the
>> prepared statement will be logged if the it contains an INSERT (if
>> 'mod' was chosen, of course).
>
> I think you mis-parsed it.  The sentence about PREPARE et al is an
> independent sentence applying to all the possible values of
> log_statement.  That is, these commands will be logged if the
> contained command is one that would have been logged, at the current
> log level.
>

But that should mean that my prepared statement that contains an INSERT
should be logged, yes? (8.1 issues notwithstanding)

>> I ask because i've set log_statement to 'mod' but am not seeing any
>> of my prepared statements in the log. INSERT, UPDATE, and friends i
>> do see.
>
> Ah.  Probably you are confusing PREPARE-the-SQL-command, which is
> what this is speaking of, with the protocol-level prepared-statement
> functionality.

I'd thought i wasn't confusing the two. For instance, the MDB2 source
reveals the following in prepare():

$query = 'PREPARE '.$statement_name.$types_string.' AS '.$query;
$statement =& $this->_doQuery($query, true, $connection);

So, i do seem to be dealing, in the end, with PREPARE-the-SQL-command here.

> 8.1 is pretty bad about logging extended-query-protocol
> operations.  If you can update to 8.2 you'll be happier.

I have been trying to find the time to move up to 8.2 lately. Perhaps
this evening is as good a time as any to do that on the dev box.

Thanks for your time.
brian

Re: log_statement and PREPARE

From
Tom Lane
Date:
brian <brian@zijn-digital.com> writes:
> But that should mean that my prepared statement that contains an INSERT
> should be logged, yes? (8.1 issues notwithstanding)
> I ask because i've set log_statement to 'mod' but am not seeing any
> of my prepared statements in the log. INSERT, UPDATE, and friends i
> do see.

Hm, works for me:

regression=# create temp table fooey(f1 int);
CREATE TABLE
regression=# prepare foo(int) as insert into fooey values($1);
PREPARE
regression=# execute foo(42);
INSERT 0 1
regression=# show log_statement;
 log_statement
---------------
 mod
(1 row)

in log:

LOG:  statement: create temp table fooey(f1 int);
LOG:  statement: prepare foo(int) as insert into fooey values($1);

The same sequence in 8.2 logs:

LOG:  statement: create temp table fooey(f1 int);
LOG:  statement: prepare foo(int) as insert into fooey values($1);
LOG:  statement: execute foo(42);
DETAIL:  prepare: prepare foo(int) as insert into fooey values($1);

If what you were looking for was that the *execute* gets logged
dependent on what the prepared statement was, then you need 8.2.
All that stuff got rewritten pretty heavily for 8.2 ...

            regards, tom lane

Re: log_statement and PREPARE

From
brian
Date:
Tom Lane wrote:
> brian <brian@zijn-digital.com> writes:
>
>>But that should mean that my prepared statement that contains an INSERT
>>should be logged, yes? (8.1 issues notwithstanding)
>>I ask because i've set log_statement to 'mod' but am not seeing any
>>of my prepared statements in the log. INSERT, UPDATE, and friends i
>>do see.
>
>
> Hm, works for me:
>
> regression=# create temp table fooey(f1 int);
> CREATE TABLE
> regression=# prepare foo(int) as insert into fooey values($1);
> PREPARE
> regression=# execute foo(42);
> INSERT 0 1
> regression=# show log_statement;
>  log_statement
> ---------------
>  mod
> (1 row)
>
> in log:
>
> LOG:  statement: create temp table fooey(f1 int);
> LOG:  statement: prepare foo(int) as insert into fooey values($1);
>
> The same sequence in 8.2 logs:
>
> LOG:  statement: create temp table fooey(f1 int);
> LOG:  statement: prepare foo(int) as insert into fooey values($1);
> LOG:  statement: execute foo(42);
> DETAIL:  prepare: prepare foo(int) as insert into fooey values($1);

OK, maybe i *am* confused about PREPARE. The PEAR MDB2 source is doing:

$query = 'PREPARE '.$statement_name.$types_string.' AS '.$query;

which becomes something like:

PREPARE mdb2_statement_pgsqla0e8d35156e904f9581ac790eb917b98 AS ...

So i think i see your point. The "mdb2_statement_pgsql ... " string
identifier is what is then passed along with my data to Pg when
executed. So, quite different than "EXECUTE foo(42)". And this sort of
thing is not logged? Even in 8.2?

On the chance that there really is something amiss, i'll continue ...

I know that the change to postgresql.conf has been recognised because
i've been seeing the regular queries logged since changing log_statement.

The only hint of a prepared statement being logged is when there's an
error. eg:

<2007-09-05 17:35:22 EDT>ERROR:  duplicate key violates unique
constraint "auth_member_id_key"
<2007-09-05 17:35:22 EDT>STATEMENT:  EXECUTE
mdb2_statement_pgsqla0e8d35156e904f9581ac790eb917b98 (A_HASH_HERE, 5271)

Otherwise, nothing but INSERT, UPDATE, etc. I'm using 8.1.4, btw.

I'll take this over to the PEAR list.

> If what you were looking for was that the *execute* gets logged
> dependent on what the prepared statement was, then you need 8.2.
> All that stuff got rewritten pretty heavily for 8.2 ...

Yeah, i'll upgrade and check that out. Thanks again.
brian

Re: log_statement and PREPARE

From
Tom Lane
Date:
brian <brian@zijn-digital.com> writes:
> The only hint of a prepared statement being logged is when there's an
> error. eg:

> <2007-09-05 17:35:22 EDT>ERROR:  duplicate key violates unique
> constraint "auth_member_id_key"
> <2007-09-05 17:35:22 EDT>STATEMENT:  EXECUTE
> mdb2_statement_pgsqla0e8d35156e904f9581ac790eb917b98 (A_HASH_HERE, 5271)

That looks like an EXECUTE to me.  If you want EXECUTEs to be logged
conditionally based on what they are executing, you need 8.2.

            regards, tom lane

Re: log_statement and PREPARE

From
brian
Date:
Tom Lane wrote:
> brian <brian@zijn-digital.com> writes:
>
>>The only hint of a prepared statement being logged is when there's an
>>error. eg:
>
>
>><2007-09-05 17:35:22 EDT>ERROR:  duplicate key violates unique
>>constraint "auth_member_id_key"
>><2007-09-05 17:35:22 EDT>STATEMENT:  EXECUTE
>>mdb2_statement_pgsqla0e8d35156e904f9581ac790eb917b98 (A_HASH_HERE, 5271)
>
>
> That looks like an EXECUTE to me.  If you want EXECUTEs to be logged
> conditionally based on what they are executing, you need 8.2.
>

That was understood. What i meant is that the only time i see anything
*related to* the prepared statement i think should be there is when the
EXECUTE fails for some reason because the context of the error is
logged. That particular EXECUTE was preceeded by a PREPARE that was not
logged. It was my understanding that the PREPARE would be logged.

In any case, i'll upgrade soonest. I keep reading here about all the 8.2
goodness.

brian

Re: log_statement and PREPARE

From
Tom Lane
Date:
brian <brian@zijn-digital.com> writes:
> That was understood. What i meant is that the only time i see anything
> *related to* the prepared statement i think should be there is when the
> EXECUTE fails for some reason because the context of the error is
> logged. That particular EXECUTE was preceeded by a PREPARE that was not
> logged. It was my understanding that the PREPARE would be logged.

[ squint... ]  It got logged when I tried it.  But I was testing 8.1
branch tip (or close to it -- post-8.1.9 for sure).  I think you said
you were on 8.1.2?  There could well have been some related bug fixes
in that branch, but I'm too lazy to check the release notes right now.

> In any case, i'll upgrade soonest. I keep reading here about all the 8.2
> goodness.

If you can update to 8.2 without too much pain, I'd sure recommend that.
But if you run into compatibility problems, it seems that 8.1.9 might
perhaps help too.

            regards, tom lane

Re: log_statement and PREPARE

From
brian
Date:
Tom Lane wrote:
> brian <brian@zijn-digital.com> writes:
>
>>That was understood. What i meant is that the only time i see anything
>>*related to* the prepared statement i think should be there is when the
>>EXECUTE fails for some reason because the context of the error is
>>logged. That particular EXECUTE was preceeded by a PREPARE that was not
>>logged. It was my understanding that the PREPARE would be logged.
>
>
> [ squint... ]  It got logged when I tried it.  But I was testing 8.1
> branch tip (or close to it -- post-8.1.9 for sure).  I think you said
> you were on 8.1.2?  There could well have been some related bug fixes
> in that branch, but I'm too lazy to check the release notes right now.
>
>
>>In any case, i'll upgrade soonest. I keep reading here about all the 8.2
>>goodness.
>
>
> If you can update to 8.2 without too much pain, I'd sure recommend that.
> But if you run into compatibility problems, it seems that 8.1.9 might
> perhaps help too.
>

I'm with 8.1.4 now. No big deal, though; this was all because i was
trying to debug something and wanted to see the PREPARE come in for a
bit. But i've already resolved the initial bug in my app. I was just
wondering if i was reading the docs correctly. I'll upgrade.

b