Thread: query execution time
Hello, everybody recently I have found that queries on our customer database take longer to execute than normally. First thing we did was to log long queries. This led to nothing as queries logged are usually executed fast. On the other hand sometimes they take considerable amount of time... Then we tried using EXPLAIN ANALYZE - that brings me to the question: "Total runtime" of the query provided by the EXPLAIN ANALYZE is 0.200ms, but the result of it comes after sometimes 0.2, sometimes 5 seconds. We use pgAdmin tool to query the DB - it shows how long the query took to execute. The question is why the difference of value provided by EXPLAIN ANALYZE and observed one is so big? I know explain analyze has its overheads, but query itself takes long to execute. Also we've checked if the internet traffic is not too high - it appears not even close... Now I have run out of ideas what to check... Can you give me a hint what else can cause such behavior ? Thank You in advance.] Julius Tuskenis
Julius T <julius@nsoft.lt> wrote: > The question is why the difference of value provided by EXPLAIN > ANALYZE and observed one is so big? There can be a number of reasons. The time to transmit the query results to the client is one that jumps to mind, if the query generates a large result set. Parts of what you described might suggest checkpoint issues, depending on the query mix, the PostgreSQL version, the hardware and the OS. You haven't given us enough information to even start to guess which of these or other issues might be involved. Please read this page, and repost with more information: http://wiki.postgresql.org/wiki/SlowQueryQuestions -Kevin
Hello, I would try reindexing it is not said that it will be the case but sometimes it may be helpful. Regards Luke 2010/10/5, Julius T <julius@nsoft.lt>: > Hello, everybody > > recently I have found that queries on our customer database take longer to > execute than normally. > > First thing we did was to log long queries. This led to nothing as queries > logged are usually executed fast. On the other hand sometimes they take > considerable amount of time... Then we tried using EXPLAIN ANALYZE - that > brings me to the question: > "Total runtime" of the query provided by the EXPLAIN ANALYZE is 0.200ms, but > the result of it comes after sometimes 0.2, sometimes 5 seconds. We use > pgAdmin tool to query the DB - it shows how long the query took to execute. > The question is why the difference of value provided by EXPLAIN ANALYZE and > observed one is so big? I know explain analyze has its overheads, but query > itself takes long to execute. Also we've checked if the internet traffic is > not too high - it appears not even close... Now I have run out of ideas what > to check... Can you give me a hint what else can cause such behavior ? > > Thank You in advance.] > > Julius Tuskenis > > > > > > -- > Sent via pgsql-admin mailing list (pgsql-admin@postgresql.org) > To make changes to your subscription: > http://www.postgresql.org/mailpref/pgsql-admin > -- Łukasz Brodziak II MU Bioinformatyka
2010.10.06 00:30, Kevin Grittner rašė: > There can be a number of reasons. The time to transmit the query > results to the client is one that jumps to mind, if the query > generates a large result set. Parts of what you described might > suggest checkpoint issues, depending on the query mix, the > PostgreSQL version, the hardware and the OS. Version string: PostgreSQL 8.3.4 on i686-pc-linux-gnu, compiled by GCC gcc (GCC) 4.1.2 (Gentoo 4.1.2 p1.0.2) > You haven't given us > enough information to even start to guess which of these or other > issues might be involved. Yes, you are right, but there is not much I can send you, because there are several unrelated queries that act the same way (that is have "jumping" execution times). If you please see https://sites.google.com/site/juliaustestukas/Home I think the picture would explain the problem better then I can... I have put red ellipses around the times that are too different. Maybe you know what is done after the query is executed? As I said the traffic limit is not reached. There must be something else. If there was a hardware issue I guess the EXPLAIN ANALYZE would show the execution time comparable to the observed one... One more thing that may be connected to this - the encoding was changed for DB using instructions on http://bryan-murdock.blogspot.com/2008/11/convert-postgresql-database-from-latin1.html . We converted it to UTF-8 from SQL_ASCII . Manual vacuum was executed after that. The settings for autovacuum were not changed so it is enabled by default on every table. Please, could you provide information what actions does the postgres take after it does actions monitored by EXPLAIN ANALYZE? Could it be libpq issue (pgAdmin uses it)? -- Julius Tuskenis Programavimo skyriaus vadovas UAB nSoft mob. +37068233050
Julius Tuskenis <julius@nsoft.lt> wrote: > 2010.10.06 00:30, Kevin Grittner raš*: >> There can be a number of reasons. The time to transmit the query >> results to the client is one that jumps to mind, if the query >> generates a large result set. Parts of what you described might >> suggest checkpoint issues, depending on the query mix, the >> PostgreSQL version, the hardware and the OS. > Version string: PostgreSQL 8.3.4 on i686-pc-linux-gnu, compiled > by GCC gcc (GCC) 4.1.2 (Gentoo 4.1.2 p1.0.2) > https://sites.google.com/site/juliaustestukas/Home Well, you're showing us a version string for a Linux PostgreSQL server, but you link to a screen shot which appears to be a client connecting to localhost on some variety of Windows. And you didn't tell us much of anything else. > I think the picture would explain the problem better then I can... > I have put red ellipses around the times that are too different. In my experience, when the time the server reports for query execution is significantly less than the time the client reports for running the query, the difference is time spent in the network or client. Since you seem to be using localhost, I think we can rule out the network as a significant factor. > One more thing that may be connected to this > We converted [the database] to UTF-8 from SQL_ASCII I suppose it's not impossible that this could have some impact on the client, particularly if it was competing with a busy database server on the same machine. > Please, could you provide information what actions does the > postgres take after it does actions monitored by EXPLAIN ANALYZE? I believe that by the time it comes up with that final timing, it has completed the query run and put all results into the OS networking buffers. What PostgreSQL would do next is wait for another request. -Kevin
2010.10.06 17:03, Kevin Grittner rašė: >> Version string: PostgreSQL 8.3.4 on i686-pc-linux-gnu, compiled >> by GCC gcc (GCC) 4.1.2 (Gentoo 4.1.2 p1.0.2) >> https://sites.google.com/site/juliaustestukas/Home > > Well, you're showing us a version string for a Linux PostgreSQL > server, but you link to a screen shot which appears to be a client > connecting to localhost on some variety of Windows. And you didn't > tell us much of anything else. You are right - we connect to localhost on windows machine because we use ssh tunel to the postgresql server on gentoo linux. The server does not have GUI, so no pgAdmin too... The DB is used for web application writen in PHP. As the DB and WEB servers are on the same machine we can rule out the network issues I guess... The query (in the screen shot) was found in postgresql server logs as a long lasting query. I will try issue the EXPLAIN ANALIZE query from the command line on server machine to be 100% sure this is not related to networking. The behavior described is observed when there is high server usage. Using "server status" tool shows several such queries executed suddenly and then after some waiting everything goes back to normal. The top command on the server shows it has enough of ram (~200Mb free all the time). -- Julius Tuskenis Programavimo skyriaus vadovas UAB nSoft mob. +37068233050
Julius Tuskenis <julius@nsoft.lt> wrote: > we connect to localhost on windows machine because we > use ssh tunel to the postgresql server on gentoo linux. Latency in the extra hop or from encryption/decryption of the streams could account for at least some of the difference between how long it took the server to run the query versus the elapsed time between when the client started sending it out and when it got the last of the response. > The DB is used for web application writen in PHP. As the DB and > WEB servers are on the same machine we can rule out the network > issues I guess... What you can't rule out is the possibility that the web app thread reading the response doesn't get a time slice for some time after the database is done. > The behavior described is observed when there is high server > usage. Using "server status" tool shows several such queries > executed suddenly and then after some waiting everything goes back > to normal. Can you run `vmstat 1` and see what it shows during an episode? This could be particularly valuable if you can timestamp the lines to compare to log entries. You might want to turn on checkpoint logging. Again, we don't know anything about the amount of RAM, your postgresql.conf settings, your disk subsystem (particularly your RAID adapter and its configuration), etc. With more information we can give better advice. -Kevin