Repository navigation
Application Profiling
In order to profile an application it's functions need to be instrumented and then linked against vftrace.
Vftrace requires instrumented functions in order to incercept and profile an application.
Compilers typically provide the -finstrument-functions flag to do so.
During the linking step the Vftrace-lib path needs to be specified with -L and libvftrace needs to be linked with -lvftrace.
#include <stdio.h>
int foo() {
return 2;
}
int bar() {
return foo();
}
int main(int argc, char** argv) {
printf("foo=%d bar=%d\n", foo(), bar());
return 0;
}$ gcc –finstrument-functions –c test.c
$ gcc –o test.x test.o –L<vftrace-install-path>/lib/ -lvftraceNote that you need to link -liberty if Vftrace was compiled with libiberty support.
In order to profile an application linked to Vftrace it is executed in the same way as would be done without Vftrace:
./test.x
mpirun -np 4 ./test.x # for MPI-codes After the program successfully terminated it should have produces a logfile <executable-name>_all.log. If this logfile is not present it needs to be checked if vftrace was properly linked to the application. One way is to use nm, which lists the symbols present in the binray:
$ nm <executable> | grep vftr_
00000000000089d0 T vftr_accumulate_callprofiling
00000000000089e0 T vftr_accumulate_callprofiling_overhead
00000000000089f0 T vftr_add_callprofiles
0000000000008c60 T vftr_add_collated_callprofiles
0000000000008860 T vftr_add_collated_profiles
0000000000008620 T vftr_add_profiles
000000000001fb90 T vftr_apply_perm_collated_stackptr
...The symbols and addresses do not need to match the example given here exactly.
But you should see an extensive list of symbols starting with vftr_.
If no vftr_ symbols are present the linker flag order should be checked.
-lvftrace should be at the end of the linker line in order to take precedence during linking.
By default Vftrace produces a logfile named <executable-name>_all.log, summarizing profiling information across all ranks.
At the very top of the logfile the used Vftrace version, start and end timestamp of your application execution, and a small disclaimer, can be found.
The summary gives an overview over your application execution timings. It's contents depends on the features compiled into vftrace and can look like this:
Nr. of MPI ranks: 4
Total runtime: 0.45 s
Application time: 0.45 s
overhead: 0.00 s
Function hooks: 0.00 s
MPI wrappers: 0.00 s
Vftrace used memory: 208.33 KiB
- Total runtime: Time in seconds between start and termination of the execution.
- Application time: An estimate by Vftrace, how much time was spent in the application and not in Vftrace related code sections for profiling.
- Overhead: An estimate by Vftrace how much time was spent in Vftrace code sections for profiling.
- Vftrace used memory: An estimate of how much extra memory vftrace used during profiling.
The runtime profile table lists all (instrumented) functions and routines encountered during execution. If functions seem to be missing from the runtime profile table they may not have been instrumented correctly, or were not called during execution. A runtime profile might look like this:
Runtime profile
+-------+-----------+-----------+-----------+----------+--------+------+
| Calls | t_excl[s] | t_excl[%] | t_incl[s] | Function | Caller | STID |
+-------+-----------+-----------+-----------+----------+--------+------+
| 1 | 2.000 | 49.7 | 3.020 | bar | main | 4 |
| 1 | 1.019 | 25.3 | 1.019 | foo | bar | 3 |
| 1 | 1.003 | 24.9 | 1.003 | foo | main | 2 |
| 1 | 0.000 | 0.0 | 4.022 | main | init | 0 |
| 0 | 0.000 | 0.0 | 0.000 | init | ---- | 1 |
+-------+-----------+-----------+-----------+----------+--------+------+
The columns are:
-
Calls: How often this function was called during execution. -
t_excl[s]: Time in seconds spent in this function, excluding time spent in further instrumented functions called by this function. By default the table is sorted by this column in descending order. -
t_excl[%]: Percentage of total runtime spent in this function, excluding time spent in further instrumented functions called by this function. -
t_incl[s]: Time in seconds spent in this function, including time spent in further instrumented functions called by this function. -
Function: Name/Symbol of the function. In case of C++, this name can be very convoluted. Settingdemangle_cxxin the config file make Vftrace demangle the function names, making them easier to read. -
Caller: Caller of the function. If a function is called by multiple other functions it appears multiple times in the profiling table. Vftrace takes the entire callstack of a function into account. In the examplefoois called twice. Once bymainonce bybar, thus appears twice in the table. -
STID: A unique ID used to identify the complete call history of this function call. The IDs are translated into stacks in Application Profiling#Global Call Stacks.
In addition to the runtime profile, where every call stack gets it's own entry, Vftrace can output a profile table, where all entries are summed over function names. It can be activated by setting the show_table variable in the name_grouped_profile_table section of the config file.
The table looks like this:
Runtime profile (Grouped by function name)
+-------+-----------+-----------+-----------+----------+-------+
| Calls | t_excl[s] | t_excl[%] | t_incl[s] | Function | STIDs |
+-------+-----------+-----------+-----------+----------+-------+
| 2 | 2.022 | 50.3 | 2.022 | foo | 2,3 |
| 1 | 2.000 | 49.7 | 3.020 | bar | 4 |
| 1 | 0.000 | 0.0 | 4.022 | main | 0 |
| 0 | 0.000 | 0.0 | 0.000 | init | 1 |
+-------+-----------+-----------+-----------+----------+-------+
If MPI is enabled Vftrace outputs a communication profile in the logfile.
It gives you information about the amount, size, and bandwidth of messages exchanged between ranks. It can be activated by setting the show_table value of the mpi section in the config file.
The table looks like this:
Communication profile
+----------+------------------+------------------+------------------+------------------+------------------+-----------+--------+------+
| Messages | avg send size[B] | avg recv size[B] | avg send BW[B/s] | avg recv BW[B/s] | avg comm time[s] | Function | Caller | STID |
+----------+------------------+------------------+------------------+------------------+------------------+-----------+--------+------+
| 12 | 2.616e+05 | 0.000e+00 | 8.036e+08 | 0.000e+00 | 6.752e-04 | MPI_Isend | main | 3 |
| 12 | 0.000e+00 | 2.616e+05 | 0.000e+00 | 1.253e+09 | 5.140e-04 | MPI_Recv | main | 2 |
+----------+------------------+------------------+------------------+------------------+------------------+-----------+--------+------+
- Messages: Number of messages send and received in total by all ranks for this function.
- avg send/recv size[B]: Average size in Bytes of send/received messages.
- avg send/recv BW[B/s]: Average bandwidth in Bytes per second of send/received messages.
- avg comm time[s]: Time in seconds spent in communication routine (blocking calls), or until a request was fulfilled (non-blocking calls).
- Function: Name/Symbol of the function.
- Caller: Caller of the function. If a function is called by multiple other functions it appears multiple times in the profiling table. Vftrace takes the entire callstack of a function into account.
- STID: A unique ID used to identify the complete call history of this function call. The IDs are translated into stacks in Application Profiling#Global Call Stacks.
The profile tables contain a stack identification number STID.
The table following the profile tables identifies the call stack of all encountered instrumented functions.
A callstack foo<bar<main<init can be interpreted like this:
- foo was called by bar
- bar was called by main
- main was called by init
The stack IDs are assigned deterministically by sorting hashed call-stack strings,
thus appear to be randomly assigned.
The stack ID is preceded by STID to make searching for specific IDs easier with grep, or within editors.
Global call stacks:
-----------------------------
STID Call stack
-----------------------------
STID0 main<init
STID1 init
STID2 foo<main<init
STID3 foo<bar<main<init
STID4 bar<main<init
-----------------------------
At the end of the logfile Vftrace writes the configuration that was used during profiling in form of a JSON file. More on how to use the configuration to tune Vftrace's run time behavior is layed out in detail in Runtime Control. A typical configuration at the end of the logfile looks like this:
Vftrace configuration read from "config.json"
{
"off": false,
"output_directory": ".",
"outfile_basename": null,
"logfile_for_ranks": "none",
"print_config": true,
"strip_module_names": false,
"demangle_cxx": false,
"include_cxx_prelude": false,
"profile_table": {
"show_table": true,
"show_calltime_imbalances": false,
"show_callpath": false,
"show_overhead": false,
"sort_table": {
"column": "time_excl",
"ascending": false
}
},
"name_grouped_profile_table": {
"show_table": false,
"max_stack_ids": 8,
"sort_table": {
"column": "time_excl",
"ascending": false
}
},
"sampling": {
"active": false,
"sample_interval": 0.005000,
"outbuffer_size": 8,
"precise_functions": null
},
"mpi": {
"show_table": true,
"log_messages": true,
"only_for_ranks": "all",
"show_sync_time": false,
"show_callpath": false,
"sort_table": {
"column": "none",
"ascending": false
}
},
"cuda": {
"show_table": true,
"sort_table": {
"column": "time",
"ascending": false
}
},
"hardware_scenarios": {
"active": false
}
}If sampling is activated in the configuration (see Runtime Control#Config File)
an application writes a vfd-file in addition to a logfile.
For MPI-parallel applications, every rank writes one.
They are named <executable-name>_<rankID>.vfd.
VFD-files are binary files where a timeline of the applications execution is recorded.
It can be brought into human readable form with the vftrace_vfd_dump tool (see Tools#vftrace_vfd_dump).
#include <stdlib.h>
#include <mpi.h>
int foo() {
return 1;
}
int bar() {
return foo()+1;
}
int main() {
MPI_Init(NULL, NULL);
foo();
bar();
int a;
MPI_Bcast(&a, 1, MPI_INT, 0, MPI_COMM_WORLD);
MPI_Finalize();
return 0;
}mpicc -finstrument-functions -o test.x test.c -L<vftrace-install-path>/lib/ -lvftrace
mpirun -np 4 ./test.x
<vftrace-install-path>/bin/vftrace_vfd_dump test.x_0.logThe dumped vfd-file contains three sections:
The Header contains general information about the application execution and information necessary to parse the rest of the vfd-file.
Version ID: Vftrace 2.0.0
Start Date: Tue Nov 15 12:14:34 2022
End Date: Tue Nov 15 12:14:35 2022
Processes: 0 of 4
Threads: 1
Sample interval: 0.000000e+00 seconds
Job runtime: 0.401 seconds
Samples: 19
Function: 15
Messages: 4
Unique stacks: 8
Stacks offset: 0x24c
Sample offset: 0x8c
Thread offset: 0x2c5
- Version ID: The Vftrace version with which this vfd-file was generated.
- Start/End Date: Timestamp of when the application started/ended.
- Processes: Process ID of this vfd-file and number of processes during application execution.
- Threads: Number of OMP-threads that were used in total during application execution.
- Sample interval: Minimum time in seconds between two consecutive samples (for more information check Runtime Control#Config File)
- Job runtime: Runtime of the application in seconds.
- Samples: Number of samples that were taken during application execution and stored in this vfd-file
- Function: Number of function-entry/exit samples.
- Messages: Number of message samples.
- Unique stacks: Number of individual call stacks that were encountered during application execution
- Stacks/Sample/Thread offset: Offset address of certain sections in the vfd-file. These are only important for parsing the rest of the vfd-file.
The Stack list contains all callstacks that were encountered during application execution. They are numbered according to the order in which they were encountered during runtime. An asterisk at the end of a function name corresponds to a "precise" function (see Runtime Control#Config File).
Stacks list:
0: init
1: main<init
2: MPI_Init*<main<init
3: foo<main<init
4: bar<main<init
5: foo<bar<main<init
6: MPI_Bcast*<main<init
7: MPI_Finalize*<main<init
This section contains the timeline of events that were sampled during application execution. There are two kinds of samples.
They consist of a timestamp in seconds since program start,
followed by an action (call/exit) depending whether this sample corresponds to the call of a function or a return therefrom.
Last is the callstack, the action was executed on. E.g. 0.401179 call foo<bar<main<init after 0.4s the function foo was called by the function bar.
They consist of three lines. The first one consists of the time stamp when the message sending/receiving was started, the executed action send/recv, the StackID (See Application Profiling#Stacks List), and the ID of the Thread (currently only 0). The second line contains information about the message itself.
- count: Amount of elements in the message.
- Type: The type of message element and it's size in bytes.
- rate: The bandwidth whith which the message was send/received.
- peer: The rank-id of the peer process that received/send the message. All MPI communication including collectives are broken down into a set of pairwise messages for vfd-sampling.
- tag: The MPI-Tag as required by some messages (If no tag was supplied, it is -1).
The last line contains the timestamp of when the message sending/receiving was complete, followed bye the action send/recv. A complete samples section can look like this:
Stack and message samples:
0.006795 call main<init
0.006814 call MPI_Init*<main<init
0.401172 exit MPI_Init*<main<init
0.401174 call foo<main<init
0.401177 exit foo<main<init
0.401177 call bar<main<init
0.401179 call foo<bar<main<init
0.401180 exit foo<bar<main<init
0.401180 exit bar<main<init
0.401180 call MPI_Bcast*<main<init
0.401182 send in stackID 6 from threadID 0
count=1 type=MPI_INT(4Bytes) rate= 0.2813 MiB/s peer=0 tag=-1
0.401196 send end
0.401182 send in stackID 6 from threadID 0
count=1 type=MPI_INT(4Bytes) rate= 0.2813 MiB/s peer=1 tag=-1
0.401196 send end
0.401182 send in stackID 6 from threadID 0
count=1 type=MPI_INT(4Bytes) rate= 0.2813 MiB/s peer=2 tag=-1
0.401196 send end
0.401182 send in stackID 6 from threadID 0
count=1 type=MPI_INT(4Bytes) rate= 0.2813 MiB/s peer=3 tag=-1
0.401196 send end
0.401202 exit MPI_Bcast*<main<init
0.401202 call MPI_Finalize*<main<init
0.401213 exit MPI_Finalize*<main<init
0.401214 exit main<init
0.401204 exit init