There are two basic rules for interpreting the output of the Analyzer:

• The time attributed to an instruction is the time that the instruction spent waiting to be executed - not the time that the instruction spent executing. So if you see an instruction which has a lot of time attributed to it - look at the previous instructions to determine which one is really to blame for the time. (Note that this means that the source code attribution of timing may not be totally accurate.)

• The processor hesitates before attributing time to floating point instructions, this means that in a sequence of floating point instructions, it is sometimes the case that the first couple do not get any time attributed to them - even when they really should.

Lets have a look at a couple of examples:

   0.            10980:  inc         9, %l6
   0.070         10984:  ld          [%i4 + %g2], %f16
   2.590         10988:  nop
   0.            1098c:  cmp         %l4, %l3

In the above example, the load instruction is actually taking all the time, but the 'nop' following it gets attributed with the 2.5 seconds of time.

   0.010        5699f0:  ldd         [%l0], %f0
   0.           5699f4:  fsubd       %f6, %f4, %f26
   2.630        5699f8:  ldd         [%l0 + %o1], %f2

In the above example, the first floating point load double actually causes the delay, but the processor hesitates in reporting the delay while it completes the floating point subtraction, and it finally reports the delay on second load.

Interpreting the analyzer output can be more of a skill. However, in most cases it is not too hard if you remember the above two rules. Note that there are other situations which can be confusing - for example a branch target might accumulate a large amount of time. The Analyzer documentation contains more details.

Returning to the example, let's have a look at how the attribution of time to the source code works:

$ er_print -metrics e.user:e.Rstall_FP_use -src main test.1.er
current: e.user:e.Rstall_FP_use:name
Source file: ./sumtest.c
Object file: ./sumtest.o
Load Object: ./sumtest

   Excl.     Excl.
User CPU  Rstall_FP_use
    sec.     Events sec.
                                     1. int main()
   0.        0.                      2. {
                                     3.   double d[20000];
                                     4.   double total,total1;
                                     5.   int count, rpt;
                                     6.
   0.        0.                      7.   for (count=0; count<20000; count++)
   0.        0.                      8.     d[count]=0.01;
                                     9.
   0.        0.                     10.   total=1;
   0.        0.                     11.   total1=0.5;
   0.        0.                     12.   for (rpt=0; rpt<50000; rpt++)
                                    13.   {
   0.        0.                     14.    for (count=0;count<20000;count++)
## 8.830     4.742                  15.     total+=total1*d[count];
   0.        0.                     16.    total1=total/1.776;
                                    17.   }
   0.        0.                     18.   if (total==0.5) return 1 ; else return 0;
                                    19. }

In this case I have asked er_print to:

• Use the metrics exclusive user CPU time, and exclusive Rstall_FP_use events (-metrics e.user:e.Rstall_FP_use). Rstall_FP_use is the hot performance counter that we collected the data for. It is quite useful to limit the number of columns of counter data reported, because interpreting the output can be tricky, and it's almost impossible to do if the lines wrap around.
• Show the source for the routine main (-src main). To show the source code you need to have compiled your application with debug information.

So immediately you can see (as you would expect) that the bulk of the time is spent on line 15 which does the summation part of the code. So we need to drill down a bit further to see what's going on at the assembly code level. Here's the disassembly code for the hottest routine, most of the code has been omitted for clarity.

$ er_print -metrics e.user:e.Rstall_FP_use -dis main test.1.er
current: e.user:e.Rstall_FP_use:name
Source file: ./sumtest.c
Object file: ./sumtest.o
Load Object: ./sumtest

   Excl.     Excl.
User CPU  Rstall_FP_use
    sec.     Events sec.
....
   0.        0.                         [12]    106d8:  add         %i2, 848, %l6
                                    13.   {
                                    14.    for (count=0;count<20000;count++)
   0.        0.                         [14]    106dc:  clr         %i1
   0.        0.                         [14]    106e0:  mov         %l4, %l7
                                    15.     total+=total1*d[count];
   0.400     0.903                      [15]    106e4:  ld          [%l7], %f0
   0.550     0.016                      [15]    106e8:  inc         %i1
   0.460     0.943                      [15]    106ec:  ld          [%l7 + 4], %f1
   0.720     0.                         [15]    106f0:  cmp         %i1, %l5
   0.        0.                         [15]    106f4:  fmuld       %f6, %f0, %f2
   0.        0.                         [15]    106f8:  faddd       %f8, %f2, %f8
## 6.240     2.879                      [15]    106fc:  bl          0x106e4
   0.460     0.                         [15]    10700:  inc         8, %l7
                                    16.    total1=total/1.776;
   0.        0.                         [16]    10704:  inc         %i3
...

In this case I have asked er_print to:

• Use the metrics exclusive user CPU time and exclusive number of cycles spent waiting for FP data (-metrics e.user:e.Rstall_FP_use).
• Disassemble the routine main (-dis main). Note that for real codes it is probably useful to use the option -outfile <filename> which will send all the following output to the specified file. The disassembly can get quite long, and it is probably best to either view it in an editor, or run the analyzer GUI.

You can see that the bulk of the time appears to be spent on the branch instruction.... however, from the discussion above, you'll be looking to see if the time is really caused by other instructions.

You can see nearly 3 seconds of FP use stalls on the branch. So we can be sure that the bulk of the time spent on that branch instruction is due to the proceeding floating point instructions.

So let's talk through this snippet of code.

Notice that there's two single-precision floating point load instructions, one to load %f0 and one to load %f1. What is happening here is that the compiler is assuming that the data is 4-byte aligned and therefore requires two four-byte loads rather than a single eight byte load. If you look at the fmuld instruction it consumes the double-precision floating point number %f0 (the double precision floating point register %f0 is made up of the two single precision registers %f0 and %f1). The compiler flag -dalign would help the compiler use a single floating point load double rather than the two floating point load singles.

The time attributable to the load instructions appears on the instructions following them. As expected there is little time here - the data is cache resident. However, if the arrays were larger, it would be useful for the compiler to insert prefetch instructions - the compiler will do this if the flags -xprefetch -xdepend -xtarget=ultra3 -xarch=v8plusa are used on the compile line.

Now we have the two floating point instructions. First the fmuld. Unfortunately the data that this instruction requires is provided by the second load instruction - this instruction will still be completing when the multiply gets issued - so there will be a delay at this point. Then there's the add. The add requires the data from the multiply - and it takes a couple of cycles for the multiply to complete - so once again there's another FP use stall.

Finally there is a branch instruction.

What can we do about this code? We can try to recompile with -fast to let the compiler be more aggressive with its optimizations. This may not be suitable for all codes, but we can give it a try for this one.

$ cc -g -fast -o sumtest sumtest.c
$ collect sumtest
Creating experiment database test.2.er ...
$ er_print -metrics e.user -func test.2.er
current: e.user:name
Functions sorted by metric: Exclusive User CPU Time

Excl.      Name
User CPU
 sec.
4.990      <Total>
4.990      main
0.         __collector_open_experiment
0.         __open
0.         _init
0.         _open
0.         _private_close
0.         _rt_boot

Now you can see that by increasing the optimization level from -O to -fast we went from nearly 9 seconds runtime down to about 5 seconds. Lets have a look at what it did to the hot bit of code to get this performance gain.

$er_print -metrics e.user -dis main test.2.er
current: e.user:name
Source file: ./sumtest.c
Object file: ./sumtest.o
Load Object: ./sumtest

   Excl.
User CPU
    sec.
...
                   Loop below pipelined with steady-state cycle count = 1 before  unrolling
                   Loop below unrolled 6 times
                   Loop below has 1 loads, 0 stores, 0 prefetches, 1 FPadds, 1 FPmuls, and 0 FPdivs per iteration
                    14.    for (count=0;count<20000;count++)
                    15.     total+=total1*d[count];
   0.                   [15]    106d0:  sethi       %hi(0x27000), %g1
....
   0.                   [14]    10764:  add         %g1, %fp, %l5
   0.                   [15]    10768:  fmuld       %f6, %f24, %f2
   0.                   [15]    1076c:  faddd       %f8, %f16, %f4
   0.210                [15]    10770:  inc         6, %i5
   0.080                [15]    10774:  ldd         [%l5], %f24
   0.                   [15]    10778:  fmuld       %f6, %f60, %f30
   0.                   [15]    1077c:  faddd       %f10, %f18, %f0
## 1.450                [15]    10780:  cmp         %i5, %i0
   0.                   [15]    10784:  ldd         [%l5 + 8], %f60
   0.                   [15]    10788:  fmuld       %f6, %f26, %f16
   0.                   [15]    1078c:  faddd       %f12, %f20, %f8
   0.130                [15]    10790:  ldd         [%l5 + 16], %f26
## 1.470                [15]    10794:  inc         48, %l5
   0.                   [15]    10798:  fmuld       %f6, %f24, %f18
   0.                   [15]    1079c:  faddd       %f14, %f22, %f10
   0.080                [15]    107a0:  ldd         [%l5 - 24], %f24
   0.                   [15]    107a4:  fmuld       %f6, %f60, %f20
   0.                   [15]    107a8:  faddd       %f4, %f2, %f12
   0.150                [15]    107ac:  ldd         [%l5 - 16], %f60
   0.                   [15]    107b0:  fmuld       %f6, %f26, %f22
   0.                   [15]    107b4:  faddd       %f0, %f30, %f14
## 1.440                [15]    107b8:  ble,pt      %icc,0x10768
   0.050                [15]    107bc:  ldd         [%l5 - 8], %f26
...

Let's discuss the commentary that the compiler inserts into the output. Here it is telling us:

• That the loop was unrolled six times. This means that six iterations of the loop were done back-to-back. This optimisation reduces the number of times that the processor has to take a branch.
• The loop was pipelined. This is a more complex optimisation where the next iteration of the loop is started before the current one completes - think of it as taking the six unrolled iterations of the loop and interleaving them so that one instruction is done from the first, then an instruction from the second etc. You can see this looking at the load at 0x10774, this loads %f24 which is used by the multiply at 0x10798. The multiply generates %f18 which is used by the add at 0x1077c.
• The compiler commentary also tells us of the instruction make up of the loop - the number of each type of instruction per iteration.

In this case the big gain comes from pipelining the loop, there's now sufficient time between one instruction generating a result and the instruction that requires that result.

There are a few other things that it is worth pointing out about the loop:

• -fast includes the -dalign flag, so the two loads of single precision values have now become a single load of a double precision value.
• The flag which allows the compiler freedom to do the floating point optimisations is -fsimple=2, which is included in -fast. This flag tells the compiler that it is not necessary to do the floating point calculations in the exact same order that they are specified in the code. So if you look at the floating point adds in the above disassembly, you can identify that what was in the source a simple summation, has been split into two separate summations (which will be added together after the loop completes). %f4, %f8, and %f12 are one group, and %f0, %f10, and %f14 are another group.