Check-in [54c0b81bab]

{"tip": {
	"527":{"url":"./tip/527.md","created":"26-Nov-2018","post-history":"","state":"Draft","tcl-branch":"sebres-8-6-timerate","tcl-version":"8.5","vote":"Pending","type":"Project","title":"# TIP 527: New measurement facilities in TCL: New command timerate.","discussions-to":"news:comp.lang.tcl","author":["Sergey G. Brester <[email protected]>"],"is-jest":false},
	"526":{"url":"./tip/526.md","created":"08-Nov-2018","post-history":"","state":"Draft","tcl-version":"9.0","vote":"Pending","type":"Project","title":"# TIP 526: Make [expr] Only Accept One Argument","author":["Donal K. Fellows <[email protected]>"],"is-jest":false},
	"525":{"url":"./tip/525.md","keywords":"Tcl, testing, continuous integration","state":"Final","type":"Project","author":["Donal K. Fellows <[email protected]>"],"vote-results":"8/0/0 accepted","votes-for":"KBK, SL, AF, DGP, FV, DKF, AK, JN","votes-against":"none","created":"24-Oct-2018","title":"# TIP 525: Make Tcltest Report Overall Success in a Machine-Readable Way","post-history":"","vote":"Done","tcl-version":"8.5","votes-present":"none","is-jest":false},
	"524":{"url":"./tip/524.md","keywords":"Tcl, object orientation, customization","state":"Final","vote-summary":"Accepted 2/0/4","type":"Project","author":["Donal K. Fellows <[email protected]>"],"votes-against":"none","votes-for":"DKF, JN","created":"23-Oct-2018","title":"# TIP 524: Custom Definition Dialects for TclOO","post-history":"","vote":"Done","tcl-version":"8.7","tcl-branch":"tip-524","votes-present":"BG, KBK, FV, SL","is-jest":false},
	"523":{"url":"./tip/523.md","keywords":"queue, stack, pop","state":"Final","vote-summary":"Accepted 7/0/0","type":"Project","author":["Peter Spjuth <[email protected]>"],"votes-against":"none","votes-for":"DKF, BG, KBK, JN, DGP, FV, SL","created":"22-Oct-2018","title":"# TIP 523: New lpop command","post-history":"","vote":"Done","tcl-version":"8.7","tcl-branch":"tip-523","votes-present":"none","is-jest":false},
	"522":{"url":"./tip/522.md","keywords":"tcltest, error codes","state":"Final","type":"Project","author":["Peter Spjuth <[email protected]>"],"vote-results":"8/0/0 accepted","votes-for":"KBK, SL, AF, DGP, FV, DKF, AK, JN","votes-against":"none","created":"22-Oct-2018","title":"# TIP 522: Test error codes with Tcltest","post-history":"","tcl-branch":"tip-522","vote":"Done","tcl-version":"8.7","votes-present":"none","is-jest":false},
	"521":{"url":"./tip/521.md","keywords":"Tcl, floating point, NaN, not a number","created":"21 October 2018","post-history":"","state":"Draft","tcl-version":"8.7","vote":"Pending","type":"Project","title":"# TIP 521: Floating Point Classification Functions","author":["Kevin B. Kenny <[email protected]>"],"is-jest":false},
	"520":{"url":"./tip/520.md","keywords":"Tcl, floating point, NaN, not a number","created":"18 October 2018","post-history":"","state":"Draft","tcl-branch":"tip-520","tcl-version":"8.7","vote":"Pending","type":"Project","title":"# TIP 520: Make NaN Quiet","author":["Kevin B. Kenny <[email protected]>"],"is-jest":false},

	"4":{"url":"./tip/4.md","created":"26-Oct-2000","post-history":"","state":"Draft","vote":"Pending","type":"Informative","title":"# TIP 4: Tcl Release and Distribution Philosophy","discussions-to":"news:comp.lang.tcl","author":["Brent Welch <[email protected]>","Donal K. Fellows <[email protected]>","Larry W. Virden <[email protected]>","Larry W. Virden <[email protected]>"],"is-jest":false},
	"3":{"url":"./tip/3.md","created":"14-Sep-2000","post-history":"","state":"Accepted","vote":"Done","type":"Process","title":"# TIP 3: TIP Format","author":["Andreas Kupries <[email protected]>","Donal K. Fellows <[email protected]>"],"is-jest":false},
	"2":{"url":"./tip/2.md","created":"12-Sep-2000","post-history":"","state":"Draft","vote":"Pending","type":"Process","title":"# TIP 2: TIP Guidelines","author":["Andreas Kupries <[email protected]>","Donal K. Fellows <[email protected]>","Don Porter <[email protected]>","Mo DeJong <[email protected]>","Larry W. Virden <[email protected]>","Kevin Kenny <[email protected]>"],"is-jest":false},
	"1":{"url":"./tip/1.md","created":"14-Sep-2000","post-history":"","state":"Active","vote":"No voting","type":"Informational","title":"# TIP 1: TIP Index","author":["TIP Editor <[email protected]>"],"is-jest":false},
	"0":{"url":"./tip/0.md","created":"11-Dec-2000","post-history":"","state":"Final","vote":"Done","type":"Process","title":"# TIP 0: Tcl Core Team Basic Rules","author":["John Ousterhout <[email protected]>"],"is-jest":false},
	"@min": 0,
	"@max": 527
}, "@timestamp": 1543334261}

<tr class='project projectdraft projectdraft85 project85'>
<td valign='top'><a href='./tip/527.md'>527</a></td>
<td valign='top'>Project</td>
<td valign='top'>8.5</td>
<td valign='top'>Draft</td>
<td valign='top'># TIP 527: New measurement facilities in TCL: New command timerate.</td>
<td valign='top'><a href='/tcl/timeline?r=sebres-8-6-timerate'>Link</a></td>
</tr>
<tr class='project projectdraft projectdraft90 project90'>
<td valign='top'><a href='./tip/526.md'>526</a></td>
<td valign='top'>Project</td>
<td valign='top'>9.0</td>
<td valign='top'>Draft</td>
<td valign='top'># TIP 526: Make [expr] Only Accept One Argument</td>

# TIP 527: New measurement facilities in TCL: New command timerate.
	Author:         Sergey G. Brester <[email protected]>
	State:          Draft
	Type:           Project
	Vote:           Pending
	Created:        26-Nov-2018
	Tcl-Version:    8.5
	Tcl-Branch:     sebres-8-6-timerate
	Discussions-To: news:comp.lang.tcl
	Post-History: 
-----

# Abstract

This TIP proposes new command `timerate` as well as measurement toolchain for TCL.

For provide a possibility to compare results between Tcl versions the version 8.5 is suggested as target version for this TIP.
(In case of some objections by extending of old versions, the command `timerate` could be placed into `::tcl::unsupported namespace`.)

Additionally this TIP proposes (optionally) a small framework to test performance. This makes possible to create a test-script for
performance-relevant coverage and allows to compare the results diff-based to find performance degradation between revisions.

# Rationale

Although the already available command `time` can be used for performance measurement, but it has several disadvantages:

 1. the execution is limited by fixed repetition count, so the real execution time is undefined (if the evaluation time of single iteration is unknown or may vary in time in different versions), thus it could grow to very long time.
 2. it does not have a calibration ability.
 3. it uses default script invocation function (`Tcl_EvalObjEx`), therefore the execution of the script differentiates from execution of compiled byte-code (e. g. in the compiled procedure),
    additionally measurement is very unprecise on extream fast scripts, so it has certain overhead (on execution up to TclNRRunCallbacks resp. corresponding TEBCResume of compiled script
    as well as the extern costs involved like a washout of the CPU-cache, branch misprediction, etc).

<hr/>
# I. Proposal of command `timerate`

	timerate - Time-related execution resp. performance measurement of a script

### Synopsis

	timerate script ?time? ?count?

	timerate ?-direct? ?-overhead double? script ?time ?count??

	timerate ?-calibrate? ?-direct? script ?time ?count??

### Description

The first and second form will evaluate script until the interval time given in milliseconds elapses, or for 1000 milliseconds (1 second) if time is not specified.
If parameter count is additionally specified (not yet introduced in mentioned tcl-branch, coming soon) it means max count times to evaluate the script, so the evalution will stop after this count of iterations reached.

It will then return a canonical tcl-list of the form (similar to command `time` but more expressive):

	.095977 µs/# 52095836 # 10419167 #/sec 5000.000 nett-ms

which indicates:

       - the average amount of time required per iteration, in microseconds (`lindex $result 0`)

       - the count how many times it was executed (`lindex $result 2`)

       - the estimated rate per second (`lindex $result 4`)

       - the estimated real execution time without measurement overhead (`lindex $result 6`)

Time is measured in elapsed time using heighest timer resolution as possible, not CPU time.
This command may be used to provide information as to how well the script or a tcl-command is per‐forming and can help determine bottlenecks and fine-tune application performance.

In opposition to `time` the execution limited here by fixed time.
Additionally the compiled variant of the script will be used during whole evaluation (as if it were part of a compiled proc),
if parameter -direct is not specified.
Therefore it provides more precise results and prevents very long execution time by slow scripts resp. scripts with unknown execution time of single iteration.

To measure very fast scripts as exact as posible the calibration process may be required.

	-calibrate

This parameter used to calibrate timerate calculating the estimated overhead of given script as default overhead for further execution of timerate.
It can take up to 10 seconds if parameter time is not specified.

	-overhead double

This parameter used to supply the measurement overhead of single iteration (in microseconds) that should be ignored during whole evaluation process.

	-direct

Causes direct execution per iteration (not compiled variant of evaluation used, similar to `time` - can be used to measure `Tcl_EvalObjEx` as well as invocation of canonical list).

### Examples

Estimate how fast it takes for a simple Tcl for loop (including operations on variable i) to count to a ten:

	# calibrate:
	timerate -calibrate {}
	# measure:
	timerate { for {set i 0} {$i<10} {incr i} {} } 5000

Estimate how fast it takes for a simple Tcl for loop only (ignoring the overhead for operations on variable i) to count to a ten:

	# calibrate for overhead of variable operations:
	set i 0; timerate -calibrate {expr {$i<10}; incr i} 1000 
	# measure:
	timerate { for {set i 0} {$i<10} {incr i} {} } 5000

Estimate the rate of calculating the hour using clock format only, ignoring overhead of the rest, without measurement how fast it takes for a whole script:

	# calibrate:
	timerate -calibrate {}
	# estimate overhead:
	set tm 0
	set ovh [lindex [timerate { incr tm [expr {24*60*60}] }] 0]
	# measure using esimated overhead:
	set tm 0
	timerate -overhead $ovh {
	  clock format $tm -format %H
	  incr tm [expr {24*60*60}]; # overhead for this is ignored
	} 5000

### Imact

As the current implementation in [sebres-8-6-timerate](/tcl/timeline?n=100&r=sebres-8-6-timerate) 
(resp. [sebres-8-5-timerate](/tcl/timeline?n=100&r=sebres-8-5-timerate)) shows, no public API's are affected by introducing this,
solely some new functions are provided for Tcl internal API (see tclInt.h).

Don Porter (dgp) has made a review of this targeting 8.7, which can be found in branch [dgp-sebres-timerate-review](/tcl/timeline?n=100&r=dgp-sebres-timerate-review).
This branch already contains the test-performance framework as well as `tests-perf/clock.perf.tcl` script (originate by me in clock speedup branch).

<hr/>
# II. Proposal of test-performance framework `::tclTestPerf`

This small test-suite should provide possibility for batch-based measurement as well as to have evaluable diff-based results
as comparison between revisions, which should allow to find performance degradation on some versions.

### Synopsis

	::tclTestPerf::_test_run time scripts

This command executes a batch of scripts, a "canonical" tcl-list with an exception that rows could be commented (using tcl comment-chars `#`), 
which simply produces an output, can be used as anchor in automated evaluation of test-results (or diff).
The execution of uncommented blocks produces tclsh-similar output so `% command ...`, result of the single execution and result of the timerate invocation.

Special tokens can be used to setup or cleanup, to execute once some script before and after the measurement:

	::tclTestPerf::_test_run 500 {
	  setup {set i 0}
	  {clock format [incr i] -format "%Y-%m-%dT%H:%M:%S" -locale en -timezone :CET}
	  cleanup {unset i}
	  ...
	}

It is recommendable to separate multiple scripts into several bolocks, be cause this produces the summary output at end of execution, 
which contains the total, average, min and max time of execution of this script-block (thus making easier to find a candidate affected by degradation).

### Usage as test-script

	## common test performance framework:
	if {![namespace exists ::tclTestPerf]} {
	  source [file join [file dirname [info script]] test-performance.tcl]
	}

	## test namespace:
	namespace eval ::tclTestPerf-Example {

	namespace path {::tclTestPerf}

	## set testing defaults:
	set ::env(TCL_TZ) :CET

	## warm-up test-related features (load clock.tcl, system zones, locales, etc.):
	clock scan "" -gmt 1
	clock scan ""
	clock scan "" -timezone :CET
	clock scan "" -format "" -locale en
	clock scan "" -format "" -locale de

	proc test-format {{reptime 1000}} {
	  _test_run $reptime {
	    # Format : short, week only (in gmt)
	    {clock format 1482525936 -format "%u" -gmt 1}
	    # Format : short, week only (system zone)
	    {clock format 1482525936 -format "%u"}
	    # Format : short, week only (CEST)
	    {clock format 1482525936 -format "%u" -timezone :CET}
	  }
	}

	proc test-scan {{reptime 1000}} {
	  _test_run $reptime {
	    # Scan : date (in gmt)
	    {clock scan "25.11.2015" -format "%d.%m.%Y" -base 0 -gmt 1}
	    # Scan : date (system time zone, with base)
	    {clock scan "25.11.2015" -format "%d.%m.%Y" -base 0}
	    # Scan : date (system time zone, without base)
	    {clock scan "25.11.2015" -format "%d.%m.%Y"}
	  }
	}

	proc test {{reptime 1000}} {
	  puts ""
	  test-format $reptime
	  test-scan $reptime
	  puts \n**OK**
	}

	}; #/::tclTestPerf-Example

	if {[info exists ::argv0] && [file tail $::argv0] eq [file tail [info script]]} {
	  array set in {-time 500}
	  array set in $::argv
	  ::tclTestPerf-Example::test $in(-time)
	}

### Result of execution:

	Calibration ... done: 0.0438427054988057 µs/#-overhead

	% # Format : short, week only (in gmt)
	% clock format 1482525936 -format "%u" -gmt 1
	5
	0.217501 µs/# 1913191 # 4597679 #/sec 416.121 nett-ms

	% # Format : short, week only (system zone)
	% clock format 1482525936 -format "%u"
	5
	0.249312 µs/# 1705587 # 4011041 #/sec 425.223 nett-ms

	% # Format : short, week only (CEST)
	% clock format 1482525936 -format "%u" -timezone :CET
	5
	0.201958 µs/# 2034167 # 4951516 #/sec 410.817 nett-ms

	********************************************************************************
	Total 3 cases in 1.52 sec. (1.25 nett-sec.):
	0.668771 µs/# 5652945 # 4514551.244 #/sec 1252.161 nett-ms
	Average:
	0.222924 µs/# 1884315 # 4514551 #/sec 417.387 nett-ms
	Min:
	0.201958 µs/# 2034167 # 4951516 #/sec 410.817 nett-ms
	Max:
	0.249312 µs/# 1705587 # 4011041 #/sec 425.223 nett-ms
	********************************************************************************

	% # Scan : date (in gmt)
	% clock scan "25.11.2015" -format "%d.%m.%Y" -base 0 -gmt 1
	1448409600
	0.359373 µs/# 1240031 # 2782622 #/sec 445.634 nett-ms

	% # Scan : date (system time zone, with base)
	% clock scan "25.11.2015" -format "%d.%m.%Y" -base 0
	1448406000
	0.406066 µs/# 1111337 # 2462654 #/sec 451.276 nett-ms

	% # Scan : date (system time zone, without base)
	% clock scan "25.11.2015" -format "%d.%m.%Y"
	1448406000
	0.448517 µs/# 1015517 # 2229568 #/sec 455.477 nett-ms

	********************************************************************************
	Total 3 cases in 1.51 sec. (1.35 nett-sec.):
	1.213956 µs/# 3366885 # 2489586.930 #/sec 1352.387 nett-ms
	Average:
	0.404652 µs/# 1122295 # 2489585 #/sec 450.796 nett-ms
	Min:
	0.359373 µs/# 1240031 # 2782622 #/sec 445.634 nett-ms
	Max:
	0.448517 µs/# 1015517 # 2229568 #/sec 455.477 nett-ms
	********************************************************************************

### Examples

For the usage examples of this test-framework, see 
[clock-speedup-branch - tests-perf/clock.perf.tcl](/tcl/artifact/afee4f40621652b1) or
[event-perf-branch - tests-perf/test-performance.tcl](/tcl/artifact/70523c268fdf9e3e).

For the result example (produced with clock.perf.tcl) see [diff in sebres/tcl#2](https://github.com/sebres/tcl/pull/2).