X-Original-To: pgsql-performance-postgresql.org@localhost.postgresql.org Received: from localhost (mx1.hub.org [200.46.208.251]) by postgresql.org (Postfix) with ESMTP id F38B79F9B01 for ; Mon, 22 May 2006 14:20:24 -0300 (ADT) Received: from postgresql.org ([200.46.204.71]) by localhost (mx1.hub.org [200.46.208.251]) (amavisd-new, port 10024) with ESMTP id 76176-01 for ; Mon, 22 May 2006 14:20:11 -0300 (ADT) X-Greylist: domain auto-whitelisted by SQLgrey- Received: from wx-out-0102.google.com (wx-out-0102.google.com [66.249.82.200]) by postgresql.org (Postfix) with ESMTP id 1BDB99F9D99 for ; Mon, 22 May 2006 14:20:10 -0300 (ADT) Received: by wx-out-0102.google.com with SMTP id i28so211946wxd for ; Mon, 22 May 2006 10:20:09 -0700 (PDT) DomainKey-Signature: a=rsa-sha1; q=dns; c=nofws; s=beta; d=gmail.com; h=received:message-id:date:from:reply-to:to:subject:cc:mime-version:content-type; b=fn6WBQ9mR/RXtviYYyJjZ7BqupOHqq/hn3Dx5m77UbT4Sc904hIhUhbHYzPC8KEj5tsA+hYWaGo2qC4F10uTdfuMx3+inwts1NIat7H05DFxjqw7OWADdXNof6J/yyrkUhl1UFg8e9qzliUcQ9pi/b4QQkES8O1kfrsxsgJgmWg= Received: by 10.70.31.19 with SMTP id e19mr5392923wxe; Mon, 22 May 2006 10:20:09 -0700 (PDT) Received: by 10.70.38.2 with HTTP; Mon, 22 May 2006 10:20:09 -0700 (PDT) Message-ID: Date: Mon, 22 May 2006 12:20:09 -0500 From: "Meetesh Karia" Reply-To: meetesh.karia@alumni.duke.edu To: pgsql-performance@postgresql.org Subject: Query hanging/not finishing inconsistently Cc: "Jean-David Dahan" MIME-Version: 1.0 Content-Type: multipart/alternative; boundary="----=_Part_23864_27685936.1148318409488" X-Virus-Scanned: Maia Mailguard 1.0.1 X-Archive-Number: 200605/421 X-Sequence-Number: 19208 ------=_Part_23864_27685936.1148318409488 Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: quoted-printable Content-Disposition: inline Hi all, We've recently started having a problem where a query that normally execute= s in ~15ms starts to take upwards of 20s to complete. When the connection that ran query is returned to the connection pool, it appears as though a transaction is still in progress so the connection pool tries to cancel the transaction and close the connection. This fails and the connection is removed from the connection pool. At this point, the situation rapidly degrades and we run out of connections to the postgres server. An inspection of the pg_stat_activity table shows that practically every connection is running the above-mentioned query and some of those queries have been active for many minutes! We've looked at the pg_locks table as well and the only exclusive locks are on transactions that are open. All other locks are AccessShareLocks. Also, as far as we can tell (from lookin= g at the Hibernate stats), every db session that is opened is closed. When this happens, if I kill one of the running postgres processes (just by picking the last process returned from "ps -ef | grep postgres"), the other queries will immediately finish and the system will respond. However, within 15 minutes, we'll be back in the same state as before. At that point, I've cycled Apache, Tomcat and Postgres and the system then seems to come back. This problem appears to be unrelated to load and in fact, the majority of the time there is very little load on the site when this occurs. We've run load tests on our dev boxes but we've been unable to reproduce the problem. We're currently working on playing back the clicks on the site previous to the weird state the site gets in and at the same time, we were wondering if anyone has experienced a problem like this or has any suggestions. The query in question is: select distinct s.screening_id, f.film_id, f.title, s.period_start, f.runtime, c.value, v.short_name, s.parent_id, stats.avg_rating, coalesce(stats.num_adds, 0) as num_adds, coalesce= ( stats.unique_visits, 0) as unique_visits, f.*, s.* from lte_screening s inner join lte_film f on s.film_id =3D f.film_id inner join lte_venue v on s.venue_id =3D v.venue_id inner join lte_film_classifier c on c.film_id =3D f.film_id left join lte_film_stats stats on stats.context =3D :context and stats.film_id =3D s.film_id where c.name =3D ? and s.period_start is not null and s.festival_id =3D= ? and s.period_start between ? + ? and ? + ? order by s.period_start, f.title; And the result of explain analyze: QUERY PLAN Unique (cost=3D1117.42..1118.71 rows=3D11 width=3D866) (actual time=3D 18.306..18.386 rows=3D15 loops=3D1) -> Sort (cost=3D1117.42..1117.44 rows=3D11 width=3D866) (actual time=3D 18.300..18.316 rows=3D15 loops=3D1) Sort Key: s.period_start, f.title, s.screening_id, f.film_id, f.runtime, c.value, v.short_name, s.parent_id, stats.avg_rating, COALESCE( stats.num_adds, 0), COALESCE(stats.unique_visits, 0::bigint), f.film_id, f.sku, f.title, f."template", f.release_date, f.runtime, f."language", f.country, f.mpaa_rating, f.synopsis, f."owner", f.ext_sales_rank, f.small_image_url, f.medium_image_url, f.large_image_url, f.detail_page, f.to_delete, f.coalesce_to, (subplan), (subplan), s.screening_id, s.period_start, s.period_end, s.ticket_price, s.tickets_avail, s.tickets_sold, s."type", s.venue_id, s.festival_id, s.film_id, s.parent_id= , s.ext_id, s.purchase_url, s.status, s.status_update_time -> Nested Loop Left Join (cost=3D2.62..1117.23 rows=3D11 width=3D= 866) (actual time=3D2.656..17.773 rows=3D15 loops=3D1) -> Nested Loop (cost=3D2.62..976.00 rows=3D11 width=3D846) = (actual time=3D2.347..16.162 rows=3D15 loops=3D1) -> Hash Join (cost=3D2.62..929.09 rows=3D10 width=3D8= 31) (actual time=3D2.217..15.480 rows=3D15 loops=3D1) Hash Cond: ("outer".venue_id =3D "inner".venue_id= ) -> Nested Loop (cost=3D0.00..926.32 rows=3D10 width=3D818) (actual time=3D1.915..14.974 rows=3D15 loops=3D1) -> Seq Scan on lte_screening s (cost=3D 0.00..886.67 rows=3D10 width=3D159) (actual time=3D1.830..14.314 rows=3D15 = loops=3D1) Filter: ((period_start IS NOT NULL) AND (festival_id =3D 316372) AND (period_start >=3D '2006-05-19 05:00:00'::timestamp without time zone) AND (period_start <=3D '2006-05-20 04:59:59'::timestamp without time zone)) -> Index Scan using lte_film_pkey on lte_film f (cost=3D0.00..3.95 rows=3D1 width=3D659) (actual time=3D0.026..0.028rows=3D1 loops=3D15) Index Cond: ("outer".film_id =3D f.film_id) -> Hash (cost=3D2.50..2.50 rows=3D50 width=3D21= ) (actual time=3D0.215..0.215 rows=3D0 loops=3D1) -> Seq Scan on lte_venue v (cost=3D 0.00..2.50 rows=3D50 width=3D21) (actual time=3D0.012..0.126 rows=3D52 loop= s=3D1) -> Index Scan using idx_classifier_film on lte_film_classifier c (cost=3D0.00..4.67 rows=3D2 width=3D23) (actual time= =3D 0.026..0.028 rows=3D1 loops=3D15) Index Cond: (c.film_id =3D "outer".film_id) Filter: ((name)::text =3D 'FestivalCategory'::tex= t) -> Index Scan using lte_film_stats_pkey on lte_film_stats stats (cost=3D0.00..4.34 rows=3D1 width=3D28) (actual time=3D0.034..0.037 = rows=3D1 loops=3D15) Index Cond: ((stats.context =3D 316372) AND (stats.film_id=3D "outer".film_id)) SubPlan -> Index Scan using idx_collateral_film on lte_film_collateral c (cost=3D0.00..4.24 rows=3D1 width=3D40) (actual time= =3D 0.009..0.011 rows=3D1 loops=3D15) Index Cond: (film_id =3D $0) Filter: ((name)::text =3D 'TVRating'::text) -> Index Scan using idx_collateral_film on lte_film_collateral c (cost=3D0.00..4.24 rows=3D1 width=3D40) (actual time= =3D 0.022..0.025 rows=3D1 loops=3D15) Index Cond: (film_id =3D $0) Filter: ((name)::text =3D 'IMDBId'::text) Total runtime: 19.077 ms Here is our setup: We have 2 machines. The first is the web server and the db server and the second is just another web server: Machine A - 1 GB RAM - 1 Intel(R) Xeon(TM) CPU 2.80GHz HyperThreaded Processor - CentOS 4.3 - Linux moe 2.6.9-22.ELsmp #1 SMP Sat Oct 8 19:11:43 CDT 2005 i686 i686 i38= 6 GNU/Linux Machine B - 1 GB RAM - 1 Intel(R) Xeon(TM) CPU 2.80GHz Processor - CentOS 4.3 - Linux larry 2.6.9-22.0.1.EL #1 Thu Oct 27 12:26:11 CDT 2005 i686 i686 i38= 6 GNU/Linux We're using the following software: - Apache 2.0.52 - Tomcat 5.5.17 - Postgres 8.0.6 - JDK 1.5.0-Release 6 - Proxool 0.8.3 - Hibernate 3.1.3 Thanks in advance for any help, Meetesh ------=_Part_23864_27685936.1148318409488 Content-Type: text/html; charset=ISO-8859-1 Content-Transfer-Encoding: quoted-printable Content-Disposition: inline Hi all,

We've recently started having a problem where a query that n= ormally executes in ~15ms starts to take upwards of 20s to complete.  = When the connection that ran query is returned to the connection pool, it a= ppears as though a transaction is still in progress so the connection pool = tries to cancel the transaction and close the connection.  This fails = and the connection is removed from the connection pool.  At this point= , the situation rapidly degrades and we run out of connections to the postg= res server.

An inspection of the pg_stat_activity table shows that practically = every connection is running the above-mentioned query and some of those que= ries have been active for many minutes!  We've looked at the pg_locks = table as well and the only exclusive locks are on transactions that are ope= n.  All other locks are AccessShareLocks.  Also, as far as we can= tell (from looking at the Hibernate stats), every db session that is opene= d is closed.

When this happens, if I kill one of the running postgres processes = (just by picking the last process returned from "ps -ef | grep postgre= s"), the other queries will immediately finish and the system will res= pond.  However, within 15 minutes, we'll be back in the same state as = before.  At that point, I've cycled Apache, Tomcat and Postgres and th= e system then seems to come back.

This problem appears to be unrelated to load and in fact, the major= ity of the time there is very little load on the site when this occurs.&nbs= p; We've run load tests on our dev boxes but we've been unable to reproduce= the problem.  We're currently working on playing back the clicks on t= he site previous to the weird state the site gets in and at the same time, = we were wondering if anyone has experienced a problem like this or has any = suggestions.

The query in question is:

select distinct s.screening_id, f.film_id, f.title, s.per= iod_start, f.runtime, c.value, v.short_name, s.parent_id,
    = ;    stats.avg_rating, coalesce(stats.num_adds, 0) as num_ad= ds, coalesce(stats.unique_visits, 0) as unique_visits,
    = ;    f.*, s.*
  &= nbsp; from lte_screening s
    = ;    inner join lte_film f on s.film_id =3D f.film_id=
        inner= join lte_venue v on=20 s.venue_id =3D v.venue_id
  &nbs= p;     inner join lte_film_classifier c on c.film_id = =3D f.film_id
    = ;    left join lte_film_stats stats on stats.context =3D :co= ntext and stats.film_id =3D s.film_id
    where c.name =3D ? and s.p= eriod_start is not null and s.festival_id =3D ?
        and s.period_start between ? + ? and ? + ?
   = ; order by s.period_start, f.title;

And the result of explain= analyze:

QUERY PLAN
Unique  (cost=3D1117.42..1118.71 rows=3D11 width= =3D866) (actual time=3D 18.306..18.386 rows=3D15 loops=3D1)
 = ->  Sort  (cost=3D1117.42..1117.44 rows=3D11 width=3D866) (ac= tual time=3D18.300..18.316 rows=3D15 loops=3D1)
       = ; Sort Key: s.period_start, f.title, s.screening_id, f.film_id, f.runtime, = c.value, v.short_name, s.parent_id,=20 stats.avg_rating, COALESCE(stats.num_adds, 0), COALESCE(stats.unique_visits= , 0::bigint), f.film_id, f.sku, f.title, f."template", f.release_= date, f.runtime, f."language", f.country, f.mpaa_rating, f.synops= is , f."owner", f.ext_sales_rank, f.small_image_url, f.medium_image_= url, f.large_image_url, f.detail_page, f.to_delete, f.coalesce_to, (subplan= ), (subplan), s.screening_id, s.period_start, s.period_end, s.ticket_price , s.tickets_avail, s.tickets_sold, s."type", s.venue_id, s.festiv= al_id, s.film_id, s.parent_id, s.ext_id, s.purchase_url, s.status, s.status= _update_time
        ->  Nested Loop Left Joi= n  (cost=3D2.62..1117.23 rows=3D11 width=3D866) (actual time=3D2.656..= 17.773 rows=3D15 loops=3D1)
            &nb= sp; ->  Nested Loop  (cost=3D2.62..976.00 rows=3D11 width=3D84= 6) (actual time=3D2.347..16.162 rows=3D15 loops=3D1)
          &nbs= p;         ->  Hash Join&nb= sp; (cost=3D 2.62..929.09 rows=3D10 width=3D831) (actual time=3D2.217..15.480 rows=3D15 = loops=3D1)
     &= nbsp;           &nbs= p;        Hash Cond: ("outer".= venue_id =3D "inner".venue_id)
       = ;            &n= bsp;      ->  Nested Loop  (cost=3D0.= 00..926.32 rows=3D10 width=3D818) (actual time=3D1.915..14.974 rows=3D15 lo= ops=3D1)
       = ;            &n= bsp;            ->= ;  Seq Scan on lte_screening s  (cost=3D0.00..886.67 rows=3D10 wi= dth=3D159) (actual time=3D 1.830..14.314 rows=3D15 loops=3D1)
 &= nbsp;           &nbs= p;            &= nbsp;           Filter: (= (period_start IS NOT NULL) AND (festival_id =3D 316372) AND (period_start &= gt;=3D '2006-05-19 05:00:00'::timestamp without time zone) AND (period_star= t <=3D '2006-05-20 04:59:59'::timestamp without time zone))
       = ;            &n= bsp;            ->= ;  Index Scan using lte_film_pkey on lte_film f  (cost=3D0.00..3.= 95 rows=3D1 width=3D659) (actual time=3D 0.026..0.028 rows=3D1 loops=3D15)
 &n= bsp;            = ;            &n= bsp;           Index Cond= : ("outer".film_id =3D f.film_id )
      &nbs= p;            &= nbsp;      ->  Hash  (cost=3D2.50..2.= 50 rows=3D50 width=3D21) (actual time=3D0.215..0.215 rows=3D0 loops=3D1)
       = ;            &n= bsp;            ->= ;  Seq Scan on lte_venue v  (cost=3D0.00..2.50 rows=3D50 width=3D= 21) (actual time=3D0.012..0.126 rows=3D52 loops=3D1)
   &n= bsp;            = ;    ->  Index Scan using idx_classifier_film on lte= _film_classifier c  (cost=3D0.00..4.67 rows=3D2 width=3D23) (actual time=3D0.026..0.028 rows=3D1 loops=3D15)
       &nbs= p;            &= nbsp;     Index Cond: (c.film_id =3D "outer".= film_id)
       = ;            &n= bsp;      Filter: ((name)::text =3D 'FestivalCateg= ory'::text)
    = ;          ->  Index S= can using lte_film_stats_pkey on lte_film_stats stats  (cost=3D0.00..4= .34 rows=3D1 width=3D28) (actual time=3D0.034..0.037 rows=3D1 loops=3D15)
    = ;            &n= bsp;   Index Cond: ((stats.context =3D 316372) AND (stats.film_id= =3D "outer".film_id))
            &nb= sp; SubPlan
     =            ->  In= dex Scan using idx_collateral_film on lte_film_collateral c  (cost=3D0= .00..4.24 rows=3D1 width=3D40) (actual time=3D0.009..0.011 rows=3D1 loops=3D15)
       &nbs= p;            &= nbsp; Index Cond: (film_id =3D $0)
    = ;            &n= bsp;     Filter: ((name)::text =3D 'TVRating'::text)
       &n= bsp;        ->  Index Scan using= idx_collateral_film on lte_film_collateral c  (cost=3D 0.00..4.24 rows=3D1 width=3D40) (actual time=3D0.022..0.025 rows=3D1 loops= =3D15)
     &nbs= p;            &= nbsp;   Index Cond: (film_id =3D $0)
       = ;            &n= bsp;  Filter: ((name)::text =3D 'IMDBId'::text)
Total runtime: 19.077 m= s


Here is our setup:

We have 2 machines.  The= first is the web server and the db server and the second is just another w= eb server:

Machine A
- 1 GB RAM
- 1 Intel(R) Xeon(TM) CPU 2.80GHz HyperT= hreaded Processor
- CentOS 4.3
- Linux moe 2.6.9-22.ELsmp #1 SMP Sat = Oct 8 19:11:43 CDT 2005 i686 i686 i386 GNU/Linux

Machine B
- 1 GB= RAM
- 1 Intel(R) Xeon(TM) CPU 2.80GHz Processor
- CentOS 4.3
- Linux larry 2.6.9-22.0.1.EL #1 Thu Oct 27 12:26:11 CDT 2005 i686 i686 i38= 6 GNU/Linux

We're using the following software:
- Apache 2.0.52- Tomcat 5.5.17
- Postgres 8.0.6
- JDK 1.5.0-Release 6
- Proxool= =20 0.8.3
- Hibernate 3.1.3

Thanks in advance for any help,
Meetes= h
------=_Part_23864_27685936.1148318409488--