Forum OpenACS Development: OpenACS Performance Tests

The first tests with 100 simultaneous connections in the start page using JMeter had a top of 7900ms response time and an average 2500ms. With 1000 simultaneous connections we had 9000ms top and 4000ms average.

Does anybody have a better test case with JMeter?

Thank you for the answers. I can say that this average response time is unacceptable. There's something very interesting about response time: when I look at the XoTcl request monitor page, the average response time is about 200ms with 100 simultaneous connections, but JMeter shows me (instantly) tops of 7900ms and average 2500ms (yes, 2.5s). I don't know where this difference comes from. Maybe somebody who knows the package better can tell how it measures the average.

However, even with this response time, I could navigate with no problems. It was a little bit slow, but nothing impossible to use. In the other hand, with 1000 simultaneous connections it was impossible to navigate.

About the db pools, I think we have a problem here. No matter how much I raise this umber, I can only see in htop something between 20 and 23 connections at the DB. Maybe this has something to do with AOLServer 4.5.0 thread pools change. Can somebody confirm that?

When I'm running JMeter, I can see all the processors with 100% (four processors) and I'm using only 4GB RAM on the machine. It seems like I can't make the machine use more memory, and that's why I've increased shared_buffers to 1.5GB.

Maybe I have to find a more clever way to track queries elapsed time. I'm going to install ptop, but I don't know if that's good enough. Does anybody know a better tool?

Thank you very much for your answers. They are being very helpfull, as allways.

We really have a problem in measurement here. I guess JMeter results will be more accurate in response time, because it can track all the time that the request is stucked. Do you think this diference between JMeter and XoTcl Request Monitor could be an I/O problem? I'm sorry if this looks like a silly question, but I'm still learning this thing.

Concerning AOLServer, I've been following the discussions in the mail list and I've realized that it has some performance problems that people are fixing. So I've checked it out from CVS using Cognovis script, like this:


cvs -z3 -d:pserver:mailto:anonymous@aolserver.cvs.sourceforge.net:/cvsroot/aolserver co aolserver


I can say I have the latest version. Do you know how I can check the source code to make sure your patches are there?

About the threads, I can see some kind of problem, maybe even a bug in thread pools definition for AOLServer 4.5.0: no matter how much I increase the number of connections in pool1, I can only see something between 20 and 23 DB connections. This makes me thing the parameter change is not working. Do you know how can I confirm that?

Your last consideration is maybe the most important: I don't know if AOLServer is compiled for 64 bits. I used Cognovis script, so I can assume it's not compiled for 64 bits. Is that right? Do you know where I can find some documentation about how to do it?

PostgreSQL is compiled for 64 bits, I'm sure, because it was installed from backports.org postgresql-8.2 package. I forgot to mention that my OS is Debian Etch.

Last question: what are these parameters maxidle e maxopen for?

Thank you again for your help.

Now I think we are getting somehwere. We've followed Gustaf's instructions and recompile AOLServer 4.5.0 (HEAD version) to 64 bits. There were some errors in the configure command, but it semms to be Ok (at least the file command shows me 64bit .so files).

We'repeated the tests with the same configuration as before, but the perfomance didn't seem to improve, and I still had the same problem: DB number of connections didn't raise. SO, I've changed the config.tcl to the following parameters:


ns_section ns/server/${server}
ns_param directoryfile $directoryfile
ns_param pageroot $pageroot
ns_param maxconnections 250 ;# Max connections to put on queue
ns_param maxdropped 0
ns_param maxthreads 120 ;# Tune this to scale your server
ns_param minthreads 100 ;# Tune this to scale your server
ns_param threadtimeout 120 ;# Idle threads die at this rate
ns_param globalstats false ;# Enable built-in statistics
ns_param urlstats true ;# Enable URL statistics
ns_param maxurlstats 1000 ;# Max number of URL's to do stats on

ns_section ns/db/pool/pool1
ns_param maxidle 1000000000
ns_param maxopen 1000000000
ns_param connections 80

ns_section ns/db/pool/pool2
ns_param maxidle 1000000000
ns_param maxopen 1000000000
ns_param connections 40

ns_section ns/db/pool/pool3
ns_param maxidle 1000000000
ns_param maxopen 1000000000
ns_param connections 40

The changes in pool2 and pool3 made the connections number in DB jump from 23 to 48 DB connections. It seemed like we did somethig right and we changed the pool numbers to this:


ns_section ns/db/pool/pool1
ns_param maxidle 1000000000
ns_param maxopen 1000000000
ns_param connections 100

ns_section ns/db/pool/pool2
ns_param maxidle 1000000000
ns_param maxopen 1000000000
ns_param connections 80

ns_section ns/db/pool/pool3
ns_param maxidle 1000000000
ns_param maxopen 1000000000
ns_param connections 80


With these changes the DB connections jumped to 160 and the response time is almost good (1200ms average). So, I could understand that the changes in pool1 didn't raise the number of connections in DB, but changes in pool2 and pool3 did changed it.

Knowing that, I've performed another test:

• Fired JMeter with 100 simultaneous connections 100 times in a row
• Enabled DB statics in Developer Support
• Tried to access the / (XoWiki page)
• Tried to access the /dotlrn
• Checked DS results

<h2>Results fo / (XoWiki page)</h2>

0 ms gethandle gethandle (returned pool2)
2 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 = '462' and ppm.party_id = '507' 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 = '4368'

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

select item_id from cr_items where name = 'pt:index' and parent_id = '4368'

2 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 = '507' and ppm.privilege = 'admin' )

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 = '1553' and ppm.party_id = '507' and ppm.privilege = 'admin' )

2 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 = '2791' and ppm.party_id = '507' and ppm.privilege = 'admin' )

2 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 = '3900' and ppm.party_id = '507' and ppm.privilege = 'create' )

2 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 = '3900' and ppm.party_id = '507' and ppm.privilege = 'admin' )

1 ms select dbqd.lars-blogger.www.blog.categories: select nsdb0

select *
from pinds_blog_categories
where package_id = '3900'

23 ms select dbqd.lars-blogger.www.blog.blog: select nsdb0

select entry_id,
entry_date,
to_char(entry_date, 'YYYY-MM-DD HH24:MI:SS')
as entry_date_ansi,
to_char(current_timestamp,'YYYY-MM-DD HH24:MI:SS')
as sysdate_ansi,
e.title,
e.title_url,
e.category_id,
com.category_id as sw_category_id,
content,
content_format,
draft_p,
p.first_names as poster_first_names,
p.last_name as poster_last_name,
o.creation_user as user_id,
(select count(gc.comment_id)
from general_comments gc,
cr_revisions cr
where gc.object_id = entry_id
and content_item__get_live_revision(gc.comment_id) =
cr.revision_id) as num_comments
from pinds_blog_entries e
join acs_objects o on (o.object_id = e.entry_id)
join persons p on (p.person_id = o.creation_user)
left outer join category_object_map com
on (com.object_id = e.entry_id)

where e.package_id = '3900'

and draft_p = 'f'
and deleted_p = 'f'

order by entry_date desc, entry_id, com.category_id

2 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 = '4020053' and ppm.party_id = '507' and ppm.privilege = 'write' )

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 = '3965018' and ppm.party_id = '507' and ppm.privilege = 'write' )

27 ms select dbqd.xowiki.www.portlets.noticias-comunidades.blog: select nsdb0

select entry_id,
entry_date,
e.package_id as package_id,
to_char(entry_date, 'YYYY-MM-DD HH24:MI:SS')
as entry_date_ansi,
to_char(current_timestamp,'YYYY-MM-DD HH24:MI:SS')
as sysdate_ansi,
e.title,
e.title_url,
e.category_id,
com.category_id as sw_category_id,
content,
content_format,
draft_p,
p.first_names as poster_first_names,
p.last_name as poster_last_name,
o.creation_user as user_id,
(select count(gc.comment_id)
from general_comments gc,
cr_revisions cr
where gc.object_id = entry_id
and content_item__get_live_revision(gc.comment_id) =
cr.revision_id) as num_comments
from pinds_blog_entries e
join acs_objects o on (o.object_id = e.entry_id)
join persons p on (p.person_id = o.creation_user)
left outer join category_object_map com
on (com.object_id = e.entry_id)
where draft_p = 'f'
and deleted_p = 'f'
and e.package_id in (select package_id from dotlrn_community_applets)
order by entry_date desc
limit '5'

0 ms gethandle gethandle (returned pool3)
20 ms 0or1row dbqd.xowiki.www.portlets.noticias-comunidades.select_community_id: 0or1row nsdb1

select community_id
from dotlrn_community_applets
where package_id = '601813'

1 ms 0or1row dbqd.xowiki.www.portlets.noticias-comunidades.select_community_id: 0or1row nsdb1

select community_id
from dotlrn_community_applets
where package_id = '3676302'

3 ms 0or1row dbqd.xowiki.www.portlets.noticias-comunidades.select_community_id: 0or1row nsdb1

select community_id
from dotlrn_community_applets
where package_id = '3676302'

6 ms 0or1row dbqd.xowiki.www.portlets.noticias-comunidades.select_community_id: 0or1row nsdb1

select community_id
from dotlrn_community_applets
where package_id = '601813'

1 ms 0or1row dbqd.xowiki.www.portlets.noticias-comunidades.select_community_id: 0or1row nsdb1

select community_id
from dotlrn_community_applets
where package_id = '4129'

2 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 = '462' and ppm.party_id = '507' and ppm.privilege = 'admin' )

2 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 = '4036424' and ppm.party_id = '507' and ppm.privilege = 'write' )

2 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 = '4014674' and ppm.party_id = '507' and ppm.privilege = 'write' )

2 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 = '4009218' and ppm.party_id = '507' and ppm.privilege = 'write' )

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 = '3985852' and ppm.party_id = '507' and ppm.privilege = 'write' )

2 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 = '3940827' and ppm.party_id = '507' and ppm.privilege = 'write' )

16 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=4384 and ci.item_id = page and ci.parent_id = f.folder_id

2 ms select dbqd.general-comments.tcl.general-comments-procs.general_comments_get_comments.get_comments: select nsdb0

select g.comment_id,
r.title,
r.mime_type,
o.creation_user,
acs_object__name(o.creation_user) as author,
o.creation_date

from general_comments g,
cr_revisions r,
acs_objects o
where g.object_id = '4384' and
r.revision_id = content_item__get_live_revision(g.comment_id) and
o.object_id = g.comment_id


order by o.creation_date

6 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 = 4384 and user_id = 507

2 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 = '4345' and ppm.party_id = '507' and ppm.privilege = 'write' )

2 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 = '4345' and ppm.party_id = '507' and ppm.privilege = 'admin' )

7 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 = '4345' and ppm.party_id = '507' and ppm.privilege = 'create' )

57 ms select dbqd.categories.tcl.category-trees-procs.category_tree::get_mapped_trees.get_mapped_trees: select nsdb0

select tree_id, subtree_category_id, assign_single_p,
require_category_p
from category_tree_map
where object_id = '4345'

2 ms select dbqd.::xowiki::portlet::categories-render.get_pages: select nsdb0

select ci.item_id, ci.name, ci.content_type, r.title, category_id , p.page_order from category_object_map c, cr_items ci, cr_revisions r, xowiki_page p where c.object_id = ci.item_id and ci.parent_id = 4368 and ci.content_type not in ('::xowiki::PageTemplate') and category_id in (3888) and r.revision_id = ci.live_revision and p.page_id = r.revision_id and ci.publish_status <> 'production'

2 ms select dbqd.xowiki.www.portlets.portlet-minimo-comunidade.select_comunidade: select nsdb0

select community_id,
pretty_name,
n_members
from dotlrn_community_members_mv
order by random()

2 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 = '507')

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

1 ms select dbqd.theme-zen.tcl.navigation-procs.zen::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

2 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 = '385' and ppm.party_id = '507' and ppm.privilege = 'admin' )

3 ms 0or1row dbqd.acs-subsite.tcl.subsite-procs.subsite::util::get_portrait_live_revision.get_portrait_info: 0or1row nsdb0

select cr.revision_id
from cr_revisions cr, cr_items ci, acs_rels a
where cr.revision_id = ci.live_revision
and ci.item_id = a.object_id_two
and a.object_id_one = '507'
and a.rel_type = 'user_portrait_rel'
and ci.live_revision is not null

222 Total Duration (ms)


<h2>Results for /dotlrn</h2>

1327 ms gethandle gethandle (returned pool2)
122 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 = '1553' and ppm.party_id = '507' and ppm.privilege = 'read' )

164 ms dml dbqd.acs-tcl.tcl.security-procs.ad_set_client_property.prop_insert_dml: dml nsdb0

insert into sec_session_properties
(session_id, module, property_name, secure_p, last_hit)
select '19981701', 'dotlrn', 'page_num', 'f', '1210872015'
from dual
where not exists (select 1
from sec_session_properties
where session_id = '19981701' and
module = 'dotlrn' and
property_name = 'page_num')

146 ms dml dbqd.acs-tcl.tcl.security-procs.ad_set_client_property.prop_update_dml: dml nsdb0

update sec_session_properties
set property_value = '0',
secure_p = 'f',
last_hit = '1210872015'
where session_id = '19981701' and
module = 'dotlrn' and
property_name = 'page_num'

223 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 = '507')

27 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 = '1553' and ppm.party_id = '507' and ppm.privilege = 'dotlrn_browse' )

26 ms 0or1row dbqd.dotlrn.www.index.get_title: 0or1row nsdb0

select pretty_name
from portal_pages
where portal_id = '2115'
and sort_key = '0'

7 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 = '2115' and ppm.party_id = '507' and ppm.privilege = 'portal_read_portal' )

7 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 = '2115' and ppm.party_id = '507' and ppm.privilege = 'portal_edit_portal' )

88 ms 0or1row dbqd.new-portal.tcl.portal-procs.portal::render.portal_select: 0or1row nsdb0

select portals.name,
portals.portal_id,
portals.theme_id,
portal_layouts.layout_id,
portal_layouts.filename as layout_filename,
portal_layouts.resource_dir as layout_resource_dir,
portal_pages.page_id
from portals,
portal_pages,
portal_layouts
where portal_pages.sort_key = '0'
and portal_pages.portal_id = '2115'
and portal_pages.portal_id = portals.portal_id
and portal_pages.layout_id = portal_layouts.layout_id

122 ms select dbqd.new-portal.tcl.portal-procs.portal::render.element_select: select nsdb0

select portal_element_map.element_id,
portal_element_map.region,
portal_element_map.sort_key
from portal_element_map,
portal_pages
where portal_pages.portal_id = '2115'
and portal_element_map.page_id = '2116'
and portal_element_map.page_id = portal_pages.page_id
and portal_element_map.state != 'hidden'
order by portal_element_map.region,
portal_element_map.sort_key

162 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 = '2791' and ppm.party_id = '507' and ppm.privilege = 'admin' )

178 ms 0or1row dbqd.new-portal.tcl.portal-procs.portal::evaluate_element.element_select: 0or1row nsdb0

select pem.element_id,
pem.datasource_id,
pem.state,
pet.filename as filename,
pet.resource_dir as resource_dir,
pem.pretty_name as pretty_name,
pd.name as ds_name
from portal_element_map pem,
portal_element_themes pet,
portal_datasources pd
where pet.theme_id = '3646465'
and pem.element_id = '3970'
and pem.datasource_id = pd.datasource_id

246 ms select dbqd.survey-portlet.www.survey-portlet.select_surveys: select nsdb0

select s.survey_id, s.name, s.editable_p, s.single_response_p,
s.package_id,
acs_object__name(apm_package__parent_id(s.package_id)) as parent_name,
(select site_node__url(site_nodes.node_id)
from site_nodes
where site_nodes.object_id = s.package_id) as url,
(select count(*) from survey_responses_latest srl where srl.survey_id=s.survey_id and initial_user_id='507') as response_count
from surveys s
where s.package_id in (3869,5768,4735,93945,51548,31329,520154,840281,601446,561005,22133,387094,1101832,1160554,1161157,1107799,627019,1444619,1664500,1500811,134088,1593736,1534926,3186181,3626690,3632822,3485800,3500450,3695786,3673866,2077568)
and s.enabled_p='t'
order by
parent_name,
upper(s.name)

0 ms gethandle gethandle (returned pool3)
9 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb1

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '520154' and ppm.party_id = '507' and ppm.privilege = 'read_private_data' )

2 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb1

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '1101832' and ppm.party_id = '507' and ppm.privilege = 'read_private_data' )

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

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '1107799' and ppm.party_id = '507' and ppm.privilege = 'read_private_data' )

5 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb1

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '51548' and ppm.party_id = '507' and ppm.privilege = 'read_private_data' )

5 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb1

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '93945' and ppm.party_id = '507' and ppm.privilege = 'read_private_data' )

6 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb1

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '1500811' and ppm.party_id = '507' and ppm.privilege = 'read_private_data' )

21 ms 0or1row dbqd.new-portal.tcl.portal-procs.portal::evaluate_element.element_select: 0or1row nsdb0

select pem.element_id,
pem.datasource_id,
pem.state,
pet.filename as filename,
pet.resource_dir as resource_dir,
pem.pretty_name as pretty_name,
pd.name as ds_name
from portal_element_map pem,
portal_element_themes pet,
portal_datasources pd
where pet.theme_id = '3646465'
and pem.element_id = '4178'
and pem.datasource_id = pd.datasource_id

72 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 = '507' and ppm.party_id = '507' and ppm.privilege = 'admin' )

25 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 = '4129' and ppm.party_id = '507' and ppm.privilege = 'read' )

77 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 = '4129' and ppm.party_id = '507' and ppm.privilege = 'create' )

35 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 = '5840' and ppm.party_id = '507' and ppm.privilege = 'read' )

12 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 = '5840' and ppm.party_id = '507' and ppm.privilege = 'create' )

42 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 = '4811' and ppm.party_id = '507' and ppm.privilege = 'read' )

111 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 = '4811' and ppm.party_id = '507' and ppm.privilege = 'create' )

64 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 = '94115' and ppm.party_id = '507' and ppm.privilege = 'read' )

100 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 = '94115' and ppm.party_id = '507' and ppm.privilege = 'create' )

126 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 = '94701' and ppm.party_id = '507' and ppm.privilege = 'read' )

230 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 = '94701' and ppm.party_id = '507' and ppm.privilege = 'create' )

56 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 = '37528' and ppm.party_id = '507' and ppm.privilege = 'read' )

57 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 = '37528' and ppm.party_id = '507' and ppm.privilege = 'create' )

164 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 = '601813' and ppm.party_id = '507' and ppm.privilege = 'read' )

58 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 = '601813' and ppm.party_id = '507' and ppm.privilege = 'create' )

21 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 = '1124207' and ppm.party_id = '507' and ppm.privilege = 'read' )

84 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 = '1124207' and ppm.party_id = '507' and ppm.privilege = 'create' )

49 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 = '1157455' and ppm.party_id = '507' and ppm.privilege = 'read' )

31 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 = '1157455' and ppm.party_id = '507' and ppm.privilege = 'create' )

25 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 = '1160724' and ppm.party_id = '507' and ppm.privilege = 'read' )

12 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 = '1160724' and ppm.party_id = '507' and ppm.privilege = 'create' )

15 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 = '1161789' and ppm.party_id = '507' and ppm.privilege = 'read' )

26 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 = '1161789' and ppm.party_id = '507' and ppm.privilege = 'create' )

63 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 = '1108048' and ppm.party_id = '507' and ppm.privilege = 'read' )

6 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 = '1108048' and ppm.party_id = '507' and ppm.privilege = 'create' )

15 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 = '631469' and ppm.party_id = '507' and ppm.privilege = 'read' )

14 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 = '631469' and ppm.party_id = '507' and ppm.privilege = 'create' )

22 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 = '1480821' and ppm.party_id = '507' and ppm.privilege = 'read' )

34 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 = '1480821' and ppm.party_id = '507' and ppm.privilege = 'create' )

20 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 = '1664639' and ppm.party_id = '507' and ppm.privilege = 'read' )

20 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 = '1664639' and ppm.party_id = '507' and ppm.privilege = 'create' )

86 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 = '134228' and ppm.party_id = '507' and ppm.privilege = 'read' )

5 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 = '134228' and ppm.party_id = '507' and ppm.privilege = 'create' )

87 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 = '1593842' and ppm.party_id = '507' and ppm.privilege = 'read' )

894 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 = '1593842' and ppm.party_id = '507' and ppm.privilege = 'create' )

235 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 = '2654094' and ppm.party_id = '507' and ppm.privilege = 'read' )

494 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 = '2654094' and ppm.party_id = '507' and ppm.privilege = 'create' )

196 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 = '3199080' and ppm.party_id = '507' and ppm.privilege = 'read' )

144 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 = '3199080' and ppm.party_id = '507' and ppm.privilege = 'create' )

124 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 = '3633817' and ppm.party_id = '507' and ppm.privilege = 'read' )

259 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 = '3633817' and ppm.party_id = '507' and ppm.privilege = 'create' )

229 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 = '3695972' and ppm.party_id = '507' and ppm.privilege = 'read' )

227 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 = '3695972' and ppm.party_id = '507' and ppm.privilege = 'create' )

241 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 = '3676302' and ppm.party_id = '507' and ppm.privilege = 'read' )

158 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 = '3676302' and ppm.party_id = '507' and ppm.privilege = 'create' )

424 ms select dbqd.weblogger-portlet.www.weblogger-portlet.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 (4129, 5840, 4811, 94115, 94701, 37528, 601813, 1124207, 1157455, 1160724, 1161789, 1108048, 631469, 1480821, 1664639, 134228, 1593842, 2654094, 3199080, 3633817, 3695972, 3676302)
and e.draft_p = 'f'
and e.deleted_p = 'f'
order by e.entry_date desc, p.package_id asc
limit 5

227 ms 0or1row dbqd.new-portal.tcl.portal-procs.portal::evaluate_element.element_select: 0or1row nsdb0

select pem.element_id,
pem.datasource_id,
pem.state,
pet.filename as filename,
pet.resource_dir as resource_dir,
pem.pretty_name as pretty_name,
pd.name as ds_name
from portal_element_map pem,
portal_element_themes pet,
portal_datasources pd
where pet.theme_id = '3646465'
and pem.element_id = '4215'
and pem.datasource_id = pd.datasource_id

204 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 = '507' and ppm.party_id = '507' and ppm.privilege = 'chat_room_create' )

193 ms select dbqd.chat-portlet.www.chat-portlet.rooms_list: select nsdb0

select rm.room_id,
rm.pretty_name as pretty_name,
rm.description as description,
rm.moderated_p,
rm.active_p,
rm.archive_p,
acs_permission__permission_p(room_id, '507', 'chat_room_admin') as admin_p,
acs_permission__permission_p(room_id, '507', 'chat_read') as user_p,
(select site_node__url(site_nodes.node_id)
from site_nodes
where site_nodes.object_id = obj.context_id) as base_url
from chat_rooms rm,
acs_objects obj
where rm.room_id = obj.object_id
and obj.context_id IN (4194, 5787, 4772, 94093, 94751, 37420, 565956, 871211, 601791, 567335, 1088764, 1160700, 1261501, 1161758, 1108019, 631445, 1480873, 1664689, 134348, 2654018, 3633903, 3673928, 3696022, 3676260, 2077587)
order by rm.pretty_name

5 ms 0or1row dbqd.new-portal.tcl.portal-procs.portal::evaluate_element.element_select: 0or1row nsdb0

select pem.element_id,
pem.datasource_id,
pem.state,
pet.filename as filename,
pet.resource_dir as resource_dir,
pem.pretty_name as pretty_name,
pd.name as ds_name
from portal_element_map pem,
portal_element_themes pet,
portal_datasources pd
where pet.theme_id = '3646465'
and pem.element_id = '4240'
and pem.datasource_id = pd.datasource_id

10 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 = '507' and ppm.party_id = '507' and ppm.privilege = 'write' )

3396 ms select dbqd.news-aggregator-portlet.www.news-aggregator-portlet.select_items: select nsdb0

select s.source_id,
s.link,
s.description,
s.title,
acs_object__name(apm_package__parent_id(package_id)) as parent_name,
(select site_node__url(site_nodes.node_id) from site_nodes where site_nodes.object_id = package_id) as node_url,
to_char(last_scanned, 'DD-MM-YYYY HH24:MI:SS') as last_scanned,
to_char(creation_date, 'YYYY-MM-DD HH24') as sort_date,
(select site_node__url(site_nodes.node_id)
from site_nodes
where site_nodes.object_id = package_id) as url,
feed_url,
item_id,
i.title as item_title,
i.link as item_link,
i.description as item_description,
package_id
from na_sources s left outer join
na_items i on (s.source_id = i.source_id)
where deleted_p = '0'
and package_id in (4223, 4754, 50130, 94075, 94773, 46633, 601895, 1406991, 1108000, 134329)
order by creation_date desc
limit 10

210 ms 0or1row dbqd.new-portal.tcl.portal-procs.portal::evaluate_element.element_select: 0or1row nsdb0

select pem.element_id,
pem.datasource_id,
pem.state,
pet.filename as filename,
pet.resource_dir as resource_dir,
pem.pretty_name as pretty_name,
pd.name as ds_name
from portal_element_map pem,
portal_element_themes pet,
portal_datasources pd
where pet.theme_id = '3646465'
and pem.element_id = '199852'
and pem.datasource_id = pd.datasource_id

226 ms select dbqd.wps-portlet.www.wps-portlet.select_presentations: select nsdb0

select o.context_id as package_id, i.item_id as pres_item_id,
acs_object__name(apm_package__parent_id(o.context_id)) as parent_name,
p.pres_title, (select site_node__url(site_nodes.node_id) from site_nodes where site_nodes.object_id = o.context_id) as url
from cr_items i, cr_wp_presentations p , acs_objects o
where o.context_id in ( 199186 )
and p.presentation_id = i.live_revision
and i.item_id = o.object_id
and p.public_p = 't'
order by i.item_id desc, pres_title

153 ms 0or1row dbqd.new-portal.tcl.portal-procs.portal::evaluate_element.element_select: 0or1row nsdb0

select pem.element_id,
pem.datasource_id,
pem.state,
pet.filename as filename,
pet.resource_dir as resource_dir,
pem.pretty_name as pretty_name,
pd.name as ds_name
from portal_element_map pem,
portal_element_themes pet,
portal_datasources pd
where pet.theme_id = '3646465'
and pem.element_id = '598208'
and pem.datasource_id = pd.datasource_id

287 ms select dbqd.assessment-portlet.www.assessment-portlet.open_asssessments: select nsdb0

select * from (select cr.item_id as assessment_id, cr.title, cr.description, a.password,
a.type,
to_char(a.start_time, 'YYYY-MM-DD HH24:MI:SS') as start_time,
to_char(a.end_time, 'YYYY-MM-DD HH24:MI:SS') as end_time,
to_char(now(), 'YYYY-MM-DD HH24:MI:SS') as cur_time,
cf.package_id, p.instance_name as community_name,
sc.node_id as comm_node_id, sa.node_id as as_node_id, a.anonymous_p,
acs_permission__permission_p(a.assessment_id,'507','admin') as admin_p,
(select count(*) from as_sessions s1,
cr_revisions cr1 where
s1.assessment_id=cr1.revision_id
and cr1.item_id=cr.item_id
and s1.subject_id='507'
and completed_datetime is null) as in_progress_p,
(select count(*) from as_sessions s1,
cr_revisions cr1 where
s1.assessment_id=cr1.revision_id
and cr1.item_id=cr.item_id
and s1.subject_id='507'
and completed_datetime is not null) as completed_p,
a.number_tries

from as_assessments a, cr_revisions cr, cr_items ci, cr_folders cf,
site_nodes sa, site_nodes sc, apm_packages p,
(select distinct asm.assessment_id
from as_assessment_section_map asm, as_item_section_map ism
where ism.section_id = asm.section_id
and exists (select 1 from acs_object_party_privilege_map ppm
where ppm.object_id = asm.assessment_id
and ppm.privilege = 'read'
and ppm.party_id = '507')) s
where a.assessment_id = cr.revision_id
and cr.revision_id = ci.latest_revision
and ci.parent_id = cf.folder_id
and ci.publish_status = 'live'
and cf.package_id in (594079, 2472808)
and sa.object_id = cf.package_id
and sc.node_id = sa.parent_id
and p.package_id = sc.object_id
and s.assessment_id = a.assessment_id
and ((a.start_time < current_timestamp and a.end_time > current_timestamp) or a.start_time is null)
order by lower(p.instance_name), lower(cr.title)
) q where (q.completed_p < q.number_tries) or (q.number_tries=0 or q.number_tries is null)

45 ms select dbqd.assessment-portlet.www.assessment-portlet.answered_assessments: select nsdb0

select * from (select ass.*, sc.node_id as comm_node_id, sa.node_id as as_node_id, p.instance_name as community_name,
acs_permission__permission_p(ass.assessment_id,'507','admin') as admin_p,
(select count(*) from as_sessions s1,
cr_revisions cr1 where
s1.assessment_id=cr1.revision_id and
cr1.item_id=ass.assessment_id
and s1.subject_id='507'
and completed_datetime is null) as in_progress_p,
(select count(*) from as_sessions s1,
cr_revisions cr1 where
s1.assessment_id=cr1.revision_id
and cr1.item_id=ass.assessment_id
and s1.subject_id='507'
and completed_datetime is not null) as completed_p


from
(select cr.item_id as assessment_id, cr.title, cr.description, cf.package_id,
a1.number_tries, a1.end_time
from as_assessments a, cr_revisions cr, cr_items ci, cr_folders cf,
as_assessments a1,
( select distinct s.assessment_id
from as_sessions s
where s.subject_id = '507'
and s.completed_datetime is not null) s
where a.assessment_id = cr.revision_id --
and cf.package_id in (594079, 2472808)
and cr.item_id = ci.item_id
and ci.parent_id = cf.folder_id
and s.assessment_id = a.assessment_id
and a1.assessment_id = ci.latest_revision
) ass,
site_nodes sa, site_nodes sc, apm_packages p
where sa.object_id = ass.package_id
and sc.node_id = sa.parent_id
and p.package_id = sc.object_id
order by lower(p.instance_name), lower(ass.title)
) q
where (q.number_tries is not null and q.number_tries >0 and q.completed_p >= q.number_tries) or (q.end_time is not null and q.end_time < current_timestamp)

23 ms 0or1row dbqd.new-portal.tcl.portal-procs.portal::evaluate_element.element_select: 0or1row nsdb0

select pem.element_id,
pem.datasource_id,
pem.state,
pet.filename as filename,
pet.resource_dir as resource_dir,
pem.pretty_name as pretty_name,
pd.name as ds_name
from portal_element_map pem,
portal_element_themes pet,
portal_datasources pd
where pet.theme_id = '3646465'
and pem.element_id = '3664907'
and pem.datasource_id = pd.datasource_id

13 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 = '3664369' and ppm.party_id = '507' and ppm.privilege = 'read' )

42 ms 0or1row dbqd.new-portal.tcl.portal-procs.portal::evaluate_element.element_select: 0or1row nsdb0

select pem.element_id,
pem.datasource_id,
pem.state,
pet.filename as filename,
pet.resource_dir as resource_dir,
pem.pretty_name as pretty_name,
pd.name as ds_name
from portal_element_map pem,
portal_element_themes pet,
portal_datasources pd
where pet.theme_id = '3646465'
and pem.element_id = '4030'
and pem.datasource_id = pd.datasource_id

48 ms 0or1row dbqd.static-portlet.www.static-portlet.select_content: 0or1row nsdb0

select body, pretty_name, format
from static_portal_content
where content_id = '4021'

7 ms 0or1row dbqd.new-portal.tcl.portal-procs.portal::evaluate_element.element_select: 0or1row nsdb0

select pem.element_id,
pem.datasource_id,
pem.state,
pet.filename as filename,
pet.resource_dir as resource_dir,
pem.pretty_name as pretty_name,
pd.name as ds_name
from portal_element_map pem,
portal_element_themes pet,
portal_datasources pd
where pet.theme_id = '3646465'
and pem.element_id = '2127'
and pem.datasource_id = pd.datasource_id

49 ms select dbqd.dotlrn.www.dotlrn-main-portlet.select_communities: select nsdb0

select dotlrn_communities_all.*,
dotlrn_community__url(dotlrn_communities_all.community_id) as url,
(CASE
WHEN
dotlrn_communities_all.community_type = 'dotlrn_community'
THEN 'dotlrn_community'
WHEN dotlrn_communities_all.community_type = 'dotlrn_club'
THEN 'dotlrn_club'
WHEN dotlrn_communities_all.community_type = 'dotlrn_pers_community'
THEN 'dotlrn_pers_community'
ELSE 'dotlrn_class_instance'
END) as simple_community_type,
tree_level(dotlrn_communities_all.tree_sortkey) as tree_level,
coalesce((select tree_level(dotlrn_community_types.tree_sortkey)
from dotlrn_community_types
where dotlrn_community_types.community_type = dotlrn_communities_all.community_type), 0) as community_type_level,
acs_permission__permission_p(dotlrn_communities_all.community_id, '507', 'admin') as admin_p
from dotlrn_communities_all,
dotlrn_member_rels_approved
where dotlrn_communities_all.community_id = dotlrn_member_rels_approved.community_id
and dotlrn_member_rels_approved.user_id = '507'
and archived_p='f'

order by dotlrn_communities_all.tree_sortkey

258 ms 0or1row dbqd.new-portal.tcl.portal-procs.portal::evaluate_element.element_select: 0or1row nsdb0

select pem.element_id,
pem.datasource_id,
pem.state,
pet.filename as filename,
pet.resource_dir as resource_dir,
pem.pretty_name as pretty_name,
pd.name as ds_name
from portal_element_map pem,
portal_element_themes pet,
portal_datasources pd
where pet.theme_id = '3646465'
and pem.element_id = '2141'
and pem.datasource_id = pd.datasource_id

175 ms select dbqd.forums-portlet.www.forums-portlet.select_forums: select nsdb0

select forums_forums.package_id,
acs_object__name(apm_package__parent_id(forums_forums.package_id)) as parent_name,
(select site_node__url(site_nodes.node_id)
from site_nodes
where site_nodes.object_id = forums_forums.package_id) as url,
forums_forums.forum_id,
forums_forums.name,
case when last_modified > (cast(current_timestamp as date)- 1) then 't' else 'f' end as new_p
from forums_forums_enabled forums_forums,
acs_objects
where acs_objects.object_id = forums_forums.forum_id and
forums_forums.package_id in (0,3779,5678,4645,93855,51458,31239,520062,840191,601355,560915,22043,387004,1101742,1160464,1161067,1107709,626929,1444529,1664410,1500721,133998,1593646,1534836,3186091,3626598,3632732,3485710,3500360,3695694,3673774,2077478)

and exists (
select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = forums_forums.package_id
and ppm.party_id = '507'
and ppm.privilege = 'read_private_data'
)

order by parent_name,
forums_forums.name

352 ms 0or1row dbqd.new-portal.tcl.portal-procs.portal::evaluate_element.element_select: 0or1row nsdb0

select pem.element_id,
pem.datasource_id,
pem.state,
pet.filename as filename,
pet.resource_dir as resource_dir,
pem.pretty_name as pretty_name,
pd.name as ds_name
from portal_element_map pem,
portal_element_themes pet,
portal_datasources pd
where pet.theme_id = '3646465'
and pem.element_id = '2133'
and pem.datasource_id = pd.datasource_id

245 ms select dbqd.faq-portlet.www.faq-portlet.select_faqs: select nsdb0

select acs_objects.context_id as package_id,
acs_object__name(apm_package__parent_id(acs_objects.context_id)) as parent_name,
(select site_node__url(site_nodes.node_id)
from site_nodes
where site_nodes.object_id = acs_objects.context_id) as url,
faqs.faq_id,
faqs.faq_name
from faqs,
acs_objects
where faqs.faq_id = acs_objects.object_id
and faqs.disabled_p <> 't'
and acs_objects.context_id in (0, 3810, 5709, 4676, 93886, 51489, 31270, 520095, 840222, 601386, 560946, 22074, 387035, 1101773, 1160495, 1161098, 1107740, 626960, 1444560, 1664441, 1500752, 134029, 1593677, 1534867, 3186122, 3626629, 3632763, 3485741, 3500391, 3695727, 3673807, 2077509)
order by lower(faq_name)

181 ms 0or1row dbqd.new-portal.tcl.portal-procs.portal::evaluate_element.element_select: 0or1row nsdb0

select pem.element_id,
pem.datasource_id,
pem.state,
pet.filename as filename,
pet.resource_dir as resource_dir,
pem.pretty_name as pretty_name,
pd.name as ds_name
from portal_element_map pem,
portal_element_themes pet,
portal_datasources pd
where pet.theme_id = '3646465'
and pem.element_id = '4089'
and pem.datasource_id = pd.datasource_id

179 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 = '1553' and ppm.party_id = '507' and ppm.privilege = 'admin' )

225 ms 0or1row dbqd.user-tracking-portlet.www.user-tracking-portlet.get_user_info: 0or1row nsdb0

select first_names , last_name
from persons
where person_id='507';

171 ms 0or1row dbqd.new-portal.tcl.portal-procs.portal::evaluate_element.element_select: 0or1row nsdb0

select pem.element_id,
pem.datasource_id,
pem.state,
pet.filename as filename,
pet.resource_dir as resource_dir,
pem.pretty_name as pretty_name,
pd.name as ds_name
from portal_element_map pem,
portal_element_themes pet,
portal_datasources pd
where pet.theme_id = '3646465'
and pem.element_id = '4186'
and pem.datasource_id = pd.datasource_id

268 ms select dbqd.latest-portlet.www.latest-portlet.communities_all_select: select nsdb0

select dotlrn_communities_all.package_id
from
dotlrn_communities_all, dotlrn_member_rels_approved
where
dotlrn_communities_all.community_id = dotlrn_member_rels_approved.community_id and
dotlrn_member_rels_approved.user_id = '507' and archived_p='f'

272 ms select dbqd.latest.tcl.latest-procs.latest::forums.forums_select: select nsdb0

select o.title, o.object_id, t.pretty_name as object_type, to_char(o.last_modified, 'MM-DD-YYYY') as last_modified
from acs_object_types t, acs_objects o
where t.object_type = o.object_type and
o.object_type in ('forums_forum')
and o.package_id in (37528,37420,31255,31283,31318,31329,37719,31239,796,796,46633,31270,31204,1664426,796,4223,3810,796,623663,625988,796,3869,626054,1664375,2077587,4098,3779,796,1664639,625754,796,1664311,624763,625485,623679,2077522,3795,625450,625924,625437,625789,796,796,623694,796,796,624814,1664489,796,21944,796,625726,625146,624842,22008,625307,625067,625611,625118,796,796,626102,625675,623707,626039,1664500,2077557,4194,796,22074,22122,625800,625741,625422,1664604,796,624829,626113,1664410,3823,2077568,796,2077443,625710,624888,3991,626023,2077609,2077478,624699,625192,796,4073,624798,3744,22059,623742,796,1664441,625102,4129,2077379,796,1664689,623628,3858,626067,623564,625371,624877,796,22133,625181,567335,625003,1664454,625133,625496,2077494,22043,22087,625406,623753,2077509,796,601435,601895,601371,601446,601864,601791,601355,601399,796,601320,601386,601813,51458,594079,386905,796,94751,94773,796,51502,1088764,1088811,387083,386969,387048,387035,387020,51423,51489,94701,796,796,387094,51537,387004,51474,51548,94669,1664426,1664375,1664639,1664489,796,1664500,1664604,796,1664410,1664441,1664689,1664454,93934,93945,94165,93855,1521764,93886,94093,93820,93899,94115,796,94075,796,93871,4689,4794,3897870,3991,4610,199186,4811,4676,796,4754,4724,796,4661,4735,4861,4645,4772,796,1088764,387083,386969,387048,387035,387020,796,387094,387004,53783,54470,54181,5840,796,796,53479,796,54115,50130,50392,5768,53415,5694,5787,5809,5678,54498,53593,53834,53849,5722,796,53908,53862,54485,53818,796,53545,5757,53604,54533,54240,53514,796,54194,796,53530,54150,5709,796,54051,54355,796,54544,54419,54454,54166,54229,53719,796,53897,53558,5643,2979629,1534801,3664369,1534926,2610638,1534836,1534915,796,1534880,1534867,796,1534852,1161789,1161146,1161157,1161727,1161067,1161098,1161083,796,796,1161758,1161111,1161032,1160480,1160554,1160669,1160464,1160429,1160724,796,1160543,796,1160495,1160700,1160508,1593662,1593677,796,3673928,2496906,1593690,1593736,1593759,1593646,1593725,796,1593611,1593842,840156,1486799,1831555,871235,1486924,1486865,840207,1486992,840281,1486834,841893,840191,871211,796,1529671,840235,1486913,1486735,1486878,840222,796,840270,796,796,1486850,1107799,1107918,1107709,796,1108000,1108019,1107788,2472808,1107674,1107753,1107740,1107725,1108048,796,560880,560931,560959,561005,1308874,560915,560946,796,796,560994,134088,134014,134197,133963,133998,134228,796,134329,134029,134077,796,134348,134042,1664426,796,623663,625988,796,626054,1664375,1664639,625754,796,1664311,624763,625485,623679,625450,625924,625437,625789,796,623694,796,796,624814,1664489,796,796,625726,625146,624842,22008,625307,625067,625611,625118,796,796,626102,625675,623707,626039,1664500,796,22074,22122,625800,625741,625422,1664604,796,624829,626113,1664410,796,625710,624888,626023,624699,625192,624798,22059,623742,796,1664441,625102,796,1664689,623628,626067,623564,625371,624877,796,22133,625181,567335,625003,1664454,625133,625496,22043,22087,625406,623753,1444560,1444494,1480821,1444619,1626202,1444529,796,1444545,1444608,1480873,1444573,796,2077587,2077522,796,2077557,2077568,2077443,2077609,2077478,796,2077494,2077509,3485726,796,3485741,3485800,3485789,3485754,3485710,3485675,796,2979629,631469,3829959,796,627008,1534801,1941724,1941838,632586,632540,3830018,632715,632496,796,3830108,3829926,796,626960,3664369,1534926,796,627019,632904,2610638,632246,1534836,1534915,626929,796,632397,632814,1534737,626945,796,1534880,796,1534867,632512,632845,632575,632779,796,796,796,3832620,632527,3830007,3829972,3829824,1941849,796,632893,632461,632830,1943332,631445,1941759,796,1534852,1941803,1941660,3829943,626973,632858,3991,3829891,860767,1941790,626894,1941775,3676225,3676677,3673774,796,3673855,3676494,796,3676260,3676613,3687013,796,3686949,3673820,3673791,3673739,796,3676302,3686830,3673807,3687749,3686965,3686897,3676561,3687024,3676642,3688104,3688017,3688069,3686932,3687858,3686978,796,3676629,3676688,796,3687773,3676596,3673866,3500325,3500391,3500404,3500450,3501507,3500360,796,796,3500439,3500376,3186107,3186181,796,3199137,3186122,3186091,3186170,3186056,796,3199080,3186135,520108,796,520095,2684721,2685334,2684631,520154,2684710,970315,520143,520062,2684596,796,2684647,2684662,796,2684675,796,520027,1124207,520078,2684532,565956,3991,3626642,3626690,796,3626598,3626679,3626563,796,3626614,3626629,3632811,3632697,796,3633817,3632748,3632763,3633903,3632776,3632822,796,3633868,3632732,796,3696022,3695775,3695659,3695740,3695727,3695711,3695972,796,3695786,3695937,3695694,1500811,1500752,1548305,1500721,796,1500686,2654094,1500737,1500800,796,2654018,1500765,1160480,1517889,796,1161789,1101773,1160554,1161146,1160669,1500981,1160464,1161157,1160429,1501159,1101821,1160968,1161727,1161067,1501045,1160724,1161098,796,1161083,1501096,1160543,796,796,1501111,1406991,1101707,796,1501170,1501124,796,1157455,796,1501080,1101832,796,1157522,1160495,1160700,1161758,1101742,1101758,1160365,1160508,1161111,1261501,1101786,1161032) order by last_modified desc limit 5

38 ms select dbqd.latest.tcl.latest-procs.latest::fs.fs_select: select nsdb0

select o.title, o.object_id, t.pretty_name as object_type, to_char(o.last_modified, 'MM-DD-YYYY') as last_modified
from acs_object_types t, acs_objects o
where t.object_type = o.object_type and
o.object_type in ('file_storage_object')
and o.package_id in (37528,37420,31255,31283,31318,31329,37719,31239,796,796,46633,31270,31204,1664426,796,4223,3810,796,623663,625988,796,3869,626054,1664375,2077587,4098,3779,796,1664639,625754,796,1664311,624763,625485,623679,2077522,3795,625450,625924,625437,625789,796,796,623694,796,796,624814,1664489,796,21944,796,625726,625146,624842,22008,625307,625067,625611,625118,796,796,626102,625675,623707,626039,1664500,2077557,4194,796,22074,22122,625800,625741,625422,1664604,796,624829,626113,1664410,3823,2077568,796,2077443,625710,624888,3991,626023,2077609,2077478,624699,625192,796,4073,624798,3744,22059,623742,796,1664441,625102,4129,2077379,796,1664689,623628,3858,626067,623564,625371,624877,796,22133,625181,567335,625003,1664454,625133,625496,2077494,22043,22087,625406,623753,2077509,796,601435,601895,601371,601446,601864,601791,601355,601399,796,601320,601386,601813,51458,594079,386905,796,94751,94773,796,51502,1088764,1088811,387083,386969,387048,387035,387020,51423,51489,94701,796,796,387094,51537,387004,51474,51548,94669,1664426,1664375,1664639,1664489,796,1664500,1664604,796,1664410,1664441,1664689,1664454,93934,93945,94165,93855,1521764,93886,94093,93820,93899,94115,796,94075,796,93871,4689,4794,3897870,3991,4610,199186,4811,4676,796,4754,4724,796,4661,4735,4861,4645,4772,796,1088764,387083,386969,387048,387035,387020,796,387094,387004,53783,54470,54181,5840,796,796,53479,796,54115,50130,50392,5768,53415,5694,5787,5809,5678,54498,53593,53834,53849,5722,796,53908,53862,54485,53818,796,53545,5757,53604,54533,54240,53514,796,54194,796,53530,54150,5709,796,54051,54355,796,54544,54419,54454,54166,54229,53719,796,53897,53558,5643,2979629,1534801,3664369,1534926,2610638,1534836,1534915,796,1534880,1534867,796,1534852,1161789,1161146,1161157,1161727,1161067,1161098,1161083,796,796,1161758,1161111,1161032,1160480,1160554,1160669,1160464,1160429,1160724,796,1160543,796,1160495,1160700,1160508,1593662,1593677,796,3673928,2496906,1593690,1593736,1593759,1593646,1593725,796,1593611,1593842,840156,1486799,1831555,871235,1486924,1486865,840207,1486992,840281,1486834,841893,840191,871211,796,1529671,840235,1486913,1486735,1486878,840222,796,840270,796,796,1486850,1107799,1107918,1107709,796,1108000,1108019,1107788,2472808,1107674,1107753,1107740,1107725,1108048,796,560880,560931,560959,561005,1308874,560915,560946,796,796,560994,134088,134014,134197,133963,133998,134228,796,134329,134029,134077,796,134348,134042,1664426,796,623663,625988,796,626054,1664375,1664639,625754,796,1664311,624763,625485,623679,625450,625924,625437,625789,796,623694,796,796,624814,1664489,796,796,625726,625146,624842,22008,625307,625067,625611,625118,796,796,626102,625675,623707,626039,1664500,796,22074,22122,625800,625741,625422,1664604,796,624829,626113,1664410,796,625710,624888,626023,624699,625192,624798,22059,623742,796,1664441,625102,796,1664689,623628,626067,623564,625371,624877,796,22133,625181,567335,625003,1664454,625133,625496,22043,22087,625406,623753,1444560,1444494,1480821,1444619,1626202,1444529,796,1444545,1444608,1480873,1444573,796,2077587,2077522,796,2077557,2077568,2077443,2077609,2077478,796,2077494,2077509,3485726,796,3485741,3485800,3485789,3485754,3485710,3485675,796,2979629,631469,3829959,796,627008,1534801,1941724,1941838,632586,632540,3830018,632715,632496,796,3830108,3829926,796,626960,3664369,1534926,796,627019,632904,2610638,632246,1534836,1534915,626929,796,632397,632814,1534737,626945,796,1534880,796,1534867,632512,632845,632575,632779,796,796,796,3832620,632527,3830007,3829972,3829824,1941849,796,632893,632461,632830,1943332,631445,1941759,796,1534852,1941803,1941660,3829943,626973,632858,3991,3829891,860767,1941790,626894,1941775,3676225,3676677,3673774,796,3673855,3676494,796,3676260,3676613,3687013,796,3686949,3673820,3673791,3673739,796,3676302,3686830,3673807,3687749,3686965,3686897,3676561,3687024,3676642,3688104,3688017,3688069,3686932,3687858,3686978,796,3676629,3676688,796,3687773,3676596,3673866,3500325,3500391,3500404,3500450,3501507,3500360,796,796,3500439,3500376,3186107,3186181,796,3199137,3186122,3186091,3186170,3186056,796,3199080,3186135,520108,796,520095,2684721,2685334,2684631,520154,2684710,970315,520143,520062,2684596,796,2684647,2684662,796,2684675,796,520027,1124207,520078,2684532,565956,3991,3626642,3626690,796,3626598,3626679,3626563,796,3626614,3626629,3632811,3632697,796,3633817,3632748,3632763,3633903,3632776,3632822,796,3633868,3632732,796,3696022,3695775,3695659,3695740,3695727,3695711,3695972,796,3695786,3695937,3695694,1500811,1500752,1548305,1500721,796,1500686,2654094,1500737,1500800,796,2654018,1500765,1160480,1517889,796,1161789,1101773,1160554,1161146,1160669,1500981,1160464,1161157,1160429,1501159,1101821,1160968,1161727,1161067,1501045,1160724,1161098,796,1161083,1501096,1160543,796,796,1501111,1406991,1101707,796,1501170,1501124,796,1157455,796,1501080,1101832,796,1157522,1160495,1160700,1161758,1101742,1101758,1160365,1160508,1161111,1261501,1101786,1161032) order by last_modified desc limit 5

3 ms 0or1row dbqd.acs-content-repository.tcl.content-revision-procs.content::revision::item_id.item_id: 0or1row nsdb1

select item_id
from cr_revisions
where revision_id = '2863943'

200 ms 0or1row dbqd.acs-content-repository.tcl.content-revision-procs.content::revision::item_id.item_id: 0or1row nsdb1

select item_id
from cr_revisions
where revision_id = '2857211'

189 ms 0or1row dbqd.acs-content-repository.tcl.content-revision-procs.content::revision::item_id.item_id: 0or1row nsdb1

select item_id
from cr_revisions
where revision_id = '2806819'

148 ms 0or1row dbqd.acs-content-repository.tcl.content-revision-procs.content::revision::item_id.item_id: 0or1row nsdb1

select item_id
from cr_revisions
where revision_id = '2806822'

230 ms 0or1row dbqd.acs-content-repository.tcl.content-revision-procs.content::revision::item_id.item_id: 0or1row nsdb1

select item_id
from cr_revisions
where revision_id = '2788261'

286 ms select dbqd.latest.tcl.latest-procs.latest::asm.answered_assessments: select nsdb0

select cr.item_id as assessment_id, cr.title, a.password,
to_char(a.start_time, 'YYYY-MM-DD HH24:MI:SS') as start_time,
to_char(a.end_time, 'YYYY-MM-DD HH24:MI:SS') as end_time,
to_char(now(), 'YYYY-MM-DD HH24:MI:SS') as cur_time,
to_char(cr.publish_date, 'MM-DD-YYYY') as publish_date,
sc.node_id as comm_node_id, sa.node_id as as_node_id
from as_assessments a, cr_revisions cr, cr_items ci, cr_folders cf,
site_nodes sa, site_nodes sc, apm_packages p
where a.assessment_id = cr.revision_id
and cr.revision_id = ci.latest_revision
and ci.parent_id = cf.folder_id
and sa.object_id = cf.package_id
and sc.node_id = sa.parent_id
and cf.package_id in (37528,37420,31255,31283,31318,31329,37719,31239,796,796,46633,31270,31204,1664426,796,4223,3810,796,623663,625988,796,3869,626054,1664375,2077587,4098,3779,796,1664639,625754,796,1664311,624763,625485,623679,2077522,3795,625450,625924,625437,625789,796,796,623694,796,796,624814,1664489,796,21944,796,625726,625146,624842,22008,625307,625067,625611,625118,796,796,626102,625675,623707,626039,1664500,2077557,4194,796,22074,22122,625800,625741,625422,1664604,796,624829,626113,1664410,3823,2077568,796,2077443,625710,624888,3991,626023,2077609,2077478,624699,625192,796,4073,624798,3744,22059,623742,796,1664441,625102,4129,2077379,796,1664689,623628,3858,626067,623564,625371,624877,796,22133,625181,567335,625003,1664454,625133,625496,2077494,22043,22087,625406,623753,2077509,796,601435,601895,601371,601446,601864,601791,601355,601399,796,601320,601386,601813,51458,594079,386905,796,94751,94773,796,51502,1088764,1088811,387083,386969,387048,387035,387020,51423,51489,94701,796,796,387094,51537,387004,51474,51548,94669,1664426,1664375,1664639,1664489,796,1664500,1664604,796,1664410,1664441,1664689,1664454,93934,93945,94165,93855,1521764,93886,94093,93820,93899,94115,796,94075,796,93871,4689,4794,3897870,3991,4610,199186,4811,4676,796,4754,4724,796,4661,4735,4861,4645,4772,796,1088764,387083,386969,387048,387035,387020,796,387094,387004,53783,54470,54181,5840,796,796,53479,796,54115,50130,50392,5768,53415,5694,5787,5809,5678,54498,53593,53834,53849,5722,796,53908,53862,54485,53818,796,53545,5757,53604,54533,54240,53514,796,54194,796,53530,54150,5709,796,54051,54355,796,54544,54419,54454,54166,54229,53719,796,53897,53558,5643,2979629,1534801,3664369,1534926,2610638,1534836,1534915,796,1534880,1534867,796,1534852,1161789,1161146,1161157,1161727,1161067,1161098,1161083,796,796,1161758,1161111,1161032,1160480,1160554,1160669,1160464,1160429,1160724,796,1160543,796,1160495,1160700,1160508,1593662,1593677,796,3673928,2496906,1593690,1593736,1593759,1593646,1593725,796,1593611,1593842,840156,1486799,1831555,871235,1486924,1486865,840207,1486992,840281,1486834,841893,840191,871211,796,1529671,840235,1486913,1486735,1486878,840222,796,840270,796,796,1486850,1107799,1107918,1107709,796,1108000,1108019,1107788,2472808,1107674,1107753,1107740,1107725,1108048,796,560880,560931,560959,561005,1308874,560915,560946,796,796,560994,134088,134014,134197,133963,133998,134228,796,134329,134029,134077,796,134348,134042,1664426,796,623663,625988,796,626054,1664375,1664639,625754,796,1664311,624763,625485,623679,625450,625924,625437,625789,796,623694,796,796,624814,1664489,796,796,625726,625146,624842,22008,625307,625067,625611,625118,796,796,626102,625675,623707,626039,1664500,796,22074,22122,625800,625741,625422,1664604,796,624829,626113,1664410,796,625710,624888,626023,624699,625192,624798,22059,623742,796,1664441,625102,796,1664689,623628,626067,623564,625371,624877,796,22133,625181,567335,625003,1664454,625133,625496,22043,22087,625406,623753,1444560,1444494,1480821,1444619,1626202,1444529,796,1444545,1444608,1480873,1444573,796,2077587,2077522,796,2077557,2077568,2077443,2077609,2077478,796,2077494,2077509,3485726,796,3485741,3485800,3485789,3485754,3485710,3485675,796,2979629,631469,3829959,796,627008,1534801,1941724,1941838,632586,632540,3830018,632715,632496,796,3830108,3829926,796,626960,3664369,1534926,796,627019,632904,2610638,632246,1534836,1534915,626929,796,632397,632814,1534737,626945,796,1534880,796,1534867,632512,632845,632575,632779,796,796,796,3832620,632527,3830007,3829972,3829824,1941849,796,632893,632461,632830,1943332,631445,1941759,796,1534852,1941803,1941660,3829943,626973,632858,3991,3829891,860767,1941790,626894,1941775,3676225,3676677,3673774,796,3673855,3676494,796,3676260,3676613,3687013,796,3686949,3673820,3673791,3673739,796,3676302,3686830,3673807,3687749,3686965,3686897,3676561,3687024,3676642,3688104,3688017,3688069,3686932,3687858,3686978,796,3676629,3676688,796,3687773,3676596,3673866,3500325,3500391,3500404,3500450,3501507,3500360,796,796,3500439,3500376,3186107,3186181,796,3199137,3186122,3186091,3186170,3186056,796,3199080,3186135,520108,796,520095,2684721,2685334,2684631,520154,2684710,970315,520143,520062,2684596,796,2684647,2684662,796,2684675,796,520027,1124207,520078,2684532,565956,3991,3626642,3626690,796,3626598,3626679,3626563,796,3626614,3626629,3632811,3632697,796,3633817,3632748,3632763,3633903,3632776,3632822,796,3633868,3632732,796,3696022,3695775,3695659,3695740,3695727,3695711,3695972,796,3695786,3695937,3695694,1500811,1500752,1548305,1500721,796,1500686,2654094,1500737,1500800,796,2654018,1500765,1160480,1517889,796,1161789,1101773,1160554,1161146,1160669,1500981,1160464,1161157,1160429,1501159,1101821,1160968,1161727,1161067,1501045,1160724,1161098,796,1161083,1501096,1160543,796,796,1501111,1406991,1101707,796,1501170,1501124,796,1157455,796,1501080,1101832,796,1157522,1160495,1160700,1161758,1101742,1101758,1160365,1160508,1161111,1261501,1101786,1161032)
and p.package_id = sc.object_id
and exists (select 1
from as_assessment_section_map asm, as_item_section_map ism
where asm.assessment_id = a.assessment_id
and ism.section_id = asm.section_id)
and acs_permission__permission_p (a.assessment_id, '507', 'read') = 't'
order by publish_date desc limit 5

602 ms 0or1row dbqd.latest-portlet.www.latest-portlet.check_lors: 0or1row nsdb0

select package_key, pretty_name, installed_p from apm_package_version_info where package_key = 'lors'

12 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 = '507' and ppm.privilege = 'admin' )

522 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 = '507')

167 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 = '507')

258 ms select dbqd.theme-zen.tcl.navigation-procs.zen::portal_subnavbar.list_page_nums_select: select nsdb0

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

202 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 = '385' and ppm.party_id = '507' and ppm.privilege = 'admin' )

270 ms 0or1row dbqd.acs-subsite.tcl.subsite-procs.subsite::util::get_portrait_live_revision.get_portrait_info: 0or1row nsdb0

select cr.revision_id
from cr_revisions cr, cr_items ci, acs_rels a
where cr.revision_id = ci.live_revision
and ci.item_id = a.object_id_two
and a.object_id_one = '507'
and a.rel_type = 'user_portrait_rel'
and ci.live_revision is not null

0 ms releasehandle releasehandle nsdb1
1 ms releasehandle releasehandle nsdb0
18,977 Total Duration (ms)


What I can take from these tests is: I'm not using pool1, only pool2 and pool3. I don't know why that happens. Can somebody tell me how it works?

I'm still running some other tests, but I've seen some odd thing: the command db_available_pools "" returned this:

pool2 pool3 pool1

It seems like the pool order is reversed, and I have no idea what was causing it. There's also something that is making my test results be a little bit wrong: the repeated query Operation Blocked thing. As the requests are made simultaneously from the same machine, the system is stoping it thinking the same query is being sent. I have to find a way to untoggle this feature so the results can be OK.

I'm still working with your others suggestions and I'll put my results here as soon as I can.

Sorry for the late answer, but I was doing some other things and I left the tests a little bit aside. I'm going to have a report really soon about the effects of changing every parameter in the performance.

My question now is much more related to the service itself than the tests environment. I'm facing some performance issue right now that I don't where it comes from. Evry once in a while, about every ten minutes to half hour, I can see a major performance issue. I just can't get no response and the db queries seem to get real slow. Trying o find out what this is about, I"ve found that, in my log, I can see these messages:


[16/Jun/2008:21:58:57][14985.1296435552][-default:720-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:57][14985.1317448032][-default:721-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:57][14985.1401497952][-default:728-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:57][14985.1300638048][-default:736-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:57][14985.1275423072][-default:730-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:57][14985.1174587744][-default:756-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:57][14985.1393092960][-default:705-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:57][14985.1103145312][-default:747-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:57][14985.1334258016][-default:724-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:57][14985.1342663008][-default:726-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:57][14985.1107347808][-default:745-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:57][14985.1292233056][-default:718-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:58][14985.1204005216][-default:744-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:58][14985.1174587744][-thread1174587744-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:58:58][14985.1174587744][-thread1174587744-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 302ms)
[16/Jun/2008:21:58:58][14985.1275423072][-thread1275423072-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:58:59][14985.1191397728][-default:759-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:59][14985.1275423072][-thread1275423072-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 497ms)
[16/Jun/2008:21:58:59][14985.1288030560][-default:733-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:59][14985.1103145312][-thread1103145312-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:58:59][14985.1145170272][-default:713-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:59][14985.1267018080][-default:742-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:59][14985.1199802720][-default:702-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:00][14985.1376282976][-default:735-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:00][14985.1103145312][-thread1103145312-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 667ms)
[16/Jun/2008:21:59:02][14985.1325853024][-default:737-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:03][14985.1212410208][-thread1212410208-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:59:03][14985.1212410208][-thread1212410208-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 233ms)
[16/Jun/2008:21:59:03][14985.1393092960][-thread1393092960-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:59:04][14985.1393092960][-thread1393092960-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 1050ms)
[16/Jun/2008:21:59:05][14985.1321650528][-default:722-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:07][14985.1199802720][-thread1199802720-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:59:08][14985.1199802720][-thread1199802720-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 1202ms)
[16/Jun/2008:21:59:10][14985.1170385248][-default:717-] Warning: db_exec: longdb 5 seconds nsdb0 dml dbqd.acs-tcl.tcl.security-procs.sec_update_user_session_
info.update_last_visit
[16/Jun/2008:21:59:11][14985.1149372768][-default:753-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:11][14985.1166182752][-default:716-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:12][14985.1111550304][-default:746-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:18][14985.1292233056][-thread1292233056-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:59:18][14985.1334258016][-thread1334258016-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:59:19][14985.1292233056][-thread1292233056-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 936ms)
[16/Jun/2008:21:59:20][14985.1334258016][-thread1334258016-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 2293ms)
[16/Jun/2008:21:59:25][14985.1140967776][-default:731-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:26][14985.1132562784][-default:712-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:29][14985.1254410592][-default:738-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:29][14985.1149372768][-thread1149372768-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:59:30][14985.1149372768][-thread1149372768-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 1293ms)
[16/Jun/2008:21:59:30][14985.1338460512][-default:725-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:31][14985.1182992736][-default:757-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:34][14985.1161980256][-default:696-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:35][14985.1271220576][-default:719-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:35][14985.1098942816][-default:749-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:36][14985.1317448032][-thread1317448032-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:59:36][14985.1317448032][-thread1317448032-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 327ms)
[16/Jun/2008:21:59:40][14985.1098942816][-thread1098942816-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:59:40][14985.1178790240][-default:741-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:41][14985.1098942816][-thread1098942816-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 1219ms)
[16/Jun/2008:21:59:42][14985.1258613088][-default:708-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:42][14985.1153575264][-thread1153575264-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:59:44][14985.1304840544][-default:734-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:44][14985.1166182752][-thread1166182752-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:59:44][14985.1119955296][-default:750-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:44][14985.1153575264][-thread1153575264-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 1685ms)
[16/Jun/2008:21:59:46][14985.1208207712][-default:740-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:46][14985.1090537824][-default:727-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:46][14985.1115752800][-default:697-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:46][14985.1136765280][-default:752-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:46][14985.1372080480][-default:698-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:46][14985.1140967776][-thread1140967776-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:59:46][14985.1262815584][-default:707-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:46][14985.1166182752][-thread1166182752-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 2535ms)
[16/Jun/2008:21:59:46][14985.1145170272][-thread1145170272-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:59:48][14985.1140967776][-thread1140967776-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 2978ms)
[16/Jun/2008:21:59:50][14985.1145170272][-thread1145170272-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 4059ms)
[16/Jun/2008:21:59:53][14985.1401497952][-thread1401497952-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:59:57][14985.1304840544][-thread1304840544-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:59:57][14985.1401497952][-thread1401497952-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 4555ms)
[16/Jun/2008:22:00:00][14985.1271220576][-thread1271220576-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:22:00:01][14985.1304840544][-thread1304840544-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 4575ms)
[16/Jun/2008:22:00:02][14985.1288030560][-thread1288030560-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:22:00:04][14985.1271220576][-thread1271220576-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 4110ms)
[16/Jun/2008:22:00:05][14985.1372080480][-thread1372080480-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:22:00:05][14985.1178790240][-thread1178790240-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:22:00:08][14985.1288030560][-thread1288030560-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 5566ms)
[16/Jun/2008:22:00:08][14985.1372080480][-thread1372080480-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 2902ms)
[16/Jun/2008:22:00:08][14985.1178790240][-thread1178790240-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 2884ms)
[16/Jun/2008:22:00:14][14985.1208207712][-thread1208207712-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:22:00:17][14985.1262815584][-thread1262815584-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:22:00:17][14985.1182992736][-thread1182992736-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:22:00:17][14985.1262815584][-thread1262815584-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 624ms)
[16/Jun/2008:22:00:18][14985.1208207712][-thread1208207712-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 3466ms)
[16/Jun/2008:22:00:19][14985.1107347808][-thread1107347808-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:22:00:20][14985.1090537824][-thread1090537824-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:22:00:24][14985.1107347808][-thread1107347808-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 4952ms)
[16/Jun/2008:22:00:24][14985.1090537824][-thread1090537824-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 3785ms)
[16/Jun/2008:22:00:24][14985.1132562784][-thread1132562784-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:22:00:25][14985.1086335328][-sched-] Warning: db_exec: longdb 9 seconds nsdb0 dml dbqd.acs-tcl.tcl.security-procs.sec_sweep_sessions.sessions_sw
eep
[16/Jun/2008:22:00:25][14985.1342663008][-thread1342663008-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:22:00:26][14985.1086335328][-sched-] Warning: sched: excessive time taken by proc 4 (11 seconds)
[16/Jun/2008:22:00:28][14985.1132562784][-thread1132562784-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 3387ms)
[16/Jun/2008:22:00:28][14985.1191397728][-thread1191397728-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:22:00:29][14985.1300638048][-thread1300638048-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:22:00:30][14985.1191397728][-thread1191397728-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 1976ms)
[16/Jun/2008:22:00:32][14985.1342663008][-thread1342663008-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 7163ms)
[16/Jun/2008:22:00:35][14985.1325853024][-thread1325853024-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:22:00:37][14985.1300638048][-thread1300638048-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 7627ms)
[16/Jun/2008:22:00:37][14985.1325853024][-thread1325853024-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 2453ms)


All of a sudden the XoTcl get destroied, and I have no idea where it comes from. Can you give some hint about it?

Thank you for your quick answer. I have already installed in my machine ptop and some other tools to monitor PostgreSQL. From the PostgreSQL analysis, it seems like every time I can see these messages in my log, all the DB queries get very slow and ptop shows me that they are waiting to be parsed (they are in waiting state). From this analysis, my first thought is that this destroy objects call is bringing the performance down.

Then, I'm asking myself: why it happens? When I run the benchmark, the system uses all DB connections and threads available. After that, it destroys some of them, what shows me the log messages above. However, when the threads are being destroyed, the system gets so slow that we just can't navigate.

So, there are some thoughts I can get from here:

1 - Is the thread destroy proccess being a performance problem?
2 - Why the DB connections stay in waiting when this destroy is hapenning if I have memory, processor and connections available?

I'll try to take a closer look at the PostgreSQL performance info at this time and try to see something I haven't seem yet. Thank you for your help.

the aolserver has the bad behavior, that it is likely that the thread termination parameters (maxconnections, threadtimeout) terminate all connection threads at the same time. This happens, when these threads were started at more or less the same time, which is likely on busy sites or during benchmarks. This mass extinction of threads is performance-wise not a good idea, especially when most of the threads have to be recreated afterwards. Termination and recration of threads are costly operations learning to noticeable delays.

To overcome this problem i have committed a small change to aolserver 4.5 head, that introduces a "spread", a randomization factor for the two mentioned thread termination parameters. The spread will lead to slightly different values for maxconnections and threadtimeout per connection thread (default is +- 20%). When spread is 0 one obtains the original behavior. You might be interested in trying this version.

Thank you very much for your replies. I'm sorry for the time I've taken to post, but I had some personal issue to solve.

With our tests and observations, we are writing some kind of benchmark howto document that should go somewhere in the community, maybe in the XoWiki instance. Our tests had three branches of observation:

1 - AOLServer (OpenACS?) Tunning
2 - PostgreSQL Tunning
3 - SO Tunning

I'm going to try to make a brief description about the specific and generic observations we could find:

<h4> AOLServer (OpenACS? Tunning) </h4>

Our first issue with AOLServer was the 4.5.0 parameters problem that somebody fixed with the file /acs-tcl/tcl/pools-init.tcl as said in this post in Tom's message. With a simple update we where able to solve this issue.

The other problem was with the thread creation process wich, as you just said, is a mixed XoTcl + AOLServer problem. The most important thing we've realized is that the creation and destruction process consumes a lot of I/O operations. To improve the I/O performance we've tried to change the file system, but it had no effect due to the most important thing we've find out: DON'T EVER USE VM's IN PRODUCTION SITES.

Our server was based on Xen VM's and it was impossible to have I/O performance with Virtual Machines. The whole thing about it is that there's no virtualization process able to split the blocks and inodes completely when using virtual machines, so all the I/O is shared between the VM's in the Cluster. It's a little bit different from what happens with logical partitions possible in some hardwares, such as IBM's big servers. In that case the files are completely separated and the partition works with no I/O issues.

Based on this observation, we've switched the production environment to a dedicated server with the specifications described in the first post of this thread, and most of the problems with threads creation and destruction are gone.

The next step was to adjust the configuration file. I guess the biggest challenge to everybody using OpenACS is the best relation between number of users X maxconnections X requests X maxthreads. This is the part where we are stuck right now. According to this Gustaf's Post on AOLServer list:

the question certainly is, what "concurrent users" means (...) note, that when talking about "concurrent users", it might be the case that one user has many requests concurrently running. To simplify things, we should talk about e.g. 10 concurrent requests.

Then you need
- at least 10 threads
- at least 10 connections
The number of database connections is more difficult to estimate, since
this in an application(oacs) matter. In oacs, most dynamic requests need
1 or 2 db connections concurrently.

I know this is not like a cookbook, but using his observation we could think about one thread, one connection and 2 db connections for each request. With these parameters, concerning that the tests are going to perform all the requests we configure at the same time, the results are most likely following this logic. When we set the maxthreads to 150, there's a little bit of degradation in memory trying to serve 100 simultaneous requests. This degradation is over when you set the parameters minthreads to 80 and maxthreads to 120. What we can get from here is that one thread is able to serve one request in the best performance adjustments.

However, when you send these setting to production, there's maybe the most difficult problem: to estimate the number of requests per user. Maybe one patch in xotcl-request-monitor could answer this question, but we are still thinking about the best way to do it. We could also see that the number of connections per user is very different from the relation 1 X 1, and this another thing we are trying to find the best relation.

<h4> PostgreSQL Tunning </h4>

All the tests we are performing until now consider DB and OpenACS in the same box. The goal is to find out the performance limit to this setting, so we can remove PostgreSQL from the machine and measure how it gets better.

There's a lot of material for PostgreSQL in the Internet, and I'm not one specialist myself, but I guess there are some specific observations that could be done.

Everybody says that Internet applications are doing most of the time SELECT operations in the database. This is a myth. If you consider number of operations maybe it can be true, but it's not when you consider execution time and resources usage. The number of TPS (Transactions Per Second) in an application using OpenACS is very large, and that's a good thing. In the old Internet you where creating content to people see. The new paradigm says the opposite: now the users create the content, and that's why I use OpenACS. There's just no better option to build social and collaborative networks in the market.

Concerning this matter, most of PostgreSQL tuning involves transaction improvements. I can't still understand completely the pools mechanism that OpenACS uses for PostgreSQL, and I guess some improvement in this area could make my tests better.

The most important thing to adjust here is the shared memory mechanism. We've seen that, if you put a too big number in PostgreSQL and OS, the memory shared between PostgreSQL and AOLServer can cause the system to crash under stress situations, and that's not a good thing. The I/O becomes a problem with a large number of INSERT and DELETE operations, mostly because the thread creation process is also heavy for the system.

The conclusion is: if you want to have the best performance, you really have to split AOLServer and PostgreSQL in different boxes. The exact point to do it (DB size, number of users) is what we are trying to find out.

<h4> OS Tuning </h4>

Maybe this is the most difficult part to be done, because Linux has a lot of options that can be changed. A better analysis concerning resource usage is necessary so we can have better numbers. I'm going to put here a list of parameters we are changing in a Debian GNU/Linux Etch system:

# echo 2 > /proc/sys/vm/overcommit_memory
# echo 27910635520 > /proc/sys/kernel/shmmax
# echo 32707776 > /proc/sys/kernel/shmall
# echo deadline > /sys/block/sda/queue/scheduler
# echo 250 32000 100 128 > /proc/sys/kernel/sem
# cat /proc/sys/fs/file-max
753884
# echo 16777216 > /proc/sys/net/core/rmem_default
# echo 16777216 > /proc/sys/net/core/wmem_default
# echo 16777216 > /proc/sys/net/core/wmem_max
# echo 16777216 > /proc/sys/net/core/rmem_max
# su - postgres
postgres@nodo406:~$ ulimit 753883

There are some other things, such as Kernel changes and TCP/IP configuration we are changing, but I don't think we have the better adjusts yet, so let's wait a little longer.

That's it. Sorry about the long post, but I guess I should give the community some qualified feedback, concerning all the help you guys always give to us.

It would be certainly an interesting project to build something like OpenACS based on a P2P-network and DHTs (cassandra, bigtable, ... coral, cfs, oceanstore .... pier), but this will be a different project, since some basic assumption about the data storage are different.

Sure, DHT is just the basic workhorse, most of the other examples have also quite different properties than e.g. cassandra. What is the problem with the term "project"? xotcl-core and xowiki went out to be compatible with the acs data model. There is nothing wrong in having a project developing an acs package based on p2p technology. Many people will appreciate it. From the scope of the work, it is a project.

Now, an interesting argument would be the one that makes the case for the use of ACID properties for content-oriented applications and semi-structured data.

You can do the same thing for resources (css, javascript, images, graphics) using a reverse proxy. The idea is that you should not keep threads loaded with the full blueprint of your installation for these tasks.

The way you use background delivery is similar to ns_returnfile, i.e.

ad_returnfile_background 200 [ns_guesstype ${filename}] ${filename}

Though, you need to make sure that you have tthread installed and the background delivery code that Gustaf wrote.

PS. The NaviServer project went the extra mile of serving requests by loading the procs dynamically --- only those required for a given request. My understanding is that the xorb package does something similar but at a higher level of abstraction.

about tclthreads: The package on TCL's file distribution area (on sf) is called thread-2.6.5 (not sure if that's what you mean). That package also includes ttrace, yes.

about ttrace: NaviServer has that integrated or makes use of it in order to provide tracing as an option. I haven't used that due to some problems that existed between that mechanism and XOTCL back when I tried (as soon as it was released). I remember sending you a message about that but I am not sure what's the current status.

about xorb: yes, I did not mean to imply that it is a replacement but it does serialize/deserialize code from a single thread and it also makes threads thinner, right? (just asking)

1. xotcl-core (sure, if it is defined there)
2. one needs either a "new" aolserver, or an "old" with the required patches (see discussion above and Boost...), and
3. one has to have libthread installed (tcl thread library, as described in the request-monitor wiki page)

Hope this helps -gustaf neumann

Your considerations are very helpful, as they always are. I can have now a more general view about threads X requests behavior. I'll try to make comments based on what you've posted.

- When I said there was a XoTcl problem, I was talking about how the destroy process can be painful depending on the OS + Hardware set. But as you said better, it's not like a XoTcl problem, is more like an AOLServer problem. I guess we agree here.

- I guess I could finally understand what the threads are meant to do. If you have a portion of memory that includes all the procs in the system that can be shared, I can see how 150 is a too large number. Thank you very much for this explanation. I was seeing in production an error that says that maxconnections is exceeded, even with machine resources available. Your explanation shows me that there where a lot of threads in queue waiting for a large download to finish,and background delivery could be a solution for that. I'll think about more testing on that and I'll give everybody a feedback about it.

- About use PostgreSQL and AOLServer in the same box, I've seen in this post here that you run in learn@wu the IBM logical partitions. Is that right? In that case you have no degradation and the system allows you to do everything in the same box without I/O issues. If you consider that a socket connection is quite faster than a TCP/IP one, it's probably a good idea to use the same box. Otherwise, I guess the split is a better option.

That's it. Thank you for the help.

Now I've got what you said. You see: IBM has an OS split mechanism called LPAR or logical partitions, as it's explained here. Using this feature is like if you have a VM, but without the software and hardware limitations that makes it impossible to split completely the I/O between all the machines you have. I thought that was the case for your production system, wich now you say it's not.

If you consider that a socket connection is quite faster than a TCP/IP connection, I can see that having both DB and AOLServer in the same box can be faster if you have enough available resources.

Concerning our tests, however, there's something showing up that can bring more issues to this matter. Linux Kernel has a parameter that sets the maximum amount of shared memory your applications can use in the system, wich is located at /proc/sys/kernel/shmmax. This parameter controls, for example, the amount of memory PostgreSQL can use in the shared buffers. In our test cases, we had the following set of parameters:

## AOLServer parameters
ns_section ns/threads
    ns_param   mutexmeter         true      ;# measure lock contention
    # The per-thread stack size must be a multiple of 8k for AOLServer to run under MacOS X
    ns_param   stacksize          [expr 1 * 8192 * 256]
ns_section ns/server/${server}
    ns_param   maxconnections     1000      ;# Max connections to put on queue
    ns_param   maxdropped         0
    ns_param   maxthreads         300      ;# Tune this to scale your server
    ns_param   minthreads         200       ;# Tune this to scale your server
    ns_param   threadtimeout      120      ;# Idle threads die at this rate
    ns_param   globalstats        false    ;# Enable built-in statistics
    ns_param   urlstats           true     ;# Enable URL statistics
    ns_param   maxurlstats        1000     ;# Max number of URL's to do stats on
ns_section ns/db/pool/pool1
#    ns_param   maxidle            0
#    ns_param   maxopen            0
    ns_param   connections        200
    ns_param   verbose            $debug
    ns_param   extendedtableinfo  true
    ns_param   logsqlerrors       $debug
    if { $database == "oracle" } {
        ns_param   driver             ora8
        ns_param   datasource         {}
        ns_param   user               $db_name
        ns_param   password           $db_password
    } else {
        ns_param   driver             postgres
        ns_param   datasource         ${db_host}:${db_port}:${db_name}
        ns_param   user               $db_user
        ns_param   password           ""
    }
ns_section ns/db/pool/pool2
#    ns_param   maxidle            0
#    ns_param   maxopen            0
    ns_param   connections        150
    ns_param   verbose            $debug
    ns_param   extendedtableinfo  true
    ns_param   logsqlerrors       $debug
    if { $database == "oracle" } {
        ns_param   driver             ora8
        ns_param   datasource         {}
        ns_param   user               $db_name
        ns_param   password           $db_password
    } else {
        ns_param   driver             postgres
        ns_param   datasource         ${db_host}:${db_port}:${db_name}
        ns_param   user               $db_user
        ns_param   password           ""
    }
ns_section ns/db/pool/pool3
#    ns_param   maxidle            0
#    ns_param   maxopen            0
    ns_param   connections        150
    ns_param   verbose            $debug
    ns_param   extendedtableinfo  true
    ns_param   logsqlerrors       $debug
    if { $database == "oracle" } {
        ns_param   driver             ora8
        ns_param   datasource         {}
        ns_param   user               $db_name
        ns_param   password           $db_password
    } else {
        ns_param   driver             postgres
        ns_param   datasource         ${db_host}:${db_port}:${db_name}
        ns_param   user               $db_user
        ns_param   password           ""
    }
## Kernel Parameters:
/proc/sys/kernel/shmall	2097152
/proc/sys/kernel/shmmax	2156978176
## PostgreSQL Parameters:
max_connections = 1000           # (change requires restart)
shared_buffers = 2000MB         # min 128kB or max_connections*16kB
work_mem = 1MB              # min 64kB
max_stack_depth = 5MB           # min 100kB

With these values, the memory was corrupted and caused the database to crash under the stress test, wich means that PostgreSQL process did shut down all connections and killed the postmaster process, making the server to show a message and don't shut down or come back.

With all the information I have now, I can see this was probably caused by the huge amount of threads I've put. The new threads where trying to get more and more memory, and the OS just couldn't give it. As both AOLServer and PostgreSQL where theoretically using the same memory area, it caused the DB to corrupt and to kill the process. If they where split in different servers maybe this wouldn't happen, and it made us think that different servers are always the best solution. No matter what you do wrong and what happens to the server, the AOLServer crash will not kill the DB process and DB will also not kill AOLServer too. This could be the safer choice for the case.

I'm bringing back this topic because one of the most discussed things was the background delivery. I'm running some tests and the results are really impressive. The waiting time is dramatically reduced as we have the control thread responsible for the downloads.

I've written a patch based based on oacs-5-3 that puts the background delivery in some more places. I've put it in the bugtracker and you can see it here: http://www.openacs.org/bugtracker/openacs/patch?patch_number=894

However, there's still something missing. When I look at the request-monitor running requests page, I can see a lot of files that are being downloaded for hours wich are still there. It seems like the channel isn't closed if the user doesn't finish the download in the usual way.

Perharps we should have some kind of scheduled procedure to close this kind of channel, or some tool to check if it isn't used anymore, but I don't have a clue on how to do it. Can somebody point me a direction on that?