Welcome to Cosniwa’s documentation!

1. About Cosniwa

Cosniwa [(Co)de (sni)ppet stop(wa)tch] is a tool for profiling code using timestamps. Cosniwa uses timestamps, so you CAN NOT expect nanosecond precision, but it is precise enough for most of the applications.

Read more on www.speedupcode.com.

1.1 Platforms

  1. Cosniwa is officially supported on LINUX and MAC.
  2. It is planned to add support for WINDOWS in the near future.

1.2 Languages

Currently (mid 2017) Cosniwa can be used with the following languages:

1. C++. The first version of Cosniwa was written in C++. Cosniwa can be used with both GCC and Clang compilers. Timing precision below 10 us can be expected.

2. Python 3. Cosniwa can be used with CPython interpreter for Python 3. Cosniwa Python3 port uses Cosniwa C++ modules via the Python-to-C++ interface provided by CPython. Timing precision below 10 us can be expected.

3. Octave. Cosniwa can be used with GNU Octave. There are two versions of Cosniwa prepared for Octave:

  • C++ based. This version uses Cosniwa C++ modules via GNU Octave interface for modules written in C++. It is a recommended version which ensures highest possible timing precision (below 10 us).

  • Native. This version uses GNU Octave functions to obtain timestamps. It should be used if modules written in C++ can not be used. Worse timing precision than for C++ modules can be expected, below 100 us.

1.3 License

Cosniwa is (very) free software, it is licensed under BSD 2-clause license.

1.4 Author

Cosniwa v1.0 is written by Jacek Pierzchlewski (http://pierzchlewski.com)
email: jacek@pierzchlewski.com

1.5 Download

Cosniwa repository is hosted on github.com.

Download Cosniwa zipped or as tar ball.

You can also download the zipped package from Github.

2. Cosniwa Tutorial for C++

Here is a little tutorial about using Cosniwa with C++.

Cosniwa C++ examples can be found on github.com.

The list of topics in the tutorial is as follows:

2.0. Installing Cosniwa for C++

In the main Cosniwa directory run as root:

# make install_cpp

The installation script will compile Cosniwa static library libcosniwa.a and install it in your system.

2.1. C++ example1: Simplest example

Note

Example1 is available on github.com: example1 for C++.

This is the simplest example of using Cosniwa to time code.

2.1.1 First things first

In C++ you need to include “cosniwa.h”.

12
 #include "cosniwa.h"

Furthermore, linker must be called with `-lcosniwa` flag, to include Cosniwa static library.

2.1.2 Time consuming function

C++ examples 1, 2, 3A, 3B and 4 use the following ‘add()’ function which adds two positive integer numbers in a very unoptimised way.

Function ‘add()’ in C++:

15
16
17
18
19
20
21
22
23
24
25
 int add(int iA, int iB)
 {
 /*
  *  Add iA + iB in a slow way.
  */
     for(int i=0; i < iB; i++)
     {
         iA = iA + 1;
     }
     return iA;
 }

2.1.3 Setting up the stopwatch

Cosniwa, as its name denotes, is a stopwatch for code snippets.

In this example, a single line calling ‘add()’ function is the code snippet to be timed (line 34). Function call_start() starts the stopwatch, call_stop() stops it.

Both functions call_start() and call_stop() have the same argument: in this case ‘1’. It is a ‘registration number’ (‘rego’) of the code snippet. Rego can be any positive number, except zero.

Finally, function resultsc() prints to the console the results of timing.

28
29
30
31
32
33
34
35
36
37
38
39
 int main()
 {
     // Create Cosniwa object
     Cosniwa csw = Cosniwa();

     csw.call_start(1);   // Start code snippet
     add(1, 100000);
     csw.call_stop(1);    // Stop code snippet

     // Print the results
     csw.resultc();
 }

2.1.4 Let’s time!

Warning

All the examples in this tutorial were run on MacBook Pro (late 2016) with 2GHz Intel Core i5. On your computer timing results may vary!

Ok, let’s run example1 and see the results:

For C++ (in c++/examples/):

$ make example1
$ ./example1

results for C++:

_images/example1cpp.png

Let’s go through the results column by column.

1. The first column (#1) holds an order number of a code snippet. In this example there is only one code snippet, which has a ‘#1’ in the first column. Please note that Cosniwa orders code snippets by the total execution time.

2. The second column (rego: 1) holds a registration number (‘rego’) given to a code snippet.

3. The third column is empty in this example. It holds a label given to a code snippet. Look at example3 (‘Code registration’) below for more info about labeling.

4. The fourth column ([calls: 1]) holds the number of calls of a code snippet. In the current example the code was called only once.

5. Finally, the fifth column (0.204 ms) holds the total execution time of a code snippet.

2.2. C++ example2: Two code snippets

Note

Example2 is available on github.com: example2 for C++.

2.2.1 Adding a second code snippet

In this example ‘add()’ function is called one hundred times in a loop. The ‘add()’ function inside the loop is a code snippet with registration ‘1’.

The whole loop is a code snippet with registration ‘2’.

Cosniwa timer for the loop is started in line 33 and stopped in line 40.

28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
 int main()
 {
     // Create Cosniwa object
     Cosniwa csw = Cosniwa();

     csw.call_start(2);   // Start code snippet (loop)
     for (int inxAdd = 0 ; inxAdd < 100 ; inxAdd++)
     {
         csw.call_start(1);   // Start code snippet (add)
         add(1, 100000);
         csw.call_stop(1);    // Stop code snippet (add)
     }
     csw.call_stop(2);  // Stop code snippet (loop)

     // Print the results
     csw.resultc();
 }

2.2.2 Let’s time!

Ok, let’s run example2:

For C++ (in c++/examples/):

$ make example2
$ ./example2

Cosniwa’s output from this example contains more data than previously.

Results for C++:

_images/example2cpp.png

The first line corresponds to the loop (rego 2).

The second line corresponds to the function ‘add()’ called inside the loop, let’s go through this line column by column.

1. The first column (#2) is an order number of a code snippet.

2. The second column (rego: 1) is a registration number of a code snippet.

3. The third column is empty in this example. It holds labels given to code snippets. Look at example 3 (Code registration) for details.

4. The fourth column ([calls: 100]) holds the number of calls of a code snippet. The ‘add’ function was called one hundred times within the loop.

5. The fifth column (19.010 [ms]) holds the total execution time of a code snippet. The total execution time of one hundred calls of function ‘add()’ is 19.010 ms in C++.

  1. The sixth column (0.190 [ms]) holds the average execution time of a code snippet.
  2. The seventh column (C++: 0.835 [ms]) holds the variance of execution times.

8. The last, eigth column (0.162 / 0.314 [ms]) holds the minimum and the maximum execution time of a code snippet.

The columns 6th - 8th are printed only for code snippets which are called more than once.

2.3. C++ example3: Code registration

2.3.1 Example3A: Static labeling of code snippets

Note

Example3A is available on github.com: example3A for C++.

Registering time snippets using arbitrarily chosen number may not be convenient, especially if there are many code snippets to be timed. Cosniwa provides function reg_code() which can be used to label a code snippet and automatically assign a registration number.

Look at the examples below. Two code snippets are registered using reg_code() function (lines 34 and 35).

28
29
30
31
32
33
34
35
 int main()
 {
     // Create Cosniwa object
     Cosniwa csw = Cosniwa();

     // Register code snippets
     unsigned int iRego1 = csw.reg_code("add");
     unsigned int iRego2 = csw.reg_code("100 x add");

The returned values (iRego1, iRego2) are then used in functions call_start() and call_stop().

37
38
39
40
41
42
43
44
     csw.call_start(iRego2);   // Start code snippet (loop)
     for (int inxAdd = 0 ; inxAdd < 100 ; inxAdd++)
     {
         csw.call_start(iRego1);   // Start code snippet (add)
         add(1, 100000);
         csw.call_stop(iRego1);    // Stop code snippet (add)
     }
     csw.call_stop(iRego2);  // Stop code snippet (loop)

2.3.2 Let’s time!

Let’s run example3A.

For C++ (in c++/examples/) run:

$ make example3A
$ ./example3A

Cosniwa’s outputs in this example are similiar to results from the previous example.

Results for C++:

_images/example3Acpp.png

The main difference is the third column. It contains labels (“100 x add”, “add”) given to the code.

2.3.3 Example3B: Dynamic labeling of code snippets

Note

Example3B is available on github.com: example3B for C++.

It is possible to use reg_code() directly in functions call_start() and call_stop() as in the examples below:

28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
 int main()
 {
     // Create Cosniwa object
     Cosniwa csw = Cosniwa();

     csw.call_start(csw.reg_code("100 x add"));  // Start code snippet (loop)
     for (int inxAdd = 0 ; inxAdd < 100 ; inxAdd++)
     {
         csw.call_start(csw.reg_code("add"));    // Start code snippet (add)
         add(1, 100000);
         csw.call_stop(csw.reg_code("add"));     // Stop code snippet (add)
     }
     csw.call_stop(csw.reg_code("100 x add"));   // Stop code snippet (loop)

     // Print the results
     csw.resultc();
 }

Let’s run example 3B.

For C++ (in c++/examples/) run:

$ make example3B
$ ./example3B

Results for C++:

_images/example3Bcpp.png

The results are similar to the previous example, however, the timing results will be affected a bit by function reg_code() which is called before calling call_stop() function.

Note

In Cosniwa 1.1 this disadvantage will be removed, and dynamic labeling will have no effect on timing.

2.4. C++ example4: Add main time

Note

Example4 is available on github.com: example4 for C++.

Cosniwa provides two functions start() and stop() which can be used to start and stop the main timer in Cosniwa.

Take a look at the examples below. Four code snippets are registered:

33
34
35
36
37
 // Register the code snippets
 unsigned int iRego1 = csw.reg_code("add(1, 100000)");
 unsigned int iRego2 = csw.reg_code("100 x add(1, 100000)");
 unsigned int iRego3 = csw.reg_code("add(1, 10000)");
 unsigned int iRego4 = csw.reg_code("100 x add(1, 10000)");

Two loops are timed in the example below.

Before the loops the start() function is called (line 40), after the loops the stop() function is called (line 61).

Code between these function is called ‘main code’.

39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
 // Start the main CoSniWa time
 csw.start();

 csw.call_start(iRego2);   // Start loop 100 x add(1, 100000)
 for (int inxAdd = 0 ; inxAdd < 100 ; inxAdd++)
 {
     csw.call_start(iRego1);   // Start code snippet (add(1, 100000))
     add(1, 100000);
     csw.call_stop(iRego1);    // Stop code snippet (add(1, 100000))
 }
 csw.call_stop(iRego2);   // Stop loop 100 x add(1, 100000)

 csw.call_start(iRego4);   // Start loop 100 x add(1, 10000)
 for (int inxAdd = 0 ; inxAdd < 100 ; inxAdd++)
 {
     csw.call_start(iRego3);   // Start code snippet (add(1, 10000))
     add(1, 10000);
     csw.call_stop(iRego3);    // Stop code snippet (add(1, 10000))
 }
 csw.call_stop(iRego4);  // Stop loop 100 x add(1, 10000)

 // Stop the main CoSniWa time
 csw.stop();

Hence to these functions, more data is added to Cosniwa’s output.

Let’s run example 4.

For C++ run (in c++/examples/):

$ make example4
$ ./example4

Results for C++:

_images/example4cpp.png

The first visible difference comparing to the previous examples is the ‘Total measured time’ printed just after Cosniwa’s header. It gives the time measured between start() and stop() functions, which is called ‘main time’.

Furthermore, there are two new columns int the Cosniwa’s output. The columns are between the total execution time and average execution time (marked with a green rectangle).

The first new column is the column with percentage (%) at the end of the number. It compares the total execution time of a code snippet with the main time. For example, loop which calls ‘add(1, 100000)’ function takes 92.16 % of the main time (21.014 ms) in C++.

The second column which was not present in the previous examples is the column which starts with ‘MPA’. The three letters acronym ‘MPA’ means ‘maximum possible acceleration’.

Value in this column gives information about how much execution of main code would be accelerated if a code snippet corresponding to the column would be executed in no time.

2.5. C++ example5: Using Cosniwa with classes

2.5.1 Example 5A: Let’s time ten code snippets

Note

Example5A is available on github.com: example5A for C++.

Cosniwa is a tool dedicated for profiling multi-object and multi-language code. This example shows how to use Cosniwa with objects.

To use Cosniwa in C++, a Cosniwa object must be created:

110
111
     // Create Cosniwa object
     Cosniwa csw = Cosniwa();

Then a handle (address) of Cosniwa object can be propagated to other objects which use Cosniwa.

In the current example (example5A) a ‘Fibonacci’ class is used. It is a class which computes n-th element of the Fibonacci sequence.

Constructor of the class is below:

36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
 Fibonacci::Fibonacci(int iIndex_, Cosniwa* csw_)
 {
 /*
  *  CONSTRUCTOR.
  *
  *  Parameters:
  *   iIndex_:  [int]       Index of a class
  *   csw_:     [Cosniwa*]  Pointer to Cosniwa object
  *
  */

     // Store the index of the class and the pointer to Cosniwa
     iIndex = iIndex_;
     csw = csw_;

     // Create a class name
     std::stringstream streamIndex;
     streamIndex << iIndex_;
     strName = "Fibonacci #" + streamIndex.str();

     // Regsiter the class in Cosniwa
     iCSWRego = csw->reg_code(strName);
 }

There are are two arguments which must be given to a created ‘Fibonacci’ object: index of a new object and a handle to Cosniwa object. Index of a new ‘Fibonacci’ object is used to create a name of the object, which is further used to register the object in Cosniwa.

The newly generated object stores these arguments (lines 48, 49), generates a new object name (lines 52-54), and registers itself in Cosniwa (line 57).

Cosniwa is used by ‘Fibonacci’ class in ‘run()’ function which computes n-th element of the Fibonacci sequence:

 61
 62
 63
 64
 65
 66
 67
 68
 69
 70
 71
 72
 73
 74
 75
 76
 77
 78
 79
 80
 81
 82
 83
 84
 85
 86
 87
 88
 89
 90
 91
 92
 93
 94
 95
 96
 97
 98
 99
100
101
102
103
104
105
 long unsigned int Fibonacci::run(unsigned int iNLen)
 {
 /*
  *  run:  COMPUTE THE n-TH ELEMENT OF THE FIBONACCI SEQUENCE.
  *
  *  Function computes the n-th element of the Fibonacci sequence by
  *  iterating through all the sequence until n-th elements.
  *  It is preassumed that the 1st (index 0) and the 2nd (index 1) elements of
  *  the sequence equal 1.
  *
  *  Parameters:
  *   iNLen:  [unsigned int]  Index of the element to be computed
  *
  *  Returns:
  *   iFibo:  [long unsigned int]  n-th element of the Fibonacci sequence
  *
  */

     long unsigned int iFibo = 1;
     long unsigned int iFiboPrev = 1;
     long unsigned int iFiboPrevPrev = 1;

     // Start the Cosniwa stopwatch
     csw->call_start(iCSWRego);

     // 1st and 2nd element equals 1
     if (iNLen < 2)
     {
         return 1;
     }

     // Loop unitl n-th elements
     for (int inxFib=0 ; inxFib < (iNLen - 2) ; inxFib++)
     {
         iFiboPrevPrev = iFiboPrev;
         iFiboPrev = iFibo;

         iFibo = iFiboPrev + iFiboPrevPrev;
     }

     // Stop the Cosniwa stopwatch
     csw->call_stop(iCSWRego);

     return iFibo;
 }

Below is the ‘main()’ function:

108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
 int main()
 {
     // Create Cosniwa object
     Cosniwa csw = Cosniwa();

     // Start the main CoSniWa time
     csw.start();

     // Define 10 Fibonacci classes with indices from 0 to 9
     Fibonacci f0(0, &csw);
     Fibonacci f1(1, &csw);
     Fibonacci f2(2, &csw);
     Fibonacci f3(3, &csw);
     Fibonacci f4(4, &csw);
     Fibonacci f5(5, &csw);
     Fibonacci f6(6, &csw);
     Fibonacci f7(7, &csw);
     Fibonacci f8(8, &csw);
     Fibonacci f9(9, &csw);

     // Compute Fibonacci sequences with different number of elements
     f0.run(100000);
     f1.run(90000);
     f2.run(80000);
     f3.run(70000);
     f4.run(60000);
     f5.run(50000);
     f6.run(40000);
     f7.run(30000);
     f8.run(20000);
     f9.run(1000);

     // Stop the main CoSniWa time
     csw.stop();

     // Print out the timing results
     csw.resultc();
 }

If you are familiar with C++, and studied previous examples, this function do not require a lot of explanation.

Ten Fibonacci objects are created with different indices (lines 117 - 126).

Then, run() function is called for all the objects, (lines 129 - 138) with different argument (requested element of the Fibonacci sequence).

Please note that the main time is also timed (lines 114, 141).

Let’s run this example and see the results.

For C++ (in c++/examples/) run:

$ make example5A
$ ./example5A

Results for C++:

_images/example5Acpp.png

The above results are as expected. Every object was registered as a separated code snippet, so in the above timing results there are ten different code snippets timed.

2.5.2 Example 5B: Let’s time classes together

Note

Example5B is available on github.com: example5B for C++.

This example differs a bit from the previous one. All the objects are registered in Cosniwa with the same name, because index of ‘Fibonacci’ object is not added to the name of the object.

Part of the code which is different than in the previous example (example5A) is below:

51
52
53
54
55
     // Create a class name
     strName = "Fibonacci";

     // Regsiter the class in Cosniwa
     iCSWRego = csw->reg_code(strName);

Let’s run this example and see the results.

For C++ (in c++/examples/) run:

$ make example5B
$ ./example5B

Results for C++:

_images/example5Bcpp.png

Since all the objects were registered with the same label, all the ‘run()’ functions are treated as one code snippet. Therefore, there is only one code snippet in the timing results.

2.6. C++ case1: Test ‘usleep()’ function using Cosniwa

Note

Case1 is available on github.com: case1 for C++.

In this case Cosniwa is used to test ‘usleep()’ function which is suppose to sleep for a certain amount of time.

To test the ‘usleep()’ function run (in c++/examples/):

$ make case1
$ ./case1

Results for C++:

_images/case1cpp.png

It can be seen from the results above that the sleeping function is not very precise.

Sleeping time is always longer than requested. However, it can be observed that relative error between the requested sleeping time and real sleeping time is lower for longer requested sleeping times.

2.7. C++ functions

2.7.1. C++ Cosniwa constructors

Cosniwa ()

CONSTRUCTOR (v1). Use default maximum number of intervals.

Cosniwa (unsigned int iMaxNCalls)

CONSTRUCTOR (v2). Set maximum number of intervals.

PARAMETERS:
iMaxNCalls: [unsigned int] The maximum number of intervals.

2.7.2. C++ code snippet registration functions

unsigned int reg_code (std::string strLabel, unsigned int iRego)

REGISTER CODE SNIPPET (v1A).

Function registers new code snippet label (strLabel) in the snippets database.

Function registers the label with a requested registration number (iRego).

If label already exists with a different registration number, function returns NULL.

Function returns iRego in case of no errors.

PARAMETERS:
strLabel: [std::string] Label for the code snippet.
iRego: [unsigned int] Requested registration number of the code snippet.
RETURN:
[unsigned int] Registration number of the code snippet. It is equal to parameter iRego if there are no errors.

unsigned int reg_code (const char* csLabel, unsigned int iRego)

REGISTER CODE SNIPPET (v1B).

Function registers new code snippet label (csLabel) in the snippets database.

Function registers the label with a requested registration number (iRego).

If label already exists with a different registration, function returns NULL.

Function returns iRego in case of no errors.

PARAMETERS:
csLabel: [const char*] Label for the code snippet.
iRego: [unsigned int] Requested registration number of the code snippet.
RETURN:
[unsigned int] Registration number of the code snippet. It is equal to parameter iRego if there are no errors.

unsigned int reg_code (char* csLabel, unsigned int iRego)

REGISTER CODE SNIPPET (v1C).

Function registers new code snippet label (csLabel) in the snippets database.

Function registers the label with a requested registration number (iRego).

If label already exists with a different registration, function returns NULL.

Function returns iRego in case of no errors.

PARAMETERS:
csLabel: [char*] Label for the code snippet.
iRego: [unsigned int] Requested registration number of the code snippet.
RETURN:
[unsigned int] Registration number of the code snippet. It is equal to parameter iRego if there are no errors.

unsigned int reg_code (std::string strLabel)

REGISTER CODE SNIPPET (v2A).

Function registers new code snippet label (strLabel) in the snippets database.

Function returns registration number iRego given to the code snippet label.

PARAMETERS:
strLabel: [std::string] Label for the code snippet.
RETURN:
[unsigned int] Registration number of the code snippet.

unsigned int reg_code (const char* csLabel)

REGISTER CODE SNIPPET (v2B).

Function registers new code snippet label (csLabel) in the snippets database.

Function returns registration number iRego given to the code snippet label.

PARAMETERS:
csLabel: [const char] Label for the code snippet.
RETURN:
[unsigned int] Registration number of the code snippet.

unsigned int reg_code (char* csLabel)

REGISTER CODE SNIPPET (v2C).

Function registers new code snippet label (csLabel) in the snippets database.

Function returns registration number iRego given to the code snippet label.

PARAMETERS:
csLabel: [char*] Label for the code snippet.
RETURN:
[unsigned int] Registration number of the code snippet.

2.7.3. C++ stoper start/stop functions

void reset ()

RESET COSNIWA OBJECT.

void start ()

START THE MAIN TIME.

void stop ()

STOP THE MAIN TIME.

void call_start (unsigned int iRego)

START A CODE SNIPPET CALL.

PARAMETERS:
iRego: [unsigned int] Registration number of a code snippet.

void call_stop (unsigned int iRego)

STOP A CODE SNIPPET CALL.

PARAMETERS:
iRego: [unsigned int] Registration number of a code snippet.

2.7.4. C++ timing results functions

std::string result ()

GET TIMING RESULTS.

RETURN:
[std::string] String with timing results.

void resultc ()

PRINT TIMING RESULTS TO THE CONSOLE OUTPUT.

std::string result ()

GET TIMING RESULTS (SHORT VERSION).

RETURN:
[std::string] String with timing results (short version).

void resultc_short ()

PRINT TIMING RESULTS (SHORT VERSION) TO THE CONSOLE OUTPUT.

3. Cosniwa Tutorial for Python 3

Here is a little tutorial about using Cosniwa with Python 3.

Warning

Cosniwa will NOT work with Python 2.

Warning

Cosniwa for Python 3 uses modules written in C++ and Python-to-C++ interface provieded by CPython interpreter (default Python interpreter on most of systems). Cosniwa will not work with PyPy, Jython, IronPython, etc.

Cosniwa Python examples can be found on github.com.

The list of topics in the tutorial is as follows:

3.0. Installing Cosniwa for Python

In the main Cosniwa directory run as root:

# make install_py

The installation script will compile Cosniwa Python module and install it in your system.

3.1. Python example1: Simplest example

Note

Example1 is available on github.com: example1 for Python.

This is the simplest example of using Cosniwa to time code.

3.1.1 First things first

Cosniwa for Python3 is written in C++, so the Python module is called ‘cCosniwa’:

13
 import cCosniwa as csw

All the Python examples below import Cosniwa in the same way (as ‘csw’).

3.1.2 Time consuming function

Python examples 1, 2, 3A, 3B and 4 use the following ‘add()’ function which adds two positive integer numbers in a very unoptimised way.

Function ‘add()’ in Python:

18
19
20
21
22
23
 def add(iA, iB):
     """
     Add iA + iB in a slow way.
     """
     for i in range(iB):
         iA = iA + 1

3.1.3 Setting up the stopwatch

Cosniwa, as its name denotes, is a stopwatch for code snippets.

In this example, a single line calling ‘add()’ function is the code snippet to be timed (line 22). Function call_start() starts the stopwatch, call_stop() stops it.

Both functions call_start() and call_stop() have the same argument: in this case ‘1’. It is a ‘registration number’ (‘rego’) of the code snippet. Rego can be any positive number, except zero.

Finally, function resultsc() prints to the console the results of timing.

19
20
21
22
23
24
25
26
 def main():

     csw.call_start(1)  # Start code snippet
     add(1, 100000)
     csw.call_stop(1)   # Stop code snippet

     # Print the results
     csw.resultc()

3.1.4 Let’s time!

Warning

All the examples in this tutorial were run on MacBook Pro (late 2016) with 2GHz Intel Core i5. On your computer timing results may vary!

Ok, let’s run example1 and see the results:

For Python run (in python/examples/):

$ python3 example1.py

Results for Python:

_images/example1py.png

Let’s go through the results column by column.

1. The first column (#1) holds an order number of a code snippet. In this example there is only one code snippet, which has a ‘#1’ in the first column. Please note that Cosniwa orders code snippets by the total execution time.

2. The second column (rego: 1) holds a registration number (‘rego’) given to a code snippet.

3. The third column is empty in this example. It holds a label given to a code snippet. Look at example3 (‘Code registration’) below for more info about labeling.

4. The fourth column ([calls: 1]) holds the number of calls of a code snippet. In the current example the code was called only once.

5. Finally, the fifth column (6.342 ms) holds the total execution time of a code snippet.

3.2. Python example2: Two code snippets

Note

Example2 is available on github.com: example2 for Python.

3.2.1 Adding a second code snippet

In this example ‘add()’ function is called one hundred times in a loop. The ‘add()’ function inside the loop is a code snippet with registration ‘1’.

The whole loop is a code snippet with registration ‘2’.

Cosniwa timer for the loop is started in line 28 and stopped in line 33.

26
27
28
29
30
31
32
33
34
35
36
 def main():

     csw.call_start(2)   # Start code snippet (loop)
     for inxAdd in range(100):
         csw.call_start(1)    # Start code snippet (add)
         add(1, 100000)
         csw.call_stop(1)     # Stop code snippet (add)
     csw.call_stop(2)   # Stop code snippet (loop)

     # Print the results
     csw.resultc()

3.2.2 Let’s time!

Ok, let’s run example2:

For Python run (in python/examples/):

$ python3 example2.py

Cosniwa’s output from this example contains more data than previously.

Results for Python:

_images/example2py.png

The first line corresponds to the loop (rego 2).

The second line corresponds to the function ‘add()’ called inside the loop, let’s go through this line column by column.

1. The first column (#2) is an order number of a code snippet.

2. The second column (rego: 1) is a registration number of a code snippet.

3. The third column is empty in this example. It holds labels given to code snippets. Look at example 3 (Code registration) for details.

4. The fourth column ([calls: 100]) holds the number of calls of a code snippet. The ‘add’ function was called one hundred times within the loop.

5. The fifth column (672.682 [ms]) holds the total execution time of a code snippet. The total execution time of one hundred calls of function ‘add()’ is 672.682 ms.

  1. The sixth column (6.727 [ms]) holds the average execution time of a code snippet.

7. The seventh column (328.237 [ms]) holds the variance of execution times.

8. The last, eigth column (5.905 / 8.269 [ms]) holds the minimum and the maximum execution time of a code snippet.

The columns 6th - 8th are printed only for code snippets which are called more than once.

3.3. Python example3: Code registration

Note

Example3A is available on github.com: example3A for Python.

3.3.1 Example3A: Static labeling of code snippets

Registering time snippets using arbitrarily chosen number may not be convenient, especially if there are many code snippets to be timed. Cosniwa provides function reg_code() which can be used to label a code snippet and automatically assign a registration number.

Look at the examples below. Two code snippets are registered using reg_code() function (lines 29 and 30).

26
27
28
29
30
 def main():

     # Register the code snippets
     iRego1 = csw.reg_code("add")
     iRego2 = csw.reg_code("100 x add")

The returned values (iRego1, iRego2) are then used in functions call_start() and call_stop().

32
33
34
35
36
37
38
39
40
 csw.call_start(iRego2)    # Start code snippet (loop)
 for inxAdd in range(100):
     csw.call_start(iRego1)    # Start code snippet (add)
     add(1, 100000)
     csw.call_stop(iRego1)     # Stop code snippet (add)
 csw.call_stop(iRego2)    # Stop code snippet (loop)

 # Print the results
 csw.resultc()

3.3.2 Let’s time!

Let’s run example3A.

For Python run (in python/examples/):

$ python3 example3A.py

Cosniwa’s outputs in this example are similiar to results from the previous example.

Timing results for Python:

_images/example3Apy.png

The main difference is the third column. It contains labels (“100 x add”, “add”) given to the code.

3.3.3 Example3B: Dynamic labeling of code snippets

Note

Example3B is available on github.com: example3B for Python.

It is possible to use reg_code() directly in functions call_start() and call_stop() as in the examples below:

26
27
28
29
30
31
32
33
34
35
36
 def main():

     csw.call_start(csw.reg_code("100 x add"))  # Start code snippet (loop)
     for inxAdd in range(100):
         csw.call_start(csw.reg_code("add"))    # Start code snippet (add)
         add(1, 100000)
         csw.call_stop(csw.reg_code("add"))     # Stop code snippet (add)
     csw.call_stop(csw.reg_code("100 x add"))   # Stop code snippet (loop)

     # Print the results
     csw.resultc()

Let’s run example 3B.

For Python run (in python/examples/):

$ python3 example3B.py

Results for Python:

_images/example3Bpy.png

The results are similar to the previous example, however, the timing results will be affected a bit by function reg_code() which is called before calling call_stop() function.

Note

In Cosniwa 1.1 this disadvantage will be removed, and dynamic labeling will have no effect on timing.

3.4. Python example4: Add main time

Note

Example4 is available on github.com: example4 for Python.

Cosniwa provides two functions start() and stop() which can be used to start and stop the main timer in Cosniwa.

Take a look at the examples below. Four code snippets are registered:

29
30
31
32
33
 # Register the code snippets
 iRego1 = csw.reg_code("add(1, 100000)")
 iRego2 = csw.reg_code("100 x add(1, 100000)")
 iRego3 = csw.reg_code("add(1, 10000)")
 iRego4 = csw.reg_code("100 x add(1, 10000)")

Two loops are timed in the example below.

Before the loops the start() function is called (line 36), after the loops the stop() function is called (line 53).

Code between these function is called ‘main code’.

35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
 # Start the main CoSniWa time
 csw.start()

 csw.call_start(iRego2)   # Start loop 100 x add(1, 100000)
 for inxAdd in range(100):
     csw.call_start(iRego1)   # Start code snippet (add(1, 100000))
     add(1, 100000)
     csw.call_stop(iRego1)    # Stop code snippet (add(1, 100000))
 csw.call_stop(iRego2)  # Stop loop 100 x add(1, 100000)

 csw.call_start(iRego4)   # Start loop 100 x add(1, 10000)
 for inxAdd in range(100):
     csw.call_start(iRego3)   # Start code snippet (add(1, 10000))
     add(1, 10000)
     csw.call_stop(iRego3)    # Stop code snippet (add(1, 10000))
 csw.call_stop(iRego4)  # Stop loop 100 x add(1, 10000)

 # Stop the main CoSniWa time
 csw.stop()

Hence to these functions, more data is added to Cosniwa’s output.

Let’s run example 4.

For Python run (in python/examples/):

$ python3 example4.py

Results for Python:

_images/example4py.png

The first visible difference comparing to the previous examples is the ‘Total measured time’ printed just after Cosniwa’s header. It gives the time measured between start() and stop() functions, which is called ‘main time’.

Furthermore, there are two new columns in the Cosniwa’s output. The columns are between the total execution time and average execution time (marked with a green rectangle).

The first new column is the column with percentage (%) at the end of the number. It compares the total execution time of a code snippet with the main time. For example, loop which calls ‘add(1, 100000)’ function takes 90.81% of the main time (719.206 ms).

The second column which was not present in the previous examples is the column which starts with ‘MPA’. The three letters acronym ‘MPA’ means ‘maximum possible acceleration’.

Value in this column gives information about how much execution of main code would be accelerated if a code snippet corresponding to the column would be executed in no time.

3.5. Python example5: Using Cosniwa with classes

3.5.1 Example 5A: Let’s time ten code snippets

Note

Example5A is available on github.com: example5A for Python.

Cosniwa is a tool dedicated to profiling multi-object and multi-language code. This example shows how to use Cosniwa with objects.

In In Python Cosniwa’s functions are used directly from the module. So to give a handle of Cosniwa to other objects the handle must be obtained.

Function get_handle() returns a handle to Cosniwa:

83
84
85
86
 def main():

     # Get handle to Cosniwa module
     hCsw = csw.get_handle()

In the current example (example5A) a ‘Fibonacci’ class is used. It is a class which computes n-th element of the Fibonacci sequence.

Initialisation method of the class is below:

18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
 class Fibonacci():
     """
     'Fibonacci': Class which computes n-th element
                  of the Fibonacci sequence.
     """

     def __init__(self, iIndex_, Cosniwa_):
         """
         INITIALISATION METHOD.

         Arguments:
           iIndex_:   [int]             Index of a class
           Cosniwa_:  [Cosniwa handle]  Handle to Cosniwa object

         """

         # Store the index of the class and the handle to Cosniwa
         self.iIndex = iIndex_
         self.hCsw = Cosniwa_

         # Create a class name
         self.strName = 'Fibonacci #%d' % self.iIndex

         # Register the class in Cosniwa
         self.iCswReg = csw.xreg_code(self.hCsw, self.strName)

There are are two arguments which must be given to a created ‘Fibonacci’ object: index of a new object and a handle to Cosniwa object. Index of a new ‘Fibonacci’ object is used to create a name of the object, which is further used to register the object in Cosniwa.

The newly generated object stores these two arguments (lines 35, 36), generates a new object name (line 39), and registers itself in Cosniwa (line 42).

Cosniwa is used by ‘Fibonacci’ class in ‘run()’ function which computes n-th element of the Fibonacci sequence:

44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
 def run(self, iNEl):
     """
     run:  COMPUTE THE n-TH ELEMENT OF THE FIBONACCI SEQUENCE.

      Function computes the n-th element of the Fibonacci sequence by
      iterating through all the sequence until n-th element.
      It is preassumed that the 1st (index 0) and the 2nd (index 1)
      elements of the sequence equal 1.

       Arguments:
         iNLen:  [int]  Index of the element to be computed

       Returns:
         iFibo:  [int]  n-th element of the Fibonacci sequence
     """

     iFibo = 1
     iFiboPrev = 1
     iFiboPrevPrev = 1

     # Start the Cosniwa stopwatch
     csw.xcall_start(self.hCsw, self.iCswReg)

     # 1st and 2nd element equals 1
     if (iNEl < 2):
         return 1

     # Loop unitl n-th element
     for inxFib in range(iNEl - 2):
         iFiboPrevPrev = iFiboPrev
         iFiboPrev = iFibo
         iFibo = iFiboPrev + iFiboPrevPrev

     # Stop the Cosniwa stopwatch
     csw.xcall_stop(self.hCsw, self.iCswReg)

     return iFibo

In Python, functions xcall_start() and xcall_stop() are used (lines 65, 78). These functions are provided by Cosniwa module (cCosniwa), letter ‘x’ at the beginning comes from ‘eXternal’.

Purpose of functions xcall_start() and xcall_stop() is to run call_start() and call_stop() with external Cosniwa using a handle. The first argument is a handle to an external Cosniwa.

There are more ‘x’ functions provided by Python Cosniwa module (cCosniwa). First argument of all these functions is a handle to an external Cosniwa. Take a look at List of functions below for more details.

Below is the ‘main()’ functions of the example:

 83
 84
 85
 86
 87
 88
 89
 90
 91
 92
 93
 94
 95
 96
 97
 98
 99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
 def main():

     # Get handle to Cosniwa module
     hCsw = csw.get_handle()

     # Start the main CoSniWa time
     csw.start()

     # Generate 10 Fibonacci classes
     f0 = Fibonacci(0, hCsw)
     f1 = Fibonacci(1, hCsw)
     f2 = Fibonacci(2, hCsw)
     f3 = Fibonacci(3, hCsw)
     f4 = Fibonacci(4, hCsw)
     f5 = Fibonacci(5, hCsw)
     f6 = Fibonacci(6, hCsw)
     f7 = Fibonacci(7, hCsw)
     f8 = Fibonacci(8, hCsw)
     f9 = Fibonacci(9, hCsw)

     # Compute Fibonacci sequences with different number of elements
     f0.run(100000)
     f1.run(90000)
     f2.run(80000)
     f3.run(70000)
     f4.run(60000)
     f5.run(50000)
     f6.run(40000)
     f7.run(30000)
     f8.run(20000)
     f9.run(1000)

     # Stop the main CoSniWa time
     csw.stop()

     # Print out the timing results
     csw.resultc()

If you are familiar with Python these functions do not require a lot of explanation.

Ten Fibonacci objects are created with different indices (lines 92 - 101).

Then, run() function is called for all the objects, (lines 104 - 113) with different argument (requested element of the Fibonacci sequence).

Please note that the main time is also timed (lines 89, 116).

Let’s run this example and see the results.

For Python run (in python/examples/):

$ python3 example5A.py

Results for Python:

_images/example5Apy.png

The above results are as expected. Every object was registered as a separated code snippet, so in the above timing results there are ten different code snippets timed.

3.5.2 Example 5B: Let’s time classes together

Note

Example5B is available on github.com: example5B for Python.

This example differs a bit from the previous one. All the objects are registered in Cosniwa with the same name, because index of ‘Fibonacci’ object is not added to the name of the object.

Part of the code which is different than in the previous example (example5A) is below:

38
39
40
41
42
     # Create a class name
     self.strName = 'Fibonacci'

     # Register the class in Cosniwa
     self.iCswReg = csw.xreg_code(self.hCsw, self.strName)

Let’s run this example and see the results.

For Python run (in python/examples/):

$ python3 example5B.py

Results for Python:

_images/example5Bpy.png

Since all the objects were registered with the same label, all the ‘run()’ functions are treated as one code snippet. Therefore, there is only one code snippet in the timing results.

3.6. Python case1: Test ‘time.sleep()’ function using Cosniwa

Note

Case1 is available on github.com: case1 for Python.

In the current case Cosniwa is used to time ‘time.sleep()’ function which is suppose to sleep for a certain amount of time.

To test the ‘time.sleep()’ function run (in python/examples/):

$ python3 case1.py

Results for Python:

_images/case1py.png

It can be seen from the results above that the sleeping functions are not very precise.

Sleeping time is always longer than requested. However, it can be observed that relative error between the requested sleeping time and real sleeping time is lower for longer requested sleeping times.

3.7. Python functions

3.7.1. Python code snippet registration functions

reg_code_with_rego (string strLabel, int iRego)

REGISTER CODE SNIPPET (v1).

Function registers new code snippet label (strLabel) in the snippets database.

Function registers the label with a requested registration number (iRego).

If label already exists with a different registration number, function returns 0.

Function returns number iRego in case of no errors.

ARGUMENTS:
strLabel: [string] Label for the code snippet.
iRego: [int] Requested registration number of the code snippet.
RETURN:
[int] Registration number of the code snippet.It is equal to argument iRego if there are no errors.

reg_code (string strLabel)

REGISTER CODE SNIPPET (v2).

Function registers new code snippet label (strLabel) in the snippets database. Function returns registration number iRego given to the code snippet label.

ARGUMENTS:
strLabel: [string] Label for the code snippet.
RETURN:
[int] Registration number of the code snippet.

xreg_code_with_rego (cosniwahandle hCosniwa, string strLabel, int iRego)

REGISTER CODE SNIPPET (v1) IN EXTERNAL COSNIWA.

Function registers new code snippet label (strLabel) in the snippets database in an external Cosniwa.

Function registers the label with a requested registration number (iRego).

If label already exists with a different registration number, function returns 0.

ARGUMENTS:
hCosniwa: [cosniwahandle] Handle to an external Cosniwa.
strLabel: [string] Label for the code snippet.
iRego: [int] Requested registration number of the code snippet.
RETURN:
[int] Registration number of the code snippet. It is equal to argument iRego if there are no errors.

xreg_code (cosniwahandle hCosniwa, string strLabel)

REGISTER CODE SNIPPET (v2) IN EXTERNAL COSNIWA.

Function registers new code snippet label (strLabel) in the snippets database in an external Cosniwa.

Function returns registration number iRego given to the code snippet label.

ARGUMENTS:
hCosniwa: [cosniwahandle] Handle to an external Cosniwa.
strLabel: [string] Label for the code snippet.
RETURN:
[int] Registration number of the code snippet.

3.7.2. Python stoper start/stop functions

reset ()

RESET COSNIWA MODULE.

Function resets Cosniwa module.

start ()

START THE MAIN TIME.

stop ()

STOP THE MAIN TIME.

call_start (int iRego)

START A CODE SNIPPET CALL.

ARGUMENTS:
iRego: [int] Registration number of a code snippet.

call_stop (int iRego)

STOP A CODE SNIPPET CALL.

ARGUMENTS:
iRego: [int] Registration number of a code snippet.

xreset (cosniwahandle hCosniwa)

RESET EXTERNAL COSNIWA MODULE.

ARGUMENTS:
hCosniwa: [cosniwahandle] Handle to an external Cosniwa.

xstart (cosniwahandle hCosniwa)

START THE MAIN TIME IN EXTERNAL COSNIWA.

ARGUMENTS:
hCosniwa: [cosniwahandle] Handle to an external Cosniwa.

xstop (cosniwahandle hCosniwa)

STOP THE MAIN TIME IN EXTERNAL COSNIWA.

ARGUMENTS:
hCosniwa: [cosniwahandle] Handle to an external Cosniwa.

xcall_start (cosniwahandle hCosniwa, int iRego)

START A CODE SNIPPET CALL IN EXTERNAL COSNIWA.

ARGUMENTS:
hCosniwa: [cosniwahandle] Handle to an external Cosniwa.
iRego: [int] Registration number of a code snippet.

xcall_stop (cosniwahandle hCosniwa, int iRego)

STOP A CODE SNIPPET CALL IN EXTERNAL COSNIWA.

ARGUMENTS:
hCosniwa: [cosniwahandle] Handle to an external Cosniwa.
iRego: [int] Registration number of a code snippet.

3.7.3. Python timing results functions

result ()

GET TIMING RESULTS.

RETURN:
[string] String with timing results.

resultc ()

PRINT TIMING RESULTS TO THE CONSOLE OUTPUT.

result_short ()

GET TIMING RESULTS (SHORT VERSION).

RETURN:
[string] String with timing results (short version).

resultc_short ()

PRINT TIMING RESULTS (SHORT VERSION) TO THE CONSOLE OUTPUT.

xresult (cosniwahandle hCosniwa)

GET TIMING RESULTS FROM EXTERNAL COSNIWA.

ARGUMENTS:
hCosniwa: [cosniwahandle] Handle to an external Cosniwa.
RETURN:
[string] String with timing results (short version).

xresultc (cosniwahandle hCosniwa)

PRINT TIMING RESULTS FROM EXTERNAL COSNIWA TO THE CONSOLE OUTPUT.

ARGUMENTS:
hCosniwa: [cosniwahandle] Handle to an external Cosniwa.

xresult_short (cosniwahandle hCosniwa)

GET TIMING RESULTS (SHORT VERSION) FROM EXTERNAL COSNIWA.

ARGUMENTS:
hCosniwa: [cosniwahandle] Handle to an external Cosniwa.
RETURN:
[string] String with timing results (short version).

xresultc_short (cosniwahandle hCosniwa)

PRINT TIMING RESULTS (SHORT VERSION) FROM EXTERNAL COSNIWA TO THE CONSOLE OUTPUT.

ARGUMENTS:
hCosniwa: [cosniwahandle] Handle to an external Cosniwa.

3.7.4. Python external Cosniwa handle function

get_handle ()

GET HANDLE TO A COSNIWA MODULE.

RETURN:
[cosniwahandle] Handle to Cosniwa module.

4. Cosniwa Tutorial for Octave

Here is a little tutorial about using Cosniwa with Octave.

4.0. Two versions of Cosniwa for Octave

There are two version of Cosniwa of Octave: cCosniwa implemented in C++, and oCosniwa implemented in native Octave language. The first version, cCosniwa, is recommended.

Cosniwa implemented in native Octave language (oCosniwa) should be used only if there are problems with compilation and/or running C++ modules for Octave.

4.0.1 Compilation of cCosniwa for Octave

To use the recommended version of Cosniwa for Octave, an .oct file must be compiled.

In the main Cosniwa directory run:

$ make octave_cpp

The script will compile Cosniwa using mkoctfile compiler. This compiler is a part of Octave tool, which allows for compilation of C, C++ and Fortran code so that it can be used by Octave.

If compilation process ends with no errors, and there is a new file cCosniwa.oct created in octave/cpp/ directory, cCosniwa for Octave is ready to be used.

Linking error.
If during compilation linker returns an error: “cannot find -loctinterp” or “cannot find -loctave”, it means that a wrong directory with Octave library is given in compile.sh file in octave/cpp/ directory. The compile.sh file is as follows:

1
2
 OCTAVELIB="/usr/lib/octave/4.2.1"
 mkoctfile -L${OCTAVELIB} cCosniwa.cpp cosniwa4Octave.cpp

To fix the problem, please locate the directory with Octave libraries liboctave and liboctinterp in your system (usually somewhere in /usr/lib or /opt/). Then please change the first line in compile.sh so that it contains a correct directory with Octave libraries.

4.1. Octave example1 [cOctave]: Simplest example

Warning

The next four examples are concerned on using cCosniwa (C++ implemented) for Octave. Go to examples 4.5 - 4.8 for oCosniwa (native Octave implementation).

Note

Example1 is available on github.com: example1 for Octave [cOctave].

This is the simplest example of using Cosniwa to time code in Octave.

4.1.1 First things first

File with compiled Cosniwa for Octave (cCosniwa.oct) must be present in a directory with a .m file which uses Cosniwa.

4.1.2 Time consuming function

Octave examples 4.1, 4.2, 4.3 and 4.4 use the following ‘add()’ function which adds two positive integer numbers in a very unoptimised way.

Function ‘add()’ in Octave:

18
19
20
21
22
23
24
 function add(iA, iB)
 % Add iA + iB in a slow way.

     for i = 1:iB
         iA = iA + 1;
     endfor
 end

4.1.3 Setting up the stopwatch

Cosniwa, as its name denotes, is a stopwatch for code snippets.

In this example, a single line calling ‘add()’ function is the code snippet to be timed (line 21). Function call_start() starts the stopwatch, call_stop() stops it.

Both functions call_start() and call_stop() have the same argument: in this case ‘1’. It is a ‘registration number’ (‘rego’) of the code snippet. Rego can be any positive number, except zero.

Finally, function resultsc() prints to the console the results of timing.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
 %
 % example1.m [version 1.0]
 % CoSniWa:  COde SNIppet stopWAtch [Octave port] - Example 1.
 %
 %
 % CoSniWa is dedicated to profile code using time stamps.
 % Cosniwa  [Octave port - C++ implementation ] v1.0, 31 May 2017.
 %
 % read more on: www.speedupcode.com
 %
 % (c) Jacek Pierzchlewski, 2017  jacek@pierzchlewski.com
 % license: BSD-2-Clause.
 %

 function example1()

     % Initalise cosniwa
     cCosniwa('init');

     cCosniwa('call_start', 1);  % Start code snippet (add)
     add(1, 100000);
     cCosniwa('call_stop', 1);   % Stop code snippet (add)

    % Print the results
     cCosniwa('resultc');
 end


 function add(iA, iB)
 % Add iA + iB in a slow way.

     for i = 1:iB
         iA = iA + 1;
     endfor
 end

Note

Please note how Cosniwa functions are called in Octave if the compiled version (cCosniwa) is used.
            The first argument for cCosniwa module is the name of Cosniwa function (‘call_start’, ‘call_stop’, ‘resultc’, etc.).
            The next argumements are arguments for the Cosniwa function.

            e.g.: cCosniwa(‘call_start’,1) calls Cosniwa function ‘call_start’ with argument ‘1’.

4.1.4 Let’s time!

Warning

All the examples in this tutorial were run on Asus G752V laptop (mid 2016) with 2.6GHz Intel Core i7 with Gentoo Linux. On your computer timing results may vary!

Ok, let’s run example1 and see the results:

For Octave run (in octave/cpp/):

$ octave example1.m

Results for Octave:

_images/example1cm.png

Let’s go through the results column by column.

1. The first column (#1) holds an order number of a code snippet. In this example there is only one code snippet, which has a ‘#1’ in the first column. Please note that Cosniwa orders code snippets by the total execution time.

2. The second column (rego: 1) holds a registration number (‘rego’) given to a code snippet.

3. The third column is empty in this example. It holds a label given to a code snippet. Look at example3 (‘Code registration’) below for more info about labeling.

4. The fourth column ([calls: 1]) holds the number of calls of a code snippet. In the current example the code was called only once.

5. Finally, the fifth column (115.470 ms) holds the total execution time of a code snippet.

4.2. Octave example2 [cOctave]: Two code snippets

Note

Example2 is available on github.com: example2 for Octave [cOctave].

4.2.1 Adding a second code snippet

In this example ‘add()’ function is called one hundred times in a loop. The ‘add()’ function inside the loop is a code snippet with registration ‘1’.

The whole loop is a code snippet with registration ‘2’.

Cosniwa timer for the loop is started in line 20 and stopped in line 26.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
 %
 % example2.m [version 1.0]
 % CoSniWa:  COde SNIppet stopWAtch [Octave port] - Example 2.
 %
 %
 % CoSniWa is dedicated to profile code using time stamps.
 % Cosniwa  [Octave port - C++ implementation ] v1.0, 31 May 2017.
 %
 % read more on: www.speedupcode.com
 %
 % (c) Jacek Pierzchlewski, 2017  jacek@pierzchlewski.com
 % license: BSD-2-Clause.
 %

 function example2()

     % Initalise cosniwa
     cCosniwa('init');

     cCosniwa('call_start', 2);  % Start code snippet (loop)
     for inxAdd=1:100
         cCosniwa('call_start', 1);  % Start code snippet (add)
         add(1, 10000);
         cCosniwa('call_stop', 1);   % Stop code snippet (add)
     endfor
     cCosniwa('call_stop', 2);   % Stop code snippet (loop)

    % Print the results
     cCosniwa('resultc');
 end


 function add(iA, iB)
 % Add iA + iB in a slow way.

     for i = 1:iB
         iA = iA + 1;
     endfor
 end

4.2.2 Let’s time!

Ok, let’s run example2:

For Octave run (in octave/cpp/):

$ octave example2.py

Cosniwa’s output from this example contains more data than previously.

Results for Octave:

_images/example2cm.png

The first line corresponds to the loop (rego 2).

The second line corresponds to the function ‘add()’ called inside the loop, let’s go through this line column by column.

1. The first column (#2) is an order number of a code snippet.

2. The second column (rego: 1) is a registration number of a code snippet.

3. The third column is empty in this example. It holds labels given to code snippets. Look at example 3 (Code registration) for details.

4. The fourth column ([calls: 100]) holds the number of calls of a code snippet. The ‘add’ function was called one hundred times within the loop.

5. The fifth column (1138.380 [ms]) holds the total execution time of a code snippet. The total execution time of one hundred calls of function ‘add()’ is 1137.815 ms.

  1. The sixth column (11.378 [ms]) holds the average execution time of a code snippet.

7. The seventh column (3.189 [ms]) holds the variance of execution times.

8. The last, eigth column (11.259 / 11.501 [ms]) holds the minimum and the maximum execution time of a code snippet.

The columns 6th - 8th are printed only for code snippets which are called more than once.

4.3. Octave example3 [cOctave]: Code registrations

Note

Example3 is available on github.com: example3 for Octave [cOctave].

4.3.1 Example3: Static labeling of code snippets

Registering time snippets using arbitrarily chosen number may not be convenient, especially if there are many code snippets to be timed. Cosniwa provides function reg_code() which can be used to label a code snippet and automatically assign a registration number.

Look at the example below. Two code snippets are registered using reg_code() function (lines 21 and 22). The returned values (iRego1, iRego2) are then used in functions call_start() and call_stop() (lines 24, 26, 28, 30).

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
 %
 % example3.m [version 1.0]
 % CoSniWa:  COde SNIppet stopWAtch [Octave port] - Example 3.
 %
 %
 % CoSniWa is dedicated to profile code using time stamps.
 % Cosniwa  [Octave port - C++ implementation ] v1.0, 31 May 2017.
 %
 % read more on: www.speedupcode.com
 %
 % (c) Jacek Pierzchlewski, 2017  jacek@pierzchlewski.com
 % license: BSD-2-Clause.
 %

 function example3()

     % Initalise cosniwa
     cCosniwa('init');

     % Register the code snippets
     iRego1 = cCosniwa('reg_code', 'add');
     iRego2 = cCosniwa('reg_code', '100 x add');

     cCosniwa('call_start', iRego2);  % Start code snippet (loop)
     for inxAdd=1:100
         cCosniwa('call_start', iRego1);  % Start code snippet (add)
         add(1, 10000);
         cCosniwa('call_stop', iRego1);   % Stop code snippet (add)
     endfor
     cCosniwa('call_stop', iRego2);   % Stop code snippet (loop)

    % Print the results
     cCosniwa('resultc');
 end


 function add(iA, iB)
 % Add iA + iB in a slow way.

     for i = 1:iB
         iA = iA + 1;
     endfor
 end

4.3.2 Let’s time!

Let’s run example3.

For Octave run (in octave/cpp/):

$ octave example3.py

Cosniwa’s outputs in this example are similiar to results from the previous example.

Results for Octave:

_images/example3cm.png

The main difference is the third column. It contains labels (“100 x add”, “add”) given to the code.

4.4. Octave example4 [cOctave]: Add main time

Note

Example4 is available on github.com: example4 for Octave [cOctave].

4.4.1 Main time

Cosniwa provides two functions start() and stop() which can be used to start and stop the main timer in Cosniwa.

Take a look at the examples below. Four code snippets are registered (lines 21 - 24):

15
16
17
18
19
20
21
22
23
24
 function example4()

     % Initalise cosniwa
     cCosniwa('init');

     % Register the code snippets
     iRego1 = cCosniwa('reg_code', 'add(1, 100000)');
     iRego2 = cCosniwa('reg_code', '100 x add(1, 100000)');
     iRego3 = cCosniwa('reg_code', 'add(1, 10000)');
     iRego4 = cCosniwa('reg_code', '100 x add(1, 10000)');

Two loops are timed in the example below.

Before the loops the start() function is called (line 27), after the loops the stop() function is called (line 46).

Code between these function is called ‘main code’.

26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
     % Start the main CoSniWa time
     cCosniwa('start');

     cCosniwa('call_start', iRego2);  % Start code snippet (loop)
     for inxAdd=1:100
         cCosniwa('call_start', iRego1);  % Start code snippet (add)
         add(1, 100000);
         cCosniwa('call_stop', iRego1);   % Stop code snippet (add)
     endfor
     cCosniwa('call_stop', iRego2);   % Stop code snippet (loop)

     cCosniwa('call_start', iRego4);  % Start code snippet (loop)
     for inxAdd=1:100
         cCosniwa('call_start', iRego3);  % Start code snippet (add)
         add(1, 10000);
         cCosniwa('call_stop', iRego3);  % Stop code snippet (add)
     endfor
     cCosniwa('call_stop', iRego4);   % Stop code snippet (loop)

     % Stop the main CoSniWa time
     cCosniwa('stop');

     % Print the results
     cCosniwa('resultc');

 end


 function add(iA, iB)
 % Add iA + iB in a slow way.

     for i = 1:iB
         iA = iA + 1;
     endfor
 end

Hence to these functions, more data is added to Cosniwa’s output.

4.4.2 Let’s time!

Let’s run example 4.

For Octave run (in octave/cpp/):

$ octave example4.m

Results for Octave:

_images/example4cm.png

The first visible difference comparing to the previous examples is the ‘Total measured time’ printed just after Cosniwa’s header. It gives the time measured between start() and stop() functions, which is called ‘main time’.

Furthermore, there are two new columns int the Cosniwa’s output. The columns are between the total execution time and average execution time (marked with a green rectangle).

The first new column is the column with percentage (%) at the end of the number. It compares the total execution time of a code snippet with the main time. For example, loop which calls ‘add(1, 100000)’ function takes 90.89% of the main time (11393.793 ms).

The second column which was not present in the previous examples is the column which starts with ‘MPA’. The three letters acronym ‘MPA’ means ‘maximum possible acceleration’.

Value in this column gives information about how much execution of main code would be accelerated if a code snippet corresponding to the column would be executed in no time.

4.5. Octave example1 [oOctave]: Simplest example

Note

Example1 is available on github.com: example1 for Octave [oOctave].

This is the simplest example of using Cosniwa to time code in Octave using oCosniwa, Cosniwa implemented entirely in the native Octave language (without C++ modules).

4.5.1 First things first

Octave Load Path must contain directory with oCosniwa (octave/native/). Use ‘addpath()’ to ensure that oCosniwa is in Octave Load Path.

4.5.2 Time consuming function

Octave examples 4.5, 4.6, 4.7 and 4.8 use the following ‘add()’ function which adds two positive integer numbers in a very unoptimised way.

4.5.3 Setting up the stopwatch

Cosniwa, as its name denotes, is a stopwatch for code snippets.

In this example, a single line calling ‘add()’ function is the code snippet to be timed (line 21). Function call_start() starts the stopwatch, call_stop() stops it.

Both functions call_start() and call_stop() have the same argument: in this case ‘1’. It is a ‘registration number’ (‘rego’) of the code snippet. Rego can be any positive number, except zero.

Finally, function resultsc() prints to the console the results of timing.

Function ‘add()’ in Octave:

18
19
20
21
22
23
24
 function add(iA, iB)
 % Add iA + iB in a slow way.

     for i = 1:iB
         iA = iA + 1;
     endfor
 end
 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
 %
 % example1.m [version 1.0]
 % CoSniWa:  COde SNIppet stopWAtch [Octave port] - Example 1.
 %
 %
 % CoSniWa is dedicated to profile code using time stamps.
 % Cosniwa  [Octave port - native .m implementation ] v1.0, 30 May 2017.
 %
 % read more on: www.speedupcode.com
 %
 % (c) Jacek Pierzchlewski, 2017  jacek@pierzchlewski.com
 % license: BSD-2-Clause.
 %

 function example1()

     % Initalise cosniwa
     csw = cosniwa_init();

     csw = cosniwa_call_start(csw, 1);  % Start code snippet
     add(1, 1000000);
     csw = cosniwa_call_stop(csw, 1);   % Stop code snippet

     % Print the results
     cosniwa_resultc(csw);
 end


 function add(iA, iB)
 % Add iA + iB in a slow way.

     for i = 1:iB
         iA = iA + 1;
     endfor
 end

4.5.4 Let’s time!

Warning

All the examples in this tutorial were run on Asus G752V laptop (mid 2016) with 2.6GHz Intel Core i7 with Gentoo Linux. On your computer timing results may vary!

Ok, let’s run example1 and see the results:

For Octave run (in octave/native/):

$ octave example1.m

_images/example1om.png

Let’s go through the results column by column.

1. The first column (#1) holds an order number of a code snippet. In this example there is only one code snippet, which has a ‘#1’ in the first column. Please note that Cosniwa orders code snippets by the total execution time.

2. The second column (rego: 1) holds a registration number (‘rego’) given to a code snippet.

3. The third column is empty in this example. It holds a label given to a code snippet. Look at example3 (‘Code registration’) below for more info about labeling.

4. The fourth column ([calls: 1]) holds the number of calls of a code snippet. In the current example the code was called only once.

5. Finally, the fifth column (1139.779 ms) holds the total execution time of a code snippet.

4.6. Octave example2 [oOctave]: Two code snippets

Note

Example2 is available on github.com: example2 for Octave [oOctave].

4.6.1 Adding a second code snippet

In this example ‘add()’ function is called one hundred times in a loop. The ‘add()’ function inside the loop is a code snippet with registration ‘1’.

The whole loop is a code snippet with registration ‘2’.

Cosniwa timer for the loop is started in line 20 and stopped in line 26.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
 %
 % example2.m [version 1.0]
 % CoSniWa:  COde SNIppet stopWAtch [Octave port] - Example 2.
 %
 %
 % CoSniWa is dedicated to profile code using time stamps.
 % Cosniwa  [Octave port - native .m implementation ] v1.0, 30 May 2017.
 %
 % read more on: www.speedupcode.com
 %
 % (c) Jacek Pierzchlewski, 2017  jacek@pierzchlewski.com
 % license: BSD-2-Clause.
 %

 function example2()

     % Initalise cosniwa
     csw = cosniwa_init();

     csw = cosniwa_call_start(csw, 2);  % Start code snippet (loop)
     for inxAdd=1:100
         csw = cosniwa_call_start(csw, 1);  % Start code snippet (add)
         add(1, 10000);
         csw = cosniwa_call_stop(csw, 1);   % Stop code snippet (add)
     endfor
     csw = cosniwa_call_stop(csw, 2);   % Stop code snippet (loop)

     % Print the results
     cosniwa_resultc(csw);
 end


 function add(iA, iB)
 % Add iA + iB in a slow way.

     for i = 1:iB
         iA = iA + 1;
     endfor
 end

4.6.2 Let’s time!

Ok, let’s run example2 and see the results:

For Octave run (in octave/native/):

$ octave example2.m

Cosniwa’s output from this example contains more data than previously.

_images/example2om.png

The first line corresponds to the loop (rego 2).

The second line corresponds to the function ‘add()’ called inside the loop, let’s go through this line column by column.

1. The first column (#2) is an order number of a code snippet.

2. The second column (rego: 1) is a registration number of a code snippet.

3. The third column is empty in this example. It holds labels given to code snippets. Look at example 3 (Code registration) for details.

4. The fourth column ([calls: 100]) holds the number of calls of a code snippet. The ‘add’ function was called one hundred times within the loop.

5. The fifth column (1142.626 [ms]) holds the total execution time of a code snippet. The total execution time of one hundred calls of function ‘add()’ is 1142.626 ms.

  1. The sixth column (11.426 [ms]) holds the average execution time of a code snippet.

7. The seventh column (4.827 [ms]) holds the variance of execution times.

8. The last, eigth column (11.331 / 11.729 [ms]) holds the minimum and the maximum execution time of a code snippet.

The columns 6th - 8th are printed only for code snippets which are called more than once.

4.7. Octave example3 [oOctave]: Code registrations

Note

Example3 is available on github.com: example3 for Octave [oOctave].

4.7.1 Example3: Static labeling of code snippets

Registering time snippets using arbitrarily chosen number may not be convenient, especially if there are many code snippets to be timed. Cosniwa provides function reg_code() which can be used to label a code snippet and automatically assign a registration number.

Look at the examples below. Two code snippets are registered using reg_code() function (lines 22 and 23).

16
17
18
19
20
21
22
23
 function example3()

     % Initalise cosniwa
     csw = cosniwa_init();

     % Register the code snippets
     [csw, iRego1] = cosniwa_reg_code(csw, 'add');
     [csw, iRego2] = cosniwa_reg_code(csw, '100 x add');

The returned values (iRego1, iRego2) are then used in functions call_start() and call_stop().

25
26
27
28
29
30
31
32
33
34
35
     csw = cosniwa_call_start(csw, iRego2);  % Start code snippet (loop)
     for inxAdd=1:100
         csw = cosniwa_call_start(csw, iRego1);  % Start code snippet (add)
         add(1, 10000);
         csw = cosniwa_call_stop(csw, iRego1);   % Stop code snippet (add)
     endfor
     csw = cosniwa_call_stop(csw, iRego2);   % Stop code snippet (loop)

     % Print the results
     cosniwa_resultc(csw);
 end

4.7.2 Let’s time!

Ok, let’s run example3 and see the results:

For Octave run (in octave/native/):

$ octave example3.m

Cosniwa’s outputs in this example are similiar to results from the previous example.

_images/example3om.png

The main difference is the third column. It contains labels (“100 x add”, “add”) given to the code.

4.8. Octave example4 [oOctave]: Add main time

Note

Example4 is available on github.com: example4 for Octave [oOctave].

Cosniwa provides two functions start() and stop() which can be used to start and stop the main timer in Cosniwa.

Take a look at the examples below. Four code snippets are registered:

15
16
17
18
19
20
21
22
23
24
 function example4()

     % Initalise cosniwa
     cCosniwa('init');

     % Register the code snippets
     iRego1 = cCosniwa('reg_code', 'add(1, 100000)');
     iRego2 = cCosniwa('reg_code', '100 x add(1, 100000)');
     iRego3 = cCosniwa('reg_code', 'add(1, 10000)');
     iRego4 = cCosniwa('reg_code', '100 x add(1, 10000)');

Two loops are timed in the example below.

Before the loops the start() function is called (line 27), after the loops the stop() function is called (line 49).

Code between these function is called ‘main code’.

26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
     % Start the main CoSniWa time
     cCosniwa('start');

     cCosniwa('call_start', iRego2);  % Start code snippet (loop)
     for inxAdd=1:100
         cCosniwa('call_start', iRego1);  % Start code snippet (add)
         add(1, 100000);
         cCosniwa('call_stop', iRego1);   % Stop code snippet (add)
     endfor
     cCosniwa('call_stop', iRego2);   % Stop code snippet (loop)

     cCosniwa('call_start', iRego4);  % Start code snippet (loop)
     for inxAdd=1:100
         cCosniwa('call_start', iRego3);  % Start code snippet (add)
         add(1, 10000);
         cCosniwa('call_stop', iRego3);  % Stop code snippet (add)
     endfor
     cCosniwa('call_stop', iRego4);   % Stop code snippet (loop)

     % Stop the main CoSniWa time
     cCosniwa('stop');

     % Print the results
     cCosniwa('resultc');

 end

Hence to these functions, more data is added to Cosniwa’s output.

Let’s run example 4.

For Octave run (in octave/native/):

$ octave example4.m

Results for Octave:

_images/example4om.png

The first visible difference comparing to the previous examples is the ‘Total measured time’ printed just after Cosniwa’s header. It gives the time measured between start() and stop() functions, which is called ‘main time’.

Furthermore, there are two new columns in the Cosniwa’s output. The columns are between the total execution time and average execution time (marked with a green rectangle).

The first new column is the column with percentage (pct.) at the end of the number. It compares the total execution time of a code snippet with the main time. For example, loop which calls ‘add(1, 100000)’ function takes 90.81% of the main time (11357.673 ms).

The second column which was not present in the previous examples is the column which starts with ‘MPA’. The three letters acronym ‘MPA’ means ‘maximum possible acceleration’.

Value in this column gives information about how much execution of main code would be accelerated if a code snippet corresponding to the column would be executed in no time.

4.9. Octave functions

4.9.1. Octave Cosniwa initialisation functions [cCosniwa]

cCosniwa (‘init’)

INITIALISE NEW COSNIWA.

4.9.2. Octave code snippet registration functions [cCosniwa]

cCosniwa (‘reg_code’, strLabel, iRego)

REGISTER CODE SNIPPET (v1).

Function registers new code snippet label (strLabel) in the snippets database.

Function registers the label with a requested registration number (iRego).

If label already exists with a different registration number, function returns 0.

Function returns number iRego in case of no errors.

ARGUMENTS:
strLabel:   [string]                   Label for the code snippet.
iRego:       [integer number]   Requested registration number of the code snippet.
RETURN:
[integer number]   Registration number of the code snippet. It is equal to argument iRego if there are no errors.

cCosniwa (‘reg_code’, strLabel)

REGISTER CODE SNIPPET (v2).

Function registers new code snippet label (strLabel) in the snippets database. Function returns registration number iRego given to the code snippet label.

ARGUMENTS:
strLabel:   [string]   Label for the code snippet.
RETURN:
[integer number]   Registration number of the code snippet.

4.9.3. Octave stoper start/stop functions [cCosniwa]

cCosniwa (‘start’)

START THE MAIN TIME.

cCosniwa (‘stop’)

STOP THE MAIN TIME.

cCosniwa (‘call_start’, iRego)

START A CODE SNIPPET CALL.

ARGUMENTS:
iRego:   [integer number]   Registration number of a code snippet.

cCosniwa (‘call_stop’, iRego)

STOP A CODE SNIPPET CALL.

ARGUMENTS:
iRego:   [integer number]   Registration number of a code snippet.

4.9.4. Octave timing results functions [cCosniwa]

cCosniwa (‘result’)

GET TIMING RESULTS.

RETURN:
[string]   String with timing results.

cCosniwa (‘resultc’)

PRINT TIMING RESULTS TO THE CONSOLE OUTPUT.

4.9.5. Octave Cosniwa initialisation functions [oCosniwa]

cosniwa_init()

INITIALISE NEW COSNIWA.

RETURN:
[structure]   Initialised Cosniwa structure.

4.9.6. Octave code snippet registration functions [oCosniwa]

cosniwa_reg_code (csw, strLabel, iRego = -1000)

REGISTER CODE SNIPPET.

PARAMETERS:
csw           [structure]             Cosniwa structure.
strLabel   [string]                   Label for the code snippet.
iRego       [integer number]   Requested registration number of the code snippet. (optional).
RETURN:
[structure]             Cosniwa structure.
[integer number]   Registration number of the code snippet.

4.9.7. Octave stoper start/stop functions [oCosniwa]

cosniwa_start (csw)

START THE MAIN TIME.

PARAMETERS:
csw   [structure]   Cosniwa structure
RETURN:
[structure]   Cosniwa structure

cosniwa_stop (csw)

STOP THE MAIN TIME.

PARAMETERS:
csw   [structure]   Cosniwa structure
RETURN:
[structure]   Cosniwa structure

cosniwa_call_start (csw, iRego)

START A CODE SNIPPET CALL.

PARAMETERS:
csw       [structure]             Cosniwa structure
iRego   [integer number]   Registration number of a code snippet.
RETURN:
[structure]   Cosniwa structure

cosniwa_call_stop (csw, iRego)

STOP A CODE SNIPPET CALL.

PARAMETERS:
csw       [structure]             Cosniwa structure
iRego   [integer number]   Registration number of a code snippet.
RETURN:
[structure]   Cosniwa structure

4.9.8. Octave timing results functions [oCosniwa]

cosniwa_result (csw, bShort = 0)

GET TIMING RESULTS.

PARAMETERS:
csw         [structure]   Cosniwa structure
bShort     [bool]           Flag: short / full results message (optional)
RETURN:
[string] String with timing results.

cosniwa_resultc (csw, bShort = 0)

PRINT TIMING RESULTS TO THE CONSOLE OUTPUT.

PARAMETERS:
csw         [structure]   Cosniwa structure
bShort     [bool]           Flag: short / full results message (optional)