Обсуждение: 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.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
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
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
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
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');
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
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
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
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? > 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
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, Pennsylvania19073
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