Re: [HACKERS] Timing of 'SELECT 1'
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 [EMAIL PROTECTED] | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup.| Newtown Square, Pennsylvania 19073 ---(end of broadcast)--- TIP 4: Don't 'kill -9' the postmaster
Re: [HACKERS] 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 -- [EMAIL PROTECTED] Alex J. Avriette, Unix Systems Gladiator ---(end of broadcast)--- TIP 5: Have you checked our extensive FAQ? http://www.postgresql.org/docs/faqs/FAQ.html
Re: [HACKERS] Timing of 'SELECT 1'
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 ---(end of broadcast)--- TIP 1: subscribe and unsubscribe commands go to [EMAIL PROTECTED]
Re: [HACKERS] Timing of 'SELECT 1'
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 ---(end of broadcast)--- TIP 5: Have you checked our extensive FAQ? http://www.postgresql.org/docs/faqs/FAQ.html
Re: [HACKERS] Timing of 'SELECT 1'
Neil Conway wrote: Bruce Momjian [EMAIL PROTECTED] 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 [EMAIL PROTECTED] | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup.| Newtown Square, Pennsylvania 19073 ---(end of broadcast)--- TIP 4: Don't 'kill -9' the postmaster
Re: [HACKERS] Timing of 'SELECT 1'
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 [EMAIL PROTECTED] | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup.| Newtown Square, Pennsylvania 19073 ---(end of broadcast)--- TIP 7: don't forget to increase your free space map settings
Re: [HACKERS] Timing of 'SELECT 1'
Tom Lane wrote:
Bruce Momjian [EMAIL PROTECTED] 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
[EMAIL PROTECTED] | (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');
---(end of broadcast)---
TIP 8: explain analyze is your friend
Re: [HACKERS] Timing of 'SELECT 1'
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 [EMAIL PROTECTED] | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup.| Newtown Square, Pennsylvania 19073 ---(end of broadcast)--- TIP 9: the planner will ignore your desire to choose an index scan if your joining column's datatypes do not match
Re: [HACKERS] Timing of 'SELECT 1'
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 ---(end of broadcast)--- TIP 4: Don't 'kill -9' the postmaster
Re: [HACKERS] Timing of 'SELECT 1'
Kurt Roeckx [EMAIL PROTECTED] 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 ---(end of broadcast)--- TIP 4: Don't 'kill -9' the postmaster
[HACKERS] Timing of 'SELECT 1'
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.26 elapsed 0.07 user 0.21 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.62 elapsed 0.04 user 0.10 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.05 elapsed 0.02 user 0.04 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.17 elapsed 0.04 user 0.12 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.37 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 [EMAIL PROTECTED] | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup.| Newtown Square, Pennsylvania 19073 ---(end of broadcast)--- TIP 6: Have you searched our list archives? http://archives.postgresql.org
Re: [HACKERS] Timing of 'SELECT 1'
Bruce Momjian [EMAIL PROTECTED] 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 ---(end of broadcast)--- TIP 2: you can get off all lists at once with the unregister command (send unregister YourEmailAddressHere to [EMAIL PROTECTED])
