Question

Is it normal for each page in twiki to take about 5 seconds to appear? This occurs for my implementation. I tried running bin/view from the shell prompt and it also takes about 4 seconds before any html appears. Everything appears to work fine however.

Any advice on how to investigate this further? I don't think its the web server since just executing the view script shows the same symptoms. The delay is in the statement TWiki::UI::run( \&TWiki::UI::View::view );. Which is to be expected I supp0ose.

Thanks

Environment

-- TWikiGuest - 25 Nov 2006

Answer

If you answer a question - or someone answered one of your questions - please remember to edit the page and set the status to answered. The status selector is below the edit box.

TWiki performance is always a heavily discussed topic - but about five seconds sounds too much, even for subsonic hardware.

There are a bunch of topics in CategoryPerformance for various aspects, so let me just enumerate some things which are known to be costly:

1. Things like %SEARCH{...}% spanning many webs, e.g. in Codev.WebChangesForAllWebs
2. In general, anything where TWiki has to examine many data (searches, includes, ...)
3. User interface Internationalisation
4. Having several thousands of users
5. Having too many plugins activated
6. Not enough RAM
7. Includes from HTTP sites which take long to respond (or even run into a timeout)
8. LDAP integration

If you are familiar with Perl, you could profile with Devel::DProf where the time is spent. If you are working in a SVN checkout, you could use the BenchmarkContrib there which is still too experimental to be released on twiki.org.

-- HaraldJoerg - 25 Nov 2006

Thanks. It appears if the delay is occurring before the program starts running proper. ie sometime during or just after compiling the BEGIN's. I added some trace lines and executed it from the command prompt.

I have one user, default plugin's, nothing unusual I can see. I have <100 topics. I do have only 256MB ram with apache, tomcat, samba plus more running.

However this is predictable delay. I shutdown the above and still see it.

-- RobertPalmer - 26 Nov 2006

256MB RAM is very little. It is likely that there is a lot of swapping going on, which could be the reason for the delay. Run Linux utilities to find out.

-- PeterThoeny - 26 Nov 2006

While checking for swapping is something you should do first, you can get TWiki to function in 256k of ram. I have a minimal Ubuntu install that is not running X and only running the required services (TWiki/apache, LDAP, ssh, samba) and it still has about 50k+ free. It is using a Intel Celeron 2.5 GHz and has a few extra plugins installed. When I run time ./bin/view > /dev/nul I get time of just over 1 second.

-- RickMach - 27 Nov 2006

I will add ram and see what happens.

-- RobertPalmer - 27 Nov 2006

Ram didn't help unfortunately. Here's a trace of the command ./view

[robert@robert bin]$ dprofpp -r
Total Elapsed Time = 4.491687 Seconds
         Real Time = 4.491687 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 15.3   0.690  1.658     28   0.0246 0.0592  TWiki::BEGIN
 9.13   0.410  5.521     11   0.0372 0.5019  main::BEGIN
 5.12   0.230  0.230     27   0.0085 0.0085  TWiki::Store::RcsFile::_readFile
 4.45   0.200  0.200     76   0.0026 0.0026  TWiki::Store::RcsFile::storedDataE
                                             xists
 4.23   0.190  0.250      7   0.0271 0.0357  TWiki::Form::BEGIN
 4.23   0.190  0.759     10   0.0190 0.0759  TWiki::Store::BEGIN
 4.23   0.190  0.459     10   0.0190 0.0459  TWiki::Attach::BEGIN
 3.54   0.159  1.906    308   0.0005 0.0062  TWiki::_processTags
 3.34   0.150  0.160     24   0.0062 0.0066  TWiki::Store::RcsFile::getAttachme
                                             ntList
 2.67   0.120  0.120      7   0.0171 0.0171  TWiki::Plugins::BEGIN
 2.45   0.110  0.110      8   0.0137 0.0137  TWiki::Store::RcsFile::getWebNames
 2.45   0.110  0.110     26   0.0042 0.0042  TWiki::Plugin::BEGIN
 2.23   0.100  0.149    142   0.0007 0.0010  TWiki::Store::RcsWrap::BEGIN
 2.00   0.090  0.090     17   0.0053 0.0053  CGI::_compile
 1.78   0.080  0.080      5   0.0160 0.0160  TWiki::Plugins::TablePlugin::BEGIN
[robert@robert bin]$ dprofpp
Total Elapsed Time = 4.505365 Seconds
  User+System Time = 2.919012 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 17.8   0.520  1.099     28   0.0186 0.0392  TWiki::BEGIN
 10.9   0.320  3.792     11   0.0291 0.3448  main::BEGIN
 5.10   0.149  1.040    308   0.0005 0.0034  TWiki::_processTags
 4.45   0.130  0.300     10   0.0130 0.0300  TWiki::Attach::BEGIN
 3.43   0.100  0.277      3   0.0332 0.0924  TWiki::Render::getRenderedVersion
 2.74   0.080  0.080     17   0.0047 0.0047  CGI::_compile
 2.74   0.080  0.130      7   0.0114 0.0185  TWiki::Form::BEGIN
 2.40   0.070  0.419     10   0.0070 0.0419  TWiki::Store::BEGIN
 2.40   0.070  0.149    142   0.0005 0.0011  TWiki::Store::RcsWrap::BEGIN
 2.40   0.070  0.080      7   0.0100 0.0114  TWiki::Plugins::BEGIN
 2.06   0.060  0.060      5   0.0120 0.0120  TWiki::Plugins::TablePlugin::BEGIN
 2.06   0.060  0.130     30   0.0020 0.0043  TWiki::Meta::BEGIN
 1.71   0.050  0.050    195   0.0003 0.0003  TWiki::Attrs::new
 1.71   0.050  0.246     21   0.0024 0.0117  TWiki::Prefs::PrefsCache::BEGIN
 1.71   0.050  0.050      8   0.0062 0.0062  TWiki::Store::RcsFile::getWebNames
 

-- RobertPalmer - 29 Nov 2006

TWiki does a great deal of work in the BEGIN blocks. it does this specifically so it can leverage accelerators, such as mod_perl, that make those BEGIN executions one-time activities.

Recommend you investigate mod_perl, or failing that, speedy cgi. See ModPerlUnix for assistance in getting it set up.

-- CrawfordCurrie - 29 Nov 2006

Many thanks for the figures. Unfortunately this clearly points to a problem with a slow CPU

Your percentual distribution looks quite typical. I get similar figures with a virtual machine on a 1.7GHz Pentium 4 CPU, but managed to improve performance with mod_perl to 1-2 seconds for most topics. With mod_perl, or with PersistentPerl (which has fewer options, but is easier to install) you can eliminate most of the times you see in BEGIN blocks, which are basically Perl's compilation time of TWiki code. By the way - I can confirm RickMach's statement about RAM. My mod_perlized virtual TWiki runs on 256 MB, and it starts to swap only if users run viewfile with huge attachments (>10MB). The only things I tuned was to reduce the number of initial worker threads, since I rarely have simultaneous access by several users, and to restart Apache once per night to make sure to processes which got fat.

(I am setting the status to answered though I think that you might not like the answer)

-- HaraldJoerg - 29 Nov 2006