Go Up
 

Timelog

© Medianet 2020

By Klaus Garms (kgarms) @ https://git.medianet-home.de/kgarms/timelog

1. Purpose

timelog is a PHP utility for structured code performance analysis via plain text and/or graphical HTML logs.

While there are other utilities which run page requests and then report the response times, those tools can only answer how slow a specific request is, but that doesn't really help much for doing something about it.

That is where timelog comes in: It is basically an x-ray device for the running PHP code because it can answer the much more pressing questions:

Where does the PHP code spend all that time, and how much time, exactly, does it spend in each part of the code, and with which parameters?

A frequent problem is having to guess which parts of the code actually need optimization – in many cases such guesses are actually mistaken and valuable developer time is spent on optimizations which actually aren't particularly effective while less obvious but more critical issues such as session locking between Ajax requests and possibly unnecessary calls or calls with unnecessary options and parameter settings may get overlooked.

timelog can be used to clearly and unmistakably expose the real sinks of CPU time and the real drag anchors pulling down site and application performance and it provides objective proof of both existing problems but also of optimization successes in comparison.

It is included into existing PHP code and it can produce timelogs in two different formats:

1.1. Plain text timelog

This can be written to the PHP error log and/or to stdout and it describes the hierarchy of timelog-marked calls and declared sections with the absolute time each part of the code has taken and also the percentage that time was of the total execution time overall:

+ SCLAN/index.php: /SCLAN/index.php/music/smusic/6
| 0.000535s (0.372%)
|
|+ core/CodeIgniter.php
|| 0.007299s (5.081%) includes and setup
|| 0.010762s (7.492%) sanity checks
|| 0.000011s (0.008%)
||
||+ new Music()
||| 0.000006s (0.004%)
|||
|||+ Common __construct()
|||| 0.000002s (0.001%)
||||
||||+ CI_Controller __construct()
||||| 0.000015s (0.010%) set_userdata
||||| 0.001422s (0.990%) all loaded
||||| 0.000007s (0.005%)
|||||
|||||+ _ci_autoloader()
|||||| 0.002847s (1.982%)
||||||
||||||+ CI_SESSION __construct()
||||||| 0.000614s (0.427%)
|||||||
|||||||+ session_start()
|||||||| 0.000183s (0.127%) 
|||||||= 0.000183s (0.127%) (total)
|||||||
||||||| 0.000011s (0.008%) loading completed
||||||| 0.000004s (0.003%) loading _ci_init_vars completed
||||||| 0.000005s (0.003%) 
||||||= 0.000817s (0.569%) (total)
||||||
|||||| 0.000008s (0.005%) 
|||||= 0.003672s (2.556%) (total)
|||||
||||| 0.000003s (0.002%) initialized
||||= 0.005119s (3.564%) (total)
||||
|||| 0.006499s (4.524%)
||||
||||+ WATT::startup(/Users/kgarms/Sites/SCLAN/assets/locale/,/Users/kgarms/Sites/SCLAN/,sclan,en_US,English,UTF-8,"English",kgarms)
||||| 0.009619s (6.696%) 
||||= 0.009619s (6.696%) (total)
||||
|||| 0.000009s (0.006%) locale handling
|||| 0.001872s (1.303%) exception handlers set
|||| 0.000006s (0.004%)
||||
||||+ get session model
||||| 0.021065s (14.665%) load session model
||||| 0.001455s (1.013%) load playlist model
||||| 0.000058s (0.040%) load session library
||||| 0.001664s (1.159%) 
||||= 0.024242s (16.876%) (total)
||||
|||| 0.000015s (0.010%) get music contexts
|||= 0.047383s (32.986%) (total)
|||
||| 0.000705s (0.491%) 
||= 0.048094s (33.481%) (total)
||
|| 0.000007s (0.005%)
||
||+ requested method: Music::smusic()
||| 0.076624s (53.342%) 
||= 0.076624s (53.342%) (total)
||
|| 0.000297s (0.207%) 
|= 0.143094s (99.616%) (total)
|
| 0.000017s (0.012%) 
= 0.143646s (100.000%) (total)
2020-05-25 19:23:24 timelog generation took extra 0.000337s (0.235%) dumpmode='log fold<5% file+="develop/timelog/timelog_kgarms.html"'

1.2. HTML timelog

This can be written to the page itself or to a file and it presents the same information but in a more intuitive form and with interactive navigation:

timelog sample log screenshot

An HTML timelog can also show the request loading the actual page together with the Ajax calls that page triggers directly or later on, coloring each of them according to their absolute execution times (redder: slower; greener: faster):

timelog sample log screenshot

As HTML File

1.2.1. HTML timelog interactions

In an HTML timelog each timed sub-section can be clicked on the time block to collapse the display of the elements it contains and back again:

Expanded:

timelog sample log screenshot

Collapsed:

timelog sample log screenshot

Even if a section is collapsed, its title can still be viewed as a tooltip by hovering the mouse pointer over it or by touching and holding it:

timelog sample log screenshot

2. Using timelog in an application

This chapter explains the basics of using timelog in an application and also different strategies of using it depending on what is needed at the time.

Note: See the documented public functions in timelog.php for further details.

2.1. General principles of using timelog in an application

A timelog effectively gives you a structured report on how much time each part of the PHP code has taken.

2.1.1. Recording the time

You only need to tell timelog where to start keeping track of the time (usually on the main code level), when to finish and where to take the time in between by adding three kinds of timelog calls to your code where you want to check on the execution times:

timelog::begin() and timelog::end() will show up in the timelog as indented blocks of time recordings, including the entire recording overall. For each section the total time that section has taken will be shown.

timelog::log() shows up in the timelog as single time recording.

Note: These calls are very fast even if time recording is enabled, so adding a timelog recording call causes almost no distortion of the actual application code's execution time. The more time-consuming task of generating the plain text and/or HTML reports is actually only done once in the very last timelog::end() call on the main level and the time that consumes is reported separately and does not distort the recorded times either.

2.1.2. Enabling and disabling time recording

In any place in the code you can call timelog::enable() or timelog::disable() as needed, possibly depending on debug modes and other application conditions.

The effect will be that timelog recording is either enabled or disabled until the respective other call is made or until the next timelog::end().

In particular, the application may choose to disable timelog recording even before the first timelog::begin() and that will disable recording completely (unless switched back on again).

2.1.3. Example

This is an example of an extremely simple piece of code using timelog without any extra configuration:

require_once("lib/timelog.php");

// this opens the first timelog section:
timelog::begin("demo()");

// just wasting time so timelog has something to report:
timelog::delay(.01);
// now let's see how much time has been spent:
timelog::log("first delay");

// do some other work...

// keep the time again:

timelog::log("some other work");

    
// open an inner timelog section (could also be in a function called)
    
timelog::begin("important section");

    
// just wasting time so timelog has something to report:
    
timelog::delay(.02);
    
timelog::log("inner delay");

    
// the inner section ends here:
    
timelog::end();

// just wasting time so timelog has something to report:
timelog::delay(.03);
timelog::log("second delay");

// the outer section ends here, and timelog will now produce the actual dump:
timelog::end("done."); 

As a result, this report will be dumped to the PHP error log:

+ demo()
| 0.020793s (25.730%) first delay
| 0.000007s (0.009%) some other work
| 0.000003s (0.004%)
|
|+ important section
|| 0.024823s (30.717%) inner delay
|| 0.000013s (0.016%) 
|= 0.024836s (30.733%) (total)
|
| 0.035162s (43.511%) second delay
| 0.000011s (0.014%) done.
= 0.080812s (100.000%) (total)
2020-05-26 05:21:02 timelog generation took extra 0.000075s (0.093%) dumpmode='log'

2.2. Optional configurations

2.2.1. Configure where the timelog will go

By default, timelog dumps its log to the PHP error log, but there are actually multiple options available, which can all be combined as needed:

timelog::setDumpMode('log stdout page file="develop/timelog/demo.html"'); 

Note: This call can be made at any time before the final timelog::end() which produces the timelogs.

In detail:

  • log (default): Dump the plain text timelog to the PHP error log.

  • stdout: Print the plain text timelog to stdout so it will be displayed when the PHP script is run from the command line or dumped to the page as plain text if run as a web script.

  • page: Display the HTML timelog on the current page.

  • file="filename" or file+="filename": Save or append the HTML timelog to the indicated file.

Additional options which affect only HTML timelogs:

  • fold<0.1 or fold<5%: Automatically fold (collapse) any inner section in the HTML timelog if its time is <0.1s or if it makes up less than 5% of the total running time.

When the file+="filename" option is being used, timelogs will accumulate in that file. That is why there is also a call to indicate that this timelog run should actually flush the old content of the file before adding this current timelog:

timelog::dumpFlush(); 

Notes:

  • This call can be made at any time before the final timelog::end() which produces the timelogs.

  • This call should be made if this PHP run actually produces a new main page (for instance in something like pageheaders.php) so a new timelog will be started, while timelogs for the Ajax requests coming from the loaded page can just accumulate below.

2.2.2. Enable user control of timelog

While it can be sufficient to just set up timelog configuration in the PHP source code, timelog also offers the option of letting the user / developer control timelog from the URL field of the browser.

For this it is enough to simply add the following call to the application after the application calls session_start() but before the application calls the final timelog::end() (and also before the application potentially closes the session for write access if it does):

timelog::useSession(); 

That is all that is required to offer the following features to the user / developer:

  • Activate and deactivate timelog and set a timelog session ID:

    • ?timelog: activate timelog within this session and set $_SESSION['timelog']['ID'] = ''

    • ?timelog=myID: activate timelog and set $_SESSION['timelog']['ID'] = 'myID'

    • ?timelog=0 or ?timelog=off: deactivate timelog within this session

  • Set the reference time for timelog coloring:

    • ?timelogref=0.2: Logs with total time >= 0.2s are shown in red, shorter ones shift towards green.

Of course these parameters can be combined, too: ?timelog=myID&timelogref=0.2

Note: The timelog setting is preserved in the PHP session until logout and the parameters only need to be added when this setting is to be changed.

2.2.3. Full-featured example of timelog use

This is an example of how an application could be using timelog with all its features, assuming that all pages and all Ajax requests run this same script:

require_once("lib/timelog.php");

//-- close to the start of the main code:
if(!file_exists('develop/timelog')) {
    
// disable timelog if this is not a development system:
    
timelog::disable();
}


//-- begin the entire timelog recording:
timelog::begin("my application: ".$_SERVER["REQUEST_URI"]);

//... (application code)

//-- activate timelog URL/session control:

session_start();
timelog::useSession();

//... (application code)

//-- if this is an actual page load instead of just an Ajax request, flush the HTML timelog file:

if($is_main_page) {
    
timelog::dumpFlush();
}


//... (application code)

//-- close to the end of the main code:

if(file_exists('develop/timelog') && isset($_SESSION['timelog'])) {
    
// log only if we're on a development system and the user has activated timelog for the session:
    
timelog::setDumpMode('fold<5% file+="develop/timelog/timelog'.
    ((
$_SESSION['timelog']['ID'] == '') ? '' '_'.$_SESSION['timelog']['ID']).'.html"');
} else {
    
// otherwise do nothing:
    
timelog::setDumpMode('');
}


//-- finish the entire timelog recording and if enabled this call will generate all requested timelogs:
timelog::end(); 

In this example the user / developer will normally not have any timelog generated until they activate it by appending parameters like these:

http://localhost/myapplication/somepage?timelog=myname&timelogref=0.5

Which will make the HTML timelog available at a location like this:

http://localhost/myapplication/develop/timelog/timelog_myname.html

After any page load and after any Ajax request that timelog can be reloaded to update it in a second browser window.

And finally the user / developer may simply log out of their session or deactivate timelog again like this:

http://localhost/myapplication/somepage?timelog=off

Notes:

  • By indicating different timelog IDs when enabling timelog, different users can each have their own, separate timelogs apart from the other users.

  • The timelog directory can and should of course be password-secured to protect any internal information which could otherwise become available to unauthorized users through timelogs.

--END--