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

Hi everybody,

I have a very strange behavior with my dotLRN installation. There are huge performance differences if I login as an admin or as a normal user into the system. As soon as I give admin rights to a user his acess gets almost 10 times faster. This behavior is very strange.

For an Admin

• 4s login
• 3s to load a class
• 0s to load a php page

Normal User - External Authenticated over PAM

• 20s to login
• 25-30s to load a class
• endless to load a php page

The performance went down even for an admin when I added a second authority. It improved when I disabled the local and run dotLRN over pam external authentication. But now users have to wait far too long to see a page being rendered if at all.

The user management is done via PAM Authentication Driver. The batch synchronization uploaded 21000 users to the system. The authentication parameter SyncAddUsersToDotLrnP was set on 1.

Could this be the reason?

Can some kindly look at my system below and check what could be the reason for this?

Thank you very much. I really appreciate your help!

Software:

• dotlrn 2.0.0b4 2.0.0b4
• PostgreSQL 7.3.4
• PHP 4.3.4
• AOLServer 3.3oas.1
• SuSE Linux 9.0 Kernel version 2.4.21-144-smp
• gcc version 3.3.1 (SuSE Linux)

Hardware:

• Siemens Fujitsu
• 4 CPU, each Intel(R) Xeon(TM) CPU 3.06GHz
• VGA compatible controller: ATI Technologies Inc Rage XL Bus
• 2 Ethernet controller: Broadcom Corporation NetXtreme BCM5704 Gigabit Ethernet
• 2 Fibre Channel: Emulex Corporation LP9000 Fibre Channel Host Adapter

Memory and Swap Information:

             total       used       free     shared    buffers     cached
Mem:       4058928    3648248     410680          0     271168    2575920
-/+ buffers/cache:     801160    3257768
Swap:      3911816          0    3911816

Driver Space Usage:

Filesystem            Size  Used Avail Use% Mounted on
/dev/md1               11G  2.9G  7.2G  29% /
/dev/md0              198M  6.1M  182M   4% /boot
/dev/sdc1              28G  1.4G   27G   5% /www
/dev/sdc3              37G  768M   37G   3% /pgdata
tmpfs                 2.0G     0  2.0G   0% /dev/shm
AFS                   8.6G     0  8.6G   0% /afs

All important Config.tcl Seetings:

set httpport              8000
set httpsport             8443
set debug false
set homedir                 /opt/aolserver
ns_param   nssock          ${bindir}/nssock.so 
ns_param   nslog           ${bindir}/nslog.so 
ns_param   nssha1          ${bindir}/nssha1.so 
ns_param   nscache         ${bindir}/nscache.so 
ns_param   nsrewrite       ${bindir}/nsrewrite.so 
ns_param   libtdom         ${bindir}/libtdom.so
ns_param   php             ${bindir}/libphp4.so
ns_param   nsopenssl       ${bindir}/nsopenssl.so
ns_param    nsfts           ${bindir}/nsfts.so
ns_param   nspam           ${bindir}/nspam.so
set directoryfile index.adp,index.tcl,index.php,index.html,index.htm
ns_param   maxkeepalive       5
ns_param   logroll            on
ns_param   maxbackup          5
ns_param   debug              $debug
ns_param   mutexmeter         true      ;# measure lock contention 
ns_param   stacksize          500000
ns_param   directoryfile      $directoryfile
ns_param   pageroot           $pageroot
ns_param   maxconnections     50
ns_param   maxdropped         0
ns_param   maxthreads         40
ns_param   minthreads         40
ns_param   threadtimeout      3600
ns_param   globalstats        false    ;# Enable built-in statistics 
ns_param   urlstats           false    ;# Enable URL statistics 
ns_param   maxurlstats        1000     ;# Max number of URL's to do stats on
ns_param   enableexpire  false     ;# Set "Expires: now" on all ADP's 
ns_param   enabledebug   $debug    ;# Allow Tclpro debugging with "?debug"
ns_param   defaultparser fancy
ns_param map /*.php
ns_param map /*.php3
ns_param map /*.php4
ns_param   timeout            120
ns_param   address            $address
ns_param   hostname           $hostname
ns_param   port               $httpport

# NSD-driven connections:
ns_param ServerPort                      $httpsport
ns_param ServerHostname                  $hostname
ns_param ServerAddress                   $address
ns_param ServerCertFile                  certfile.pem
ns_param ServerKeyFile                   keyfile.pem
ns_param ServerProtocols                 "SSLv2, SSLv3, TLSv1"
ns_param ServerCipherSuite               "ALL:!ADH:RC4+RSA:+HIGH:+MEDIUM:+LOW:+SSLv2:+EXP"
ns_param ServerSessionCache              false
ns_param ServerSessionCacheID            1
ns_param ServerSessionCacheSize          512
ns_param ServerSessionCacheTimeout       300
ns_param ServerPeerVerify                true
ns_param ServerPeerVerifyDepth           3
ns_param ServerCADir                     ca
ns_param ServerCAFile                    ca.pem
ns_param ServerTrace                     false

# For listening and accepting SSL connections via Tcl/C API:
ns_param SockServerCertFile              certfile.pem
ns_param SockServerKeyFile               keyfile.pem
ns_param SockServerProtocols             "SSLv2, SSLv3, TLSv1"
ns_param SockServerCipherSuite           "ALL:!ADH:RC4+RSA:+HIGH:+MEDIUM:+LOW:+SSLv2:+EXP"
ns_param SockServerSessionCache          false
ns_param SockServerSessionCacheID        2
ns_param SockServerSessionCacheSize      512
ns_param SockServerSessionCacheTimeout   300
ns_param SockServerPeerVerify            false
ns_param SockServerPeerVerifyDepth       3
ns_param SockServerCADir                 internal_ca
ns_param SockServerCAFile                internal_ca.pem
ns_param SockServerTrace                 true

# Outgoing SSL connections
ns_param SockClientCertFile              certfile.pem
ns_param SockClientKeyFile               keyfile.pem
ns_param SockClientProtocols             "SSLv2, SSLv3, TLSv1"
ns_param SockClientCipherSuite           "ALL:!ADH:RC4+RSA:+HIGH:+MEDIUM:+LOW:+SSLv2:+EXP"
ns_param SockClientSessionCache          false
ns_param SockClientSessionCacheID        3
ns_param SockClientSessionCacheSize      512
ns_param SockClientSessionCacheTimeout   300
ns_param SockClientPeerVerify            true
ns_param SockServerPeerVerifyDepth       3
ns_param SockClientCADir                 ca
ns_param SockClientCAFile                ca.pem
ns_param SockClientTrace                 false

# OpenSSL library support:
ns_param SeedBytes                       1024

ns_section ns/db/pools 
ns_param   pool1       "Pool 1"
ns_param   pool2       "Pool 2"
ns_param   pool3       "Pool 3"

ns_section ns/db/pool/pool1
ns_param   maxidle            1000000000
ns_param   maxopen            1000000000
ns_param   connections        5
ns_param   verbose            $debug
ns_param   extendedtableinfo  true
ns_param   logsqlerrors       $debug

ns_section ns/db/pool/pool2
ns_param   maxidle            1000000000
ns_param   maxopen            1000000000
ns_param   connections        5
ns_param   verbose            $debug
ns_param   extendedtableinfo  true
ns_param   logsqlerrors       $debug

ns_section ns/db/pool/pool3
ns_param   maxidle            1000000000
ns_param   maxopen            1000000000
ns_param   connections        5
ns_param   verbose            $debug
ns_param   extendedtableinfo  true
ns_param   logsqlerrors       $debug

ns_section ns/server/${server}/db
ns_param   pools              "*" 
ns_param   defaultpool        pool1

ns_param   enablehostnamelookup true
ns_param   logcombined          true
ns_param   maxbackup            1000
ns_param   rollday              *
ns_param   rollfmt              %Y-%m-%d-%H:%M
ns_param   rollhour             0
ns_param   rollonsignal         true
ns_param   rolllog              true

ns_section ns/server/${server}/module/nsjava
ns_param   enablejava         off  ;# Set to on to enable nsjava.
ns_param   verbosejvm         off  ;# Same as command line -debug.
ns_param   loglevel           Notice
ns_param   destroyjvm         off  ;# Destroy jvm on shutdown.
ns_param   disablejitcompiler off  
ns_param   classpath          /usr/local/jdk/jdk118_v1/lib/classes.zip:${bindir}/nsjava.jar:${pageroot}/webmail/java/activation.jar:${pageroot}/webmail/java/mail.jar:${pageroot}/webmail/java 

ns_param   PamDomain               "aolserver"

I vacuumed and analyzed postgres and installed developer support.

The Developer Support says the following: 5 database commands totalling -1877234293 ms Page served in 402999323 ms

01:05:20      134.155.53.42  GET /ds/ 
 01:05:18   321650 ms   134.155.53.42  GET /dotlrn/user-add-3 
 01:05:15   324516 ms   134.155.53.42  GET /ds/request-info?request=214 
 01:03:57   402999 ms   134.155.53.42  GET /dotlrn/user-add-3 
 01:03:15   444857 ms   134.155.53.42  GET /dotlrn/design/images/zufall/015.jpg 
 01:03:15   444902 ms   134.155.53.42  GET /dotlrn/design/images/spacer.gif 
 01:03:15   444906 ms   134.155.53.42  GET /dotlrn/design/images/zufall/logoUniMannheim.gif 
 01:03:15   444960 ms   134.155.53.42  GET /dotlrn/design/scripts/zufallscript.js 
 01:03:15   445039 ms   134.155.53.42  GET /dotlrn/stylesheets/portlets.css 
 01:03:15   445085 ms   134.155.53.42  GET /dotlrn/design/stylesheets/uni-headerFooter.css 
 01:03:15   445189 ms   134.155.53.42  GET /dotlrn/dotlrn-master.css 
 01:03:14   445465 ms   134.155.53.42  GET /dotlrn/user-add-2?read%5fprivate%5fdata%5fp=t&can%5fbrowse%5fp=1&... 
 01:03:10   449318 ms   134.155.53.42  POST /dotlrn/admin/user-new-2 
 01:03:04   455951 ms   134.155.53.42  GET /dotlrn/admin/design/images/spacer.gif 
 01:03:04   455967 ms   134.155.53.42  GET /dotlrn/design/images/zufall/006.jpg 
 01:03:04   455983 ms   134.155.53.42  GET /dotlrn/design/images/zufall/logoUniMannheim.gif 
 01:03:04   456026 ms   134.155.53.42  GET /dotlrn/design/scripts/zufallscript.js 
 01:03:04   456089 ms   134.155.53.42  GET /dotlrn/admin/stylesheets/portlets.css 
 01:03:04   456133 ms   134.155.53.42  GET /dotlrn/design/stylesheets/uni-headerFooter.css 
 01:03:03   456220 ms   134.155.53.42  GET /dotlrn/dotlrn-master.css 
 01:03:03   456399 ms   134.155.53.42  GET /dotlrn/admin/user-new-2?referer=%2e%2e%2fuser%2dadd%2d2%3fread%255fpriv... 
 01:03:03   456556 ms   134.155.53.42  GET /dotlrn/user-add-2?read%5fprivate%5fdata%5fp=t&can%5fbrowse%5fp=1&... 
 01:03:02   457658 ms   134.155.53.42  POST /dotlrn/user-add 
 01:02:44   475609 ms   134.155.53.42  GET /dotlrn/design/images/zufall/008.jpg 
 01:02:44   475873 ms   134.155.53.42  GET /dotlrn/user-add?add_membership_p=f&dotlrn_interactive_p=1&refer... 
 01:01:49   530318 ms   134.155.53.42  GET /dotlrn/design/images/zufall/019.jpg 

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..."

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.

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.

Right ... use acs_permission__permission_p() in the result set (the list of expressions between SELECT and FROM) to return 't' or 'f' for permission information on returned rows.

But use the view form in WHERE clauses to check of a particular row has a permission set or not.

A lot of code was written using the function calls because the old views from aD ACS 4.2 didn't scale but my work on permission last year fixed that issue.

From the object_ids being passed in to acs_permission__permission_p it looks like you're near the million object mark ...

I created a cronjob for every night calling

vauumdb -f -Z -U service0 -d service0

For other interested folks:
-f for full
-Z for analyze aswell
-U user
-d database

Dirk mentioned that the auth:::auth statement is used in many pages..also that I can use the OpenACS shell of the developer support to pass commands to OpenACS directly. But I didn't understand exactly how or which statements are relevant for testing performance leaks.

Any suggestions from the community?

Also ... looking forward to the future, one thing we've discussed is to reduce the number of privileges defined in the system (all those 'forum_read' or "portal_read" type privileges that are children of 'read' and which could just be 'read').  The permission queries look to be O(n) in the number of distinct privileges defined in the system, so if we shrink the number from the thirty or forty or fifty or whatever we see in a .LRN installation to ten or so we'll see a nice speed-up.

And the portal system rewrite creates many fewer objects, which should help a bit.

Thank you all very much for the help. I turned on the PermissionCacheP. And it is true...the pages are served much faster.

But what about the note that is stated for the usage of PermissionCacheP:

Whether to cache permission_p calls. Use with extreme caution. Only direct permissions managed via the tcl api are properly handled and some packages modify permissions directly in the database and will not work properly when this is turned on. You must restart the server after changing this param. 

Don: Two short questions.

1. Where do I

   allocate enough space to the pool the permissions code uses to cache them?

2. Also where do I configure the

   buffer size I have set in PG

The next two things I will try to do is

1. Enabling performance statistics in PG
2. Usage of MRTG The Multi Router Traffic Grapher or something alike

Thanks to you all

Nima

While testing the discussion forum with the PermissionCacheP I experienced the following error:

Request Error
Too many positional parameters specified
    while executing
"permission::permission_p_not_cached__arg_parser"
    (procedure "permission::permission_p_not_cached" line 1)
    invoked from within
"permission::permission_p_not_cached -party_id 0 -object_id  -privilege write"
    ("eval" body line 1)
    invoked from within
"eval $script"
    invoked from within
"ns_cache eval util_memoize $script {
	    list $current_time [eval $script]
	}"
    (procedure "util_memoize" line 20)
    invoked from within
"util_memoize "permission::permission_p_not_cached -party_id $party_id -object_id $object_id -privilege $privilege"  [parameter::get -package_id [ad_ac..."
    (procedure "permission::permission_p" line 10)
    invoked from within
"permission::permission_p -party_id $user_id -object_id $message_id -privilege write"
    (procedure "forum::security::can_post_message_p" line 3)
    invoked from within
"forum::security::can_post_message_p -message_id $parent_id -user_id 0"
    invoked from within
"expr [ad_conn user_id] != 0 &&  ([empty_string_p $forum_id] ||  [forum::security::can_post_forum_p -forum_id $forum_id -user_id 0]) &&  ([empty_string..."
    invoked from within
"set anonymous_allowed_p [expr [ad_conn user_id] != 0 &&  ([empty_string_p $forum_id] ||  [forum::security::can_post_forum_p -forum_id $forum_id -user_..."
    ("uplevel" body line 65)
    invoked from within
"uplevel {
    	  ad_page_contract {
    
    Form to create message and insert it

    @author Ben Adida (ben@openforce.net)
    @creation-date 2002-0..."
    (procedure "code::tcl::/www/unima0/packages/forums/www/message-post" 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..."

Turning the PermissionCacheP solved the error

Has someone an idea what happens here. Looks like a bug, but I am not sure. Could also be why the note to PermissionCacheP emphasises

Whether to cache permission_p calls. Use with extreme caution. Only 
direct permissions managed via the tcl api are properly handled and 
some packages modify permissions directly in the database and will not 
work properly when this is turned on. You must restart the server 
after changing this param.

Created a new bug :)

Hi Joel,

what did you acutally do to fix developer-support? I checked out the package from HEAD. It works but all the time details that are listed weired again: -274162 ms.

You remember these behaviour?

Also strange is (now independent of package release) that suddenly I get an error message calling developer support. The index.tcl complains. I have remove the line break "\" of

[ad_decode $user_switching_enabled_p 1 \
    "on (<a href=\"set-user-switching-enabled?enabled_p=0\">turn it off</a>)" \
    "off (<a href=\"set-user-switching-enabled?enabled_p=1\">turn it on</a>)"]

to a single line:

[ad_decode $user_switching_enabled_p 1 "on (<a href=\"set-user-switching-enabled?enabled_p=0\">turn it off</a>)" "off (<a href=\"set-user-switching-enabled?enabled_p=1\">turn it on</a>)"]

so the page is displayed properly. But this used to work before. Any idea why this happens?