Thread: Timing of 'SELECT 1'

Timing of 'SELECT 1'

From

Bruce Momjian

Date:

10 March 2004, 00:30:27

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.

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

test=> PREPARE xx AS SELECT 1;
PREPARE
-- run EXECUTE several times
test=> EXECUTE xx;
LOG:  PARSER STATISTICS
DETAIL:  ! system usage stats:
!       0.000026 elapsed 0.000007 user 0.000021 system sec
!       [0.006128 user 0.018384 sys total]
!       0/0 [17/16] filesystem blocks in/out
!       0/0 [0/0] page faults/reclaims, 0 [0] swaps
!       0 [0] signals rcvd, 0/0 [21/97] messages rcvd/sent
!       0/0 [38/78] voluntary/involuntary context switches
! buffer usage stats:
!       Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
!       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
!       Direct blocks:          0 read,          0 written
LOG:  PARSE ANALYSIS STATISTICS
DETAIL:  ! system usage stats:
!       0.000062 elapsed 0.000004 user 0.000010 system sec
!       [0.006168 user 0.018504 sys total]
!       0/0 [17/16] filesystem blocks in/out
!       0/0 [0/0] page faults/reclaims, 0 [0] swaps
!       0 [0] signals rcvd, 0/0 [21/98] messages rcvd/sent
!       0/0 [38/79] voluntary/involuntary context switches
! buffer usage stats:
!       Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
!       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
!       Direct blocks:          0 read,          0 written
LOG:  REWRITER STATISTICS
DETAIL:  ! system usage stats:
!       0.000005 elapsed 0.000002 user 0.000004 system sec
!       [0.006205 user 0.018615 sys total]
!       0/0 [17/16] filesystem blocks in/out
!       0/0 [0/0] page faults/reclaims, 0 [0] swaps
!       0 [0] signals rcvd, 0/0 [21/99] messages rcvd/sent
!       0/0 [38/80] voluntary/involuntary context switches
! buffer usage stats:
!       Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
!       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
!       Direct blocks:          0 read,          0 written
LOG:  EXECUTOR STATISTICS
DETAIL:  ! system usage stats:
!       0.000017 elapsed 0.000004 user 0.000012 system sec
!       [0.006248 user 0.018744 sys total]
!       0/0 [17/16] filesystem blocks in/out
!       0/0 [0/0] page faults/reclaims, 0 [0] swaps
!       0 [0] signals rcvd, 0/0 [21/100] messages rcvd/sent
!       0/0 [38/81] voluntary/involuntary context switches
! buffer usage stats:
!       Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
!       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
!       Direct blocks:          0 read,          0 written
LOG:  EXECUTOR STATISTICS
DETAIL:  ! system usage stats:
!       0.000288 elapsed 0.000037 user 0.000113 system sec
!       [0.006281 user 0.018845 sys total]
!       0/0 [17/16] filesystem blocks in/out
!       0/0 [0/0] page faults/reclaims, 0 [0] swaps
!       0 [0] signals rcvd, 0/1 [21/101] messages rcvd/sent
!       0/1 [38/82] voluntary/involuntary context switches
! buffer usage stats:
!       Shared blocks:          0 read,          0 written, buffer hit rate = 0.00%
!       Local  blocks:          0 read,          0 written, buffer hit rate = 0.00%
!       Direct blocks:          0 read,          0 written
LOG:  duration: 1.230 ms?column?
----------       1
(1 row)

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


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

Re: Timing of 'SELECT 1'

From

Tom Lane

Date:

10 March 2004, 02:13:24

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

Re: Timing of 'SELECT 1'

From

"Merlin Moncure"

Date:

10 March 2004, 11:00:13

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

Re: Timing of 'SELECT 1'

From

Bruce Momjian

Date:

10 March 2004, 14:41:55

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

Re: Timing of 'SELECT 1'

From

Bruce Momjian

Date:

10 March 2004, 14:51:33

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

Re: Timing of 'SELECT 1'

From

Bruce Momjian

Date:

10 March 2004, 14:53:39

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
\set ECHO all
\timing
DROP TABLE perftest;
CREATE TABLE perftest (col text);

-- prime table with one row
INSERT INTO perftest VALUES ('0.364461265208414');

-- continously double the table size
INSERT INTO perftest SELECT random()::text FROM perftest;
INSERT INTO perftest SELECT random()::text FROM perftest;
INSERT INTO perftest SELECT random()::text FROM perftest;
INSERT INTO perftest SELECT random()::text FROM perftest;
INSERT INTO perftest SELECT random()::text FROM perftest;
INSERT INTO perftest SELECT random()::text FROM perftest;
INSERT INTO perftest SELECT random()::text FROM perftest;
INSERT INTO perftest SELECT random()::text FROM perftest;
INSERT INTO perftest SELECT random()::text FROM perftest;
INSERT INTO perftest SELECT random()::text FROM perftest;
INSERT INTO perftest SELECT random()::text FROM perftest;
INSERT INTO perftest SELECT random()::text FROM perftest;
INSERT INTO perftest SELECT random()::text FROM perftest;
INSERT INTO perftest SELECT random()::text FROM perftest;

-- insert a constant in the middle of the table, for use later
INSERT INTO perftest VALUES ('0.608254158221304');
INSERT INTO perftest SELECT random()::text FROM perftest;
-- 32770 rows

-- vacuum, create index
VACUUM ANALYZE perftest;
CREATE INDEX i_perftest ON perftest (col);
-- reduce chance of checkpoint during tests
CHECKPOINT;

-- turn on logging
SET log_duration = TRUE;
SET client_min_messages = 'log';

-- run normal and prepared queries
SELECT col FROM perftest WHERE col = '0.608254158221304';
SELECT col FROM perftest WHERE col = '0.608254158221304';
SELECT col FROM perftest WHERE col = '0.608254158221304';
SELECT col FROM perftest WHERE col = '0.608254158221304';
SELECT col FROM perftest WHERE col = '0.608254158221304';
PREPARE perftest_prep (text) AS SELECT col FROM perftest WHERE col = $1;
EXECUTE perftest_prep ('0.608254158221304');
EXECUTE perftest_prep ('0.608254158221304');
EXECUTE perftest_prep ('0.608254158221304');
EXECUTE perftest_prep ('0.608254158221304');
EXECUTE perftest_prep ('0.608254158221304');

-- first time the entire statement
SET log_statement_stats = TRUE;

-- run normal and prepared queries
SELECT col FROM perftest WHERE col = '0.608254158221304';
SELECT col FROM perftest WHERE col = '0.608254158221304';
SELECT col FROM perftest WHERE col = '0.608254158221304';
SELECT col FROM perftest WHERE col = '0.608254158221304';
SELECT col FROM perftest WHERE col = '0.608254158221304';
PREPARE perftest_prep (text) AS SELECT col FROM perftest WHERE col = $1;
EXECUTE perftest_prep ('0.608254158221304');
EXECUTE perftest_prep ('0.608254158221304');
EXECUTE perftest_prep ('0.608254158221304');
EXECUTE perftest_prep ('0.608254158221304');
EXECUTE perftest_prep ('0.608254158221304');

-- now log each query stage
SET log_statement_stats = FALSE;
SET log_parser_stats = TRUE;
SET log_planner_stats = TRUE;
SET log_executor_stats = TRUE;

-- run normal and prepared queries
SELECT col FROM perftest WHERE col = '0.608254158221304';
SELECT col FROM perftest WHERE col = '0.608254158221304';
SELECT col FROM perftest WHERE col = '0.608254158221304';
SELECT col FROM perftest WHERE col = '0.608254158221304';
SELECT col FROM perftest WHERE col = '0.608254158221304';
EXECUTE perftest_prep ('0.608254158221304');
EXECUTE perftest_prep ('0.608254158221304');
EXECUTE perftest_prep ('0.608254158221304');
EXECUTE perftest_prep ('0.608254158221304');
EXECUTE perftest_prep ('0.608254158221304');

Re: Timing of 'SELECT 1'

From

Neil Conway

Date:

10 March 2004, 14:56:37

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

Re: Timing of 'SELECT 1'

From

Bruce Momjian

Date:

10 March 2004, 15:34:33

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

Re: Timing of 'SELECT 1'

From

Andreas Pflug

Date:

10 March 2004, 15:43:18

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

Re: Timing of 'SELECT 1'

From

Kurt Roeckx

Date:

10 March 2004, 15:50:36

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

Re: Timing of 'SELECT 1'

From

Tom Lane

Date:

10 March 2004, 16:36:46

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

Re: Timing of 'SELECT 1'

From

Hannu Krosing

Date:

10 March 2004, 16:38:51

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?  

> 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
> 
> ---------------------------(end of broadcast)---------------------------
> TIP 5: Have you checked our extensive FAQ?
> 
>                http://www.postgresql.org/docs/faqs/FAQ.html

Re: Timing of 'SELECT 1'

From

"Alex J. Avriette"

Date:

12 March 2004, 07:00:55

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

Re: Timing of 'SELECT 1'

From

"Merlin Moncure"

Date:

12 March 2004, 14:29:59

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

Re: Timing of 'SELECT 1'

From

Bruce Momjian

Date:

13 March 2004, 23:44:29

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

Re: Timing of 'SELECT 1'

From

Bruce Momjian

Date:

14 March 2004, 19:48:28

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