Re: Slow when joining with view - Mailing list pgsql-admin

From Kiswono Prayogo
Subject Re: Slow when joining with view
Date
Msg-id CANiF8TSDstb1+CrR4WKYsT7djGdrCQs1SpXaSo29fq6E17uS2g@mail.gmail.com
Whole thread Raw
In response to Slow when joining with view  (Kiswono Prayogo <kiswono@gmail.com>)
List pgsql-admin
This is weird

---- first component (fast):

EXPLAIN ANALYZE
        SELECT *          
        FROM V_CourseClass_Detail x1
        WHERE  x1.subject_coordinator_id IN (235,234,243,245,233,242,247,239,246,241,238,237,202,465,432,0) AND x1.semester_id = 53;

 Nested Loop  (cost=229.82..1597.02 rows=1 width=2842) (actual time=3.020..14.778 rows=268 loops=1)         
   ->  Nested Loop Left Join  (cost=229.53..1588.59 rows=1 width=2675) (actual time=3.001..13.145 rows=268 loops=1)       
         ->  Nested Loop Left Join  (cost=229.25..1588.15 rows=1 width=2508) (actual time=2.998..12.752 rows=268 loops=1) 
               ->  Nested Loop Left Join  (cost=228.97..1587.72 rows=1 width=2341) (actual time=2.993..12.244 rows=268 loops=1)       
                     ->  Nested Loop Left Join  (cost=228.68..1587.21 rows=1 width=2265) (actual time=2.988..11.674 rows=268 loops=1) 
                           ->  Nested Loop  (cost=228.39..1584.09 rows=1 width=1624) (actual time=2.987..11.322 rows=268 loops=1)     
                                 ->  Nested Loop  (cost=228.39..1579.99 rows=1 width=1492) (actual time=2.976..9.079 rows=268 loops=1)
                                       ->  Nested Loop  (cost=228.11..1579.61 rows=1 width=1063) (actual time=2.971..8.547 rows=268 loops=1)        
                                             ->  Hash Join  (cost=227.83..1553.16 rows=4 width=896) (actual time=2.958..7.951 rows=268 loops=1)     
                                                   Hash Cond: (((x1.data ->> 'open_course_id'::text))::bigint = x2.id)    
                                                   ->  Seq Scan on course_classes x1  (cost=0.00..1319.21 rows=811 width=660) (actual time=0.026..4.768 rows=269 loops=1)     
                                                         Filter: ((NOT is_deleted) AND (((data ->> 'subject_coordinator_id'::text))::bigint = ANY ('{235,234,243,245,233,242,247,239,246,241,238,237,202,465,432,0}'::bigint[]))) 
                                                         Rows Removed by Filter: 9870           
                                                   ->  Hash  (cost=227.58..227.58 rows=20 width=244) (actual time=2.925..2.925 rows=446 loops=1)    
                                                         Buckets: 1024  Batches: 1  Memory Usage: 112kB     
                                                         ->  Hash Join  (cost=66.53..227.58 rows=20 width=244) (actual time=0.667..2.831 rows=446 loops=1)      
                                                               Hash Cond: (((x2.data ->> 'trimester_course_id'::text))::bigint = x3.id
                                                               ->  Seq Scan on open_courses x2  (cost=0.00..130.58 rows=4036 width=113) (actual time=0.003..0.731 rows=4036 loops=1)      
                                                                     Filter: (NOT is_deleted)   
                                                                     Rows Removed by Filter: 22 
                                                               ->  Hash  (cost=66.44..66.44 rows=7 width=139) (actual time=0.659..0.659 rows=159 loops=1)
                                                                     Buckets: 1024  Batches: 1  Memory Usage: 28kB        
                                                                     ->  Seq Scan on trimester_courses x3  (cost=0.00..66.44 rows=7 width=139) (actual time=0.005..0.629 rows=159 loops=1)
                                                                           Filter: ((NOT is_deleted) AND (((data ->> 'semester_id'::text))::bigint = 53))       
                                                                           Rows Removed by Filter: 1263     
                                             ->  Index Scan using tags_pkey on tags x4  (cost=0.28..6.60 rows=1 width=175) (actual time=0.001..0.002 rows=1 loops=268)        
                                                   Index Cond: (id = ((x3.data ->> 'curriculum_id'::text))::bigint)
                                                   Filter: ((NOT is_deleted) AND ((data ->> 'type'::text) = 'curriculum'::text))
                                       ->  Index Scan using subjects_pkey on subjects x5  (cost=0.28..0.37 rows=1 width=437) (actual time=0.001..0.001 rows=1 loops=268)
                                             Index Cond: (id = ((x2.data ->> 'subject_id'::text))::bigint)
                                 ->  Seq Scan on events x6  (cost=0.00..4.09 rows=1 width=140) (actual time=0.005..0.008 rows=1 loops=268)
                                       Filter: (id = 53)
                                       Rows Removed by Filter: 86
                           ->  Index Scan using users_pkey on users x7  (cost=0.29..3.11 rows=1 width=649) (actual time=0.001..0.001 rows=0 loops=268)
                                 Index Cond: (((x1.data ->> 'lecturer_id'::text))::bigint = id)
                     ->  Index Scan using class_groups_pkey on class_groups x8  (cost=0.29..0.50 rows=1 width=84) (actual time=0.001..0.001 rows=1 loops=268)
                           Index Cond: (((x1.data ->> 'class_group_id'::text))::bigint = id)
               ->  Index Scan using tags_pkey on tags x9  (cost=0.28..0.43 rows=1 width=175) (actual time=0.001..0.001 rows=1 loops=268)
                     Index Cond: (((x1.data ->> 'subject_coordinator_id'::text))::bigint = id)
         ->  Index Scan using tags_pkey on tags x10  (cost=0.28..0.43 rows=1 width=175) (actual time=0.001..0.001 rows=1 loops=268)
               Index Cond: (((x1.data ->> 'room_id'::text))::bigint = id)
   ->  Index Scan using tags_pkey on tags x11  (cost=0.28..8.31 rows=1 width=175) (actual time=0.001..0.001 rows=1 loops=268)
         Index Cond: (id = ((x4.data ->> 'major_id'::text))::bigint)
 Planning time: 1.504 ms
 Execution time: 14.923 ms

---- second component (fast):

EXPLAIN ANALYZE
     SELECT cc_merged_id
             , ARRAY_TO_STRING(ARRAY[program_session,curriculum,class_group],' | ') merged_names
             , modified_at
     FROM v_courseclass_detail x1
     WHERE cc_merged_id IS NOT NULL AND  x1.subject_coordinator_id IN (235,234,243,245,233,242,247,239,246,241,238,237,202,465,432,0) AND x1.semester_id = 53;

 Nested Loop  (cost=229.82..1672.95 rows=1 width=1082) (actual time=2.799..6.618 rows=11 loops=1)
   ->  Nested Loop Left Join  (cost=229.53..1664.61 rows=1 width=1074) (actual time=2.789..6.572 rows=11 loops=1)
         ->  Nested Loop Left Join  (cost=229.25..1664.17 rows=1 width=1066) (actual time=2.788..6.565 rows=11 loops=1)
               ->  Nested Loop Left Join  (cost=228.97..1663.73 rows=1 width=1058) (actual time=2.785..6.544 rows=11 loops=1)
                     ->  Nested Loop Left Join  (cost=228.68..1663.22 rows=1 width=982) (actual time=2.779..6.516 rows=11 loops=1)
                           ->  Nested Loop  (cost=228.39..1660.10 rows=1 width=974) (actual time=2.778..6.505 rows=11 loops=1)
                                 ->  Nested Loop  (cost=228.39..1656.00 rows=1 width=966) (actual time=2.769..6.420 rows=11 loops=1)
                                       ->  Nested Loop  (cost=228.11..1655.62 rows=1 width=1055) (actual time=2.763..6.389 rows=11 loops=1)
                                             ->  Hash Join  (cost=227.83..1629.18 rows=4 width=888) (actual time=2.752..6.353 rows=11 loops=1)
                                                   Hash Cond: (((x1.data ->> 'open_course_id'::text))::bigint = x2.id)
                                                   ->  Seq Scan on course_classes x1  (cost=0.00..1395.26 rows=807 width=652) (actual time=0.210..3.801 rows=11 loops=1)
                                                         Filter: ((NOT is_deleted) AND (((data ->> 'cc_merged_id'::text))::bigint IS NOT NULL) AND (((data ->> 'subject_coordinator_id'::text))::bigint = ANY ('{235,234,243,245,233,242,247,239,246,241,238,237,202,465,432,0}'::bigint[])))
                                                         Rows Removed by Filter: 10128
                                                   ->  Hash  (cost=227.58..227.58 rows=20 width=244) (actual time=2.536..2.536 rows=446 loops=1)
                                                         Buckets: 1024  Batches: 1  Memory Usage: 112kB
                                                         ->  Hash Join  (cost=66.53..227.58 rows=20 width=244) (actual time=0.579..2.458 rows=446 loops=1)
                                                               Hash Cond: (((x2.data ->> 'trimester_course_id'::text))::bigint = x3.id)
                                                               ->  Seq Scan on open_courses x2  (cost=0.00..130.58 rows=4036 width=113) (actual time=0.003..0.663 rows=4036 loops=1)
                                                                     Filter: (NOT is_deleted)
                                                                     Rows Removed by Filter: 22
                                                               ->  Hash  (cost=66.44..66.44 rows=7 width=139) (actual time=0.572..0.572 rows=159 loops=1)
                                                                     Buckets: 1024  Batches: 1  Memory Usage: 28kB
                                                                     ->  Seq Scan on trimester_courses x3  (cost=0.00..66.44 rows=7 width=139) (actual time=0.005..0.554 rows=159 loops=1)
                                                                           Filter: ((NOT is_deleted) AND (((data ->> 'semester_id'::text))::bigint = 53))
                                                                           Rows Removed by Filter: 1263
                                             ->  Index Scan using tags_pkey on tags x4  (cost=0.28..6.60 rows=1 width=175) (actual time=0.002..0.002 rows=1 loops=11)
                                                   Index Cond: (id = ((x3.data ->> 'curriculum_id'::text))::bigint)
                                                   Filter: ((NOT is_deleted) AND ((data ->> 'type'::text) = 'curriculum'::text))
                                       ->  Index Scan using subjects_pkey on subjects x5  (cost=0.28..0.37 rows=1 width=16) (actual time=0.002..0.002 rows=1 loops=11)
                                             Index Cond: (id = ((x2.data ->> 'subject_id'::text))::bigint)
                                 ->  Seq Scan on events x6  (cost=0.00..4.09 rows=1 width=16) (actual time=0.004..0.007 rows=1 loops=11)
                                       Filter: (id = 53)
                                       Rows Removed by Filter: 86
                           ->  Index Scan using users_pkey on users x7  (cost=0.29..3.12 rows=1 width=16) (actual time=0.000..0.000 rows=0 loops=11)
                                 Index Cond: (((x1.data ->> 'lecturer_id'::text))::bigint = id)
                     ->  Index Scan using class_groups_pkey on class_groups x8  (cost=0.29..0.50 rows=1 width=84) (actual time=0.002..0.002 rows=1 loops=11)
                           Index Cond: (((x1.data ->> 'class_group_id'::text))::bigint = id)
               ->  Index Scan using tags_pkey on tags x9  (cost=0.28..0.43 rows=1 width=16) (actual time=0.001..0.001 rows=1 loops=11)
                     Index Cond: (((x1.data ->> 'subject_coordinator_id'::text))::bigint = id)
         ->  Index Scan using tags_pkey on tags x10  (cost=0.28..0.43 rows=1 width=16) (actual time=0.000..0.000 rows=0 loops=11)
               Index Cond: (((x1.data ->> 'room_id'::text))::bigint = id)
   ->  Index Scan using tags_pkey on tags x11  (cost=0.28..8.31 rows=1 width=16) (actual time=0.001..0.001 rows=1 loops=11)
         Index Cond: (id = ((x4.data ->> 'major_id'::text))::bigint)
 Planning time: 1.367 ms
 Execution time: 6.719 ms

---- but when combined (real slow):

EXPLAIN ANALYZE          
SELECT x1.id id      
        , x1.lecturer_id
        , x1.class_group_id           
        , x1.subject_coordinator_id          
        , x1.room_id          
        , x1.time_block_id
        , x1.cc_merged_id           
        , x1.open_course_id 
        , x1.subject_id   
        , x1.program_session
        , x1.semester_id 
        , x1.curriculum_id 
        , x1.major_id  
        , x1.curriculum -- or batch      
        , x1.subject      
        , x1.sks         
        , x1.semester_code 
        , x1.lecturer        
        , x1.class_group  
        , x1.coordinator   
        , x1.room        
        , x1.major        
        , GREATEST(x1.modified_at, x2.modified_at) modified_at       
        , x2.merged_names 
FROM (       
        SELECT *          
        FROM V_CourseClass_Detail x1
        WHERE  x1.subject_coordinator_id IN (235,234,243,245,233,242,247,239,246,241,238,237,202,465,432,0) AND x1.semester_id = 53
) x1
LEFT JOIN (
        SELECT cc_merged_id
                , ARRAY_TO_STRING(ARRAY[program_session,curriculum,class_group],' | ') merged_names
                , modified_at
        FROM v_courseclass_detail x1
        WHERE cc_merged_id IS NOT NULL AND  x1.subject_coordinator_id IN (235,234,243,245,233,242,247,239,246,241,238,237,202,465,432,0) AND x1.semester_id = 53
) x2 ON x1.id = x2.cc_merged_id


Nested Loop  (cost=231.81..3138.12 rows=1 width=2882) (actual time=623.088..139706.357 rows=268 loops=1)
   ->  Nested Loop Left Join  (cost=231.53..3129.68 rows=1 width=2715) (actual time=623.061..139700.924 rows=268 loops=1)
         ->  Nested Loop Left Join  (cost=231.25..3129.24 rows=1 width=2548) (actual time=623.052..139699.634 rows=268 loops=1)
               ->  Nested Loop Left Join  (cost=230.96..3128.80 rows=1 width=2381) (actual time=623.030..139697.219 rows=268 loops=1)
                     Join Filter: (x1.id = ((x1_1.data ->> 'cc_merged_id'::text))::bigint)
                     Rows Removed by Join Filter: 2937
                     ->  Nested Loop Left Join  (cost=228.97..1587.72 rows=1 width=2341) (actual time=5.029..20.389 rows=268 loops=1)
                           ->  Nested Loop Left Join  (cost=228.68..1587.21 rows=1 width=2265) (actual time=5.016..18.583 rows=268 loops=1)
                                 ->  Nested Loop  (cost=228.39..1584.09 rows=1 width=1624) (actual time=5.010..17.392 rows=268 loops=1)
                                       ->  Nested Loop  (cost=228.39..1579.99 rows=1 width=1492) (actual time=4.987..13.854 rows=268 loops=1)
                                             ->  Nested Loop  (cost=228.11..1579.61 rows=1 width=1063) (actual time=4.972..11.981 rows=268 loops=1)
                                                   ->  Hash Join  (cost=227.83..1553.16 rows=4 width=896) (actual time=4.946..10.176 rows=268 loops=1)
                                                         Hash Cond: (((x1.data ->> 'open_course_id'::text))::bigint = x2.id)
                                                         ->  Seq Scan on course_classes x1  (cost=0.00..1319.21 rows=811 width=660) (actual time=0.032..4.255 rows=269 loops=1)
                                                               Filter: ((NOT is_deleted) AND (((data ->> 'subject_coordinator_id'::text))::bigint = ANY ('{235,234,243,245,233,242,247,239,246,241,238,237,202,465,432,0}'::bigint[])))
                                                               Rows Removed by Filter: 9870
                                                         ->  Hash  (cost=227.58..227.58 rows=20 width=244) (actual time=4.884..4.884 rows=446 loops=1)
                                                               Buckets: 1024  Batches: 1  Memory Usage: 112kB
                                                               ->  Hash Join  (cost=66.53..227.58 rows=20 width=244) (actual time=1.079..4.680 rows=446 loops=1)
                                                                     Hash Cond: (((x2.data ->> 'trimester_course_id'::text))::bigint = x3.id)
                                                                     ->  Seq Scan on open_courses x2  (cost=0.00..130.58 rows=4036 width=113) (actual time=0.005..1.279 rows=4036 loops=1)
                                                                           Filter: (NOT is_deleted)
                                                                           Rows Removed by Filter: 22
                                                                     ->  Hash  (cost=66.44..66.44 rows=7 width=139) (actual time=1.057..1.057 rows=159 loops=1)
                                                                           Buckets: 1024  Batches: 1  Memory Usage: 28kB
                                                                           ->  Seq Scan on trimester_courses x3  (cost=0.00..66.44 rows=7 width=139) (actual time=0.012..0.999 rows=159 loops=1)
                                                                                 Filter: ((NOT is_deleted) AND (((data ->> 'semester_id'::text))::bigint = 53))
                                                                                 Rows Removed by Filter: 1263
                                                   ->  Index Scan using tags_pkey on tags x4  (cost=0.28..6.60 rows=1 width=175) (actual time=0.004..0.004 rows=1 loops=268)
                                                         Index Cond: (id = ((x3.data ->> 'curriculum_id'::text))::bigint)
                                                         Filter: ((NOT is_deleted) AND ((data ->> 'type'::text) = 'curriculum'::text))
                                             ->  Index Scan using subjects_pkey on subjects x5  (cost=0.28..0.37 rows=1 width=437) (actual time=0.004..0.004 rows=1 loops=268)
                                                   Index Cond: (id = ((x2.data ->> 'subject_id'::text))::bigint)
                                       ->  Seq Scan on events x6  (cost=0.00..4.09 rows=1 width=140) (actual time=0.005..0.010 rows=1 loops=268)
                                             Filter: (id = 53)
                                             Rows Removed by Filter: 86
                                 ->  Index Scan using users_pkey on users x7  (cost=0.29..3.11 rows=1 width=649) (actual time=0.002..0.002 rows=0 loops=268)
                                       Index Cond: (((x1.data ->> 'lecturer_id'::text))::bigint = id)
                           ->  Index Scan using class_groups_pkey on class_groups x8  (cost=0.29..0.50 rows=1 width=84) (actual time=0.003..0.004 rows=1 loops=268)
                                 Index Cond: (((x1.data ->> 'class_group_id'::text))::bigint = id)
                     ->  Nested Loop  (cost=1.99..1541.07 rows=1 width=684) (actual time=42.916..521.168 rows=11 loops=268)
                           ->  Nested Loop Left Join  (cost=1.71..1532.75 rows=1 width=915) (actual time=42.909..521.123 rows=11 loops=268)
                                 ->  Nested Loop Left Join  (cost=1.43..1532.31 rows=1 width=907) (actual time=42.907..521.107 rows=11 loops=268)
                                       ->  Nested Loop Left Join  (cost=1.15..1531.87 rows=1 width=899) (actual time=42.901..521.057 rows=11 loops=268)
                                             ->  Nested Loop Left Join  (cost=0.86..1531.36 rows=1 width=982) (actual time=42.886..520.957 rows=11 loops=268)
                                                   ->  Nested Loop  (cost=0.57..1528.23 rows=1 width=974) (actual time=42.884..520.933 rows=11 loops=268)
                                                         ->  Nested Loop  (cost=0.57..1524.13 rows=1 width=966) (actual time=42.875..520.824 rows=11 loops=268)
                                                               ->  Nested Loop  (cost=0.29..1523.75 rows=1 width=1055) (actual time=42.869..520.767 rows=11 loops=268)
                                                                     Join Filter: (x3_1.id = ((x2_1.data ->> 'trimester_course_id'::text))::bigint)
                                                                     Rows Removed by Join Filter: 1738
                                                                     ->  Nested Loop  (cost=0.00..1502.49 rows=25 width=958) (actual time=0.163..515.486 rows=1749 loops=268)
                                                                           ->  Nested Loop  (cost=0.00..99.16 rows=1 width=306) (actual time=0.024..6.592 rows=159 loops=268)
                                                                                 Join Filter: (((x3_1.data ->> 'curriculum_id'::text))::bigint = x4_1.id)
                                                                                 Rows Removed by Join Filter: 15741
                                                                                 ->  Seq Scan on trimester_courses x3_1  (cost=0.00..66.44 rows=7 width=139) (actual time=0.004..0.763 rows=159 loops=268)
                                                                                       Filter: ((NOT is_deleted) AND (((data ->> 'semester_id'::text))::bigint = 53))
                                                                                       Rows Removed by Filter: 1263
                                                                                 ->  Materialize  (cost=0.00..32.26 rows=3 width=175) (actual time=0.000..0.008 rows=100 loops=42612)
                                                                                       ->  Seq Scan on tags x4_1  (cost=0.00..32.24 rows=3 width=175) (actual time=0.240..0.422 rows=100 loops=1)
                                                                                             Filter: ((NOT is_deleted) AND ((data ->> 'type'::text) = 'curriculum'::text))
                                                                                             Rows Removed by Filter: 583
                                                                           ->  Seq Scan on course_classes x1_1  (cost=0.00..1395.26 rows=807 width=652) (actual time=0.156..3.197 rows=11 loops=42612)
                                                                                 Filter: ((NOT is_deleted) AND (((data ->> 'cc_merged_id'::text))::bigint IS NOT NULL) AND (((data ->> 'subject_coordinator_id'::text))::bigint = ANY ('{235,234,243,245,233,242,247,239,246,241,238,237,202,465,432,0}'::bigint[])))
                                                                                 Rows Removed by Filter: 10128
                                                                     ->  Index Scan using open_courses_pkey on open_courses x2_1  (cost=0.29..0.83 rows=1 width=113) (actual time=0.002..0.002 rows=1 loops=468732)
                                                                           Index Cond: (id = ((x1_1.data ->> 'open_course_id'::text))::bigint)
                                                                           Filter: (NOT is_deleted)
                                                               ->  Index Scan using subjects_pkey on subjects x5_1  (cost=0.28..0.37 rows=1 width=16) (actual time=0.003..0.003 rows=1 loops=2948)
                                                                     Index Cond: (id = ((x2_1.data ->> 'subject_id'::text))::bigint)
                                                         ->  Seq Scan on events x6_1  (cost=0.00..4.09 rows=1 width=16) (actual time=0.005..0.008 rows=1 loops=2948)
                                                               Filter: (id = 53)
                                                               Rows Removed by Filter: 86
                                                   ->  Index Scan using users_pkey on users x7_1  (cost=0.29..3.12 rows=1 width=16) (actual time=0.001..0.001 rows=0 loops=2948)
                                                         Index Cond: (((x1_1.data ->> 'lecturer_id'::text))::bigint = id)
                                             ->  Index Scan using class_groups_pkey on class_groups x8_1  (cost=0.29..0.50 rows=1 width=84) (actual time=0.002..0.003 rows=1 loops=2948)
                                                   Index Cond: (((x1_1.data ->> 'class_group_id'::text))::bigint = id)
                                       ->  Index Scan using tags_pkey on tags x9_1  (cost=0.28..0.43 rows=1 width=16) (actual time=0.003..0.003 rows=1 loops=2948)
                                             Index Cond: (((x1_1.data ->> 'subject_coordinator_id'::text))::bigint = id)
                                 ->  Index Scan using tags_pkey on tags x10_1  (cost=0.28..0.43 rows=1 width=16) (actual time=0.000..0.000 rows=0 loops=2948)
                                       Index Cond: (((x1_1.data ->> 'room_id'::text))::bigint = id)
                           ->  Index Scan using tags_pkey on tags x11_1  (cost=0.28..8.31 rows=1 width=16) (actual time=0.001..0.002 rows=1 loops=2948)
                                 Index Cond: (id = ((x4_1.data ->> 'major_id'::text))::bigint)
               ->  Index Scan using tags_pkey on tags x9  (cost=0.28..0.43 rows=1 width=175) (actual time=0.005..0.005 rows=1 loops=268)
                     Index Cond: (((x1.data ->> 'subject_coordinator_id'::text))::bigint = id)
         ->  Index Scan using tags_pkey on tags x10  (cost=0.28..0.43 rows=1 width=175) (actual time=0.002..0.002 rows=1 loops=268)
               Index Cond: (((x1.data ->> 'room_id'::text))::bigint = id)
   ->  Index Scan using tags_pkey on tags x11  (cost=0.28..8.31 rows=1 width=175) (actual time=0.002..0.002 rows=1 loops=268)
         Index Cond: (id = ((x4.data ->> 'major_id'::text))::bigint)
 Planning time: 14.533 ms
 Execution time: 139707.024 ms


-- 
Best Regards,
Kiswono P
GB


pgsql-admin by date:

Previous
From: Ray Stell
Date:
Subject: Re: pg_basebackup state?
Next
From: Kiswono Prayogo
Date:
Subject: Re: PostgreSQL doesn't log