interaction with gprof

[Salvatore Filippone]

Follow up: I have found the *actual* subroutine called.
-----------------------------------------------
                0.00   88.43     816/816         psb_d_base_inner_vect_sv_ [19]
[20]    30.4    0.00   88.43     816         psb_d_csr_cssv_ [20]
               88.43    0.00     816/816         psb_s_fix_coo_ [21]
                0.00    0.00    1632/20175368
__psb_string_mod_MOD_psb_toupperc [107]
                0.00    0.00     816/163361240
__psb_error_mod_MOD_psb_erractionrestore [113]
                0.00    0.00     816/180409801
__psb_error_mod_MOD_psb_erractionsave [110]
                0.00    0.00    1632/31338388
__psb_base_mat_mod_MOD_psb_base_get_nrows [173]
                0.00    0.00     816/2425
__psb_base_mat_mod_MOD_psb_base_is_asb [1159]
                0.00    0.00     816/2233
__psb_base_mat_mod_MOD_psb_base_is_triangle [1160]
                0.00    0.00     816/816
__psb_base_mat_mod_MOD_psb_base_is_lower [1172]
                0.00    0.00     816/1423
__psb_base_mat_mod_MOD_psb_base_is_unit [1165]
--------------------------------------------------
Now the peculiar thing is that psb_d_csr_cssv does *not* call
psb_s_fix_coo; rather, it calls an internal (contained) subroutine
(called inner_csrsv). It would seem that internal subroutines are
confusing the profiler; I vaguely remember seeing other instances, can
dig some more if needed.

So I ask again: is this a bug or a known feature?

Thanks
Salvatore


On Mon, Nov 18, 2013 at 1:58 PM, Salvatore Filippone
<filippone.salvatore@gmail.com> wrote:
> Hello,
> I have been tracking some performance issues, and I  came across
> something strange.
> I have a test program taken from my numerical libraries which I am
> using on a certain test case; I have been using the -pg option
> (together with -O3) to investigate hotspots, and I have found that
> compiling with 4.6.4 and 4.8.2, exact same program  and test case,
> produces two different profiles. The first few lines are as follows:
> -------------------------------------------------------
> 4.6.4:
> --------------------------------------------------------
> Flat profile:
>
> Each sample counts as 0.01 seconds.
>   %   cumulative   self              self     total
>  time   seconds   seconds    calls   s/call   s/call  name
>  28.01     88.60    88.60      816     0.11     0.11  psb_s_coo_csgetrow_
>  10.31    121.23    32.63      601     0.05     0.05  psb_d_csr_csmv_
>   7.82    145.96    24.73     1069     0.02     0.02  daxpby_
>   7.77    170.55    24.59    27320     0.00     0.00
> __mld_diluk_impl_mod_MOD_iluk_fact
>   6.80    192.05    21.50 79808971     0.00     0.00  msort_up_
>   3.32    202.55    10.50      325     0.03     0.03
> __psb_d_base_vect_mod_MOD_d_base_bld_x
>   2.72    211.16     8.61        6     1.44     1.44  dnumbmm_
>   2.67    219.62     8.46      325     0.03     0.03
> __psb_d_base_vect_mod_MOD_d_base_zero
>   2.66    228.05     8.43 67196690     0.00     0.00  psi_int_heap_get_first_
>   2.64    236.40     8.35        6     1.39     2.49  symbmm_
> -------------------------------------------------------
> 4.8.2
> -------------------------------------------------------
> Flat profile:
>
> Each sample counts as 0.01 seconds.
>   %   cumulative   self              self     total
>  time   seconds   seconds    calls   s/call   s/call  name
>  30.43     88.43    88.43      816     0.11     0.11  psb_s_fix_coo_
>  11.14    120.80    32.37      601     0.05     0.05  psb_d_csr_csmv_
>   9.49    148.38    27.58        1    27.58   113.22
> __mld_diluk_impl_mod_MOD_mld_diluk_factint
>   6.92    168.50    20.12 79808971     0.00     0.00  msort_up_
>   4.09    180.38    11.88     1069     0.01     0.01  daxpby_
>   3.72    191.19    10.81      325     0.03     0.03
> __psb_d_base_vect_mod_MOD_d_base_bld_x
>   2.91    199.66     8.47        6     1.41     2.52  symbmm_
>   2.91    208.12     8.46        6     1.41     1.41  dnumbmm_
>   2.77    216.17     8.05 67196690     0.00     0.00  psi_int_heap_get_first_
>   2.69    224.00     7.83       31     0.25     1.01  psb_d_fix_coo_inner_
>
> ========================================================
> Now the disturbing fact is that the first routine mentioned in the
> profile, with the same number of calls and the same accumulated time,
> appears with two different names, and BOTH NAMES ARE WRONG.
> In my naming scheme the _s_ stands for single precision version,
> whereas the program (as can be seen from the second routine
> psb_d_csr_csmv) is a double precision version, no single precision
> routine is called. Indeed I even put some prints in the two routines
> that GPROF is saying are called, and they do not show up.
>
> So my question is: is this supposed to work?
> If not, why (aka, what am I doing wrong)?
> If yes, is it a problem on gprof's side, gfortran's side, an
> interaction with MPI wrappers, all of the above, none of the above?
> Anybody has any suggestions on how to reduce this and/or want to look
> at the source code?
> Thanks
>
> Very perplexed yours
> Salvatore