Re: pgin.tcl pg_exec_prepared slow (was: Released...)

On Wed, Jun 30, 2004 at 11:29:32PM +0100, Nigel J. Andrews wrote:
> ... (description of prepared query execution in pgin.tcl taking 10 times
>      longer than pg_exec doing the same query)
> Obviously the prepared query execution is an order of magnitude slower and
> it's the TCL interface that's making it so.

My own tests show equivalent performance of pg_exec and pg_exec_prepared,
but that is for medium-to-large result sets. With tiny result sets - one
row, 2 values - I also see an unexpected 40 ms delay in pg_exec_prepared
when using pgin.tcl.  (Very interesting that it's the same delay on different
hardware.)

After looking at it for a while, I know where the problem is, but not
what is causing it. I also know how to fix it, but not why the fix works.
I'm going to explain what I know, hoping someone can fill in some missing
parts.

pg_exec sends 1 message: Query.  pg_exec_prepared sends 4 messages: Bind,
DescribePortal, Execute, and Sync. After that, they are identical.

The delay we are seeing (about 40 ms) is from the time the client sends the
Bind message to PostgreSQL until it gets a TCP ACK back. (It should get
a BindComplete message back, but the backend does't flush after sending
this - no pq_flush() at the end of exec_bind_message(). Hello, Tom, is this
a bug? Changing it just moves the delay around, though.) Other messages
from the client are typically replied to and/or ACK'd in under 1 ms,
according to Ethereal.  I don't know why this message takes so much longer
to ACK, nor why the client waits for the ACK. I'm sure it isn't the
backend; I don't think it is Tcl; it could be something in the TCP stack.

The fix: pgin.tcl sets its Tcl connection socket channel to "unbuffered",
which means each PostgreSQL message it sends will be go into the TCP
buffers immediately, since each message is written in a single "puts".  And
it seems to work fine with all messages except that Bind. My fix is to
change it to use Tcl "buffering full" mode; then I have it flush after each
sent message, except in pg_exec_prepared (and pg_exec_params), where it
flushes only after sending the final Sync.  The result is to combine the 4
messages from pg_exec_prepared so they get dumped into the TCP buffers at
once. The problem goes away, but I don't know why it works, and that
bothers me. Before:   39987 microseconds per iteration - pg_exec_prepared   39992 microseconds per iteration -
pg_exec_params   4133 microseconds per iteration - pg_exec After:    4483 microseconds per iteration - pg_exec_prepared
  5214 microseconds per iteration - pg_exec_params    4150 microseconds per iteration - pg_exec