Unexplained SQL behavior

From: "JOE" <joe(at)piscitella(dot)com>
To: <pgsql-sql(at)postgresql(dot)org>
Subject: Unexplained SQL behavior
Date: 2002-08-18 01:07:59
Message-ID: 018f01c24653$b23d8000$c801a8c0@joe
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-sql

I am debugging a performance problem with a view. I have narrowed down the problem to when I adeed columns to my view.
In the examples below I have a view with 10 columns. I run an explain plan and it uses the primary key of the driver table (enrollment table) as to be expected and executes in 1.86 msec. When I added another columns (and it is a null value casted to a timestamp - LASTACCESSED) the execution plan now uses a totally different plan and now runs for 8622.16 msec. Anyone have any ideas or explination that may help understand?? --- thanks

drop view lv2 \g
create view lv2
( LEARNERID, ENROLLMENTID, GUID, EXPIREDDATE, FIRSTACCESSDATE, DISPLAYORDER,
ASSESSMENTSSTARTED,COMPLETE, EXPIRED, TITLE ) AS
select distinct enr.learnerid, enr.enrollmentid, lov.ccguid, enr.enddate, null::timestamp without time zone,
lov.displayorder, 'false'::character varying, 'F'::character varying,
case when enr.endDate::timestamp without time zone > now()::timestamp without time zone then 'false' else 'true' end as "expired",
lov.displaytitlemeid
from enrollment enr, learningObjectView lov
where enr.productid = lov.productId and not exists
(select null
from learnerAttendance la, learnerLaunchableAttendance lla
where enr.enrollmentID = la.enrollmentID and la.learnerAttendanceID = lla.learnerAttendanceID and lla.launchableGUID = lov.ccGuid) \g

explain analyze select * from lv2 where enrollmentid = 21462\g
NOTICE: QUERY PLAN:
Subquery Scan lv2 (cost=264.90..264.98 rows=1 width=77) (actual time=1.53..1.61 rows=12 loops=1)
-> Unique (cost=264.90..264.98 rows=1 width=77) (actual time=1.52..1.55 rows=12 loops=1)
-> Sort (cost=264.90..264.90 rows=3 width=77) (actual time=1.52..1.53 rows=12 loops=1)
-> Nested Loop (cost=0.00..264.87 rows=3 width=77) (actual time=0.57..1.20 rows=12 loops=1)
-> Index Scan using enrollment_pk on enrollment enr (cost=0.00..3.02 rows=1 width=20) (actual time=0.21..0.21 rows=1 loops=1)
-> Index Scan using i_learningobjectview_productid on learningobjectview lov (cost=0.00..25.51 rows=6 width=57) (actual time=0.19..0.30 rows=13 loops=1)
SubPlan
-> Nested Loop (cost=0.00..36.69 rows=1 width=8) (actual time=0.04..0.04 rows=0 loops=13)
-> Index Scan using i_learnerlaunchattend_lguid on learnerlaunchableattendance lla (cost=0.00..20.19 rows=5 width=4) (actual time=0.02..0.02 rows=0 loops=13)
-> Index Scan using learnerattendance_pk on learnerattendance la (cost=0.00..3.02 rows=1 width=4) (actual time=0.16..0.16 rows=1 loops=1)
Total runtime: 1.86 msec

NOW I ADDED ANOTHER NULL column (LASTACCESSED field)

drop view lv2 \g
create view lv2
( LEARNERID, ENROLLMENTID, GUID, EXPIREDDATE, FIRSTACCESSDATE, LASTACCESSED, DISPLAYORDER,
ASSESSMENTSSTARTED,COMPLETE, EXPIRED, TITLE ) AS
select distinct enr.learnerid, enr.enrollmentid, lov.ccguid, enr.enddate, null::timestamp without time zone, null::timestamp without time zone,
lov.displayorder, 'false'::character varying, 'F'::character varying,
case when enr.endDate::timestamp without time zone > now()::timestamp without time zone then 'false' else 'true' end as "expired",
lov.displaytitlemeid
from enrollment enr, learningObjectView lov
where enr.productid = lov.productId and not exists
(select null
from learnerAttendance la, learnerLaunchableAttendance lla
where enr.enrollmentID = la.enrollmentID and la.learnerAttendanceID = lla.learnerAttendanceID and lla.launchableGUID = lov.ccGuid) \g

explain analyze select * from lv2 where enrollmentid = 21462\g
NOTICE: QUERY PLAN:
Subquery Scan lv2 (cost=1968402.36..1969071.62 rows=2677 width=77) (actual time=8273.16..8516.75 rows=12 loops=1)
-> Unique (cost=1968402.36..1969071.62 rows=2677 width=77) (actual time=8273.08..8458.33 rows=63048 loops=1)
-> Sort (cost=1968402.36..1968402.36 rows=26770 width=77) (actual time=8273.07..8343.14 rows=63048 loops=1)
-> Merge Join (cost=0.00..1965714.31 rows=26770 width=77) (actual time=1.28..7226.99 rows=63048 loops=1)
-> Index Scan using i_enrollment_product on enrollment enr (cost=0.00..608.96 rows=8746 width=20) (actual time=0.17..54.26 rows=8746 loops=1)
-> Index Scan using i_learningobjectview_productid on learningobjectview lov (cost=0.00..207.57 rows=3278 width=57) (actual time=0.15..333.79 rows=67003 loops=1)
SubPlan
-> Nested Loop (cost=0.00..36.69 rows=1 width=8) (actual time=0.09..0.09 rows=0 loops=64942)
-> Index Scan using i_learnerlaunchattend_lguid on learnerlaunchableattendance lla (cost=0.00..20.19 rows=5 width=4) (actual time=0.01..0.03 rows=5 loops=64942)
-> Index Scan using learnerattendance_pk on learnerattendance la (cost=0.00..3.02 rows=1 width=4) (actual time=0.01..0.01 rows=0 loops=309102)
Total runtime: 8622.16 msec

Responses

Browse pgsql-sql by date

  From Date Subject
Next Message Tom Lane 2002-08-18 01:55:24 Re: Unexplained SQL behavior
Previous Message Bruce Momjian 2002-08-17 11:21:20 Re: Difference between is true and = 't' in boolean feild. & bitmap