Re: Strange behaviour with a query

Hi everybody again.

Deleting rel_dis_can_fk index has solved the problem! But.... why??

-----Original Message-----
From: Iñigo Martinez Lasala <imartinez(at)vectorsf(dot)com>
To: pgsql-admin <pgsql-admin(at)postgresql(dot)org>
Cc: Jaume Sabater <jsabater(at)gmail(dot)com>, Sergio Chavarria
<sergio(dot)chavarria(at)gmail(dot)com>
Subject: Strange behaviour with a query
Date: Fri, 17 Apr 2009 10:44:29 +0200

In a production enviroment over Postgresql 8.2.13, we have found some queries take forever without finish until statement_timeout enters in play.
These queries are like this one:

SELECT ART.ART_ID, DIS.DIS_HORAS, ART.TIP_ID FROM ARTICULO ART,DISPONIBILIDAD DIS, ENTE ENT, PARTICIPACION PAR,CANCION C WHERE (ART.ART_APROBADO = 1)
AND ((ART.ART_SHOW_ANYWAY = 1) OR (ART.ART_STOCK_ALMACEN_CENTRAL >=1) OR (ART.ART_STOCK_LOCAL >=1) OR (ART.ART_STOCK_LOCAL_2 >= 1) OR (ART.ART_STOCK >= 1))
AND (ART_DESCATALOGADO != 1) AND (ART_BUYABLE = 1) AND (NVL(ART.ART_PRECIO_FNAC_WEB,0) > 0) AND (ART.ART_PMP is not null) AND ART.TIP_ID =1 AND
( (ENT.ent_nombre_search_string % 'COS') ) AND PAR.ROL_ID = 100004 AND PAR.ENT_ID = ENT.ENT_ID AND PAR.ART_ID = ART.ART_ID AND ( (c.can_nombre_search_string % 'WHAT') )
AND C.ART_ID = ART.ART_ID AND DIS.DIS_ID = ART.DIS_ID AND ART.PRE_ID = 5 ORDER BY DIS.DIS_HORAS, ART_FECHA_UP DESC LIMIT 100;

Explain:
"Limit (cost=2213.67..2213.67 rows=1 width=40)"
" -> Sort (cost=2213.67..2213.67 rows=1 width=40)"
" Sort Key: dis.dis_horas, art.art_fecha_up"
" -> Nested Loop (cost=47.44..2213.66 rows=1 width=40)"
" Join Filter: (dis.dis_id = art.dis_id)"
" -> Nested Loop (cost=47.44..2212.39 rows=1 width=40)"
" -> Nested Loop (cost=47.44..2211.89 rows=1 width=52)"
" -> Nested Loop (cost=0.00..2160.43 rows=1 width=64)"
" -> Index Scan using ix_pre_id on articulo art (cost=0.00..2134.34 rows=3 width=40)"
" Index Cond: (pre_id = 5::numeric)"
" Filter: ((art_aprobado = 1::numeric) AND ((art_show_anyway = 1::numeric) OR (art_stock_almacen_central >= 1::numeric) OR (art_stock_local >= 1::numeric) OR (art_stock_local_2 >= 1::numeric) OR (art_stock >= 1::numeric)) AND (art_descatalogado <> 1::numeric) AND (art_buyable = 1::numeric) AND (nvl(art_precio_fnac_web, 0::numeric) > 0::numeric) AND (art_pmp IS NOT NULL) AND (tip_id = 1::numeric))"
" -> Index Scan using rel_participacion_articulo_fk on participacion par (cost=0.00..8.68 rows=1 width=24)"
" Index Cond: (par.art_id = art.art_id)"
" Filter: (rol_id = 100004::numeric)"
" -> Bitmap Heap Scan on cancion c (cost=47.44..51.45 rows=1 width=12)"
" Recheck Cond: ((c.art_id = art.art_id) AND ((c.can_nombre_search_string)::text % 'NOMBRE'::text))"
" -> BitmapAnd (cost=47.44..47.44 rows=1 width=0)"
" -> Bitmap Index Scan on rel_dis_can_fk (cost=0.00..5.56 rows=163 width=0)"
" Index Cond: (c.art_id = art.art_id)"
" -> Bitmap Index Scan on cancion_nombre_search_string_trgm (cost=0.00..41.47 rows=650 width=0)"
" Index Cond: ((can_nombre_search_string)::text % 'NOMBRE'::text)"
" -> Index Scan using ix_ent_id on ente ent (cost=0.00..0.48 rows=1 width=12)"
" Index Cond: (par.ent_id = ent.ent_id)"
" Filter: ((ent_nombre_search_string)::text % 'COS'::text)"
" -> Seq Scan on disponibilidad dis (cost=0.00..1.12 rows=12 width=20)"

If I slightly change it by removing one of the conditions for CANCION table, it works an finish in miliseconds:

SELECT ART.ART_ID, DIS.DIS_HORAS, ART.TIP_ID FROM ARTICULO ART,DISPONIBILIDAD DIS, ENTE ENT, PARTICIPACION PAR,CANCION C WHERE (ART.ART_APROBADO = 1)
AND ((ART.ART_SHOW_ANYWAY = 1) OR (ART.ART_STOCK_ALMACEN_CENTRAL >=1) OR (ART.ART_STOCK_LOCAL >=1) OR (ART.ART_STOCK_LOCAL_2 >= 1) OR (ART.ART_STOCK >= 1))
AND (ART_DESCATALOGADO != 1) AND (ART_BUYABLE = 1) AND (NVL(ART.ART_PRECIO_FNAC_WEB,0) > 0) AND (ART.ART_PMP is not null) AND ART.TIP_ID =1 AND
( (ENT.ent_nombre_search_string % 'COS') ) AND PAR.ROL_ID = 100004 AND PAR.ENT_ID = ENT.ENT_ID AND PAR.ART_ID = ART.ART_ID AND ( (c.can_nombre_search_string % 'WHAT') )
AND C.ART_ID = ART.ART_ID AND DIS.DIS_ID = ART.DIS_ID AND ART.PRE_ID = 5 ORDER BY DIS.DIS_HORAS, ART_FECHA_UP DESC LIMIT 100;

SELECT ART.ART_ID, DIS.DIS_HORAS, ART.TIP_ID FROM ARTICULO ART,DISPONIBILIDAD DIS, ENTE ENT, PARTICIPACION PAR,CANCION C WHERE (ART.ART_APROBADO = 1)
AND ((ART.ART_SHOW_ANYWAY = 1) OR (ART.ART_STOCK_ALMACEN_CENTRAL >=1) OR (ART.ART_STOCK_LOCAL >=1) OR (ART.ART_STOCK_LOCAL_2 >= 1) OR (ART.ART_STOCK >= 1))
AND (ART_DESCATALOGADO != 1) AND (ART_BUYABLE = 1) AND (NVL(ART.ART_PRECIO_FNAC_WEB,0) > 0) AND (ART.ART_PMP is not null) AND ART.TIP_ID =1 AND
( (ENT.ent_nombre_search_string % 'COS') ) AND PAR.ROL_ID = 100004 AND PAR.ENT_ID = ENT.ENT_ID AND PAR.ART_ID = ART.ART_ID AND ( (c.can_nombre_search_string % 'WHAT') )
AND C.ART_ID = ART.ART_ID AND DIS.DIS_ID = ART.DIS_ID AND ART.PRE_ID = 5 ORDER BY DIS.DIS_HORAS, ART_FECHA_UP DESC LIMIT 100;

I have tried to VACUUM / ANALYZE and RECREATE indexes, change search string, but problem remains. If I launch a single select I also works:
SELECT * FROM CANCION C WHERE ( (c.can_nombre_search_string % 'WHAT') ) and ART_ID=223212;

Does anybody have an idea about what could be happening? With postgres 8.1.15 there was no problem with this query...

Thanks in advance.