Forum OpenACS Q&A: Starting OpenACS5.0.0+AOLServer4.x *really* slow

Collapse
1: Starting OpenACS5.0.0+AOLServer4.x *really* slow
Posted by Marc Fournier on 02/05/04 05:58 PM
Is this normal, for starters?  When I saw *really* slow, the site we are testing/working with, I started the AOLServer process up at:

[05/Feb/2004:16:44:56]

then, around 16:48, it seemed to stall for 5minutes:

[05/Feb/2004:16:48:00][28790.134533120][-main-] Notice: Loading packages/users-selection/tcl/users-selection-procs.tcl...
[05/Feb/2004:16:48:00][28790.134533120][-main-] Notice: Loaded packages/users-selection/tcl/users-selection-procs.tcl.
[05/Feb/2004:16:53:26][28790.134533120][-main-] Notice: Loading packages/acs-admin/tcl/test/acs-admin-procs.tcl...
[05/Feb/2004:16:53:26][28790.134533120][-main-] Notice: Loaded packages/acs-admin/tcl/test/acs-admin-procs.tcl.

Uptime on the machine is <4, and its a dual-PIII with 4Gig of RAM, and 0% swap used ... database for it is on a Dual-Xeon, 4Gig of RAM, 0% swap, and <.5 loadavg ...

Is this 'the norm', or is there something specific we should be looking at?

Collapse
2: Re: Starting OpenACS5.0.0+AOLServer4.x *really* slow (response to 1)
Posted by Jade Rubick on 02/05/04 07:29 PM
Definitely slow, I'm not sure why.
Collapse
3: Re: Starting OpenACS5.0.0+AOLServer4.x *really* slow (response to 1)
Posted by Andrew Piskorski on 02/06/04 05:14 PM
It's certainly not "normal", many more people would have been complaining by now if it was!

Back when I was running OpenACS 4.x on Solaris, I used to see AOLserver startup take a quite a long time due to very slow XML parsing of the xql files. But even that was only 1 or 2 minutes worst case, and when we moved the site to Linux (and much faster Intel hardware) everything sped up immensely.

Does the pause in the AOLserver startup happen consistently every time at the same place in the AOLserver log? Or was it a one time only or variable thing?

Note that the 16:48:00 line is probably the first line logged after whatever was blocking things went away. (You would have to confirm that by looking at exactly when the ns_log statements happen in the code though.) So the thing to do is look at the log lines immediately before and after the gap, and figure out what was going on during the gap. Presumably, whatever AOLserver was trying to do during that gap is what's responsible for the god-awful 5 minute slowdown.

The users-selection package is in contrib, so probably not many people use it and perhaps it is at fault.

Collapse
4: Re: Starting OpenACS5.0.0+AOLServer4.x *really* slow (response to 1)
Posted by Tom Jackson on 02/06/04 09:37 PM

Is it possibly a DNS issue? If a script runs which needs a dns lookup, sometimes timeouts will last for quite a while.

Collapse
5: Re: Starting OpenACS5.0.0+AOLServer4.x *really* slow (response to 1)
Posted by Caroline Meeks on 02/06/04 11:52 PM
Do you have dotLRN installed? I find my dotLRN instances are much slower to restart then my straight OACS5 ones.
Collapse
6: Re: Starting OpenACS5.0.0+AOLServer4.x *really* slow (response to 5)
Posted by Walter Smith on 02/07/04 02:59 AM
Hello. Thanks for the responses.  Marc was posting on my behalf, because the OACS 5 instance he's referring to is mine, running on his physical server.  I'm finally getting ready to let go of 3.2.5, and I'm trying to get version 5 installed and running smoothly.  These problems notwithstanding, I'm blown away by how far the toolkit has progressed.

This was actually a relatively fast restart.  It has taken as long as 45 minutes to start up this combo of OpenACS5.0.0+AOLServer4.x.  The pauses seem to happen in the same places during startup, although the whole startup process varies in length (but it's never under 10 minutes).

I don't know of any reason there would be DNS problems in this case, and dotLRN is not installed.  Following are the applications I have installed:
Bulk Mail     0.5
E-Commerce     4.6.1
Events Management     0.1d3
File Storage     5.0.0b4
General Comments     4.1
Mailing List     1.0
Notifications     5.0.0b4
Project Manager     0.25d
Search     5.0.0
Users Selection     0.1d

Below is a truncated version of my logs, which if I'm reading them correctly, show the slow-loading libraries as follows:
1) users-selection-procs.tcl took about 5:26 minutes
2) file-storage-procs.tcl took about 7 minutes
3) search-init.tcl took about 2:20 minutes.

users-selection-procs.tcl has taken as long as 20 minutes to load.

[05/Feb/2004:16:44:56][28790.134533120][-main-] Notice: nsmain: AOLserver/4.0 starting
.
.
.
[05/Feb/2004:16:48:00][28790.134533120][-main-] Notice: Loading packages/project-manager/tcl/task-procs.tcl...
[05/Feb/2004:16:48:00][28790.134533120][-main-] Notice: Loaded packages/project-manager/tcl/task-procs.tcl.
[05/Feb/2004:16:48:00][28790.134533120][-main-] Notice: Loading packages/search/tcl/search-procs.tcl...
[05/Feb/2004:16:48:00][28790.134533120][-main-] Notice: Loaded packages/search/tcl/search-procs.tcl.
[05/Feb/2004:16:48:00][28790.134533120][-main-] Notice: Loading packages/users-selection/tcl/users-selection-procs.tcl.\
..
[05/Feb/2004:16:48:00][28790.134533120][-main-] Notice: Loaded packages/users-selection/tcl/users-selection-procs.tcl.
[05/Feb/2004:16:53:26][28790.134533120][-main-] Notice: Loading packages/acs-admin/tcl/test/acs-admin-procs.tcl...
[05/Feb/2004:16:53:26][28790.134533120][-main-] Notice: Loaded packages/acs-admin/tcl/test/acs-admin-procs.tcl.
.
.
.
[05/Feb/2004:16:53:31][28790.134533120][-main-] Notice: Loading packages/acs-templating/tcl/test/spell-checker-procs.tc\
l...
[05/Feb/2004:16:53:31][28790.134533120][-main-] Notice: Loaded packages/acs-templating/tcl/test/spell-checker-procs.tcl\
.
[05/Feb/2004:16:53:31][28790.134533120][-main-] Notice: Loading packages/categories/tcl/test/categories-procs.tcl...
[05/Feb/2004:16:53:31][28790.134533120][-main-] Notice: Loaded packages/categories/tcl/test/categories-procs.tcl.
[05/Feb/2004:16:53:31][28790.134533120][-main-] Notice: Loading packages/file-storage/tcl/test/file-storage-procs.tcl..\
.
[05/Feb/2004:16:53:31][28790.134533120][-main-] Notice: Loaded packages/file-storage/tcl/test/file-storage-procs.tcl.
[05/Feb/2004:17:00:39][28790.134533120][-main-] Notice: Loading packages/acs-authentication/tcl/sync-init.tcl...
[05/Feb/2004:17:00:39][28790.134533120][-main-] Notice: Loaded packages/acs-authentication/tcl/sync-init.tcl.
.
.
.
[05/Feb/2004:17:00:56][28790.134533120][-main-] Notice: Loading packages/notifications/tcl/reply-sweep-init.tcl...
[05/Feb/2004:17:00:56][28790.134533120][-main-] Notice: Loaded packages/notifications/tcl/reply-sweep-init.tcl.
[05/Feb/2004:17:00:56][28790.134533120][-main-] Notice: Loading packages/notifications/tcl/sweep-init.tcl...
[05/Feb/2004:17:00:56][28790.134533120][-main-] Notice: Loaded packages/notifications/tcl/sweep-init.tcl.
[05/Feb/2004:17:00:56][28790.134533120][-main-] Notice: Loading packages/search/tcl/search-init.tcl...
[05/Feb/2004:17:00:56][28790.134533120][-main-] Notice: Loaded packages/search/tcl/search-init.tcl.
[05/Feb/2004:17:03:13][28790.134533120][-main-] Notice: Loading packages/acs-automated-testing/tcl/test/example-test-in\
it.tcl...
[05/Feb/2004:17:03:13][28790.134533120][-main-] Notice: Loaded packages/acs-automated-testing/tcl/test/example-test-ini\
t.tcl.
[05/Feb/2004:17:03:19][28790.134533120][-main-] Notice: Bootstrap: Done loading OpenACS.
[05/Feb/2004:17:03:19][28790.134533120][-main-] Notice: Sourcing files for postload...
[05/Feb/2004:17:03:19][28790.134533120][-main-] Notice: Done.
[05/Feb/2004:17:03:19][28790.134533120][-main-] Notice: Executing initialization code blocks...
[05/Feb/2004:17:03:19][28790.134533120][-main-] Notice: Executing initialization code block filters_register in /usr/lo\
cal/www/<mydomain>/openacs-5.0.0/packages/acs-tcl/tcl/request-processor-init.tcl
[05/Feb/2004:17:03:19][28790.134533120][-main-] Notice: Executing initialization code block procs_register in /usr/loca\
l/www/<mydomain>/openacs-5.0.0/packages/acs-tcl/tcl/request-processor-init.tcl
[05/Feb/2004:17:03:21][28790.134533120][-main-] Notice: nsmain: AOLserver/4.0 running
[05/Feb/2004:17:03:21][28790.134533120][-main-] Notice: nsmain: security info: uid=65534, euid=65534, gid=65534, egid=6\
5534
[05/Feb/2004:17:03:21][28790.134533120][-main-] Notice: nssock: listening on xxx.xxx.xxx.xxx:82
[05/Feb/2004:17:03:21][28790.134784000][-sched-] Notice: sched: starting
[05/Feb/2004:17:03:21][28790.135198720][-driver-] Notice: starting
[05/Feb/2004:17:03:21][28790.135198720][-driver-] Notice: driver: accepting connections
[05/Feb/2004:17:03:21][28790.135237632][-sched:idle0-] Notice: starting
[05/Feb/2004:17:03:21][28790.135237632][-sched:13-] Notice: acs-mail-lite: about to load qmail queue
[05/Feb/2004:17:03:21][28790.135237632][-sched:13-] Notice: queue dir = /new/*, no messages
[05/Feb/2004:17:03:21][28790.135239680][-sched:idle1-] Notice: starting
[05/Feb/2004:17:03:21][28790.135266304][-sched:idle2-] Notice: starting
[05/Feb/2004:17:03:38][28790.134959104][-conn:openacs-5.0.0::0] Notice: random: generating 1 seed

There were also a couple of warnings during startup:

[05/Feb/2004:16:45:27][28790.134533120][-main-] Warning: Multiple definition of ad_acs_kernel_id in /usr/local/www/<mydomain>/openacs-5.0.0/packages/acs-tcl/tcl/request-processor-procs.tcl and /usr/local/www/<mydomain>/opena\
cs-5.0.0/packages/acs-tcl/tcl/20-memoize-init.tcl

[05/Feb/2004:17:00:46][28790.134533120][-main-] Warning: acs-mail: ns_uuencode broken - will use the slow tcl version

Thanks!

Walter

Collapse
7: Re: Starting OpenACS5.0.0+AOLServer4.x *really* slow (response to 6)
Posted by Jeff Davis on 02/07/04 04:06 PM
If you are using postgres you might want to try turning on logging on the server side and look for queries in the startup sequence that might be causing this. Add 
log_pid = true
log_statement = true
log_duration = true
log_timestamp = true
to /var/lib/postgresql/data/postgresql.conf and restart the db server.

You could also turn on debug on aolserver and then you could see more details about what is going on in those conspicuous gaps.