Forum OpenACS Development: Re: Res: Re: Res: Re: OpenACS performance issues

Collapse
Posted by Matthew Coupe on
We started off with the Zen theme and added some extra stuff, not too much but possibly some bad code!

What you explain about the wait before it becomes active is exactly how it feels, you click on a link and then it takes a few seconds before you get any sort of response from the system. It's very strange.

From developer support these are the database queries that run on our master template. Some of them seem to take an excessive amount of time...

0 ms gethandle gethandle (returned pool2)
389 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '3551196' and ppm.party_id = '14554' and ppm.privilege = 'read' )

1 ms 0or1row dbqd.-lookup.entry_exists_select: 0or1row nsdb0

select item_id from cr_items where name = 'index' and parent_id = '3551907'

1 ms 0or1row dbqd.-lookup.entry_exists_select: 0or1row nsdb0

select item_id from cr_items where name = 'en:index' and parent_id = '3551907'

17 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '-4' and ppm.party_id = '14554' and ppm.privilege = 'admin' )

1 ms select dbqd.::xowiki::portlet::my-references-render.get_references: select nsdb0

SELECT page,ci.name,f.package_id from xowiki_references,cr_items ci,cr_folders f where reference=3553858 and ci.item_id = page and ci.parent_id = f.folder_id

1 ms getrow getrow nsdb0

1 ms select dbqd.categories.tcl.categories-procs.category::get_mapped_categories.get_mapped_categories: select nsdb0

select category_id
from category_object_map
where object_id = '3553858'

0 ms getrow getrow nsdb0

2 ms dml dbqd.::xowiki::Page-record_last_visited.update_last_visisted: dml nsdb0

update xowiki_last_visited set time = current_timestamp, count = count + 1 where page_id = 3553858 and user_id = 14554

1 ms 0or1row dbqd.views.tcl.views-procs.views::record_view.record_view: 0or1row nsdb0

select views__record_view('3553858', '14554')

1 ms 0or1row dbqd.views.tcl.views-procs.views::get.views: 0or1row nsdb0

SELECT views, unique_views, to_char(last_viewed,'YYYY-MM-DD HH24:MI:SS') as last_viewed
FROM view_aggregates
WHERE object_id = '3553858'

170 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '3551196' and ppm.party_id = '14554' and ppm.privilege = 'write' )

18 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '3551196' and ppm.party_id = '14554' and ppm.privilege = 'admin' )

23 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '3551196' and ppm.party_id = '14554' and ppm.privilege = 'create' )

17 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '109968' and ppm.party_id = '14554' and ppm.privilege = 'admin' )

2 ms 0or1row dbqd.dotlrn.tcl.community-procs.dotlrn_community::member_p.select_count_membership: 0or1row nsdb0

select count(*)
from dual
where exists (select 1
from dotlrn_member_rels_approved
where community_id = '3225'
and user_id = '14554')

3 ms 0or1row dbqd.dotlrn.tcl.dotlrn-security-procs.dotlrn::user_p.select_count: 0or1row nsdb0

select count(*)
from dual
where exists (select 1
from dotlrn_users
where user_id = '14554')

3 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '1303' and ppm.party_id = '14554' and ppm.privilege = 'admin' )

3 ms 0or1row dbqd.dotlrn.tcl.dotlrn-security-procs.dotlrn::user_p.select_count: 0or1row nsdb0

select count(*)
from dual
where exists (select 1
from dotlrn_users
where user_id = '14554')

1 ms select dbqd.theme-campus.tcl.navigation-procs.campus::portal_subnavbar.list_page_nums_select: select nsdb0

select pretty_name, accesskey, sort_key
from portal_pages
where portal_id = null and hidden_p = 'f'
order by sort_key

0 ms getrow getrow nsdb0

18 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '344' and ppm.party_id = '14554' and ppm.privilege = 'admin' )

18 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '14554' and ppm.party_id = '14554' and ppm.privilege = 'admin' )

412 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '3551056' and ppm.party_id = '14554' and ppm.privilege = 'read' )

23 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '3551056' and ppm.party_id = '14554' and ppm.privilege = 'create' )

10 ms select dbqd.weblogger-portlet.www.weblogger-portlet-front-page.entries: select nsdb0

select e.entry_id,
acs_object__name(apm_package__parent_id(e.package_id)) as parent_name,
(select site_node__url(site_nodes.node_id)
from site_nodes
where site_nodes.object_id = e.package_id) as base_url,
e.title,
e.content,
u.first_names as poster_first_names,
u.last_name as poster_last_name,
to_char(e.entry_date , 'HH24:MI') as posted_time_pretty,
p.package_id
from apm_packages p left outer join
pinds_blog_entries e on (e.package_id = p.package_id) join
acs_objects o on (o.object_id = e.entry_id) join
acs_users_all u on (u.user_id = o.creation_user)
where p.package_id in (3551056)

and e.draft_p = 'f'
and e.deleted_p = 'f'
order by p.package_id asc, e.entry_date desc, e.entry_date desc

0 ms getrow getrow nsdb0

0 ms getrow getrow nsdb0

0 ms getrow getrow nsdb0

0 ms getrow getrow nsdb0

0 ms getrow getrow nsdb0

0 ms getrow getrow nsdb0

0 ms getrow getrow nsdb0

0 ms getrow getrow nsdb0

0 ms getrow getrow nsdb0

1,136 Total Duration (ms)

Collapse
Posted by Dave Bauer on
Those long permissions queries are suspicious. Normally checking one object takes 1ms or so.
Collapse
Posted by Matthew Coupe on
How can I find out more information about what query this is? 408ms is a loooong time for every page impression.


408 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '3551196' and ppm.party_id = '14554' and ppm.privilege = 'read' )