Using Kernel.Time() for time meassure

[jkleiser]

I wanted to check how long some computation took, and I tried something like this:

start := Kernel.Time();
f := Fibo(n);
stop := Kernel.Time();
Out.Int(stop - start, 12);

However, I'm not sure what this "stop - start" tells me. It doesn't look like milliseconds or microseconds. How can I obtain milliseconds (or microseconds)? I'm doing this on Mac OSX.

[norayr]

Hello, Jon,

short answer: you are doing it right! The difference you get is in milliseconds. I've just made a test on Linux in order to make sure.

Long answer: This API itself is very old. It's inherited from the Oberon operating system. This is a quote from "The Oberon System, user guide and programmer's manual" by Martin Reiser, published in 1991, page 170:

As far as I remember, in later versions of Oberon system, self hosted, and hosted on top of Linux or Windows, Kernel.Time() was already returning time in units of 1/1000th of a second.

voc mimics Oberon system behaviour by using Unix functions. Actually this code is taken from Oberon system V4 which run on top of Linux. And Time() was returning number of milliseconds since system startup, in our case - number of milliseconds since module initialization, i. e. program start.

In the future if you need to deal with date and time functions, instead of using this old fashioned and, IMO, not very convenient API for this tasks, I would suggest to use module oocTime. It's ported from the ooc compiler, source is very well commented, and here is it's original manual. In voc oocTime, as in ooc, uses oocSysClock, however the latter relies on functions from voc's Unix.Mod. I believe I have tested functions from the module oocTime and they should work as supposed.

[norayr]

in Unix (should be the same in case with OSX), there is a commandline utility "time". It's also possible to run

time ./someprogram

and upon exit of the program you will get it's execution time metrics.

[jkleiser]

Hello Norayr,

My Fibonacci.Mod computes the Fibonacci numbers from 32 to 40 VERY fast, and they are all correct (as far as I can see), but the timing it prints out is not milliseconds at all. Something is wrong here; the first time I tried it this morning it even printed negative values:

mac3:Fibonacci jkleiser$ ./Fibonacci
Fibonacci  32     2178309 -2010044684 milliseconds
Fibonacci  33     3524578 -2010044677 milliseconds
Fibonacci  34     5702887 -2005749701 milliseconds
Fibonacci  35     9227465 -2001454718 milliseconds
Fibonacci  36    14930352 -1997159725 milliseconds
Fibonacci  37    24157817 -1992864718 milliseconds
Fibonacci  38    39088169 -1988569687 milliseconds
Fibonacci  39    63245986 -1984274610 milliseconds
Fibonacci  40   102334155 -1979979473 milliseconds
mac3:Fibonacci jkleiser$ ./Fibonacci
Fibonacci  32     2178309   137438964 milliseconds
Fibonacci  33     3524578   137438969 milliseconds
Fibonacci  34     5702887   141733947 milliseconds
Fibonacci  35     9227465   146028930 milliseconds
Fibonacci  36    14930352   150323925 milliseconds
Fibonacci  37    24157817   154618930 milliseconds
Fibonacci  38    39088169   158913962 milliseconds
Fibonacci  39    63245986   163209038 milliseconds
Fibonacci  40   102334155   167504174 milliseconds

Here is my code:

MODULE Fibonacci;
IMPORT Out := Console, Kernel;
VAR n: INTEGER;

PROCEDURE Fibo(n: INTEGER): LONGINT;
VAR f: LONGINT;
BEGIN
    IF n <= 2 THEN
        f := 1
    ELSE
        f := Fibo(n - 1) + Fibo(n - 2)
    END;
    RETURN f
END Fibo;

PROCEDURE WriteFibo(n: INTEGER);
VAR start, stop, f: LONGINT;
BEGIN
    start := Kernel.Time();
    f := Fibo(n);
    stop := Kernel.Time();
    Out.String("Fibonacci");
    Out.Int(n, 4);
    Out.Int(f, 12);
    Out.Int(stop - start, 12); Out.String(" milliseconds");
    Out.Ln
END WriteFibo;

BEGIN
    FOR n := 32 TO 40 DO WriteFibo(n) END
END Fibonacci.

[norayr]

something strange is happening in case of your code indeed.

I will try to understand what.

But this test seem to confirm that Unix.Gettimeofday works okay.

MODULE test;
IMPORT Unix, Out := Console;

VAR
  tv : Unix.Timeval; tz: Unix.Timezone;
  i, r : INTEGER;
BEGIN

  i := 0;
  REPEAT
    Out.Int(i, 0); Out.String("  ");
    r := Unix.Gettimeofday(tv, tz);
    Out.Int(tv.usec, 0); Out.String("  "); Out.Int(tv.sec, 0); Out.Ln;
    r := Unix.Sleep(1);
    INC(i);
  UNTIL i = 50;

END test.

[norayr]

ok, taking in to consideration this, the following, slightly modified version of your code seem to work:

MODULE Fibonacci;
IMPORT Out := Console, Unix;
VAR n: INTEGER;

PROCEDURE Time(): LONGINT;
VAR
   l : INTEGER;
   timeval: Unix.Timeval; timezone: Unix.Timezone;
BEGIN
   l := Unix.Gettimeofday(timeval, timezone);
RETURN 1000000 * timeval.sec + timeval.usec;
END Time;

PROCEDURE Fibo(n: INTEGER): LONGINT;
VAR f: LONGINT;
BEGIN
    IF n <= 2 THEN
        f := 1
    ELSE
        f := Fibo(n - 1) + Fibo(n - 2)
    END;
    RETURN f
END Fibo;

PROCEDURE WriteFibo(n: INTEGER);
VAR start, stop, f: LONGINT;
BEGIN
    start := Time();
    f := Fibo(n);
    stop := Time();
    Out.String("Fibonacci");
    Out.Int(n, 4);
    Out.Int(f, 12);
    Out.Int(stop - start, 12); Out.String(" microseconds");
    Out.Ln
END WriteFibo;

BEGIN
    FOR n := 32 TO 40 DO WriteFibo(n) END
END Fibonacci.

output is

noch@chinari ~ $ ./Fibonacci 
Fibonacci  32     2178309       24383 microseconds
Fibonacci  33     3524578       32777 microseconds
Fibonacci  34     5702887       43511 microseconds
Fibonacci  35     9227465       56848 microseconds
Fibonacci  36    14930352       74522 microseconds
Fibonacci  37    24157817      110280 microseconds
Fibonacci  38    39088169      177552 microseconds
Fibonacci  39    63245986      285964 microseconds
Fibonacci  40   102334155      465611 microseconds

[jkleiser]

Thanks. But for some reason I get big negative values, and I haven't figured out why yet:

mac3:Fibonacci jkleiser$ ./Fibonacci
Fibonacci  32     2178309 -4294956495 microseconds
Fibonacci  33     3524578-140733193372117 microseconds
Fibonacci  34     5702887-140733193360248 microseconds
Fibonacci  35     9227465-140733193344183 microseconds
Fibonacci  36    14930352-140733193316450 microseconds
Fibonacci  37    24157817-140733193277613 microseconds
Fibonacci  38    39088169-140733193213328 microseconds
Fibonacci  39    63245986-140733193107089 microseconds
Fibonacci  40   102334155-140733192936019 microseconds

[norayr]

I like following solution which uses oocTime module, more.

MODULE Fibonacci;
IMPORT Out := Console, Time := oocTime;
VAR n: INTEGER;

PROCEDURE Fibo(n: INTEGER): LONGINT;
VAR f: LONGINT;
BEGIN
    IF n <= 2 THEN
        f := 1
    ELSE
        f := Fibo(n - 1) + Fibo(n - 2)
    END;
    RETURN f
END Fibo;

PROCEDURE WriteFibo(n: INTEGER);
  VAR start, stop: Time.TimeStamp; 
  interval: Time.Interval;
  f: LONGINT;
BEGIN
    Time.GetTime(start);
    f := Fibo(n);
    Time.GetTime(stop);
    stop.Delta(start, interval);
    Out.String("Fibonacci");
    Out.Int(n, 4);
    Out.Int(f, 12);
    Out.Int(interval.msecInt, 12); Out.String(" milliseconds");
    Out.Ln
END WriteFibo;

BEGIN
    FOR n := 32 TO 40 DO WriteFibo(n) END
END Fibonacci.

output

noch@chinari /tmp $ ./Fibonacci 
Fibonacci  32     2178309          25 milliseconds
Fibonacci  33     3524578          34 milliseconds
Fibonacci  34     5702887          45 milliseconds
Fibonacci  35     9227465          58 milliseconds
Fibonacci  36    14930352          77 milliseconds
Fibonacci  37    24157817         116 milliseconds
Fibonacci  38    39088169         189 milliseconds
Fibonacci  39    63245986         307 milliseconds
Fibonacci  40   102334155         493 milliseconds

[jkleiser]

Strange. With your latest oocTime code, I still get strange results:

mac3:Fibonacci jkleiser$ ./Fibonacci
Fibonacci  32     2178309          10 milliseconds
Fibonacci  33     3524578     4294984 milliseconds
Fibonacci  34     5702887     4294994 milliseconds
Fibonacci  35     9227465     4295010 milliseconds
Fibonacci  36    14930352     4295037 milliseconds
Fibonacci  37    24157817     4295075 milliseconds
Fibonacci  38    39088169     4295140 milliseconds
Fibonacci  39    63245986     4295248 milliseconds
Fibonacci  40   102334155     4295420 milliseconds

[norayr]

hmmm.

negative values may mean overflow somewhere. will connect to 64bit osx to test.

[jkleiser]

I'm now using your oocTime solution (as I did in my previous run). I now start from 33 instead of 32, and as you can see, the first line makes sense (as with 32 above), but the rest is strange:

mac3:Fibonacci jkleiser$ ./Fibonacci
Fibonacci  33     3524578          17 milliseconds
Fibonacci  34     5702887     4294994 milliseconds
Fibonacci  35     9227465     4295010 milliseconds
Fibonacci  36    14930352     4295037 milliseconds
Fibonacci  37    24157817     4295076 milliseconds
Fibonacci  38    39088169     4295142 milliseconds
Fibonacci  39    63245986     4295249 milliseconds
Fibonacci  40   102334155     4295422 milliseconds

[jkleiser]

Can the warnings I get when compiling explain anything? See attachment. warnings.txt

[norayr]

I guess I have found the reason. suseconds_t is 4 byte long on osx x86_64.

let me check.

[norayr]

fixed in master.

please get new version from git and compile compiler.

probably it's good to make make -f makefile.darwin.clang.x86_64 uninstall prior to installing new version.

Please confirm that problem is solved by this.

[norayr]

make sure that prefix is right in the makefile.

[norayr]

it must be annoying to see many clang warnings on osx, I probably have to silence them by default.

[jkleiser]

Good news! Both timing methods now work. Here's the results (32-40) from the one based on Unix.Gettimeofday:

mac3:Fibonacci jkleiser$ ./Fibmicros
Fibonacci  32     2178309       10747 microseconds
Fibonacci  33     3524578       15924 microseconds
Fibonacci  34     5702887       27034 microseconds
Fibonacci  35     9227465       43711 microseconds
Fibonacci  36    14930352       70446 microseconds
Fibonacci  37    24157817      108976 microseconds
Fibonacci  38    39088169      173919 microseconds
Fibonacci  39    63245986      279708 microseconds
Fibonacci  40   102334155      449344 microseconds

Here's the results (33-40) when using oocTime:

mac3:Fibonacci jkleiser$ ./Fibonacci
Fibonacci  33     3524578          17 milliseconds
Fibonacci  34     5702887          27 milliseconds
Fibonacci  35     9227465          42 milliseconds
Fibonacci  36    14930352          70 milliseconds
Fibonacci  37    24157817         107 milliseconds
Fibonacci  38    39088169         172 milliseconds
Fibonacci  39    63245986         279 milliseconds
Fibonacci  40   102334155         454 milliseconds

Well done!

[norayr]

nice. (: