Forum OpenACS Q&A: Performance Problems - what is the bottleneck?

I have problems with the performance of our installation here I seek your advice because I don't know whether this is because of our architecture, or miss configuration of aolserver or database or small hardware.

What basically happens is that once I have more than 150 users logged in the response time for a page takes a minute or more which is very frustrating for users. Today we received an email saying that .LRN is simply "shit". I don't know what to do next. All I know is that from semester to semester the load is getting higher but the frustration as well.

Here our system details.

We have three linux boxes. One for an aolserver with database connection, one for a static aolserver and one for the database.

The database box never goes above 5-10%. The static server is also not very busy but the dynamic server can go upt to 99% and a load of 10 and more.

Any help or comment is appreciated.

Greetings,
Nima

---------------------------------
dotlrn (dynamic server)
---------------------------------

AOLServer 4.0.10 (connected to the database)
Pound 1.8.2 (as reverse proxy for ssl and load balancing)
Apache 2.0.53 (only redirect from 80 to 443 where pound is)

SuSE 9.2
Linux Linux version 2.6.8-24.18-smp (gcc version 3.3.4 (pre 3.3.5 20040809)) #1 SMP Fri Aug 19 11:56:28 UTC 2005
4 CPU Intel(R) Xeon(TM) CPU 3.06GHz , L2 cache: 512K
4 GByte RAM - Memory: 4070968k/4111296k available (2339k kernel code, 39528k reserved, 824k data, 252k init, 3193792k highmem)
2 Broadcom Corporation NetXtreme BCM5704 Gigabit Ethernet Cards

AOLServer config.tcl
...

ns_section ns/server/${server}/modules
ns_param libthread ${homedir}/lib/thread2.6.2/libthread2.6.2.so
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 php ${bindir}/libphp4.so
ns_param nsrewrite ${bindir}/nsrewrite.so
ns_param nscgi ${bindir}/nscgi.so

ns_section ns/parameters
ns_param serverlog ${serverroot}/log/error.log
ns_param home $homedir
ns_param maxkeepalive 100
ns_param logroll on
ns_param maxbackup 5
ns_param debug $debug
ns_param mailhost localhost
ns_param proxy www-cache.uni-mannheim.de
ns_param proxy_port 3128
ns_param ReverseProxyMode true

ns_section ns/threads
ns_param mutexmeter true
ns_param stacksize [expr 256*1024]

ns_section ns/server/${server}
ns_param directoryfile $directoryfile
ns_param pageroot $pageroot
ns_param maxconnections 100
ns_param keepalivetimeout 15
ns_param maxdropped 0
ns_param maxthreads 65
ns_param minthreads 65
ns_param threadtimeout 3600
ns_param globalstats true
ns_param urlstats true
ns_param maxurlstats 1000

ns_section ns/server/${server}/module/nssock
ns_param timeout 120
ns_param address $address
ns_param hostname $hostname
ns_param port $httpport
ns_param maxinput 20971520

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

ns_section ns/db/pool/pool3
ns_param maxidle 1000000000
ns_param maxopen 1000000000
ns_param connections 30
...

ns_section ns/server/${server}/module/nslog
ns_param debug false
ns_param dev false
ns_param enablehostnamelookup true
ns_param file ${serverroot}/log/${server}.log
ns_param logcombined true
#ns_param extendedheaders COOKIE
#ns_param logrefer false
#ns_param loguseragent false
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

---------------------------------
dotlrn5 (static server)
---------------------------------
AOLServer 4.0.10 (static)

SuSE 9.2
Linux version 2.6.8-24.18-smp (geeko@buildhost) (gcc version 3.3.4 (pre 3.3.5 20040809)) #1 SMP Fri Aug 19 11:56:28 UTC 2005
2 CPU Intel Pentium III (Katmai) 500 MHz
512 MB RAM - Memory: 512744k/524288k available (2339k kernel code, 11100k reserved, 824k data, 252k init, 0k highmem)
2 3Com Corporation 3c905B 100BaseTX [Cyclone] Cards

---------------------------------
dotlrn2 (database server)
---------------------------------
PostgreSQL 7.4.8

SuSE 9.2
Linux version 2.6.8-24.18-smp (geeko@buildhost) (gcc version 3.3.4 (pre 3.3.5 20040809)) #1 SMP Fri Aug 19 11:56:28 UTC 2005
4 CPU Intel(R) Xeon(TM) CPU 3.06GHz
4 GB RAM - Memory: 4071012k/4111296k available (2339k kernel code, 39484k reserved, 824k data, 252k init, 3193792k highmem)
2 Broadcom Corporation NetXtreme BCM5704 Gigabit Ethernet Cards

Postgresql configuration:

tcpip_socket = true
max_connections 200
shared_buffers = 15384
sort_mem = 16384
vacuum_mem = 131072
max_fsm_pages = 100000
max_fsm_relations = 1000
effective_cache_size = 786432
random_page_cost = 2.5
cpu_tuple_cost = 0.01
log_timestamp = true
lc_messages = 'de_DE.UTF-8' # locale for system error message strings
lc_monetary = 'de_DE.UTF-8' # locale for monetary formatting
lc_numeric = 'de_DE.UTF-8' # locale for number formatting
lc_time = 'de_DE.UTF-8' # locale for time formatting

Are there long-running queries that are blocking requests?

I don't know if a number of long running queries would show up as high load on the database server or not, if the database still had additional resource to serve more requests, but just had slow queries running at that point.

how many ram is consuming the nsd process?

shared_buffers = 65636
sort_mem = 32168

You're running vacuum analyze at least once a day, right?

pg_autovacuum is as well very good option.

Are your CR files stored in the file system?

One way to achieve that is to put ALL your static files (images, css, etc) into the resources folder of each >package, and then put them into your static site

add a rule into pound to redirect

Next step will be to have a cluster.

How many concurrent connections do you have at peak times?
Try this in your dinamic system:
while [ 1 ]; do echo -n `date` >> tcp_report.txt; echo -n ' | ' >> tcp_report.txt; lsof | grep 8000 | grep TCP | grep -v LISTEN | wc -l >> tcp_report.txt; done;
(thanks to Derick)

Also look for blocked processes in PG (something that is >waiting or blocked for too long sometimes reduces the >performance, you can kill it). ps axuf

In PG, increase:
shared_buffers = 65636
sort_mem = 32168

I would be careful of setting shared_buffers so high. Several Pg tuning articles suggest that this can cause performance degradation. Its not a straight forward calculation however so testing different values might be worthwhile. Setting shared_buffers to about 6% of memory (about 31457 on a 4Gb machine) should be starting point especially when used in conjunction with effective_cache_size set to a decent value.

A decent effective_cache_size allows the query planner to uses indexes instead of sequential scans. On a mchine dedicated to Pg this value can be set very high between 2/3 and 3/4 of RAM seems to be the suggestion - Nima has this set to 786432 which equates to 6Gb - might be a tad high on a 4Gb machine. Again experimentation to find a good value seems to be the order of the day.

- Steve

The database server's sitting mostly idle. It's the dynamic AOLserver box that's hosed with a load going over 10.

I have no solution to offer but Nima, it seems obvious you should be concentrating on the box that's the busiest, your Tcl box, not the database server or static server.

Profiling with developer support may help you gather the necessary information, along with AOLserver stats gathering. Without more information I can not offer any advice.

If it were me, I'd concentrate on that Tcl server and not worry about anything else until I had a reasonable understanding as to why it is so heavily loaded.

So now, anyone should be able to run clusters of openacs without troubles of caching.

This bug fix can be applied separately to any openacs installation (oacs-5-1).

http://cia.navi.cx/stats/author/victorg/.message/11c18

Enjoy!

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '1228' and ppm.party_id = '24471989' and ppm.privilege = 'dotlrn_browse' )

Now, with explain analyze:

QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Result  (cost=3655.01..3655.04 rows=1 width=0) (actual time=3377.385..3377.402 rows=1 loops=1)
   One-Time Filter: $0
   InitPlan
     ->  Nested Loop  (cost=6.35..3655.01 rows=38 width=0) (actual time=3377.341..3377.341 rows=1 loops=1)
           ->  Hash Join  (cost=6.35..2462.49 rows=198 width=4) (actual time=0.616..1953.102 rows=82802 loops=1)
                 Hash Cond: (("outer".privilege)::text = ("inner".privilege)::text)
                 ->  Nested Loop  (cost=0.00..2446.33 rows=626 width=16) (actual time=0.071..1060.517 rows=82804 loops=1)
                       ->  Index Scan using acs_object_context_index_pk on acs_object_context_index c  (cost=0.00..39.90 rows=13 width=4) (actual time=0.035..0.040 rows=2 loops=1)
                             Index Cond: (object_id = 1228)
                       ->  Index Scan using acs_permissions_pk on acs_permissions p  (cost=0.00..184.49 rows=50 width=20) (actual time=0.017..214.914 rows=41402 loops=2)
                             Index Cond: ("outer".ancestor_id = p.object_id)
                 ->  Hash  (cost=6.34..6.34 rows=4 width=14) (actual time=0.325..0.325 rows=0 loops=1)
                       ->  Seq Scan on acs_privilege_descendant_map pdm  (cost=0.00..6.34 rows=4 width=14) (actual time=0.252..0.302 rows=2 loops=1)
                             Filter: ((descendant)::text = 'dotlrn_browse'::text)
           ->  Index Scan using party_approved_member_map_pk on party_approved_member_map pamm  (cost=0.00..6.01 rows=1 width=4) (actual time=0.010..0.010 rows=0 loops=82802)
                 Index Cond: ((pamm.party_id = "outer".grantee_id) AND (pamm.member_id = 24471989))
   ->  Subquery Scan dual  (cost=0.00..0.02 rows=1 width=0) (actual time=0.028..0.038 rows=1 loops=1)
         ->  Result  (cost=0.00..0.01 rows=1 width=0) (actual time=0.020..0.023 rows=1 loops=1)
 Total runtime: 3377.578 ms
(19 rows)

In this case, is giving lots of rows. I don't remember right now, I think it was as well that we needed a way to stop the query execution when just one row is returned. I was diging into this like 2 months ago, we might go further into this now.