Home
The Toolkit for Online Communities
17615 Community Members, 1 member online, 2813 visitors today
Log In Register
OpenACS Home : Forums : OpenACS Q&A : Incredible Performance Decrease - Please help!!!

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

Icon of envelope Request notifications

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"
          
          
Collapse
Posted by Dirk Gomez on
Can you enable acs-developer-support please and see whether some ultra-slow db query is the culprit.

The usual question for PG: did you vacuum and did you analyze?

Collapse
Posted by Nima Mazloumi on

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 

Collapse
Posted by Dirk Gomez on
It is necessary to look at the runtime of each query. There is a setting in developer support that allows you to look at this level of granularity.
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.

Collapse
Posted by Caroline Meeks on
Hi,

A couple suggestions.

Have you tried turnign on PermissionCacheP in the Kernal parameters. Even with a low timeout it may help.

For developer support if you have two types of browsers or AOL try loging in with one browser as a regular user and another as SWA. You can see all the requests for the last 900 seconds on the ds/index page.

Collapse
Posted by Don Baccus on
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.

Collapse
Posted by Don Baccus on
Also you might want investigate enabling performance statistics in PG itself.  This will let you track disk page reads and the like ... what buffer size have you set in PG?  21,000 users is a *lot*, undoubtably our largest PG .LRN installation, maybe our largest .LRN installation altogether so I'm not terribly surprised to learn we may have some more tuning to do.

Do turn on permission caching BTW.

Collapse
Posted by Don Baccus on
From the object_ids being passed in to acs_permission__permission_p it looks like you're near the million object mark ...
Collapse
Posted by Nima Mazloumi on
select count(*) from acs_objects;

returned

217663 objects (thank you Dirk and Don, for the hint).

Collapse
Posted by Nima Mazloumi on
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

Collapse
Posted by Nima Mazloumi on
For those interested to have direct access to the existing commands for PostgreSQL 7.4
Collapse
Posted by Nima Mazloumi on
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?

Collapse
Posted by Don Baccus on
Hmmm...when I tested permissions when I improved their performance I used a large number of objects, around 50,000 or so, and had very acceptable performance.

So, to follow up on my comment above, how much buffer space are you allocating for PG's use?  A 100 bytes per average .LRN object probably isn't too great an exaggeration of space needs.  With the number of objects you have figure on about 20  MB of buffer space minimum, and since there are many non-objects in the system, too, it would be safest to set it far, far larger.

If you enable permission caching (which for .LRN you almost certainly should do, since permissions once set rarely change in .LRN), be sure you allocate enough space to the pool the permissions code uses to cache them.

Caching won't speed a user's first visit to a page, but will greatly speed subsequent visits.

Collapse
Posted by Don Baccus on
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.

Collapse
Posted by Lars Pind on
Branimir told me about a change they'd made, which is to have each privilege show up as columns in one wide table, so there's at most one row per (party x object). The table has a fixed number of columns (say a few hundred, to be on the safe side) with generic names (p1, p2, p3, ...), and this is automatically handled by the Tcl layer.

This is in addition to the normal table, but it also flattens the privilege hierarchy, so if read is a child of admin, then the uber-row would have a check mark in both the "read" and "admin" columns.

According to Branimir, it made permissions checks much faster. Not sure about the details why and how, but I'd guess that smaller indices due to fewer rows would make it faster, as well as the flattening of the privilege hierarchy, and you might avoid some 'select distinct' and other expensive operations, because there's only one row per party/object.

Aram is the chief architect behind this, so is the person to ask for details.

/Lars

Collapse
Posted by Nima Mazloumi on
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
Collapse
Posted by Dirk Gomez on
Regarding ext::auth - I was trying to make a point that we couldn't properly track down the root cause of the problem and if you are trying to find a performance problem (or bug) you shouldn't jump at a conclusion all too quickly.

I played a bit with psql trying to find a way to hardwire values into views and PL/PGSQL functions who have been looked up dynamically. Here is what I found to work:

create function inline_0 ()
returns integer as '
declare
        v_magic_object_id acs_magic_objects.object_id%TYPE;
begin
        select object_id
          into v_magic_object_id
          from acs_magic_objects
          where name = ''registered_users'';

        EXECUTE ''create or replace view cc_users '' ||
                '' as '' ||
                '' select o.*, pa.*, pe.*, u.*, mr.member_state, mr.rel_id '' ||
                '' from acs_objects o, parties pa, persons pe, users u, group_member_map m, membership_rels mr '' ||
                '' where o.object_id = pa.party_id '' ||
                ''  and pa.party_id = pe.person_id '' ||
                ''  and pe.person_id = u.user_id '' ||
                ''  and u.user_id = m.member_id '' ||
                ''  and m.group_id = '' || v_magic_object_id ||
                ''  and m.rel_id = mr.rel_id '' ||
                ''  and m.container_id = m.group_id '' ||
                ''  and m.rel_type = ''''membership_rel'''' '';
        return 0;
end;' language 'plpgsql';

select inline_0 ();

drop function inline_0 ();

There is no equivalent to sql*plus variables yet, so this is a bit klunky. (psql variables don't work here)

Should the most obvious invocations of acs_magic_objects be replaced?

(cc_users doesn't have pl/pgsql anymore anyway, I just meant to find a development query)

Collapse
Posted by Nima Mazloumi on

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.

Collapse
Posted by Lars Pind on
Nima,

This looks like a bug.

Would you mind filing in bug-tracker? Looks like something that should be fixed for 5.0.1.

/Lars

Collapse
Posted by Nima Mazloumi on
Created a new bug :)
Collapse
Posted by Don Baccus on
The permissions caching stuff was added for .LRN and should be safe in the .LRN context - Sloan runs with it enabled, and has since they first deployed it.

This has gotten me back to thinking about a better caching scheme, though ... :)

Collapse
Posted by Nima Mazloumi on
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?

Collapse
Posted by Dirk Gomez on

You shouldn't have taken it from HEAD :)

A while ago I fixed a little inaccuracy in our code. Here's my comment:


all TCL's clock clicks always with the -milliseconds option. The TCL manual
explicitly states that without this switch the return result is platform
dependant. The OpenACS code works at the millisecond granulartiy and silently
assumes that 1 millisecond equals 1000 clicks which is not necessarily true.

I used this shell script to automatize the replacing:

#!/bin/bash

for file in `grep -lsr "\[clock clicks\]" /web/openacs-head/packages/ `; do
  echo "repairing $file"
  sed "s/\[clock clicks\]/\[clock clicks -milliseconds\]/g" $file > fout
  mv fout $file
done

And then grepped for

grep -r "expr.*clock clicks" /web/openacs-head/packages/

to manually remove the divisions by 1000.