Profiling macros

Table of Contents Example usage Results Cycles Customization

Example usage

They live in Nemerle.Profiling namespace.

#pragma indent
using Nemerle.Profiling

[assembly: ProfSetup]

class A
 [Profile] \
 Foo () : int
   mutable cnt = 0
   unchecked
     for (mutable i = 0; i < 10000000; ++i)
       cnt += (i * i) % 100
   cnt

 [Profile] \
 Fib (n : int) : int
   if (n < 1) 1
   else Fib (n - 1) + Fib (n - 2)

 [Profile] \
 Bar () : int
   mutable cnt = 0
   unchecked
     for (mutable i = 0; i < 10000000; ++i)
       cnt += (i * i * 7) % 100
   cnt

 [Profile] \
 Qux () : int
   mutable cnt = 0
   for (mutable i = 0; i < 3; ++i)
     cnt += Foo () % 100
     cnt += Bar () % 100
     cnt += Fib (30) % 100
   cnt


 [ProfDump] \
 Dump () : void
   {}

 static Main () : void
   def a = A ()
   _ = a.Qux ()
   a.Dump ()

Running this program outputs:

  %total   cycles    calls-recurs.  cyc/call(w/o rec ) function name
  41.14%      806        3-0          268.67(268.67  ) A.Foo
  16.13%      316 13069851-13069848     0.00(105.33  ) A.Fib
  42.67%      836        3-0          278.67(278.67  ) A.Bar
 100.00%     1959        1-0         1959.00(1959.00 ) A.Qux

(or something similar).

In short: mark methods you want to profile with [Profile] attribute, then create a method that will dump out results, place [ProfDump] on it, finally put [assembly: ProfSetup] anywhere and there you go.

Results

The results are:

• percentage of total time spent in given function
• number of cycles spent in it, T
• total number of calls to the function, C
• number of recursive calls to the function from itself, R
• T/C
• T/(C-R) (this is important if you don't care how many times the function called itself)
• function name (overloading not supported yet)

Cycles

Now what are the cycles? It depends, in the default setup they are milliseconds. However it is possible to change it.

Customization

The [ProfSetup] attribute takes several named parameters. Full invocation looks like this:

[assembly: ProfSetup (Divisor = 1000,
                      GetTime = MyClass.rdtsc (),
                      TimeType = long)]

GetTime specifies expression to be used for current timestamp retrieval, TimeType -- the type returned by GetTime and Divisor is used to bring down the numbers in final dump.

On x86 and x86_64 systems, it is probably wisest to use rdtsc instruction for profiling. You however need a small C library and P/Invoke to use it.

<c>typedef union { unsigned long long value; unsigned int ints[2]; } TSC_value; long long rdtsc(void) { TSC_value v; ("rdtsc" : "=a" (v.ints[0]), "=d" (v.ints[1])) return v.value; }</c>

and later, assuming you compiled the above C file to libmydll.so (or mydll.dll on Windows), in Nemerle:

class MyClass {
  [DllImport ("mydll")]
  extern public static rdtsc () : long;
}