Forum OpenACS Q&A: Expected non-db overhead time on an OpenACS page?
In my case, I have a fairly complicated page using the templating system with several includes and the like. When several users hit this page at once (which happens frequently) it gets kind of slow, in the 2 to 5 second range.
Despite doing a bunch of database queries, according to Devloper
Support, the vast majority of the time is being spent in
non-database activity. Developer Support reports that
adp_parse_ad_conn_file is sucking up about 85% of the
time. Here are a few rather non-scientific timing samples showing
All times as reported by Developer Support. - "parse" means adp_parse_ad_conn_file. - "one" is a single page request. - "many" is about 8 or so clients hitting the page all around the same time. Ratio db/total time: Ratio parse/total: one: 486/1804 = 0.269 1499.5/1804 = 0.831 (mean 0.269) (mean 0.831) many: 436/7414 = 0.059 5634.0/7414 = 0.760 many: 427/1921 = 0.222 1725.6/1921 = 0.898 many: 388/2669 = 0.145 2345.6/2669 = 0.879 many: 473/3588 = 0.132 3320.2/3588 = 0.925 (mean 0.144, sd 0.0680) (mean 0.866, sd 0.073)
The above times are for my custom page, and I have not yet tried profiling the Tcl code on my page, so I don't really know for sure whether it's my code or something intrinsic to OpenACS. But, there's no particularly weird Tcl code on my page, it's basically just doing a bunch of queries and using the Templating system to format the results.
And more importantly, at least some stock OpenACS pages do
appear to exhibit the same behavior. For example, the Bug Tracker
main page also seems to slow down quite a bit with several concurrent
requests going, with Developer Support reporting that
adp_parse_ad_conn_file is taking up most of the time.
Actually, the Package Manager page (/acs-admin/apm/) is quite asonishingly bad, I'm seeing it take about 10 seconds, only 0.300 s or so of which are database commands. (That's for a single hit. Several concurrent requests don't seem to make much difference.)
So basically what I'm asking here is, are there any known performance problems with the Request Processor and/or the Templating system? Anyone else seen this sort of lousy page performance? Is what I'm seeing typical or unusual? Do I have something configured wrong somewhere, or what?
You might want to instrument the code that does this to make sure it's not recompiling needlessly, just grep for mtime in acs-templating/tcl/parse-procs.tcl. If you are, I'd appreciate any effort you could make to figure out why, because I've poked into this on a Linux box in the past and have verified that proc caching works (and being wrapped in a proc, the Tcl compiler should only compile it once per thread, too)
If you have minthreads set low and maxthreads set high, a sudden flurry of connections after an idle period will trigger the spawning of new threads, and therefore new template compiles because the compiled proc code is only defined in the current thread context. To maximize performance it is best to set minthreads=maxthreads at some reasonable number. Thread initialization overhead isn't confined to the template system, all the procs defined in every package's library directory (/tcl) are recompiled also when a new thread fires up.
Hmmm ... the more I think this the more I think this is probably the source of the problem, you've got minthreads set low and are respawning threads when you hit a flurry of connections. Letting threads die is appropriate on a development box or if you're hosting a low-volume site on a box the serves up a variety of services, but not on a production site with any significant level of volume.
As far as raw speed goes, I've been doing some benchmarking to get some baseline data on the request processor. On my new P4 2.4GHz machine with PC2100 DDR RAM, using AOLserver 4 in production mode and caching the read permission check, I get over 70 templated page views a second when loading it down with five tclwebtest scripts repeatedly viewing a very simple template that sets one var and displays it. I get less throughput with a single connection, apparently connection latency plays a role.
AOLserver 4 seems to perform about 20% better than AOLserver 3 in this test (this is due to Tcl8.4.3 performance improvements, you can run that Tcl version with AOLserver 3, too)
Performance mode gets about 15%, permission caching on a basic install a few percent ...
Anyway ... 70 templated page views a second ain't bad on a $389 Dell box (of course you can't get that box for $389, nah nah nah!)
I had maxthreads 20, and the defaults for minthreads and threadtimeout, which I think are 0 and 120 s, respectively. Not so good. On my Dev server, I set min and max threads both to the same number, threadtimeout to 3600 (1 hour), and tried again: Yep, saw what you'd expect:
First time a thread serves a request for a page, it's kind of slow, presumably due to the calls in template::adp_init to template::util::read_file and adp_compile. The second and subsequent times a thread servers a page, template::adp_init no longer sources the file like that, and things are faster. Some ns_logs I put in show that yes, each chunk of the page really is only being sourced once.
So everything seems correct, and speed is much improved now that I fixed my thread mis-configuration.
Things are still a bit slower than I'd like, database time of 300 ms (fast), total page serve time still of 1 or 1.5 seconds or so (kind of slow). But should improve noticeably once I move this to a much faster Linux server, and also when I switch to Tcl 8.4, so I'm happy for now.
Hm, it would be rather nice if the Developer Support request-info page reported stuff like whether the page was sourced this time around or whether it had already been cached to a proc...
The important thing is probably to set the threadtimeout to something reasonable, the default of 120 s is just horrible for most people using OpenACS.
Actually the right answer is to get ttrace working which would decrease that footprint and thread create times immensely, but I tried and did not manage it. I am sure Zoran would help though.