Forum OpenACS Q&A: Expected non-db overhead time on an OpenACS page?

What is the expected non-database overhead time to serve an OpenACS page? Reason I ask, is that with OpenACS 4.6.2 (and AOLserver 3.3+ad13, on a relatively slow Solaris box) I seem to be seeing a disproportianitely large amount of time being taken in adp_parse_ad_conn_file.

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 this:

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?

Posted by Don Baccus on
Tcl code resulting from template .adp files and their associated datasource .tcl files are wrapped by "proc ... uplevel {}", and that proc is then used forever after unless the files change.  So you should not be seeing a lot of time wasted in adp compiles.  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)

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!)

Posted by Andrew Piskorski on
Damn, I forgot to check my thread settings. Yep, Don, looks like you were right.

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

Posted by Don Baccus on
Yeah it would - submit a patch! :)
Posted by Jade Rubick on
Should we increase the minthreads and maxthreads on the default config.tcl file? They're currently set to 5 each.
Posted by Andrew Piskorski on
Hard to say, and I haven't looked at how much memory each AOLserver thread takes up with the latest OpenACS. My fairly un-informed guess is that 5 is probably fine for a Dev server but might be a bit low for any public Production server. Maybe 10 would be a better default value.

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.

Posted by Jeff Davis on
Threads are pretty fat -- It looked like roughly 12-20MB per thread if you install all the packages (it's less for just the core). I think leaving it at 5 with a BOLD comment that it should be increased for production sites on dedicated boxes is probably the right answer.

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.