Feature Proposals » TWiki Time Debug Feature

Motivation

TWiki can be slow in some cases. Finding the cause can be time consuming, but is usually attributed to slow TWikiVariables. A way to identify and fix slow code is desired.

Description and Documentation

This proposal adds time measurement feature to TWiki.

TWiki already supports the following development and debugging settings in bin/LocalLib.cfg:

• $ENV{TWIKI_ASSERTS} = 1;
• $ENV{TWIKI_MONITOR} = 1;

This proposal adds code to support this new debug setting:

• $ENV{TWIKI_TIME} = 1;

If enabled, time debug info is shown in the apache error log.

The time debug info can be added anywhere in the code using this:

    TWiki::printTime('after TWiki::UI::checkWebExists');

The static TWiki::printTime function does nothing unless $ENV{TWIKI_TIME} is set. To optimize and avoid the call in tight loops you can test beforehand:

    TWiki::printTime('after TWiki::UI::checkWebExists') if( $ENV{TWIKI_TIME} );

Example

Example output in the apache error log:

[error] [client 10.0.1.226] ---( TWIKI PROFILE TIMER START )-----------------
[error] [client 10.0.1.226] ==> 0.696 s - start view, query string: raw=on
[error] [client 10.0.1.226] ==> 0.696 s - after TWiki::UI::checkWebExists
[error] [client 10.0.1.226] ==> 0.696 s - after topicExists
[error] [client 10.0.1.226] ==> 0.699 s - after TWiki::UI::readTopic Eng.FeatureRequestForm
[error] [client 10.0.1.226] ==> 0.700 s - after TWiki::UI::checkAccess for pthoeny
...

Impact

Implementation

-- Contributors: Peter Thoeny - 2014-05-15

Discussion

Feature accepted by release meeting at KampalaReleaseMeeting2014x05x15.

To do: Support time debugging also under mod_perl and other pre-compilers.

-- Peter Thoeny - 2014-05-15

I was not aware of the functionality of the Monitor module. I am retracting this proposal, and in return enhance the existing Monitor module.

-- Peter Thoeny - 2014-05-17

Enhancements to the Monitor module and core code tuning is tracked under TWikibug:Item7491

-- Peter Thoeny - 2014-05-17