Forum OpenACS Q&A: Re: longdb 5 seconds query in assessment portlet

Here the result of analyze:

"QUERY PLAN"
"Subquery Scan q (cost=37698.83..37698.85 rows=1 width=1939) (actual time=6706.558..6706.560 rows=1 loops=1)"
" -> Sort (cost=37698.83..37698.84 rows=1 width=355) (actual time=6706.554..6706.554 rows=1 loops=1)"
" Sort Key: lower((p.instance_name)::text), lower((cr.title)::text)"
" -> Nested Loop (cost=36891.59..37698.82 rows=1 width=355) (actual time=6705.466..6706.465 rows=1 loops=1)"
" Join Filter: (((subplan) < ""outer"".number_tries) OR (""outer"".number_tries = 0) OR (""outer"".number_tries IS NULL))"
" -> Nested Loop (cost=36891.59..37673.83 rows=1 width=290) (actual time=6695.675..6696.668 rows=1 loops=1)"
" -> Nested Loop (cost=36891.59..37670.72 rows=1 width=279) (actual time=6695.638..6696.628 rows=1 loops=1)"
" -> Nested Loop (cost=36891.59..37667.69 rows=1 width=275) (actual time=6695.601..6696.586 rows=1 loops=1)"
" -> Nested Loop (cost=36891.59..37662.53 rows=1 width=267) (actual time=6695.551..6696.530 rows=1 loops=1)"
" -> Nested Loop (cost=36891.59..37658.98 rows=1 width=267) (actual time=6695.513..6696.426 rows=4 loops=1)"
" -> Nested Loop (cost=36891.59..37655.80 rows=1 width=12) (actual time=6695.480..6696.346 rows=4 loops=1)"
" -> Unique (cost=36891.59..36905.64 rows=180 width=4) (actual time=6689.629..6693.900 rows=349 loops=1)"
" -> Sort (cost=36891.59..36898.62 rows=2810 width=4) (actual time=6689.625..6691.426 rows=4997 loops=1)"
" Sort Key: asm.assessment_id"
" -> Merge Join (cost=0.00..36730.63 rows=2810 width=4) (actual time=17.690..6682.865 rows=4997 loops=1)"
" Merge Cond: (""outer"".section_id = ""inner"".section_id)"
" -> Index Scan using as_assessment_section_map_pk2 on as_assessment_section_map asm (cost=0.00..36598.65 rows=370 width=8) (actual time=9.148..6670.322 rows=740 loops=1)"
" Filter: (subplan)"
" SubPlan"
" -> Hash Join (cost=5.16..3103.83 rows=70 width=0) (actual time=9.010..9.010 rows=1 loops=740)"
" Hash Cond: ((""outer"".privilege)::text = (""inner"".privilege)::text)"
" -> Nested Loop (cost=0.00..3095.67 rows=230 width=11) (actual time=9.007..9.007 rows=1 loops=740)"
" Join Filter: (""outer"".party_id = ""inner"".grantee_id)"
" -> Index Scan using party_member_member_idx on party_approved_member_map pamm (cost=0.00..87.10 rows=23 width=4) (actual time=0.008..0.152 rows=82 loops=740)"
" Index Cond: (member_id = 12345)"
" -> Nested Loop (cost=0.00..106.48 rows=1946 width=15) (actual time=0.013..0.098 rows=17 loops=60680)"
" -> Index Scan using acs_object_context_index_pk on acs_object_context_index c (cost=0.00..24.71 rows=11 width=4) (actual time=0.006..0.014 rows=7 loops=60680)"
" Index Cond: (object_id = $1)"
" -> Index Scan using acs_permissions_object_id_idx on acs_permissions p (cost=0.00..7.33 rows=8 width=19) (actual time=0.006..0.009 rows=3 loops=420320)"
" Index Cond: (""outer"".ancestor_id = p.object_id)"
" -> Hash (cost=5.15..5.15 rows=3 width=14) (actual time=0.089..0.089 rows=2 loops=1)"
" -> Bitmap Heap Scan on acs_privilege_descendant_map pdm (cost=2.01..5.15 rows=3 width=14) (actual time=0.073..0.074 rows=2 loops=1)"
" Recheck Cond: ((descendant)::text = 'read'::text)"
" -> Bitmap Index Scan on acs_priv_desc_map_idx (cost=0.00..2.01 rows=3 width=0) (actual time=0.058..0.058 rows=2 loops=1)"
" Index Cond: ((descendant)::text = 'read'::text)"
" -> Index Scan using as_item_section_map_sort_order_idx on as_item_section_map ism (cost=0.00..90.23 rows=2643 width=4) (actual time=0.037..5.744 rows=5007 loops=1)"
" -> Index Scan using cr_items_by_latest_revision on cr_items ci (cost=0.00..4.15 rows=1 width=8) (actual time=0.006..0.006 rows=0 loops=349)"
" Index Cond: (""outer"".assessment_id = ci.latest_revision)"
" Filter: ((publish_status)::text = 'live'::text)"
" -> Index Scan using as_assessments_assessment_id_pk on as_assessments a (cost=0.00..3.17 rows=1 width=255) (actual time=0.015..0.016 rows=1 loops=4)"
" Index Cond: (""outer"".assessment_id = a.assessment_id)"
" Filter: (((start_time < now()) AND (end_time > now())) OR (start_time IS NULL))"
" -> Index Scan using cr_folders_pk on cr_folders cf (cost=0.00..3.54 rows=1 width=8) (actual time=0.023..0.024 rows=0 loops=4)"
" Index Cond: (""outer"".parent_id = cf.folder_id)"
" Filter: ((package_id = 6684174) OR (package_id = 6508603) OR (package_id = 6339314))"
" -> Index Scan using site_nodes_object_id_idx on site_nodes sa (cost=0.00..5.12 rows=3 width=12) (actual time=0.044..0.049 rows=1 loops=1)"
" Index Cond: (sa.object_id = ""outer"".package_id)"
" -> Index Scan using site_nodes_node_id_pk on site_nodes sc (cost=0.00..3.03 rows=1 width=8) (actual time=0.033..0.035 rows=1 loops=1)"
" Index Cond: (sc.node_id = ""outer"".parent_id)"
" -> Index Scan using apm_packages_pack_id_pk on apm_packages p (cost=0.00..3.09 rows=1 width=19) (actual time=0.032..0.034 rows=1 loops=1)"
" Index Cond: (p.package_id = ""outer"".object_id)"
" -> Index Scan using cr_revisions_pk on cr_revisions cr (cost=0.00..3.23 rows=1 width=77) (actual time=0.034..0.037 rows=1 loops=1)"
" Index Cond: (""outer"".assessment_id = cr.revision_id)"
" SubPlan"
" -> Aggregate (cost=7.23..7.24 rows=1 width=0) (actual time=0.113..0.113 rows=1 loops=1)"
" -> Nested Loop (cost=0.00..7.23 rows=1 width=0) (actual time=0.094..0.094 rows=0 loops=1)"
" -> Seq Scan on as_sessions s1 (cost=0.00..3.99 rows=1 width=4) (actual time=0.093..0.093 rows=0 loops=1)"
" Filter: ((subject_id = 12345) AND (completed_datetime IS NOT NULL))"
" -> Index Scan using cr_revisions_pk on cr_revisions cr1 (cost=0.00..3.23 rows=1 width=4) (never executed)"
" Index Cond: (""outer"".assessment_id = cr1.revision_id)"
" Filter: (item_id = $0)"
" -> Aggregate (cost=7.23..7.24 rows=1 width=0) (actual time=0.085..0.086 rows=1 loops=1)"
" -> Nested Loop (cost=0.00..7.23 rows=1 width=0) (actual time=0.080..0.080 rows=0 loops=1)"
" -> Seq Scan on as_sessions s1 (cost=0.00..3.99 rows=1 width=4) (actual time=0.079..0.079 rows=0 loops=1)"
" Filter: ((subject_id = 12345) AND (completed_datetime IS NOT NULL))"
" -> Index Scan using cr_revisions_pk on cr_revisions cr1 (cost=0.00..3.23 rows=1 width=4) (never executed)"
" Index Cond: (""outer"".assessment_id = cr1.revision_id)"
" Filter: (item_id = $0)"
" -> Aggregate (cost=7.23..7.24 rows=1 width=0) (actual time=0.092..0.092 rows=1 loops=1)"
" -> Nested Loop (cost=0.00..7.23 rows=1 width=0) (actual time=0.080..0.080 rows=0 loops=1)"
" -> Seq Scan on as_sessions s1 (cost=0.00..3.99 rows=1 width=4) (actual time=0.080..0.080 rows=0 loops=1)"
" Filter: ((subject_id = 12345) AND (completed_datetime IS NULL))"
" -> Index Scan using cr_revisions_pk on cr_revisions cr1 (cost=0.00..3.23 rows=1 width=4) (never executed)"
" Index Cond: (""outer"".assessment_id = cr1.revision_id)"
" Filter: (item_id = $0)"
"Total runtime: 6707.835 ms"