Module:Timing/doc

This is a documentation subpage for Module:Timing.
It may contain usage information, categories and other content that is not part of the original module page.

The purpose of this module is to provide a simple method to do timing analysis for performance tuning of Lua-functions, that is profiling of functions. Usually measuring the duration of function calls is part of a larger effort to identify bottlenecks and problematic code. This is not a full-blown profiler, as it is not possible to do line-tracing (call-graph profiling) in the current set up. Its only purpose is to measure execution time (flat profiling), and to do this interactively from the debug console (ie. on a single function).

The timing analysis is called with an executable function, and optionally a count (size, default 100) of each test set and a number of such test sets (default 10). The total number of calls will be count × sets and gives the mean runtime for the function. The standard deviation is calculated from the number of sets and will only be a coarse estimate. If only run with a single set the standard deviation will go away, but even if it isn't measured the execution time will still vary.

The profiler does two passes over the total calls, one with a dummy function and one with the actual function. This makes it possible to get a baseline for how heavy the additional code are, and then we can later subtract this from the measurement of the function we are testing. If the function under test is to simple those to execution times will be close and the uncertainty in the difference can be high. If the execution time is similar to the standard deviation, then the analysis should be rerun with larger or more sets.

During development it became clear that 100 calls in 10 sets is usually enough to get good estimates, but do not put overly much weight on those numbers. If one function is twice, or tree times, or even ten times slower, never mind as long as it runs in constant or linear time. If something is 100 times slower or have indications that it runs in exponential time, then you should probably consider other algorithms.

Usage

This module is not for use in ordinary templates, or on pages, it is to be used in the debug console below the edit window on module pages. For example, assume we open a page Module:HelloWorld, then we can write a call to profile the function p.hello(). The code in the page looks something like the example below, but local versions may be a little different. (At nowiki a similar code is at w:no:Module:HelloWorld2.)

The following code is a stripped down version of Module:HelloWorld. See the page for a full version.

my_object = {};

my_object.hello = function( frame )
    local str = "Hello World!"
    return str
end

return my_object

Access to this code will be through a generic p in the debug console. Assuming the previous code the profiler can be called as

=require 'Module:Timing'(p.hello)

A call like that produced for the same type of module a report like the following at enwiki

=require 'Module:Timing'(p.hello,1000,100)
Each call was running for about 8.5120000000022E-9 seconds.
    Mean runtime for each set was 8.5120000000022E-7 seconds,
    with standard deviation of 1.2400753202931E-6 seconds,
    minimum 1.2962E-5, maximum 1.5542E-5.
    Total time spent was about 0.00038879 seconds.

In this the important information is Each call was running for about 8.5120000000022E-9 seconds. This says how long the function actually run.

Note that this function is very simple, and therefore the run time for the function gets close to the run time for the baseline. As a result the run time for each set gets close to the standard deviation.

If a call need some parameters, then those most be provided in a wrapper function. That can be achieved by adding a separate function like the following, and then timing the resulting function

function wrap() return p.hello(mw.getCurrentFrame()) end
=require 'Module:Timing'(wrap)

A call sequence like that produced the following output

function wrap() return p.hello(mw.getCurrentFrame()) end
=require 'Module:Timing'(wrap)
Each call was running for about 3.48499E-7 seconds.
    Mean runtime for each set was 3.48499E-5 seconds,
    with standard deviation of 1.1898648017737E-5 seconds,
    minimum 8.9850000000004E-6, maximum 1.0064E-5.
    Total time spent was about 0.000585205 seconds.

Sometimes it is better to put the wrapper in the module under inspection itself

my_object = {};

my_object.hello = function( frame )
    local str = "Hello World!"
    return str
end

my_object.wrap = function ()
	return my_object.hello(mw.getCurrentFrame())
end

return my_object

That produced the following output

=require 'Module:Timing'(p.wrap)
Each call was running for about 1.91509E-7 seconds.
    Mean runtime for each set was 1.91509E-5 seconds,
    with standard deviation of 7.6705200899287E-6 seconds,
    minimum 4.5409999999994E-6, maximum 4.937E-6.
    Total time spent was about 0.000318969 seconds.

Even simple wrappers will take a lot of time. Even if we drop getting the current frame in the previous timing calls the run time is still 10 times higher than the bare call.

The morale is; do not add wrappers to very simple functions, the numbers will be far off! ;)

Gadget

There is an additional gadget (to be continued…)

Not sure if this is really useful, will be getting back to this.

Usage

Gadget

See also