The code used in this tutorial can be found in the Github repository here. The Zoom session is here.

Basic Timing

Execution time is one of the most important metrics of application performance. Its measurement may be carried out at the whole-program level as well as for selected sections of the monitored application. Each of these scenarios requires a different approach. The measurement of duration of application execution should typically be synchronized with the wall clock time to establish a common reference permitting meaningful comparisons with results obtained on other platforms and environments.

A number of timing functions accessing the system’s high-resolution clock are used. Individual implementations of high-resolution timers may differ from system to system depending on the actual processor type and system configuration. Since the native interfaces exposed by such timers are often not compatible with each other, typically the most portable way to access them is to use POSIX clock functions. The most frequently used call, clock_gettime, obtains the value of time that has elapsed from some fixed reference point in the past, typically machine boot time. Its prototype looks as follows:

#include <time.h>
int clock_gettime(clockid_t id, struct timespec tsp);

where id identifies one of the clocks available on the system and the structure to store the time data pointed to by tsp comprises two fields. The first of them, tv_sec contains the number of full seconds, and the other, tv_nsec, stores the number of nanoseconds expressing the remaining fraction of a second for the measured time interval. Both of these fields are integers of sufficient size to store the required data, frequently equal to the machine’s native word size. The function returns zero on success. To verify the actual resolution of the accessed clock, POSIX provides the clock_getres function that takes the clock identifier argument and stores the measurement resolution value in a structure pointed to by tsp:

int clock_getres(clockid_t id, struct timespec tsp);

For fine-granularity measurements, useful clock ids include CLOCK_MONOTONIC and CLOCK_MONOTONIC_RAW. Unlike the system wall clock, which may be subjected to coarse changes of value due to the administrator manually adjusting the system time, the monotonic clock is only affected by incremental adjustments performed by the time synchronization protocol in use (e.g., NTP). The raw monotonic clock has the same properties as the monotonic clock, but it is not affected by external time adjustment. The POSIX interface also supports other clocks of interest: CLOCK_BOOTTIME that is similar to the monotonic clock, but includes the time that elapsed while the system was suspended; CLOCK_PROCESS_CPUTIME_ID, which measures processor time consumed by all threads in the process it was called in; and CLOCK_THREAD_CPUTIME_ID for a processor time clock that is limited to the specific thread. Selection of the suitable clock should be performed in the context of application and type of measurement; for most performance measurements on an “always-on” platform, the monotonic clock is often sufficient as long as the overhead of several tens of nanoseconds per access is acceptable.

To take advantage of POSIX clocks, the user code needs to be explicitly instrumented with timing functions. To demonstrate this, a program performing matrix-vector multiplication. The same code is used for the next tutorial on performance monitoring tools. The application allocates heap memory, initializes the matrix and multiplicand, and product vectors perform the multiplication by invoking the CBLAS library function to compute dot products (mult function), and verifies the result by performing an absolute value sum on the elements of the product vector (cblas_dasum). Both initialization and multiplication can be performed in a row- or column-major fashion, potentially impacting the duration of computations.

To gather the timing information, clock_gettime functions were added to the main function of the source as shown in the code here. The code also defines the sec function that is used to convert the contents of the timespec structure to a floating-point number of seconds, thus enabling a straightforward calculation of time intervals. Note that the collection of timestamps is arranged with as little additional code as possible, and therefore the conversions of timing values to seconds and printout of final values are performed outside the timed regions.

The code looks like this:

#include <stdlib.h>
#include <cblas.h>
#include <time.h>

void init(int n, double **m, double **v, double **p, int trans) {
	*m = calloc(n*n, sizeof(double));
	*v = calloc(n, sizeof(double));
	*p = calloc(n, sizeof(double));
	for (int i = 0; i < n; i++) {
		(*v)[i] = (i & 1)? -1.0: 1.0;
		if (trans) 
			for (int j = 0; j <= i; j++) 
				(*m)[j*n+i] = 1.0;
		else 
			for (int j = 0; j <= i; j++) 
				(*m)[i*n+j] = 1.0;
	}
}

void mult(int size, double *m, double *v, double *p, int trans) {
	int stride = trans? size: 1;
	for (int i = 0; i < size; i++) {
		int mi = trans? i: i*size;
		p[i] = cblas_ddot(size, m+mi, stride, v, 1);
	}
}

double sec(struct timespec *ts) {
	return ts->tv_sec+1e-9*ts->tv_nsec;
}

int main(int argc, char **argv) {
	struct timespec t0, t1, t2, t3, t4;
	clock_gettime(CLOCK_MONOTONIC, &t0);
	int n = 1000, trans = 0;
	if (argc > 1) 
		n = strtol(argv[1], NULL, 10);
	if (argc > 2) 
		trans = (argv[2][0] == 't');
	double *m, *v, *p;
	clock_gettime(CLOCK_MONOTONIC, &t1);
	init(n, &m, &v, &p, trans);
	clock_gettime(CLOCK_MONOTONIC, &t2);
	mult(n, m, v, p, trans);
	clock_gettime(CLOCK_MONOTONIC, &t3);
	double s = cblas_dasum(n, p, 1);
	clock_gettime(CLOCK_MONOTONIC, &t4);

	printf("Size %d; abs. sum: %f (expected: %d)\n", n, s, (n+1)/2);
	printf("Timings:\n program: %f s\n", sec(&t4)-sec(&t0));
	printf(" init: %f s\n mult: %f s\n sum: %f s\n",sec(&t2)-sec(&t1), sec(&t3)-sec(&t2), sec(&t4)-sec(&t3));

	return 0;
}

Execution of the instrumented code in row-major mode with matrix size 10,000 x 10,000 yields:

$ ./mvmult 20000
Size 20000; abs. sum: 10000.000000 (expected: 10000)
Timings:
program: 2.226787 s
init: 1.093147 s
mult: 1.133615 s
sum: 0.000019 s

Doing the same using the less efficient column-major operation results in:

$ ./mvmult 20000 t
Size 20000; abs. sum: 10000.000000 (expected: 10000)
Timings:
program: 14.783646 s
init: 4.977392 s
mult: 9.806218 s
sum: 0.000027 s

As can be seen, program execution in the transposed mode takes an order of magnitude longer. The change is attributed primarily to a substantial increase in execution time of initialization and multiplication subroutines that access the matrix data. The absolute sum performed in the verification phase takes roughly the same amount of time since the layout of the input data (product vector) does not change.

Introduction to GPerftools

One of the most used profilers is available as a part of the gperftools package. It was originally named Google Performance Tools, the code is currently maintained by the community and distributed under the BSD license. gperftools provides a statistical CPU profiler, pprof, and several tools based around the tcmalloc (thread-caching malloc) library. Besides offering an improved memory allocation library for multithreaded environments, tcmalloc library supports memory leak detection and dynamic memory allocation profiling.

The code we are going to profile for this tutorial is a code to compute matrix-vector multiplication with BLAS. The code is provided here.

Install the required packages. On Ubuntu, you can do the following.

$ sudo apt install google-perftools libgoogle-perftools-dev libblas-dev

Basic Profiling

To illustrate the use of these features, the program below was compiled using the command shown below (note the addition of -lprofiler to the command line). To permit access to the program’s symbol table, an -ggdb option was specified as well:

$ gcc -O2 -g mvmult.c -o mvmult -ggdb -lblas -Wl,-no-as-needed -lprofiler

The gperftools CPU profiler does not require any changes to the source code, and after successfully linking the instrumented application may be executed. The location of the file containing the collected data must be specified using the CPUPROFILE environment variable, as demonstrated below:

$ env CPUPROFILE=mvmult.prof ./mvmult 20000
Size 20000; abs. sum: 10000.000000 (expected: 10000)
PROFILE: interrupts/evictions/bytes = 139/4/1320

The program execution proceeds as before, with the expected output appearing on the console. The only change is the final line, which confirms that the profiling indeed took place and collected 115 data samples. To display the obtained information, the pprof tool is used:

$ google-pprof --text mvmult mvmult.prof
Using local file mvmult.
Using local file mvmult.prof.
Total: 139 samples
      60  43.2%  43.2%       60  43.2% __sched_yield
      51  36.7%  79.9%       51  36.7% init
      24  17.3%  97.1%       24  17.3% dcopy_k_HASWELL
       2   1.4%  98.6%        3   2.2% __GI___pthread_mutex_lock
       1   0.7%  99.3%        1   0.7% __lll_lock_wait
       1   0.7% 100.0%       86  61.9% openblas_read_env
       0   0.0% 100.0%       57  41.0% __libc_start_main
       0   0.0% 100.0%       57  41.0% _start
       0   0.0% 100.0%        6   4.3% blas_level1_thread_with_return_value
       0   0.0% 100.0%       82  59.0% clone
       0   0.0% 100.0%        6   4.3% ddot_k_HASWELL
       0   0.0% 100.0%        6   4.3% exec_blas
       0   0.0% 100.0%        2   1.4% exec_blas_async_wait
       0   0.0% 100.0%       57  41.0% main
       0   0.0% 100.0%        6   4.3% mult
       0   0.0% 100.0%       82  59.0% start_thread

The produced output is organized in several columns. The first shows the sample count associated with each function. Whenever the profiler collects a sample, it records, among other things, the current address stored in the instruction pointer of the running program context.

Subsequent analysis done by pprof assigns the collected addresses to individual program functions. This is shown in the second column. The third column lists the cumulative percentage of samples for all functions displayed so far. The fourth and fifth columns deal with the aggregate sample counts and percentages for the annotated function as well as all its callees. Finally, the last column lists the affected function names, or if not available, the raw sampled addresses.

The default sampling frequency is 100 samples per second. This can be set to a custom value using the CPUPROFILE_FREQUENCY environment variable, although the maximum speed for most Linux platforms is limited to 1000 per second. Since the test application runs for only about a second, trying to increase the number of samples may offer additional insights:

$ env CPUPROFILE=mvmult1K.prof CPUPROFILE_FREQUENCY=1000 ./mvmult 20000
Size 20000; abs. sum: 10000.000000 (expected: 10000)
PROFILE: interrupts/evictions/bytes = 197/6/1424

About 10 times as many samples were collected. Their analysis reveals the following:

$ google-pprof --text mvmult mvmult1K.prof
Using local file mvmult.
Using local file mvmult1K.prof.
Total: 197 samples
     109  55.3%  55.3%      109  55.3% init
      53  26.9%  82.2%       53  26.9% __sched_yield
      27  13.7%  95.9%       27  13.7% dcopy_k_HASWELL
       3   1.5%  97.5%        3   1.5% __GI___pthread_mutex_lock
       3   1.5%  99.0%        3   1.5% __pthread_mutex_unlock_usercnt (inline)
       1   0.5%  99.5%        2   1.0% exec_blas_async
       1   0.5% 100.0%       83  42.1% openblas_read_env
       0   0.0% 100.0%        3   1.5% __GI___pthread_mutex_unlock
       0   0.0% 100.0%      115  58.4% __libc_start_main
       0   0.0% 100.0%      115  58.4% _start
       0   0.0% 100.0%        6   3.0% blas_level1_thread_with_return_value
       0   0.0% 100.0%       82  41.6% clone
       0   0.0% 100.0%        6   3.0% ddot_k_HASWELL
       0   0.0% 100.0%        6   3.0% exec_blas
       0   0.0% 100.0%        3   1.5% exec_blas_async_wait
       0   0.0% 100.0%      115  58.4% main
       0   0.0% 100.0%        6   3.0% mult
       0   0.0% 100.0%       82  41.6% start_thread

The default output of pprof is performed at function granularity, but sometimes it is useful to change this to avoid lengthy output or zoom in more closely on to the source of the problem. Adjustment options, in order of decreasing resolution, are:

--addresses
--lines annotate source code lines.
--functionslists the statistics per function.
--files switches to whole-file granularity.

To see how the samples are distributed within the init function, one may apply the following command to the set of profiling data collected before (to save space, the produced output was truncated and removed lines were replaced with “[...]”):

$ google-pprof --list=init --lines mvmult mvmult1K.prof
Using local file mvmult.
Using local file mvmult1K.prof.
ROUTINE ====================== init in /home/steven/Programs/Teaching/DD2358-VT21/DD2358/dd2358-tutorial-8/mvmult.c
   109    109 Total samples (flat / cumulative)
     .      .    1: #include <stdio.h>
     .      .    2: #include <stdlib.h>
     .      .    3: #include <cblas.h>
     .      .    4: #include <time.h>
     .      .    5: 
---
     .      .    6: void init(int n, double **m, double **v, double **p, int trans) {
     .      .    7: 	*m = calloc(n*n, sizeof(double));
     .      .    8: 	*v = calloc(n, sizeof(double));
     .      .    9: 	*p = calloc(n, sizeof(double));
     .      .   10: 	for (int i = 0; i < n; i++) {
     .      .   11: 		(*v)[i] = (i & 1)? -1.0: 1.0;
     .      .   12: 		if (trans) 
     .      .   13: 			for (int j = 0; j <= i; j++) 
     .      .   14: 				(*m)[j*n+i] = 1.0;
     .      .   15: 		else 
     1      1   16: 			for (int j = 0; j <= i; j++) 
   108    108   17: 				(*m)[i*n+j] = 1.0;
     .      .   18: 	}
     .      .   19: }
---
     .      .   20: 
     .      .   21: void mult(int size, double *m, double *v, double *p, int trans) {
     .      .   22: 	int stride = trans? size: 1;
     .      .   23: 	for (int i = 0; i < size; i++) {
     .      .   24: 		int mi = trans? i: i*size;

The inner loop performing initialization of matrix rows dominates the execution time, while the multiplicand vector initialization is marginal by comparison. Since the sources of BLAS routines are not available, a disassembled code listing may be used to identify the fine-grain hotspots in that code (again, the output was shortened to the most interesting fragment):

$ google-pprof --disasm=ddot_ mvmult mvmult.prof
Using local file mvmult.
Using local file mvmult.prof.
Warning: address    d6148:	74 26                	je     d6170 is longer than address length 16
.....
.....
ROUTINE ====================== ddot_k_HASWELL
     0      6 samples (flat, cumulative) 4.3% of total
: No such file or directory
     .      .     11202d0: endbr64 
     .      .     11202d4: push   %rbp
     .      .     11202d5: push   %rbx
     .      .     11202d6: sub    $0x428,%rsp
     .      .     11202dd: mov    %fs:0x28,%rax
     .      .     11202e6: mov    %rax,0x418(%rsp)
     .      .     11202ee: xor    %eax,%eax
     .      .     11202f0: test   %r8,%r8
     .      .     11202f3: sete   %r9b
....

We can now see the dissembled instructions.

Detecting memory leaks

One of gperftools' features is the ability to detect memory leaks. To enable this functionality, it is necessary to link the application with the tcmalloc library or set the environment variable LD_PRELOAD to libtcmalloc.so. Before launching the application, the leak detector needs to be informed about the flavor of checking that should be performed. This is accomplished by storing one of the keywords (minimal, normal, strict, or draconian) in the HEAPCHECK environment variable. They differ in scope and level of detail performed by the heap allocation checker; for most purposes normal mode is sufficient. The compilation command line and results of the instrumented program execution are shown below.

$ gcc -O2 mvmult.c -o mvmult -lblas -ltcmalloc
$ PPROF_PATH=/usr/bin/google-pprof HEAPCHECK=normal ./mvmult 20000
WARNING: Perftools heap leak checker is active -- Performance may suffer
tcmalloc: large alloc 3200000000 bytes == 0x560145c94000 @  0x7f1906033680 0x7f19060532ec 0x560144d11315 0x560144d11148 0x7f1905e370b3 0x560144d1121e
Size 20000; abs. sum: 10000.000000 (expected: 10000)
Have memory regions w/o callers: might report false leaks
Leak check _main_ detected leaks of 320000 bytes in 2 objects
The 2 largest leaks:
Using local file ./mvmult.
Leak of 160000 bytes in 1 objects allocated from:
	@ 560144d11337 init
	@ 560144d11148 main
	@ 7f1905e370b3 __libc_start_main
	@ 560144d1121e _start
Leak of 160000 bytes in 1 objects allocated from:
	@ 560144d11326 init
	@ 560144d11148 main
	@ 7f1905e370b3 __libc_start_main
	@ 560144d1121e _start


If the preceding stack traces are not enough to find the leaks, try running THIS shell command:

pprof ./mvmult "/tmp/mvmult.142269._main_-end.heap" --inuse_objects --lines --heapcheck  --edgefraction=1e-10 --nodefraction=1e-10 --gv

If you are still puzzled about why the leaks are there, try rerunning this program with HEAP_CHECK_TEST_POINTER_ALIGNMENT=1 and/or with HEAP_CHECK_MAX_POINTER_OFFSET=-1
If the leak report occurs in a small fraction of runs, try running with TCMALLOC_MAX_FREE_QUEUE_SIZE of few hundred MB or with TCMALLOC_RECLAIM_MEMORY=false, it might help find leaks more repea
Exiting with error code (instead of crashing) because of whole-program memory leaks

2. Introduction to Perf

The perf framework also referred to as perf_events, is a performance monitoring tool and event tracer closely integrated with the Linux OS kernel. Its primary functionality is based on the sys_perf_event_open system call introduced in the 2.6 series of Linux. To enable counter values collection without root permission, one can see the paranoid level.

$ sudo sh -c 'echo 1 >/proc/sys/kernel/perf_event_paranoid'

The system call enables access to special-purpose registers of the CPU that may be configured to collect the counts of specific hardware-level events. These events may vary from processor to processor, but their main categories include the following:

Cache related: misses and references issued: These may be further grouped by cache level (L1 through L3), cache type (instruction and data), and access type (loads and stores).
Translation lookaside buffer related: These may also be subdivided into instruction and data categories, and by access type (load/store).
Branch Statistics: These include counts of overall branch occurrences and missed branch target loads.
Instructions and cycles: Perf can provide the number of executed instructions or the count of CPU cycles that occurred during program execution.
Stalled or idle cycles: These further subdivide into front-end and back-end stalls. The first indicates an inability to fill completely the available capacity of the first stages of the execution pipeline and may be caused by instruction cache or translation lookaside buffer (TLB) misses, mispredicted branches, or unavailability of translation into micro-operations for specific instruction(s). The back-end issues may be caused by intel instruction dependencies (e.g., a long- latency instruction delaying the execution of other dependent instructions, such as division) or availability of memory units.
Node-level statistics: prefetches, loads and stores, and misses. Prefetch misses are counted separately to avoid false inflation of statistics describing actual data accesses generated by the monitored code.
Data collected by the processor’s performance management unit (PMU): These counters provide the aggregate values for the whole CPU, including primarily uncore-related events. Uncore is a term coined by Intel to describe segments of CPU logic that are not parts of the core execution pipeline and thus are shared by the cores. They include memory controllers and their interfaces, a node-level interconnect bus that provides NUMA functionality, a last-level cache, a coherency traffic monitor, and power management.

The perf tool also provides access to many software-level kernel events that may be of great use for performance analysis. They comprise counts of context switches, context migrations, data alignment faults, major, minor, and aggregate page faults, accurate time measurements, and custom events defined using the Berkeley Packet Filter framework. The complete list of events supported on the local system is obtained with:

$ perf list
...

Perf may be invoked in several modes of operation selected by the first argument on the command line. The frequently used commands are:

stat, which executes the provided application with arguments while collecting the counts of specified events or a default event set
record, which enables per thread, per process, or per CPU profiling report, which performs analysis of data collected by records annotate, which correlates the gathered profiling data to assembly code top, which displays the statistics in a real-time using format resembling that of the Unix top utility for the visualization of process activity bench, which invokes a number of predefined kernel benchmarks.

Simple Counter Collection

To test this functionality in practice, we can profile our test application. The result for row-major (non transposed) mode is presented below.

$ perf stat ./mvmult 20000
tcmalloc: large alloc 3200000000 bytes == 0x55f63d330000 @  0x7f8725444680 0x7f87254642ec 0x55f63b9ef315 0x55f63b9ef148 0x7f87252480b3 0x55f63b9ef21e
Size 20000; abs. sum: 10000.000000 (expected: 10000)

 Performance counter stats for './mvmult 20000':

          3 774,74 msec task-clock                #    2,458 CPUs utilized          
            52 824      context-switches          #    0,014 M/sec                  
                4      cpu-migrations            #    0,001 K/sec                  
           783 166      page-faults               #    0,207 M/sec                  
     12 376 900 881      cycles                    #    3,279 GHz                    
      5 955 837 348      instructions              #    0,48  insn per cycle         
      1 117 217 291      branches                  #  295,972 M/sec                  
         8 612 181      branch-misses             #    0,77% of all branches        

       1,535663165 seconds time elapsed

       2,017880000 seconds user
       1,757637000 seconds sys

Note that perf may accommodate a greater number of events in a single invocation than available hardware slots in the processor using a technique called multiplexing. It means that at any given moment only a subset of requested events is configured on the processor; this subset is periodically replaced with one that contains other requested events. This is repeated cyclically to permit all specified events to be active for an approximately equal share of time during application execution. The collected information may be analyzed using the “perf report” command.

Introduction to PAPI - Performance Application Programming Interface

The Performance Application Programming Interface (PAPI) is a performance monitoring toolkit developed at the University of Tennessee Innovative Computing Laboratory. It provides C and Fortran library and header files containing prototypes of functions that may be used to instrument user applications. The application programming interface (API) categories comprise library initialization and shutdown, event description and translation between symbolic event names and their codes, creation, and manipulation of event sets, starting and stopping of event counters, retrieval, accumulation, resetting, and initialization of counter values, system parameter queries, and various timing functions.

The package also provides a number of practical utilities.

papi_avail prints the symbolic names of preset events annotated with availability flags on the local systems and noting whether they are counted directly or derived by using more than one counter. Using option -a limits the display only to events locally available.
papi_native_avail similarly displays so-called native events, which typically comprise unicore and node-level events.
papi_decode outputs more detailed event descriptions in comma-separated values (CSV) format.
papi_clockres determines the practical resolution of various time and cycle measurements.
papi_cost checks the latency of invocation of various API functions in different configurations.
papi_event_chooser prints out events that may be added without conflict to a set containing events specified by the user.
papi_mem_info shows the local machine cache and TLB hierarchy information.

PAPI events are less portable across processor architectures than those exposed by the perf tool. The user always needs to confirm whether a specific event is available on the target platform by using papi_avail or papi_native_avail. Due to the growing complexity of microprocessor designs, the interpretation of seemingly the same events may change even between different iterations of the same architecture. On the other hand, PAPI may be used to instrument the application in precise locations of the code and enables the use of events that are normally not supported by perf.

To showcase the use of the interface, our test code was instrumented with two counters that tally the occurrences of double-precision operations, but one counts instances of all floating-point operations converted to scalar operations (PAPI_DP_OPS), and the other counts all vector operations (PAPI_VEC_DP).

The code instrumented with PAPI is available here.

The counters are activated just before initialization and their values are retrieved after return from the init, mult, and cblas_dasum functions. To guard against silent failures, a PAPI_CALL macro was defined to verify that called PAPI routines are completed successfully. As before, only the modified portion of the source code is provided (not counting the inclusion of the PAPI header, papi.h, in the top section of the source file)

For correct compilation, the program must be linked with the PAPI library, as shown below.

$ gcc -O2 mvmult_papi.c -o mvmult_papi -lblas -lpapi
$ ./mvmult_papi 20000
Size 20000; abs. sum: 10000.000000 (expected: 10000)
PAPI counts:
 init: event1:               0 event2:               0
 mult: event1:       100480009 event2:        25440009
 sum: event1:           20017 event2:           10013

Since the reference BLAS implementation does not use vector floating points, the count of vector operations stays at zero.

The theoretical count of scalar operations should be 20,0002 for multiplication and 20,00019,999 for addition, for a grand total of 799,980,000 in the mult function and 19,999 operations (since the absolute value computation requires only clearing the sign bit) in cblas_dasum. The counters consistently register higher values, most likely due to speculative execution.

Zoom Session