Forum OpenACS Q&A: Re: Incredible Performance Decrease - Please help!!!

Collapse
Posted by Nima Mazloumi on

When I select request information (/ds/request-info?request=1579) of the developer support I get the following exception:

Request Error
Required switch -multirow not provided
    while executing
"template::list::create__arg_parser"
    (procedure "template::list::create" line 1)
    invoked from within
"template::list::create  -name dbreqs  -elements {
        duration_ms {
            label "Duration"
            html { align right }
            disp..."
    invoked from within
"if { [info exists property(db)] } {
    multirow create dbreqs handle command sql duration_ms value

    foreach { handle command statement_name sql s..."
    ("uplevel" body line 201)
    invoked from within
"uplevel {
    	  # $Id: request-info.tcl,v 1.7 2004/01/14 08:58:34 lars Exp $
# File:        request-info.tcl
# Author:      Jon Salz 
..."
    (procedure "code::tcl::/www/unima0/packages/acs-developer-support/www/re..." line 2)
    invoked from within
"code::tcl::$__adp_stub"
    invoked from within
"if { [file exists $__adp_stub.tcl] } {

      # ensure that data source preparation procedure exists and is up-to-date
      adp_init tcl $__adp_stub
..."
    ("uplevel" body line 3)
    invoked from within
"uplevel {

    if { [file exists $__adp_stub.tcl] } {

      # ensure that data source preparation procedure exists and is up-to-date
      adp_init t..."
    (procedure "adp_prepare" line 2)
    invoked from within
"adp_prepare "
    (procedure "template::adp_parse" line 30)
    invoked from within
"template::adp_parse [file root [ad_conn file]] {}"
    (procedure "adp_parse_ad_conn_file" line 7)
    invoked from within
"$handler"
    ("uplevel" body line 2)
    invoked from within
"uplevel $code"
    invoked from within
"ad_try {
                $handler
            } ad_script_abort val {
                # do nothing
            }"
    invoked from within
"rp_serve_concrete_file [ad_conn file]"
    (procedure "rp_serve_abstract_file" line 60)
    invoked from within
"rp_serve_abstract_file "$root/$path""
    ("uplevel" body line 2)
    invoked from within
"uplevel $code"
    invoked from within
"ad_try {
	rp_serve_abstract_file "$root/$path"
	set tcl_url2file([ad_conn url]) [ad_conn file]
	set tcl_url2path_info([ad_conn url]) [ad_conn path_inf..."

Collapse
Posted by Joel Aufrecht on
I helped Nima get acs-developer-support fixed (it had to do with the bad repository files I just fixed) and did some browsing around with supplied accounts.

I am logged in via ext-auth as mazloumi, with developer support on. The front page comes up in 3 seconds (lots of 200msec permission check), not 20, but it may be cached.

While going to site-wide administration to flush the cache, I found that that page took 18 seconds, almost all here:

18061 ms
dbqd.acs-admin.lib.service-parameters.services_select: select nsdb0

                    select package_id,
                          ap.package_key,
                          acs_object__name(package_id) as
                          instance_name,
                          apm_package_type__num_parameters(ap.package_key)
                          as parameter_count
                    from apm_packages ap,
                        apm_package_types
                    where ap.package_key =
                          apm_package_types.package_key
                    and package_type = 'apm_service'
                    and (
                            acs_permission__permission_p(package_id,
                          '872797', 'read') = 't'
                        or acs_permission__permission_p(package_id,
                          acs__magic_object_id('the_public'), 'read')
                          = 't'
                        )
                    and  (ap.package_key != 'acs-subsite' or (select
                          parent_id from site_nodes where object_id =
                          package_id) is null)
                    order by instance_name

After flushing the cache, I can still access the front page in 4 seconds.  Not great, but not awful.

I did some more random browsing.  Most pages take 2-3 seconds, and the only real reason is a bunch of permission checks like:

170 ms
dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.sele\
ct_permission_p:
0or1row nsdb0

            select 1
            where 't' = acs_permission__permission_p('616213',
            '872797', 'portal_read_portal')

I browsed as both the admin user and a regular .LRN user.  I could not repro the 20-second load times.

Issues:
1) Can we fix all of these permission queries so that regular page loads aren't 3 seconds?
2) How can Nima use developer support while logged in as a regular user, in order to try and repro the 20-second problem with proper instrumentation available?

Collapse
Posted by Joel Aufrecht on
Answer to question 2:

1) Log in as a sitewide admin on one browser and go to /ds.
2) On another browser which is not sharing cookies, log in as a regular user and reproduce the problem.
3) refresh the screen on the first browser.  The long query will be sitting on the list; click on it to reveal the guilty database query.

Collapse
Posted by Lars Pind on
I got rid of the permissions-checks in the service-parameters query above, since you only see this page if you're site-wide admin, anyway. This is in HEAD, though.
Collapse
Posted by Dirk Gomez on
On the danger of repeating myself - PL/SQL or PGPL/SQL functions in where clauses are plain dangerous and do not scale at all.

If the result is known upon creation time - the result of acs__magic_object_id('the_public') is constant - then stuff its result into the view. Or for PG at least create the function as iscacheable.

As to the permissioning: Don suggests using a view instead of the acs_permission__permission_p.