Profiling

Overview

UCS contains a tool to collect profiling information and save it to a file. Profiling is based on "locations", which are places in the code to collect timestamps from.
There are 3 types of locations:

• SAMPLE - simple timestamp
• SCOPE_START - mark the beginning of a nested block (code block or function call)
• SCOPE_END - mark the end of a nested block. Scopes allow measuring the time it took to run a particular piece of code.

In addition there are several convenience macros to profile the code:

• UCS_PROFILE_CODE - Declare a profiled scope of code.
• UCS_PROFILE_FUNC - Create a profiled function.
• UCS_PROFILE_CALL - Profile a function call.

When enabling profile collection, one or more of the following modes can be used:

• accum - Accumulate time and count per location.
• log - Collect all timestamps. If the log buffer is exhausted, newer records would override old ones.

The profiling data is saved to a file when the program exits, or when UCS catches the signal SIGHUP.
In order to read it, the ucx_read_profile tool should be used:

$ ucx_read_profile -h
Usage: ucx_read_profile [options] <file>
Options:
      -r             raw output
      -t UNITS       select time units (sec/msec/usec/nsec)

Usage example

The following profiled code is a top-level function called my_func which is profiled, and in addition it calls printf("Hello World!") and profiles that call:

UCS_PROFILE_FUNC_VOID(my_func, ()) {
    UCS_PROFILE_CALL(printf, "Hello World!\n");
}

Run an application and collect profile:

$ UCX_PROFILE_MODE=log,accum UCX_PROFILE_FILE=ucx.prof ./app

Read profile output file:

$ ucx_read_profile ucx.prof      

   command : ./app
   host    : my_host
   pid     : 9999
   units   : usec

                     NAME           AVG         TOTAL      COUNT             FILE     FUNCTION
                   printf        15.316            15          1     profiling.c:13   my_func_inner()
                  my_func        15.883            16          1     profiling.c:12   my_func()

     0.000  my_func 15.883 {                           profiling.c:12   my_func()
     0.332      printf 15.316 {                        profiling.c:13   my_func_inner()
    15.316      }
     0.236  }