Timing of 'SELECT 1'

Bruce Momjian <pgman@candle.pha.pa.us> writes:

I am timing small queries, and found that a PREPARE/EXECUTE of "SELECT
1" takes about 1.2ms on my machine. A normal SELECT doesn't take much
longer, so I am wondering why a simpler query isn't faster.

Define "normal SELECT". I can think of plenty of people who would be
overjoyed if their average SELECT was only a couple millisecs.

regards, tom lane

Bruce Momjian wrote:

I am timing small queries, and found that a PREPARE/EXECUTE of "SELECT
1" takes about 1.2ms on my machine. A normal SELECT doesn't take much
longer, so I am wondering why a simpler query isn't faster.

Looking at log_executor_stats, I see the following. Execute shows
nothing taking much time, mostly < .2ms, but the total seems high. I
wonder if one of our standard query start/stop functions is taking too
long and can be optimized.

There seems to be a 'PostgreSQL ping' time of about 1-2 ms in best case
conditions which limits the amount of queries you can fire off in 1
second, no matter how simple. In certain rare cases this is something
of a bottleneck. In my personal case it would be nice to see that time
lower because converted COBOL applications tend to generate a lot of
'simple' queries.

Merlin

Bruce Momjian <pgman@candle.pha.pa.us> writes:

I am timing small queries, and found that a PREPARE/EXECUTE of
"SELECT 1" takes about 1.2ms on my machine. A normal SELECT doesn't
take much longer, so I am wondering why a simpler query isn't
faster.

log_executor_stats output isn't really too helpful -- if you can get
some gprof or oprofile output, we might have a better chance of seeing
if there is anything we can improve.

-Neil

Tom Lane wrote:

Bruce Momjian <pgman@candle.pha.pa.us> writes:

I am timing small queries, and found that a PREPARE/EXECUTE of "SELECT
1" takes about 1.2ms on my machine. A normal SELECT doesn't take much
longer, so I am wondering why a simpler query isn't faster.

Define "normal SELECT". I can think of plenty of people who would be
overjoyed if their average SELECT was only a couple millisecs.

OK, you asked, so here it is. I define a simple select as pulling a
single column from a single table using uniquely indexed key. It takes
1.182 ms on my machine, almost the same time as SELECT 1.

This tells me that the actual table access isn't the issue, it is the
overhead of the query processing itself. What I want to find out is
where that 1ms is coming from, because it isn't coming from the
executor. What I might do is to add ResetUsage/ShowUsage calls around
the other parts of the query loop to find who is using the time.

I am using log_duration, so this isn't measuring network time, just time
in the backend (at least I think so).

Run the attached script through psql and you will see the times.

-- 
  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

Merlin Moncure wrote:

Bruce Momjian wrote:

I am timing small queries, and found that a PREPARE/EXECUTE of "SELECT
1" takes about 1.2ms on my machine. A normal SELECT doesn't take much
longer, so I am wondering why a simpler query isn't faster.

Looking at log_executor_stats, I see the following. Execute shows
nothing taking much time, mostly < .2ms, but the total seems high. I
wonder if one of our standard query start/stop functions is taking too
long and can be optimized.

There seems to be a 'PostgreSQL ping' time of about 1-2 ms in best case
conditions which limits the amount of queries you can fire off in 1
second, no matter how simple. In certain rare cases this is something
of a bottleneck. In my personal case it would be nice to see that time
lower because converted COBOL applications tend to generate a lot of
'simple' queries.

Yes, most of that might be network time. I am using log_duration, which
I think just tests backend time, not network transfer time, but I might
be wrong. I want to look into this as it seems no one knows the answer.

-- 
  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

Neil Conway wrote:

Bruce Momjian <pgman@candle.pha.pa.us> writes:

I am timing small queries, and found that a PREPARE/EXECUTE of
"SELECT 1" takes about 1.2ms on my machine. A normal SELECT doesn't
take much longer, so I am wondering why a simpler query isn't
faster.

log_executor_stats output isn't really too helpful -- if you can get
some gprof or oprofile output, we might have a better chance of seeing
if there is anything we can improve.

The problem with gprof is that I am going to see all the backend startup
stuff too, no? Is there a way to get a dump just the run of the query?

-- 
  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

Bruce Momjian wrote:

There seems to be a 'PostgreSQL ping' time of about 1-2 ms in best case
conditions which limits the amount of queries you can fire off in 1
second, no matter how simple. In certain rare cases this is something
of a bottleneck. In my personal case it would be nice to see that time
lower because converted COBOL applications tend to generate a lot of
'simple' queries.

Yes, most of that might be network time. I am using log_duration, which
I think just tests backend time, not network transfer time, but I might
be wrong. I want to look into this as it seems no one knows the answer.

That's easy to verify with standard ping. In my switched 100MBit
network, roundtrip for small packets is about 0.2 ms, and 0.5ms for 1kb
packets. How about context switch latency?

Regards,
Andreas

Andreas Pflug wrote:

Bruce Momjian wrote:

There seems to be a 'PostgreSQL ping' time of about 1-2 ms in best case
conditions which limits the amount of queries you can fire off in 1
second, no matter how simple. In certain rare cases this is something
of a bottleneck. In my personal case it would be nice to see that time
lower because converted COBOL applications tend to generate a lot of
'simple' queries.

Yes, most of that might be network time. I am using log_duration, which
I think just tests backend time, not network transfer time, but I might
be wrong. I want to look into this as it seems no one knows the answer.

That's easy to verify with standard ping. In my switched 100MBit
network, roundtrip for small packets is about 0.2 ms, and 0.5ms for 1kb
packets. How about context switch latency?

I am on a dual Xeon. I wouldn't think there was that much of a context
switch overhead, except for kernel calls.

-- 
  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

On Wed, Mar 10, 2004 at 11:42:12AM -0500, Bruce Momjian wrote:

I am using log_duration, so this isn't measuring network time, just time
in the backend (at least I think so).

I don't think it is.

If I do a query on localhost with lots of data, I get a small
time in the log, if I do it over a slow link the time get higher.
It changes from 1 second to 2 minutes or something.

So I think it's until the client has received the data.

Kurt

Kurt Roeckx <Q@ping.be> writes:

If I do a query on localhost with lots of data, I get a small
time in the log, if I do it over a slow link the time get higher.
It changes from 1 second to 2 minutes or something.

So I think it's until the client has received the data.

It'll at least be until the backend has been able to send the data.
However, for a small amount of retrieved data, I doubt the kernel
will make the backend wait at the send() --- if there even is one
before the log entry is made.

regards, tom lane

Merlin Moncure kirjutas K, 10.03.2004 kell 17:00:

Bruce Momjian wrote:

I am timing small queries, and found that a PREPARE/EXECUTE of "SELECT
1" takes about 1.2ms on my machine. A normal SELECT doesn't take much
longer, so I am wondering why a simpler query isn't faster.

Looking at log_executor_stats, I see the following. Execute shows
nothing taking much time, mostly < .2ms, but the total seems high. I
wonder if one of our standard query start/stop functions is taking too
long and can be optimized.

There seems to be a 'PostgreSQL ping' time of about 1-2 ms in best case
conditions which limits the amount of queries you can fire off in 1
second, no matter how simple.

Have you checked if this is a per-backend or per-connection limit?

On Wed, Mar 10, 2004 at 11:43:48AM -0500, Bruce Momjian wrote:

The problem with gprof is that I am going to see all the backend startup
stuff too, no? Is there a way to get a dump just the run of the query?

I was sort of lurking on this thread, waiting to see what became of it. Did
nobody actually come to a conclusion on what that "last msec" was from?

Alex

--
alex@posixnap.net
Alex J. Avriette, Unix Systems Gladiator

The problem with gprof is that I am going to see all the backend

startup

stuff too, no? Is there a way to get a dump just the run of the

query?

I was sort of lurking on this thread, waiting to see what became of

it.

Did
nobody actually come to a conclusion on what that "last msec" was

from?

I think the consensus was it was coming from the network layer somehow.
If that's the case (it probably is), there isn't a whole lot that can be
done about it except to bypass it using server side functions and such.

Merlin

Merlin Moncure wrote:

The problem with gprof is that I am going to see all the backend

startup

stuff too, no? Is there a way to get a dump just the run of the

query?

I was sort of lurking on this thread, waiting to see what became of

it.

Did
nobody actually come to a conclusion on what that "last msec" was

from?

I think the consensus was it was coming from the network layer somehow.
If that's the case (it probably is), there isn't a whole lot that can be
done about it except to bypass it using server side functions and such.

I did a little more research and found an unusual cause. It turns out
enabling log_parser/executor_status itself makes SELECT 1's log_duration
go from 0.296 to 1.156 so the slowness I was seeing for SELECT 1 was
from the measurement, not slowness in the normal code path.

-- 
  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

pgman wrote:

Merlin Moncure wrote:

The problem with gprof is that I am going to see all the backend

startup

stuff too, no? Is there a way to get a dump just the run of the

query?

I was sort of lurking on this thread, waiting to see what became of

it.

Did
nobody actually come to a conclusion on what that "last msec" was

from?

I think the consensus was it was coming from the network layer somehow.
If that's the case (it probably is), there isn't a whole lot that can be
done about it except to bypass it using server side functions and such.

I did a little more research and found an unusual cause. It turns out
enabling log_parser/executor_status itself makes SELECT 1's log_duration
go from 0.296 to 1.156 so the slowness I was seeing for SELECT 1 was
from the measurement, not slowness in the normal code path.

I did a litte more testing. It turns out that turning on
log_parser_stats and log_executor_stats and _not_ modifying
client_min_messages increases the execution time to 0.564 ms, and
modifying client_min_messages so the output is sent to the client
increases execution to 1.156, so the increase is half doing the time
measurements and half sending the info to the client.

-- 
  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