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

Collapse
Posted by Gustaf Neumann on
for maxthreads=60, i would recommend 50 connections in pool1, the other ones smaller (e.g. 10). define at least 100 connectons in postgres

i would as well recommend to set maxidle and maxopen to 0, but this does not have to do with your performace problems

i have noticed on some machines problem with the keepalive (when e.g. the page is already show, the load takes forever to finish). Therefore you might try

ns_section "ns/parameters"
....
ns_param keepalivetimeout 0
This change won't help with the long times reported in the log.

By looking into the log i wonder about e.g. the line with "--starting". The reported time is the time, when xowiki starts working. In the example below, something was already taking 2.8 secs before xowiki became active

[05/Mar/2008:16:22:36][24412.2806188976][-conn:service0::12] Notice: --starting... /campus/myprogramme/ , ::35512
22 -> (2806ms)

so, the culprit might be in the master templates. Do you have custom templates with SQL-calls?

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' )

Collapse
Posted by Brian Fenton on
Hi Gustaf,

I'm just reading over this old thread and I spotted your comment "for maxthreads=60, i would recommend 50 connections in pool1, the other ones smaller (e.g. 10)". Can I ask you why you said this, instead of just giving each pool 20 connections? I'm just curious, as it seems more intuitive to equally divide the connections between each pool.

many thanks
Brian Fenton

Is more related to your applications and how many nested queries (api-db-calls) you run.

Gustaf, when you mention "i would as well recommend to set maxidle and maxopen to 0, but this does not have to do with your performace problems"; can you elaborate why?

Collapse
Posted by Gustaf Neumann on
Brian,

for each request, the openacs handle allocator tries to first to satisfy requests for handle from the first pool, for nested queries for the second pool, etc. Every request accessing the database will need a handle from pool1. If you have e.g. 60 connection threads, the needed number depends on how many of these potential concurrent threads need the database. The value certainly depends on the applications, it might be different for custom applications. The values above are based on our experience in our learn@wu system (we added some monitoring to get better understanding of this issue).

Roc, see the two following postings for the maxidle/maxopen magic:
http://dossy.org/archives/000319.html
http://openacs.org/forums/message-view?message_id=921467

The folklore setting of

ns_param maxidle 1000000000
ns_param maxopen 1000000000

are just another source for possible confusion and overflow, not contributing anything useful.

hope, this helps
-gustaf neumann

Collapse
Posted by Brian Fenton on
Many thanks Gustaf. That makes sense. Thanks for taking the time to respond.

Brian