Page 1 of 1

[Mod] Stopwatch (Benchmarking Utility) [stopwatch]

PostPosted: Wed Aug 22, 2018 23:42
by sorcerykid
Stopwatch Mod v1.2
stopwatch (by sorcerykid)

Stopwatch is a utility for developers to very quickly benchmark portions of Lua code, but without the complexity and overhead of enabling the mod profiler. I created this mod because my code was becoming littered with far too many time-keeping calculations while debugging. It should be fully compatible with all versions of Minetest 0.4.x+ since it only depends on the monotonic clock function.

Repository:

https://bitbucket.org/sorcerykid/stopwatch

Download Archive (.zip)
Download Archive (.tar.gz)

Dependencies:

None

Source Code License:

The MIT License (MIT)

Installation:

  1. Unzip the archive into the mods directory of your game
  2. Rename the stopwatch-master directory to "stopwatch"
  3. Add "stopwatch" as a dependency for any mods using the API

Usage Instructions

You will first need to create a Stopwatch object at the top of the mod that you want to benchmark. The constructor accepts four parameters: a unique identifier for the test series (required), the output color of the results (default is "white"), the numeric scale of each value (default is "ms"), and the numeric precision of each value (default is 3)

    local S, S_ = Stopwatch( id, color, scale, prec )
After initializing its internal state, the constructor returns two functions that can be used to benchmark your code.

    S( )

    S_( is_show )
The S( ) function starts a new trial for the given test series, and the S_( ) function stops the current trial, outputting the elapsed execution time if is_show is true. When the server is shutdown, the total elapsed time for the test series will be output in addition to a variety of other statistics:

  • total = the total execution time for the test series.
  • rep = the number of trials within the test series
  • avg = the mean execution time of all the trials
  • min = the minimum execution time of all the trials
  • max = the maximum execution time of all the trials
  • med = the median execution time of all the trials
  • dev = the standard deviation of all the trials
A new Stopwatch object should be instantiated for each additional benchmark that you wish to perform. In addition, you will want to append digits or some other unique signifier to distinguish the corresponding start and stop functions.

In this example, I'm measuring the performance of Lua's table.insert function in append vs. prepend mode:

Code: Select all
local S1, S1_ = Stopwatch("table_prepend")
local S2, S2_ = Stopwatch("table_append")

local y = { }
S1( )
for x = 0, 5000 do
        table.insert( y, 1, x )
end
S1_( )

y = { }
S2( "table prepend" )
for x = 0, 5000 do
        table.insert( y, x )
end
S2_( )


The output should look something like this.

Image

By performing multiple iterations, it is possible to get a more representative sample for each trial.

Image

It is worth noting that Lua's print function tends to somewhat CPU intensive. Therefore you should avoid outputting the per-trial execution times for nested test series, otherwise the results will be skewed. For linear test series, this is not a concern since the execution times are already calculated prior to being output.

Re: [Mod] Stopwatch (Benchmarking Utility) [stopwatch]

PostPosted: Fri Aug 24, 2018 21:08
by sorcerykid
Version 1.1b Released

A new version of Stopwatch is ready for download. Here is a complete change log:

  • included mod.conf and description.txt files
  • included working code examples for developers
  • implemented stack for non-linear testing of code
The start and stop functions S( ) and S_( ) now behave as a stack. This means that tiered performance measurements are possible.

Code: Select all
local function test1()
     S("test1")
     :
     S_()
end


local function test2()
     S("test2")
     :
     S_()
end

minetest.register_on_joinplayer( function( )
     S("main test")
     test1()
     test2()
     S_()
end )

The trial start and stop functions should always be balanced, so be certain to take into account all returns, breaks, etc.

Re: [Mod] Stopwatch (Benchmarking Utility) [stopwatch]

PostPosted: Sat Aug 25, 2018 10:54
by Hybrid Dog
I think for benchmarking specific algorithms, this is more suitable: https://dev.minetest.net/Lua_Optimizati ... nchmarking
I used the stopwatch mod to measure the time swamp mapgen takes:
** trial total = 10919.735 ms 74 tries 147.564 ms each @sumpf mg
** trial total = 8710.302 ms 74 tries 117.707 ms each @sumpf vmset
** grand total = 19630.037 ms
The vmanip set_data, set_param2_data, set_lighting, calc_lighting and write_to_map take about 0.12 seconds, the actual swamp generation takes about 0.15 seconds.
Could you also print the variance of the times?

Re: [Mod] Stopwatch (Benchmarking Utility) [stopwatch]

PostPosted: Mon Aug 27, 2018 02:36
by sorcerykid
Thanks for your feedback. The routine linked above is suitable for for stress testing algorithms. Stopwatch mod, however, is designed for measuring the mean execution time of discrete segments of code to aid in locating potential bottlenecks or analyzing the costs associated with certain data structures (as in amortized analysis).

For the next version, I will include max, min, median, and standard deviation values in the aggregate report.

Re: [Mod] Stopwatch (Benchmarking Utility) [stopwatch]

PostPosted: Tue Aug 28, 2018 16:51
by sorcerykid
Version 1.2b Released

A new version of Stopwatch is ready for download. Here is a complete change log:

  • Major rewrite to improve accuracy and efficiency
  • Updated code examples with latest feature-set
I've completely overhauled the Stopwatch API, as I was fairly dissatisfied with the performance of the previous implementation. There was on average a 16 microsecond difference between the true execution time of each trial vs. the execution time reported by the Stopwatch mod. While most of the overhead was caused by Lua's print function, even with that disabled, a 6 microsecond average difference remained.

To resolve this disparity, the bulk of the logic has been offloaded till server shutdown, so that the start and stop functions can focus exclusively on polling the monotonic clock. This has reduced the inaccuracy of each trial to about 1 microsecond.

Of course, these changes will necessitate a different workflow as well. Instead of instantiating a single Stopwatch object for the entire mod, a unique Stopwatch object should be instantiated for every test series that you want to perform (if you don't care about the totals, then a single object will suffice). The parameters for the constructor are as follows:

    local S, S_ = Stopwatch( id, color, scale, prec )
    • id - a unique identifier for the test series (required)
    • color - the output color of the results (default is "white")
    • scale - the numeric scale of each value (default is "ms")
    • prec - the numeric precision of each value (default is 3)
For sake of convention, the start and stop functions can still be named as S() and S_(). In the case of multiple test series, however, you may want to append digits or some other unique signifier.

As you'll notice in the screenshot below, the results for each test series are also far more exhaustive:

  • total = the total execution time for the test series.
  • rep = the number of trials within the test series
  • avg = the mean execution time of all the trials
  • min = the minimum execution time of all the trials
  • max = the maximum execution time of all the trials
  • med = the median execution time of all the trials
  • dev = the standard deviation of all the trials
Here is the code from the original example, revisited:

Code: Select all
local S1, S1_ = Stopwatch("table_prepend", "cyan")
local S2, S2_ = Stopwatch("table_append", "yellow")

for trial = 0, 5 do
        local y = {}
        S1()
        for x = 0, 5000 do
                table.insert(y, 1, x)
        end
        S1_(1)
end

for trial = 0, 5 do
        local y = {}
        S2()
        for x = 0, 5000 do
                table.insert(y, x)
        end
        S2_(1)
end

These are the results as they will appear in your terminal (the actual values will differ, of course):

Image

Helpful Tip: When you begin work on a new mod, I would suggest always creating a generic Stopwatch object at the top of the file, so that you are always prepared to test any random section of code on the fly.