# Presentation: 424068

## Profiler Introduction

- 1. Features
- 2. Using the profiler
- 3. Notes
- 4. Manual Profiling

## Profiler Overview

- Get cpu time/memory usage/hw counters by routine/line/node/job
- Easy to use: compile and link with one of:
- -Mprof=func
- -Mprof=lines
- Run the job as usual.
- Easy to get profile results: just run ‘profile’

## Profiler FeaturesCpu time/HW counters

- Low overhead: 1-10% overhead depending on features
- Precise: not based on sampling
- Function-level and basic-block-level profiling (R2.7)
- -Mprof=func for function level profiling
- -Mprof=lines profiles at the 'basic block' level
- CPU time and hardware (HW) counters. (R2.7)
- Always get cpu time for function level-profiling. Elapsed time and self-time (elapsed minus profiled children).
- Optionally specify 2 HW counters to monitor at function level.(R2.7)
- setenv PROFILE_COUNTERS PP_FLOPS,PP_RESOURCE_STALLS
- Get 'self' and elapsed counter values by routine. (R2.7)
- Optionally specify that one of the counters be used for line level profiling instead of using cpu time. (R2.7)
- setenv PROFILE_COUNTERS PP_FLOPS,LINE,PP_RESOURCE_STALLS
- List of HW counters with descriptions is on the web:
- http://www.sandia.gov/ASCI/Red/usage/perfeva.htm

## Profiler FeaturesMemory usage/Env. variables

- Stack and Heap usage (R2.8)
- Always get max stack and heap usage. Profiler reports max used, node and routine that hit the value. You can use the debugger to stop your application when the high water mark is hit.
- If you want more memory usage data, you can monitor malloc/free by setting the environment variable PROFILE_WATCH_HEAP. See below for more on this feature.
- Environment Variables
- PROFILE_TURN_OFF: turns off profiling (R2.8)
- PROFILE_START_WITH_ROUTINE routine_name (R2.7)
- Profile only routine_name and its children. Permits timing of ‘solver’ while excluding startup/shutdown.
- PROFILE_COUNTERS hw_counter0[,LINE][,hw_counter1] (R2.7)
- Specify HW counters for function profiling (and line-level profiling optionally). See /usr/include/perfmon.h for list of counters.

## Profiler FeaturesMore Env. Variables

- Env variables (cont.)
- PROFILE_WATCH_HEAP (R2.8)
- If this variable is found, the profiler collects total bytes malloc’d and free’d by routine, net bytes malloc’d/free’d by self and children, high heap watermark, and fragments. Can’t be used with PROFILE_COUNTERS. Use ‘profile -m ...’.
- PROFILE_GSYNC_ROUTINE routine_name (R2.8)
- Insert global sync()s before and after routine_name. Report time each node spends waiting at each gsync(). All nodes must execute routine (due to the gsyncs). This helps determine load balancing by node. Use ‘profile -g’
- PROFILE_COMMENT comment_string (R2.7)
- comment_string will be written into profile data sets.
- PROFILE_DIR directory_name (R2.7)
- Write profile datasets to directory_name. Default subdirectory is ‘pmon.out’.

## Profiler FeaturesCall Tree/Ancestor Tree/Load Bal.

- Call tree (R2.7)
- For each called routine, show how much of the cpu time is due to each caller. Use ‘profile -C ...’.
- Ancestor tree (R2.8)
- Invert the call tree. Still a ‘beta’ feature. Use ‘profile -A ...’
- Load balancing (R2.7)
- Use ‘profile -b ...’ get high/low/ave/dev. Cpu time for each routine by node.

## Profiler:Compiling/Running/Getting Results

- How to compile
- Use ‘-Mprof=func’ for function level profiling.
- Use ‘-Mprof=lines’ for basic block level profiling.
- If you are compiling with ‘-O2’, then a basic block might be one to hundreds of source code lines. This option will slow performance maybe by 2x.
- If you compile with ‘-O0’, the basic block is 1 line and performance will really suffer overheads, but the relative line number performance should be correct.
- How to run
- Run the job as usual. Output files are put in subdirectory pmon.out in the current directory by default.
- How to get results
- Run ‘profile’ (/usr/bin/profile).
- Run ‘profile -h’ for options.

## Profiler exampleexam1.c - the basics on 1 node

- janus> cat exam1.c
- void sub2() { sleep(10); }
- void sub1() { sub2();sleep(4); }
- int main() {
-   sub1();
-   sleep(2);
-   return 0;
- }
- janus> pgcc -cougar exam1.c -Mprof=func -o tstc
- Linking:
- janus> yod -sz 1 tstc

## Profiler exampleexam1.c - Profile output

- janus> profile -C
-          Profile Data Summary
- Code:    tstc
- Last Mod:  Mon Sep 13 13:15:33 1999   Size: 392216
- Run on:    Mon Sep 13 13:27:38 1999   CWD:  /Net/usr/home/pfay
- nodes:    1    proc mode: 0   elapsed time:    16.00 wall_sec.
- Max stack used:          32   Max stack avail:     2097152
- Node/Rtn which hit max stack: 0000,sub2
- Max heap used:       112800   Node/Rtn which hit max heap: 0000,sub2
- Elapsed time=   16.000068 (node secs)  for start with routine= main
- Routine            #calls     Time        Time     Cumu.  File
-                               (sec)        (%)     Time
- --------------------------------------------------------------------
- sub2                     1      10.00002  62.500    10.00 exam1.c
- sub1                     1       4.00002  25.000    14.00 exam1.c
- main                     1       2.00003  12.500    16.00 exam1.c

## Profiler Exampleexam1.c - Call Tree

- janus> profile -C
-          Profile Data Summary
- ...
-                          Call Tree Data
- Routine                            #calls    Time      Self        Cumu.
-      Called by                             per call    Time        Time
- -------------------------------------------------------------------------
- sub2
-      sub1                              1   10.00002      10.000      10.000
- sub1
-      main                              1    4.00002       4.000      14.000
- main

## Profiler Exampleexam1.c - Running on 2 nodes

- Now on 2 nodes:
- janus> yod -sz 2 tstc
- janus> profile -C
-          Profile Data Summary
- Code:    tstc
- Last Mod:  Mon Sep 13 13:15:33 1999   Size: 392216
- Run on:    Mon Sep 13 13:29:00 1999   CWD:  /home/pfay/ark/pres/prof_sam
- nodes:    2    proc mode: 0   elapsed time:    16.00 wall_sec.
- Max stack used:          32   Max stack avail:     2097152
- Node/Rtn which hit max stack: 0001,sub2
- Max heap used:       902912   Node/Rtn which hit max heap: 0000,sub2
- Elapsed time=   32.000122 (node secs)  for start with routine= main
- Routine            #calls     Time        Time     Cumu.  File
-                               (sec)        (%)     Time
- -----------------------------------------------------------------------------
- sub2                     2      20.00002  62.500    20.00 exam1.c
- sub1                     2       8.00005  25.000    28.00 exam1.c
- main                     2       4.00005  12.500    32.00 exam1.c

## Profiler Exampleexam1.c - Call Tree for 2 nodes

- And the call tree:
-  Call Tree Data
- Routine                            #calls    Time      Self        Cumu.
-      Called by                             per call    Time        Time
- -------------------------------------------------------------------------
- sub2
-      sub1                              2   10.00001      20.000      20.000
- sub1
-      main                              2    4.00003       8.000      28.000
- main

## Profiler Exampleexam2.c - Using the HW Counters to Gets Flops by Routine

- Now for a hw counter example:
- janus> setenv PROFILE_COUNTERS PP_FLOPS
- janus> cat exam2.c
- double x=0.0;
- void add_to_x(){ int i; for(i=0;i<100;i++){x +=1.0;}}
- void sub2() { add_to_x(); }
- void sub1() { sub2();add_to_x(); }
- int main() {
-   sub1();
-   add_to_x();
-   return 0;
- }
- janus> pgcc -cougar exam2.c -Mprof=func -o tstc

## Profiler Exampleexam2.c - Display the flops

- janus> yod -sz 1 tstc
- janus> profile -p
-          Profile Data Summary
- Code:    tstc
- Last Mod:Mon Sep 13 13:4  Size:           392487
- Run on:  Mon Sep 13 13:4  cwd:  /Net/user/home/pfay
- nodes:    1    proc mode: 0   elapsed time:    0.000 wall_sec.
- Max stack used:          32   Max stack avail:     2097152
- Node/Rtn which hit max stack: 0000,add_to_x
- Max heap used:       112800   Node/Rtn which hit max heap: 0000,add_to_x
- Elapsed time=       5e-05 (node secs)  for start with routine= main
- Routine             #calls          Time    Time   Cumu.       PP_FLOPS
-                                    (sec)     (%)   Time          (self)(self+chld)
- ------------------------------------------------------------------------------------
- sub2                     1       0.00002  32.000     0.00             2      103
- main                     1       0.00002  30.000     0.00             3      311
- add_to_x                 3       0.00001  26.000     0.00           303      303
- sub1                     1       0.00001  12.000     0.00             3      207

## Profiler & Load BalanceSample Code

- #include "mpi.h"
- void wait1(int nsec)
- {
-        sleep(nsec);
- }
- void wait2(int nsec,int max)
- {
-         int shortwait, longwait;
-         shortwait = 10;
-         longwait = 45;
-         if (nsec == 0) {
-                 sleep(0);
-         }else if (nsec == (max-1)) {
-                 sleep(longwait);
-         } else {
-                 sleep(shortwait);
-         }
- }
- void dummy1()
- {
-          MPI_Barrier(MPI_COMM_WORLD);
- }
- void dummy2()
- {
-          MPI_Barrier(MPI_COMM_WORLD);
- }

- void main(int argc, char **argv)
- {
-         int rank,size;
-         MPI_Init(&argc,&argv);
-         MPI_Comm_rank( MPI_COMM_WORLD, &rank );
-         MPI_Comm_size( MPI_COMM_WORLD, &size );
-         wait1(rank);
-         dummy1();
-         wait2(rank,size);
-         dummy2();
- }
**wait1() takes ‘rank’ sec per node**
**dummy1 is just a sync**
**wait2() is more complicated**
- node 0 takes essentially zero time
- node “size-1” takes 45 sec.
- Others take 10

## First Look with Profiler,Basic and PROFILE_GSYNC_ROUTINE

- Profile on 8 nodes
- Routine            #calls     Time        Time     Cumu.  File
-                               (sec)        (%)     Time
- ---------------------------------------------------------------------
- dummy2                   8     255.00167  61.126   255.00 waittest.c
- wait2                    8     105.00035  25.169   105.00 waittest.c
- dummy1                   8      28.00116   6.712    28.00 waittest.c
- wait1                    8      28.00026   6.712    28.00 waittest.c
- main                     8       1.17210   0.281   417.18 waittest.c
- So it looks like dummy1 and dummy2 are significant, from this
- use PROFILE_GSYNC_ROUTINE dummy2
- Routine            #calls     Time        Time     Cumu.  File
-                               (sec)        (%)     Time
- --------------------------------------------------------------------
- main                     8     256.18515  61.407   417.19 waittest.c
- wait2                    8     105.00037  25.169   105.00 waittest.c
- dummy1                   8      28.00110   6.712    28.00 waittest.c
- wait1                    8      28.00026   6.712    28.00 waittest.c
- dummy2                   8       0.00231   0.001     0.00 waittest.c

## Looking at wait1() & wait2()

- No PROFILE_GSYNC_ROUTINE
- run on 64 nodes; profile -b
-                 nodes   Time                          Calls
- --------------------------------------------------------------------------------
- Routine               |  Min       Max      Avg.     |  Min.    Max.  Avg.
-                       |  node      node     sigma    |  node    node  sigma
-                       |                     frac     |                frac
- --------------------------------------------------------------------------------
- dummy2             64     0.000    45.000    34.610        1       1       1
-                              63         0     4.533       63      63     0.0
-                                               0.969                    0.000
- dummy1             64     0.000    63.000    31.500        1       1       1
-                              63         0    18.473       63      63     0.0
-                                               0.563                    0.000
- wait1              64     0.000    63.000    31.500        1       1       1
-                               0        63    18.473       63      63     0.0
-                                               0.563                    0.000
- wait2              64     0.000    45.000    10.391        1       1       1
-                               0        63     4.533       63      63     0.0
-                                               0.969                    0.000

## Interpreting the Output

- All routines are called once per node.
- Wait1()
- consumes 0 seconds on node 0, and 63 seconds on node 63
- avg time spent in wait1 over all nodes is 31.5 sec
- width (rms) of distribution of times is 18.47
- only about half of the nodes are within one rms of the avg
*so the times for wait1 are all over the place*
- wait2()
- consumes 0 seconds on node 0, and 45 seconds on node 63
- avg time spent in wait2 over all nodes is 10.391 sec
- width (rms) of distribution of times is 4.53
- 97% of nodes are within one rms of the avg.
*so the times for wait2 are clustered around 10 sec, with a couple of outliers*

## Profiler Notes - 2nd CPU and Useful HW Counters

- The 2nd CPU is ‘handled’ by not allowing the 2nd cpu to enter the profiler ‘hook’ routines. If you’ve compiled with OMP (pgcc -cougar -mp ...) and you’ve used proc 2 mode (yod -proc 2 -sz ...), the profiler doesn’t collect any data for the 2nd CPU. You will have to infer that the change in cpu time for your OMP routine is due to the 2nd processor. The profiler is thread safe.
- Useful HW counters:
- PP_FLOPS the number of flops (more or less)
- PP_FP_ASSIST Usually corresponds to number of NANs
- PP_CYCLES_DIV_BUSY cpu cycles that the divide unit was busy. Divides are slooow. Try to replace with inverse operation.
- PP_MISALIGN_MEM_REF Misaligned memory references can really slow down code. Unfortunately, many cougar message passing routines generate misaligned references.
- PP_RESOURCE_STALLS Number of cycles the CPU was blocked waiting on some resource, usually memory. This is frequently 80-90% of total cpu time but if a certain loop has a very high stall count,then perhaps the loop indices can be swapped to access memory in a more efficient manner.
- PP_BUS_SNOOP_STALL Number of CPU clock cycles that the CPU was stalled fetching data out of the other CPU’s cache. Useful for OMP optimization.
- PP_DATA_MEM_REFS The number of loads and stores to registers

## Manual Profiling - genperf and perfrep

- Beginmflops, etc.. These routines don’t handle the hw counter overflow properly so if you get more than 2^30 events, the counters will wrap.
- There are a set of routines similar to the begin/end/print series that handle the wrap around properly. These are the genperf routines.
- Genperf can be simpler if you just want to collect something like flops for a loop or a subroutine.
- The list of genperf routines are on the web:
- http://www.sandia.gov/ASCI/Red/usage/genperf.html
- Unlike using the profiler with -Mprof=func, you need to link in libperfmon.a (so add ‘-lperfmon’ to the link command)
- We have a routine to globally block and return the number of flops on all nodes and processors: beginflopmon_(), endflopmon_(), printflopmon_()
- Genperf has cache info routines, flops, branch prediction and much more.
- Perfrep: These routines are designed to iterate over all hw counters, then generate a table of values. Useful for examining kernels in detail, or looking at sections of code within an application that is visited many times with similar data.  It does handle overflow and it prints out some additional computed quantities to assist optimization.

## Another Profile Example -- CTH

- Where to start? (Pretend we don’t know the answer)
- Pick representative dataset (efp3d.in, 8 nodes)
- compile with -Mprof=func
- run it.
-  Profile Data Summary
- Code:    /scratch/tmp_4/bhcole/cth/bin/tf/mpicth
- Last Mod:  Mon Sep 13 09:01:56 1999   Size: 5683742
- Run on:    Mon Sep 13 09:36:33 1999   CWD:  /scratch/tmp_4/bhcole/cth/pr
- nodes:    8  proc mode: 0   elapsed time:    233.6 sec.
- Routine            #calls     Time        Time     Cumu.  File
-                               (sec)        (%)     Time
- ----------------------------------------------------------------------
- cthsnd                2412     115.57845   6.893   115.58 mpmpi.F
- erpy                  4800     100.93678   6.020   234.01 erpy.F
- elsg                  4880      97.40255   5.809   101.36 elsg.F
- ermz                  4880      94.42748   5.631   160.52 ermz.F
- cthrcv                2412      91.38929   5.450    91.39 mpmpi.F
- bdsnde              143664      74.62850   4.451   257.35 bdsnde.F

## Messaging calls
erpy, elsg.  -- know there’s a lot of meat in there. OMP candidate if cache-friendly.
Performance counters:
PP_DATA_MEM_REFS: all memory references (memory or cache)
PP_L2_LINES_IN:  Number of cache lines (4 doubles or 8 floats each) that had to come in from memory.
Set env. variable PROFILE_COUNTERS PP_DATA_MEM_REFS,PP_L2_LINES_IN

nodes:    8  proc mode: 0   elapsed time:    228.6 sec.

Routine             #calls          Time    Time   Cumu.  PP_L2_LINES_I            PP_DATA_MEM_REF
                                   (sec)     (%)   Time          (self)  (self+chld)        (self)  (self+chld)
----------------------------------------------------------------------------------------------------------------
cthsnd                2412     116.20015   6.859   116.20        698677       698677   11392211209  11392211209
erpy                  4800     104.25719   6.154   238.87     113242733    196167754   13888374735  43360398351
elsg                  4880      97.86985   5.777   101.92      99701007    100295819   14885584301  15550245866
ermz                  4880      96.59638   5.702   163.15     181399829    274772956   14452980462  23422777400
cthrcv                2412      91.05389   5.374    91.05        272221       272221    9424437784   9424437784
bdsnde              143664      74.73297   4.411   257.60     194261860    495293743    3584845611  18637630975
Compute fraction of data from memory:
(4*PP_L2_LINES_IN)/(PP_DATA_MEM_REFS)
ERPY: 1.8% from memory -- good candidate!!
Go through, put the OMP directives in.
<erpy is rezone calculation in ydirection; one big main loop over columns. There’s a lot of work in each iteration of the main loop.>

- erpy, elsg.  -- know there’s a lot of meat in there. OMP candidate if cache-friendly.
- Performance counters:
- PP_DATA_MEM_REFS: all memory references (memory or cache)
- PP_L2_LINES_IN:  Number of cache lines (4 doubles or 8 floats each) that had to come in from memory.
- Set env. variable PROFILE_COUNTERS PP_DATA_MEM_REFS,PP_L2_LINES_IN
- nodes:    8  proc mode: 0   elapsed time:    228.6 sec.
- Routine             #calls          Time    Time   Cumu.  PP_L2_LINES_I            PP_DATA_MEM_REF
-                                    (sec)     (%)   Time          (self)  (self+chld)        (self)  (self+chld)
- ----------------------------------------------------------------------------------------------------------------
- cthsnd                2412     116.20015   6.859   116.20        698677       698677   11392211209  11392211209
- erpy                  4800     104.25719   6.154   238.87     113242733    196167754   13888374735  43360398351
- elsg                  4880      97.86985   5.777   101.92      99701007    100295819   14885584301  15550245866
- ermz                  4880      96.59638   5.702   163.15     181399829    274772956   14452980462  23422777400
- cthrcv                2412      91.05389   5.374    91.05        272221       272221    9424437784   9424437784
- bdsnde              143664      74.73297   4.411   257.60     194261860    495293743    3584845611  18637630975
- Compute fraction of data from memory:
- (4*PP_L2_LINES_IN)/(PP_DATA_MEM_REFS)
- ERPY: 1.8% from memory -- good candidate!!
- Go through, put the OMP directives in.
- <erpy is rezone calculation in ydirection; one big main loop over columns. There’s a lot of work in each iteration of the main loop.>

**What do we learn from this?**

## Taking the next step... More OMP

- Add OMP Directives to ERPY, debug it, etc.
- Run it w/ -proc 2 and profile again:
- Profile Data Summary
- Code:    /scratch/tmp_4/bhcole/cth/bin/tf/mpicth
- Last Mod:  Mon Sep 13 09:54:45 1999   Size: 5686754
- Run on:    Mon Sep 13 09:59:12 1999   CWD:  /scratch/tmp_4/bhcole/cth/pr
- nodes:    8  proc mode: 2   elapsed time:    215.1 sec.
- Routine            #calls     Time        Time     Cumu.  File
-                               (sec)        (%)     Time
- -----------------------------------------------------------------------------
- cthsnd                2412     111.39164   7.117   111.39 mpmpi.F
- elsg                  4880      97.56098   6.233   101.56 elsg.F
- ermz                  4880      94.81277   6.057   161.03 ermz.F
- cthrcv                2412      86.53987   5.529    86.54 mpmpi.F
- bdsnde              143664      74.76909   4.777   253.32 bdsnde.F
- erpx                  4800      65.66172   4.195   172.18 erpx.F
- erpy                  4800      58.99054   3.769   128.30 erpy.F
- Time spent in ERPY is down from 234.01 node-sec to 128.3 node-sec: a parallel efficiency of 91% for this routine.
- Overall elapsed time is not that much impacted from this single routine (233 sec to 215 sec.)
- *BUT* if you press on....

## CTH w/ “full” OMP utilization

- Profile Data Summary
- Code:    /scratch/tmp_4/bhcole/cth/bin/tf/mpicth
- Last Mod:  Mon Sep 13 10:24:21 1999   Size: 5557879
- Run on:    Mon Sep 13 10:34:21 1999   CWD:  /scratch/tmp_4/bhcole/cth/pr
- nodes:    8  proc mode: 2   elapsed time:    160.1 sec.
- Routine            #calls     Time        Time     Cumu.  File
-                               (sec)        (%)     Time
- -----------------------------------------------------------------------------
- bdsnde              143664      74.48228   6.664   203.23 bdsnde.F
- cthrcv                2412      70.36390   6.296    70.36 mpmpi.F
- ermz                  4880      61.95159   5.543    98.43 ermz.F
- cthsnd                2412      61.16924   5.473    61.17 mpmpi.F
- elsg                  4880      59.70557   5.342    61.87 elsg.F
- erpy                  4800      58.56535   5.240   127.19 erpy.F
- Run time is now down from 233 to 160 seconds!!!
- 1.45x speed-up