Date: Mon, 5 Jul 2004 21:07:31 -0400
From: L J Bayuk <ljb220@mindspring.com>
To: "Nigel J. Andrews" <nandrews@investsystems.co.uk>
Cc: pgsql-interfaces@postgresql.org
Subject: Re: pgin.tcl pg_exec_prepared slow (was: Released...)
Message-ID: <20040706010731.GA15183@bxlbisnugqvi.mindspring.com>
References: <24110.1087945736@sss.pgh.pa.us>
	<Pine.LNX.4.21.0406302310340.12226-100000@ponder.fairway2k.co.uk>
Mime-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <Pine.LNX.4.21.0406302310340.12226-100000@ponder.fairway2k.co.uk>
User-Agent: Mutt/1.4.1i

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