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, Pennsylvania 19073

Tue, 9 Mar 2004 23:30:10 -0500 (EST)
Bruce Momjian <pgman@candle.pha.pa.us>
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

Wed, 10 Mar 2004 01:13:16 -0500
Tom Lane <tgl@sss.pgh.pa.us>
Re: 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.

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


Wed, 10 Mar 2004 11:39:57 -0500
Neil Conway <neilc@samurai.com>
Re: Timing of 'SELECT 1'
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');
Wed, 10 Mar 2004 11:42:12 -0500 (EST)
Bruce Momjian <pgman@candle.pha.pa.us>
Re: Timing of 'SELECT 1'
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

Wed, 10 Mar 2004 11:43:48 -0500 (EST)
Bruce Momjian <pgman@candle.pha.pa.us>
Re: Timing of 'SELECT 1'
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


Wed, 10 Mar 2004 20:47:54 +0100
Kurt Roeckx <Q@ping.be>
Re: Timing of 'SELECT 1'
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

Wed, 10 Mar 2004 15:04:50 -0500
Tom Lane <tgl@sss.pgh.pa.us>
Re: Timing of 'SELECT 1' 
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

Fri, 12 Mar 2004 06:05:27 -0500
"Alex J. Avriette" <alex@posixnap.net>
Re: Timing of 'SELECT 1'