Received: from localhost (postgresql.org [64.49.215.8]) by postgresql.org (Postfix) with ESMTP id EA738475C68 for ; Sat, 17 Aug 2002 21:07:14 -0400 (EDT) Received: from ns1.noc.com (cpe-24-221-43-101.az.sprintbbd.net [24.221.43.101]) by postgresql.org (Postfix) with ESMTP id 3AC2E475A61 for ; Sat, 17 Aug 2002 21:07:13 -0400 (EDT) Received: from joe (cpe-24-221-43-42.az.sprintbbd.net [24.221.43.42]) by ns1.noc.com (8.11.6/8.11.6) with SMTP id g7I1bdq22503 for ; Sat, 17 Aug 2002 18:37:39 -0700 (MST) (envelope-from joe@piscitella.com) Message-ID: <018f01c24653$b23d8000$c801a8c0@joe> From: "JOE" To: Subject: Unexplained SQL behavior Date: Sat, 17 Aug 2002 18:07:59 -0700 MIME-Version: 1.0 Content-Type: multipart/alternative; boundary="----=_NextPart_000_018C_01C24619.053C9BA0" X-Priority: 3 X-MSMail-Priority: Normal X-Mailer: Microsoft Outlook Express 5.50.4807.1700 X-MimeOLE: Produced By Microsoft MimeOLE V5.50.4910.0300 X-Virus-Scanned: by AMaViS new-20020517 X-Archive-Number: 200208/255 X-Sequence-Number: 9101 This is a multi-part message in MIME format. ------=_NextPart_000_018C_01C24619.053C9BA0 Content-Type: text/plain; charset="iso-8859-1" Content-Transfer-Encoding: quoted-printable I am debugging a performance problem with a view. I have narrowed down the= problem to when I adeed columns to my view.=20 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 b= e 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 n= ow uses a totally different plan and now runs for 8622.16 msec. Anyone hav= e 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, n= ull::timestamp without time zone, lov.displayorder, 'false'::character varying, 'F'::character varyi= ng, 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 =3D lov.productId and not exists (select null from learnerAttendance la, learnerLaunchableAttendance lla where enr.enrollmentID =3D la.enrollmentID and la.learnerAttendance= ID =3D lla.learnerAttendanceID and lla.launchableGUID =3D lov.ccGuid) \g explain analyze select * from lv2 where enrollmentid =3D 21462\g NOTICE: QUERY PLAN: Subquery Scan lv2 (cost=3D264.90..264.98 rows=3D1 width=3D77) (actual time= =3D1.53..1.61 rows=3D12 loops=3D1) -> Unique (cost=3D264.90..264.98 rows=3D1 width=3D77) (actual time=3D1.= 52..1.55 rows=3D12 loops=3D1) -> Sort (cost=3D264.90..264.90 rows=3D3 width=3D77) (actual time= =3D1.52..1.53 rows=3D12 loops=3D1) -> Nested Loop (cost=3D0.00..264.87 rows=3D3 width=3D77) (a= ctual time=3D0.57..1.20 rows=3D12 loops=3D1) -> Index Scan using enrollment_pk on enrollment enr (= cost=3D0.00..3.02 rows=3D1 width=3D20) (actual time=3D0.21..0.21 rows=3D1 l= oops=3D1) -> Index Scan using i_learningobjectview_productid on = learningobjectview lov (cost=3D0.00..25.51 rows=3D6 width=3D57) (actual ti= me=3D0.19..0.30 rows=3D13 loops=3D1) SubPlan -> Nested Loop (cost=3D0.00..36.69 rows=3D1 width= =3D8) (actual time=3D0.04..0.04 rows=3D0 loops=3D13) -> Index Scan using i_learnerlaunchattend_lgui= d on learnerlaunchableattendance lla (cost=3D0.00..20.19 rows=3D5 width=3D= 4) (actual time=3D0.02..0.02 rows=3D0 loops=3D13) -> Index Scan using learnerattendance_pk on le= arnerattendance la (cost=3D0.00..3.02 rows=3D1 width=3D4) (actual time=3D0= .16..0.16 rows=3D1 loops=3D1) 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, n= ull::timestamp without time zone, null::timestamp without time zone, lov.displayorder, 'false'::character varying, 'F'::character varyin= g, 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 =3D lov.productId and not exists (select null from learnerAttendance la, learnerLaunchableAttendance lla where enr.enrollmentID =3D la.enrollmentID and la.learnerAttendance= ID =3D lla.learnerAttendanceID and lla.launchableGUID =3D lov.ccGuid) \g explain analyze select * from lv2 where enrollmentid =3D 21462\g NOTICE: QUERY PLAN: Subquery Scan lv2 (cost=3D1968402.36..1969071.62 rows=3D2677 width=3D77) (= actual time=3D8273.16..8516.75 rows=3D12 loops=3D1) -> Unique (cost=3D1968402.36..1969071.62 rows=3D2677 width=3D77) (actua= l time=3D8273.08..8458.33 rows=3D63048 loops=3D1) -> Sort (cost=3D1968402.36..1968402.36 rows=3D26770 width=3D77) (= actual time=3D8273.07..8343.14 rows=3D63048 loops=3D1) -> Merge Join (cost=3D0.00..1965714.31 rows=3D26770 width= =3D77) (actual time=3D1.28..7226.99 rows=3D63048 loops=3D1) -> Index Scan using i_enrollment_product on enrollment= enr (cost=3D0.00..608.96 rows=3D8746 width=3D20) (actual time=3D0.17..54.= 26 rows=3D8746 loops=3D1) -> Index Scan using i_learningobjectview_productid on = learningobjectview lov (cost=3D0.00..207.57 rows=3D3278 width=3D57) (actua= l time=3D0.15..333.79 rows=3D67003 loops=3D1) SubPlan -> Nested Loop (cost=3D0.00..36.69 rows=3D1 width= =3D8) (actual time=3D0.09..0.09 rows=3D0 loops=3D64942) -> Index Scan using i_learnerlaunchattend_lgui= d on learnerlaunchableattendance lla (cost=3D0.00..20.19 rows=3D5 width=3D= 4) (actual time=3D0.01..0.03 rows=3D5 loops=3D64942) -> Index Scan using learnerattendance_pk on le= arnerattendance la (cost=3D0.00..3.02 rows=3D1 width=3D4) (actual time=3D0= .01..0.01 rows=3D0 loops=3D309102) Total runtime: 8622.16 msec ------=_NextPart_000_018C_01C24619.053C9BA0 Content-Type: text/html; charset="iso-8859-1" Content-Transfer-Encoding: quoted-printable
I am debugging a performance problem with = a=20 view.  I have narrowed down the problem to when I adeed columns to my = view.=20
In the examples below I have a view with 1= 0=20 columns.  I run an explain plan and it uses the primary key of the dri= ver=20 table (enrollment table) as to be expected and executes in 1.86 msec. = When=20 I added another columns (and it is a null value casted to a timestamp -=20 LASTACCESSED) the execution plan now uses a totally different plan and now = runs=20 for 8622.16 msec.  Anyone have any ideas or explination that may help= =20 understand??  --- thanks
 
drop view lv2 \g
create view lv2
( L= EARNERID,=20 ENROLLMENTID, GUID, EXPIREDDATE, FIRSTACCESSDATE,=20 DISPLAYORDER,
     ASSESSMENTSSTARTED,COMPLETE, EXPI= RED,=20 TITLE ) AS
select distinct enr.learnerid, enr.enrollmentid, lov.ccguid,= =20 enr.enddate, null::timestamp without time zone,
    = =20 lov.displayorder,   'false'::character varying,  =20 'F'::character varying,
     case when=20 enr.endDate::timestamp without time zone > now()::timestamp without time= zone=20 then 'false' else 'true' end as "expired",
    =20 lov.displaytitlemeid
  from enrollment enr, learningObjectView=20 lov
where enr.productid =3D lov.productId and not=20 exists
        (select=20 null
          from=20 learnerAttendance la, learnerLaunchableAttendance=20 lla
        where enr.enrollmentID = =3D=20 la.enrollmentID and la.learnerAttendanceID =3D lla.learnerAttendanceID and= =20 lla.launchableGUID =3D lov.ccGuid) \g
explain analyze select * from lv2 where=20 enrollmentid =3D 21462\g
NOTICE:  QUERY PLAN:
Subquery Scan lv2  (cost=3D264.90..26= 4.98 rows=3D1=20 width=3D77) (actual time=3D1.53..1.61 rows=3D12 loops=3D1)
  ->&= nbsp;=20 Unique  (cost=3D264.90..264.98 rows=3D1 width=3D77) (actual time=3D1.5= 2..1.55=20 rows=3D12 loops=3D1)
        ->&nb= sp;=20 Sort  (cost=3D264.90..264.90 rows=3D3 width=3D77) (actual time=3D1.52.= .1.53 rows=3D12=20 loops=3D1)
          &= nbsp;  =20 ->  Nested Loop  (cost=3D0.00..264.87 rows=3D3 width=3D77) (ac= tual=20 time=3D0.57..1.20 rows=3D12=20 loops=3D1)
          &= nbsp;        =20 ->  Index Scan using enrollment_pk on enrollment enr =20 (cost=3D0.00..3.02 rows=3D1 width=3D20) (actual time=3D0.21..0.21 rows=3D1= =20 loops=3D1)
          &= nbsp;        =20 ->  Index Scan using i_learningobjectview_productid on=20 learningobjectview lov  (cost=3D0.00..25.51 rows=3D6 width=3D57) (actu= al=20 time=3D0.19..0.30 rows=3D13=20 loops=3D1)
          &= nbsp;        =20 SubPlan
          &nbs= p;          =20 ->  Nested Loop  (cost=3D0.00..36.69 rows=3D1 width=3D8) (actu= al=20 time=3D0.04..0.04 rows=3D0=20 loops=3D13)
          =             &nb= sp;    =20 ->  Index Scan using i_learnerlaunchattend_lguid on=20 learnerlaunchableattendance lla  (cost=3D0.00..20.19 rows=3D5 width=3D= 4) (actual=20 time=3D0.02..0.02 rows=3D0=20 loops=3D13)
          =             &nb= sp;    =20 ->  Index Scan using learnerattendance_pk on learnerattendance la&n= bsp;=20 (cost=3D0.00..3.02 rows=3D1 width=3D4) (actual time=3D0.16..0.16 rows=3D1= =20 loops=3D1)
Total runtime: 1.86 msec
 
NOW I ADDED ANOTHER NULL column (LASTACCES= SED=20 field)
 
drop view lv2 \g
create view lv2
( L= EARNERID,=20 ENROLLMENTID, GUID, EXPIREDDATE, FIRSTACCESSDATE, LASTACCESSED,=20 DISPLAYORDER,
     ASSESSMENTSSTARTED,COMPLETE, EXPI= RED,=20 TITLE ) AS
select distinct enr.learnerid, enr.enrollmentid, lov.ccguid,= =20 enr.enddate, null::timestamp without time zone, null::timestamp without tim= e=20 zone,
    lov.displayorder,   'false'::characte= r=20 varying,   'F'::character varying,
     ca= se=20 when enr.endDate::timestamp without time zone > now()::timestamp without= time=20 zone then 'false' else 'true' end as "expired",
    = =20 lov.displaytitlemeid
  from enrollment enr, learningObjectView=20 lov
where enr.productid =3D lov.productId and not=20 exists
        (select=20 null
          from=20 learnerAttendance la, learnerLaunchableAttendance=20 lla
        where enr.enrollmentID = =3D=20 la.enrollmentID and la.learnerAttendanceID =3D lla.learnerAttendanceID and= =20 lla.launchableGUID =3D lov.ccGuid) \g
explain analyze select * from lv2 where=20 enrollmentid =3D 21462\g
NOTICE:  QUERY PLAN:
Subquery Scan lv2 =20 (cost=3D1968402.36..1969071.62 rows=3D2677 width=3D77) (actual time=3D8273.= 16..8516.75=20 rows=3D12 loops=3D1)
  ->  Unique  (cost=3D1968402.36.= .1969071.62=20 rows=3D2677 width=3D77) (actual time=3D8273.08..8458.33 rows=3D63048=20 loops=3D1)
        ->  Sort&n= bsp;=20 (cost=3D1968402.36..1968402.36 rows=3D26770 width=3D77) (actual time=3D8273= .07..8343.14=20 rows=3D63048=20 loops=3D1)
          &= nbsp;  =20 ->  Merge Join  (cost=3D0.00..1965714.31 rows=3D26770 width=3D= 77) (actual=20 time=3D1.28..7226.99 rows=3D63048=20 loops=3D1)
          &= nbsp;        =20 ->  Index Scan using i_enrollment_product on enrollment enr = =20 (cost=3D0.00..608.96 rows=3D8746 width=3D20) (actual time=3D0.17..54.26 row= s=3D8746=20 loops=3D1)
          &= nbsp;        =20 ->  Index Scan using i_learningobjectview_productid on=20 learningobjectview lov  (cost=3D0.00..207.57 rows=3D3278 width=3D57) (= actual=20 time=3D0.15..333.79 rows=3D67003=20 loops=3D1)
          &= nbsp;        =20 SubPlan
          &nbs= p;          =20 ->  Nested Loop  (cost=3D0.00..36.69 rows=3D1 width=3D8) (actu= al=20 time=3D0.09..0.09 rows=3D0=20 loops=3D64942)
         &nb= sp;            =      =20 ->  Index Scan using i_learnerlaunchattend_lguid on=20 learnerlaunchableattendance lla  (cost=3D0.00..20.19 rows=3D5 width=3D= 4) (actual=20 time=3D0.01..0.03 rows=3D5=20 loops=3D64942)
         &nb= sp;            =      =20 ->  Index Scan using learnerattendance_pk on learnerattendance la&n= bsp;=20 (cost=3D0.00..3.02 rows=3D1 width=3D4) (actual time=3D0.01..0.01 rows=3D0= =20 loops=3D309102)
Total runtime: 8622.16 msec
 
------=_NextPart_000_018C_01C24619.053C9BA0--