Forum OpenACS Development: slow query in project-manager (HEAD)

Hi,

I am trying project-manager from HEAD to a company i am working for. The company already uses dotLRN for supporting communities of practice about one year and now i expect pm software could enhance these communities with a area for people get in touch with research activities conducted by the company itself and other partners.

The Research & Development Departament has a lot of projects already started and i am trying to insert the informations inside project-manager.

After importing some data i observed a slow query in showing tasks for projects. Please could someone using project-manager help me trying understanding how to improve this query?

The sistem is running on postgresql 7.4.8.
Database server is a Dell Optiplex Gx270 (pentium IV) 1Gb RAM running only one instance of OpenACS

acs_objects table has about 55,000 rows
users table has about 3,100 rows
cr_items table has about 10,000 rows and cr_revisions has about 17,000 rows

The query itself (postgresql specific) is

dbqd.project-manager.lib.tasks.tasks: select nsdb0

called inside tasks-portlet for a project (project-manager/lib/tasks-postgresql.xql

tasks are for one subproject
subproject is integrated with logger instance with 4 logger variables (no entries for logger variables were loaded yet)

query is returning 16 rows

vacuumdb --full --analyze was running before get explain analyze results

SELECT distinct
t.item_id as task_item_id,
t.parent_id as project_item_id,
t.title,
to_char(t.end_date,'YYYY-MM-DD HH24:MI:SS') as end_date,
to_char(t.earliest_start,'YYYY-MM-DD HH24:MI:SS') as earliest_start,
t.earliest_start - current_date as days_to_earliest_start,
to_char(t.earliest_start,'J') as earliest_start_j,
to_char(t.earliest_finish,'YYYY-MM-DD HH24:MI:SS') as earliest_finish,
t.earliest_finish - current_date as days_to_earliest_finish,
to_char(t.latest_start,'YYYY-MM-DD HH24:MI:SS') as latest_start,
t.latest_start - current_date as days_to_latest_start,
to_char(t.latest_start,'J') as latest_start_j,
to_char(current_date,'J') as today_j,
to_char(t.latest_finish,'YYYY-MM-DD HH24:MI:SS') as latest_finish,
t.latest_finish - current_date as days_to_latest_finish,
to_char(t.end_date,'YYYY-MM-DD HH24:MI:SS') as end_date,
t.end_date - current_date as days_to_end_date,
u.person_id,
u.first_names,
u.last_name,
t.percent_complete,
d.parent_task_id,
d.dependency_type,
t.estimated_hours_work,
t.estimated_hours_work_min,
t.estimated_hours_work_max,
t.actual_hours_worked,
s.status_type,
s.description as status_description,
r.is_lead_p,
t.priority,
p.customer_id,
p.title as project_name,
ar.object_id_two as logger_project
FROM
pm_roles pr,
pm_task_assignment pa,
(select tr.item_id,
ta.party_id,
ta.role_id,
tr.title,
tr.end_date,
tr.earliest_start,
tr.earliest_finish,
tr.latest_start,
tr.latest_finish,
tr.percent_complete,
tr.estimated_hours_work,
tr.estimated_hours_work_min,
tr.estimated_hours_work_max,
tr.actual_hours_worked,
tr.parent_id,
tr.revision_id,
tr.priority
from pm_tasks_revisionsx tr
LEFT JOIN
pm_task_assignment ta ON tr.item_id = ta.task_id) t
LEFT JOIN
persons u
ON
t.party_id = u.person_id
LEFT JOIN
pm_roles r
ON t.role_id = r.role_id,
cr_items i
LEFT JOIN
pm_task_dependency d
ON
i.item_id = d.task_id,
acs_objects o,
pm_tasks_active ti,
pm_task_status s,
pm_projectsx p,
acs_rels ar
WHERE
t.parent_id = p.item_id and
t.revision_id = i.live_revision and
t.item_id = ti.task_id and
ti.status = s.status_id

and ar.object_id_one = t.parent_id
and ar.rel_type = 'application_data_link'
and o.object_id = ar.object_id_two
and o.object_type = 'logger_project'
and exists (select 1 from acs_object_party_privilege_map ppm
where ppm.object_id = ti.task_id
and ppm.privilege = 'read'
and ppm.party_id = '498')
and t.percent_complete < 100
and t.parent_id = '19319'
order by end_date, task_item_id asc, u.first_names, u.last_name

EXPLAIN ANALYZE for the above query shows Total runtime of 45961.236 ms

Unique (cost=843.20..865.25 rows=252 width=394) (actual time=40816.693..45926.995 rows=16 loops=1)
-> Sort (cost=843.20..843.83 rows=252 width=394) (actual time=40816.683..41885.846 rows=246624 loops=1)
Sort Key: to_char(pm_tasks_revisions.end_date, 'YYYY-MM-DD HH24:MI:SS'::text), cr.item_id, u.first_names, u.last_name, i.parent_id, cr.title, to_char(pm_tasks_revisions.earliest_start, 'YYYY-MM-DD HH24:MI:SS'::text), (pm_tasks_revisions.earliest_start - (('now'::text)::date)::timestamp with time zone), to_char(pm_tasks_revisions.earliest_start, 'J'::text), to_char(pm_tasks_revisions.earliest_finish, 'YYYY-MM-DD HH24:MI:SS'::text), (pm_tasks_revisions.earliest_finish - (('now'::text)::date)::timestamp with time zone), to_char(pm_tasks_revisions.latest_start, 'YYYY-MM-DD HH24:MI:SS'::text), (pm_tasks_revisions.latest_start - (('now'::text)::date)::timestamp with time zone), to_char(pm_tasks_revisions.latest_start, 'J'::text), to_char((('now'::text)::date)::timestamp with time zone, 'J'::text), to_char(pm_tasks_revisions.latest_finish, 'YYYY-MM-DD HH24:MI:SS'::text), (pm_tasks_revisions.latest_finish - (('now'::text)::date)::timestamp with time zone), to_char(pm_tasks_revisions.end_date, 'YYYY-MM-DD HH24:MI:SS'::text), (pm_tasks_revisions.end_date - (('now'::text)::date)::timestamp with time zone), u.person_id, pm_tasks_revisions.percent_complete, d.parent_task_id, d.dependency_type, pm_tasks_revisions.estimated_hours_work, pm_tasks_revisions.estimated_hours_work_min, pm_tasks_revisions.estimated_hours_work_max, pm_tasks_revisions.actual_hours_worked, s.status_type, s.description, r.is_lead_p, pm_tasks_revisions.priority, pm_projects.customer_id, cr.title, ar.object_id_two
-> Merge Join (cost=726.80..833.15 rows=252 width=394) (actual time=815.626..12583.572 rows=246624 loops=1)
Merge Cond: ("outer".status_id = "inner".status)
-> Nested Loop (cost=0.00..264.54 rows=10276 width=38) (actual time=0.043..73.978 rows=5139 loops=1)
-> Index Scan using pm_task_status_pk on pm_task_status s (cost=0.00..3.02 rows=2 width=38) (actual time=0.018..0.031 rows=2 loops=1)
-> Seq Scan on pm_task_assignment pa (cost=0.00..79.38 rows=5138 width=0) (actual time=0.007..14.080 rows=2570 loops=2)
-> Sort (cost=726.80..726.81 rows=1 width=364) (actual time=815.458..1654.185 rows=241487 loops=1)
Sort Key: pm_tasks.status
-> Nested Loop (cost=201.25..726.79 rows=1 width=364) (actual time=137.793..815.215 rows=48 loops=1)
-> Nested Loop (cost=191.56..587.24 rows=1 width=268) (actual time=123.800..139.720 rows=16 loops=1)
-> Nested Loop (cost=191.56..520.04 rows=1 width=268) (actual time=122.832..130.586 rows=16 loops=1)
-> Nested Loop (cost=0.00..7.90 rows=1 width=8) (actual time=0.057..0.079 rows=1 loops=1)
-> Index Scan using acs_rels_object_id_one_idx on acs_rels ar (cost=0.00..3.09 rows=1 width=8) (actual time=0.024..0.031 rows=1 loops=1)
Index Cond: (19319 = object_id_one)
Filter: ((rel_type)::text = 'application_data_link'::text)
-> Index Scan using acs_objects_pk on acs_objects o (cost=0.00..4.80 rows=1 width=4) (actual time=0.019..0.024 rows=1 loops=1)
Index Cond: (o.object_id = "outer".object_id_two)
Filter: ((object_type)::text = 'logger_project'::text)
-> Hash Join (cost=191.56..512.11 rows=3 width=264) (actual time=122.750..130.204 rows=16 loops=1)
Hash Cond: ("outer".live_revision = "inner".revision_id)
-> Hash Left Join (cost=0.00..275.15 rows=9075 width=40) (actual time=0.180..95.032 rows=9075 loops=1)
Hash Cond: ("outer".item_id = "inner".task_id)
-> Seq Scan on cr_items i (cost=0.00..229.75 rows=9075 width=8) (actual time=0.007..32.914 rows=9075 loops=1)
-> Hash (cost=0.00..0.00 rows=1 width=40) (actual time=0.010..0.010 rows=0 loops=1)
-> Seq Scan on pm_task_dependency d (cost=0.00..0.00 rows=1 width=40) (actual time=0.004..0.004 rows=0 loops=1)
-> Hash (cost=191.55..191.55 rows=5 width=240) (actual time=4.167..4.167 rows=0 loops=1)
-> Hash Left Join (cost=1.04..191.55 rows=5 width=240) (actual time=0.560..4.080 rows=16 loops=1)
Hash Cond: ("outer".role_id = "inner".role_id)
-> Nested Loop Left Join (cost=0.00..190.43 rows=5 width=239) (actual time=0.241..3.508 rows=16 loops=1)
-> Nested Loop Left Join (cost=0.00..175.30 rows=5 width=208) (actual time=0.205..2.955 rows=16 loops=1)
-> Nested Loop (cost=0.00..147.15 rows=5 width=200) (actual time=0.168..2.410 rows=16 loops=1)
-> Seq Scan on cr_text (cost=0.00..1.01 rows=1 width=0) (actual time=0.006..0.010 rows=1 loops=1)
-> Nested Loop (cost=0.00..146.09 rows=5 width=200) (actual time=0.126..2.173 rows=16 loops=1)
-> Nested Loop (cost=0.00..126.84 rows=4 width=196) (actual time=0.090..1.614 rows=16 loops=1)
-> Nested Loop (cost=0.00..87.47 rows=13 width=108) (actual time=0.047..0.803 rows=32 loops=1)
-> Index Scan using cr_items_by_parent_id on cr_items i (cost=0.00..26.43 rows=7 width=8) (actual time=0.016..0.094 rows=16 loops=1)
Index Cond: (parent_id = 19319)
-> Index Scan using cr_revisions_item_id_idx on cr_revisions cr (cost=0.00..8.68 rows=3 width=100) (actual time=0.010..0.019 rows=2 loops=16)
Index Cond: (cr.item_id = "outer".item_id)
-> Index Scan using pm_task_revs_id_pk on pm_tasks_revisions (cost=0.00..3.02 rows=1 width=88) (actual time=0.010..0.012 rows=0 loops=32)
Index Cond: ("outer".revision_id = pm_tasks_revisions.task_revision_id)
Filter: (percent_complete < 100::numeric)
-> Index Scan using acs_objects_pk on acs_objects (cost=0.00..4.80 rows=1 width=4) (actual time=0.010..0.014 rows=1 loops=16)
Index Cond: (acs_objects.object_id = "outer".task_revision_id)
-> Index Scan using pm_task_assignment_uq on pm_task_assignment ta (cost=0.00..5.62 rows=1 width=12) (actual time=0.009..0.013 rows=1 loops=16)
Index Cond: ("outer".item_id = ta.task_id)
-> Index Scan using persons_pk on persons u (cost=0.00..3.01 rows=1 width=35) (actual time=0.009..0.013 rows=1 loops=16)
Index Cond: ("outer".party_id = u.person_id)
-> Hash (cost=1.03..1.03 rows=3 width=9) (actual time=0.050..0.050 rows=0 loops=1)
-> Seq Scan on pm_roles r (cost=0.00..1.03 rows=3 width=9) (actual time=0.009..0.022 rows=3 loops=1)
-> Index Scan using pm_task_task_id_pk on pm_tasks (cost=0.00..67.19 rows=1 width=8) (actual time=0.536..0.542 rows=1 loops=16)
Index Cond: (pm_tasks.task_id = "outer".item_id)
Filter: ((deleted_p = 'f'::bpchar) AND (subplan))
SubPlan
-> Hash Join (cost=62.10..64.17 rows=1 width=0) (actual time=0.480..0.480 rows=1 loops=16)
Hash Cond: (("outer".privilege)::text = ("inner".privilege)::text)
-> Seq Scan on acs_privilege_descendant_map pdm (cost=0.00..2.05 rows=3 width=13) (actual time=0.027..0.027 rows=1 loops=16)
Filter: ((descendant)::text = 'read'::text)
-> Hash (cost=62.09..62.09 rows=1 width=8) (actual time=0.198..0.198 rows=0 loops=16)
-> Hash Join (cost=18.27..62.09 rows=1 width=8) (actual time=0.089..0.178 rows=1 loops=16)
Hash Cond: ("outer".grantee_id = "inner".party_id)
-> Nested Loop (cost=0.00..43.67 rows=7 width=12) (actual time=0.051..0.129 rows=2 loops=16)
-> Index Scan using acs_object_context_index_pk on acs_object_context_index c (cost=0.00..13.65 rows=4 width=4) (actual time=0.019..0.033 rows=3 loops=16)
Index Cond: (object_id = $0)
-> Index Scan using acs_permissions_pk on acs_permissions p (cost=0.00..7.49 rows=2 width=16) (actual time=0.012..0.015 rows=1 loops=48)
Index Cond: ("outer".ancestor_id = p.object_id)
-> Hash (cost=18.25..18.25 rows=7 width=4) (actual time=0.117..0.117 rows=0 loops=1)
-> Index Scan using party_member_member_idx on party_approved_member_map pamm (cost=0.00..18.25 rows=7 width=4) (actual time=0.019..0.069 rows=9 loops=1)
Index Cond: (member_id = 498)
-> Nested Loop (cost=9.69..139.46 rows=9 width=100) (actual time=13.808..42.159 rows=3 loops=16)
-> Nested Loop (cost=8.66..138.25 rows=3 width=100) (actual time=13.791..42.106 rows=1 loops=16)
-> Nested Loop (cost=8.66..132.42 rows=1 width=100) (actual time=13.763..42.064 rows=1 loops=16)
-> Hash Join (cost=8.66..127.60 rows=1 width=108) (actual time=13.732..42.020 rows=1 loops=16)
Hash Cond: ("outer".project_id = "inner".revision_id)
-> Nested Loop (cost=0.00..103.75 rows=3037 width=8) (actual time=0.023..31.747 rows=3037 loops=16)
-> Seq Scan on cr_text (cost=0.00..1.01 rows=1 width=0) (actual time=0.005..0.010 rows=1 loops=16)
-> Seq Scan on pm_projects (cost=0.00..72.37 rows=3037 width=8) (actual time=0.005..11.026 rows=3037 loops=16)
-> Hash (cost=8.65..8.65 rows=4 width=100) (actual time=0.050..0.050 rows=0 loops=1)
-> Index Scan using cr_revisions_item_id_idx on cr_revisions cr (cost=0.00..8.65 rows=4 width=100) (actual time=0.019..0.030 rows=2 loops=1)
Index Cond: (19319 = item_id)
-> Index Scan using acs_objects_pk on acs_objects (cost=0.00..4.80 rows=1 width=4) (actual time=0.016..0.020 rows=1 loops=16)
Index Cond: (acs_objects.object_id = "outer".project_id)
-> Index Scan using cr_items_pk on cr_items i (cost=0.00..5.81 rows=2 width=4) (actual time=0.013..0.018 rows=1 loops=16)
Index Cond: (19319 = item_id)
-> Materialize (cost=1.03..1.06 rows=3 width=0) (actual time=0.005..0.017 rows=3 loops=16)
-> Seq Scan on pm_roles pr (cost=0.00..1.03 rows=3 width=0) (actual time=0.006..0.019 rows=3 loops=1)
Total runtime: 45961.236 ms

Thanks in advance