When running with autocommit false only the first BEGIN and COMMIT are logged on server

While debugging my other server problem, I noticed that that only the
first BEGIN and COMMIT are logged on the server with sql statement
logging enabled. It seems that the subsequent transaction control
statements are being executed correctly, it is just that they are not
being logged by the server. Is this to be expected? If so, it makes
debugging a bit difficult as you can't see what commits are really being
executed when you have sql statement logging enabled.

Thanks,
--Barry

Barry Lind wrote:
> While debugging my other server problem, I noticed that that only the
> first BEGIN and COMMIT are logged on the server with sql statement
> logging enabled. It seems that the subsequent transaction control
> statements are being executed correctly, it is just that they are not
> being logged by the server. Is this to be expected? If so, it makes
> debugging a bit difficult as you can't see what commits are really being
> executed when you have sql statement logging enabled.

Yeah, it's a limitation of statement logging. Statements are logged only
on Parse, not on Bind/Execute. The driver reuses the internal
BEGIN/COMMIT statements, so only one Parse is done for each. You will
see the same thing for user queries if they end up using server-side
prepare.

There should be some past discussion about this in the -hackers archives.

-O

That certainly doesn't seem acceptable. As Barry points out people will
really be in the dark when their code doesn't work.

--dc--

Oliver Jowett wrote:

> Barry Lind wrote:
>
>> While debugging my other server problem, I noticed that that only the
>> first BEGIN and COMMIT are logged on the server with sql statement
>> logging enabled. It seems that the subsequent transaction control
>> statements are being executed correctly, it is just that they are not
>> being logged by the server. Is this to be expected? If so, it makes
>> debugging a bit difficult as you can't see what commits are really being
>> executed when you have sql statement logging enabled.
>
>
> Yeah, it's a limitation of statement logging. Statements are logged
> only on Parse, not on Bind/Execute. The driver reuses the internal
> BEGIN/COMMIT statements, so only one Parse is done for each. You will
> see the same thing for user queries if they end up using server-side
> prepare.
>
> There should be some past discussion about this in the -hackers archives.
>
> -O
>
> ---------------------------(end of broadcast)---------------------------
> TIP 7: don't forget to increase your free space map settings
>
>

--
Dave Cramer
http://www.postgresintl.com
519 939 0336
ICQ#14675561

Dave Cramer wrote:
> That certainly doesn't seem acceptable. As Barry points out people will
> really be in the dark when their code doesn't work.

There's nothing much the driver can do about it other than not using the
new features of V3. This needs a server-side fix.

We could make BEGIN/COMMIT/ROLLBACK more visible at the (small) cost of
an extra Parse on each execution. But you're still going to have the
same problem with user queries once statements start using server-side
prepare.

See http://archives.postgresql.org/pgsql-hackers/2004-05/msg01173.php
for past discussion. I looked at fixing it briefly but didn't have time
to put together a patch.

-O

On Tuesday 23 November 2004 07:18, Oliver Jowett wrote:
> Dave Cramer wrote:
> > That certainly doesn't seem acceptable. As Barry points out people
> > will really be in the dark when their code doesn't work.
>
> There's nothing much the driver can do about it other than not using
> the new features of V3. This needs a server-side fix.

Can some kind of statement logging be implemented on the client side?

Or do you think there isn't much to be gained by this beyond whatever
functionality is already provided by proxying JDBC drivers like P6Spy
(http://p6spy.sf.net)?

> We could make BEGIN/COMMIT/ROLLBACK more visible at the (small) cost
> of an extra Parse on each execution.

I'm not sure if you need an extra parse. I'd be happy to have the
backend log a (semi-) unique statement ID for each statement it
executes. If a statement is reused, its unique ID allows me to find
its prior occurrences in the log. It then becomes a matter of having
an intelligent log viewer or post-processor, one that shouldn't be too
hard to write.

Additionally, another thing that could be _really_ useful is the
ability to send an arbitrary message to be logged on the backend side
along with each statement. For instance, you can log the Java thread
name, so you can map statements to threads later on. Another example
would be mapping each statement from the back end log to the
corresponding Java stack trace on the client side. This could be done
by

(a) capturing the current stack trace on the client side via
org.postgresql.Driver.debug(uniqueID + ": " + p_sql,
new Exception());

or some such.

(b) sending uniqueID to the backend along with the statement.

Thoughts?

Vadim

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

P.S. BTW, Driver#log(String,Exception) currently drops the stack
trace on the floor. All it does is

public static void debug(String msg, Exception ex)
{
if (logDebug)
{
DriverManager.println(msg);
if (ex != null)
{
DriverManager.println(ex.toString());
}
}
}

Would it make more sense to do something like this:

public static void debug(String msg, Exception ex)
{
if (logDebug)
{
DriverManager.println(msg);
if (ex != null)
{
ex.printStackTrace(DriverManager.getLogWriter());
}
}
}

Oliver Jowett <oliver(at)opencloud(dot)com> writes:
> Dave Cramer wrote:
>> That certainly doesn't seem acceptable. As Barry points out people will
>> really be in the dark when their code doesn't work.

> There's nothing much the driver can do about it other than not using the
> new features of V3. This needs a server-side fix.

Step right up ;-)

> See http://archives.postgresql.org/pgsql-hackers/2004-05/msg01173.php
> for past discussion. I looked at fixing it briefly but didn't have time
> to put together a patch.

I think the code changes would be minimal, the hard part is agreeing on
desirable behavior. From the point of view of "logging what actually
happened", logging at Execute would make sense; but as Oliver noted in
the above thread, that would lose the ability to log statements with
parse errors, which is not good either. And what about being able to
see the actual parameters sent in Bind?

Also it would be good to think about a saner behavior for logging
statements executed via SPI (ie plpgsql functions) --- we've been living
with essentially these same problems for years there, and no one's very
happy about it.

regards, tom lane