Feature Wiki

Information about planned and released features

Tabs

Lightweight profiling of requests

Page Overview

[Hide]

1 Requirements

Provides a new class ilprofiler which measures script-performance
 
ilProfiler tries to determine a basic performance-profile (e.g. how much time was spent on SQLs, Templates, Initialisation, ..). It’s very useful to give you some insights on ILIAS script-performance and how it breaks down. It’s designed to be run on productive environments, i.e. to have an extremely small footprint on script-performance.
 
What is profiled?

  • Total script-execution time
  • Peak memore usage
  • Time spent + number of calls
    • SQLs - differentiated by context, i.e. "select" vs. "update" vs. ...
    • Template-Constructors - everything else of the template engine is hard to track
  • Time of important events during command flow (relative to total script-execution time)
    • ilInitialisation::initILIAS() finished
    • ilTemplate::show() called
    • ilUtil::redirect() called
When enabled ilProfiler writes one condensed line per request containing the above data + script-name + get-parameters. When set to verbose mode each SQL- and Template-Constructor call is logged additionally with more details (not recommended for production environments).

1.1 Example Output

[14-06-19 01:13:51] [ilias] Profiler: Request in 0.032s, 0.9% SQL-SHO:1, 0.4% SQL-SET:2, 53.0% SQL-SEL:168, 4.9% TPL():4, 51.9% @INIT:1. peak-memory: 2,048KB, /ilias-ng/ilias.php, baseClass=ilAdministrationGUI cmd=getDropDown cmdMode=asynch

 
The above measurement was made running ILIAS with HHVM (which speeds up all scripts about roughly 2x)

  • The example request took 32ms – ilias.php / ilAdministrationGUI / getDropDown / asynch
  • There have been 171 SQL-Query calls (1 SHOW, 2 SET, 168 SELECT)
  • 54% was spent waiting for all SQL-Responses (SHOW/SET/SELECT)
  • There have been 4 Template-Constructor calls (that’s all we track in the Template-Engine currently!)
  • 5% was spent on Template-Constructor calls (the dropdown-template in this example is quite simple)
  • 52% was spent to initialise ILIAS, i.e. before control is passed to the baseClass
  • peak-memory usage was 2 MB
All measured parts appear in the order of first occurrence during script runtime.
Note: Of course there can be an overlap between initialisation, SQLs and template constructor calls - so it’s not as simple as adding these numbers together to get new meaningful numbers. But each number has a meaning for itself.
 

1.2 Configuration

ilias.ini.php
 

[profiler]
enabled = "1" ; enables the profiler (default: 1)
verbose = "0" ; enables per-SQL-profiling (default: 0, NOTE: only for local debugging - don't use it on production)
high-accuracy = "0" ; comes with a performance-penalty (default: 0)
; path = "/www/log" ; (default: "", use standard-log if unset)
; file = "ilias-profiler.log" ; (default: "", use standard-log if unset)
; firephpkey = "" ; stub - idea for future-versions (could be useful for remote analysis of detailed per-SQL-profiling)

1.3 Why not xDebug or ilBenchmark??

  • xDebug is very good to analyse single requests in full detail. But it’s not so good to run it on production environments because it adds a huge overhead (roughly 200% compared to 0.5% of ilProfiler).
  • ilBenchmark is very similar: it is designed for detailed analysis of single requests and adds some noticeable overhead.
  • ilProfiler on the other hand gives you a very condensed overview about the script performance. This makes it very easy to keep track of it during server configuration, or for bulk analysis of heavy-load situations on production environments. And the overhead is barely noticeable - by design.

2 Status

  • Scheduled for: Not scheduled yet (will be set by Jour Fixe)
  • Funding: Colin Kiegel / leisure time :-)
  • Maintainer: (will be set by Jour Fixe)
  • Implementation of the feature is done by (company, developer)
  • Contract settled: (fill in "Yes" if a contract is already settled, otherwise "No" )
  • Tested by / status: (name, e-mail), (status information set after implementation)

3 Additional Information

Contact the following persons if you want to know more about this feature, its implementation or funding:

  • Information about concept: (name, e-mail)
  • Information about funding: (name, e-mail)
  • Information about implementation: (name, e-mail)

4 Discussion

Colin Kiegel, 20140713: A patch including the implementation is appended below. In order to be able to track the template-constructors I had to "rearrange" the setup-initialisation quite a bit in order to make sure that templates are constructed only after the profiler is initialised. If profiling template-constructors is dropped this rearrangement is not neccessary of course. - What do you think of the idea to add firephp-support (or something similar) in a future-version? Verbose-Firephp-mode could be triggered by a secret key configured in ilias.ini.php.

Colin Kiegel, 20150401: I can provide it as a Pull-Request, so review and minor changes would still be possible via github.

5 Implementation

The patch below is based on ILIAS 4.4.3 (originally including the HHVM-patchset - but that has been removed from this patch)

Last edited: 1. Apr 2015, 12:25, Kiegel, Colin [kiegel]