Re: Profiling Ada applications using gprof

[Petter Fryklund <petter.fryklund@atero.se>]

Den tisdag 4 december 2018 kl. 16:04:42 UTC+1 skrev joak...@kth.se:
> Consider the following code:
> 
> with Ada.Text_IO;
> procedure Main is
> 
>    task A is
>       entry Stop;
>    end A;
>    
>    task body A is
>    begin
>       select
>          accept Stop do
>             delay 10.0;
>          end Stop;
>       end select;
>    end A;
>    
>    procedure Work is
>    begin
>       A.Stop;
>    end Work;
>    
> begin
>    Work;
>    Ada.Text_IO.Put_Line ("Stopped");
> end Main;
> 
> It is an application that takes 10.17 seconds to execute and "the problem" is the call A.Stop which takes too long (10 seconds) to return. The hope is to find this time consuming call with gprof.
> 
> The code is built with the file default.gpr:
> 
> project Default is
>    for Source_Dirs use ("src");
>    for Object_Dir use "obj";
>    for Main use ("main.adb");
>    
>    package Compiler is
> 
>       for Switches ("Ada") use
>         (
>          "-g",
>          "-pg"
>         );
>    
>    end Compiler;
>    
>    package Linker is
> 
>       for Switches ("Ada") use
>         (
>          "-g",
>          "-pg"
>         );
>    
>    end Linker;
>    
> end Default;
> 
> Running the application creates a file gmon.out and running gprof on it and save the result in result.txt:
> gprof --demangle=gnat main gmon.out > result.txt
> 
> Looking at the contents of result.txt:
> 
> Flat profile:
> 
> Each sample counts as 0.01 seconds.
>  no time accumulated
> 
>   %   cumulative   self              self     total           
>  time   seconds   seconds    calls  Ts/call  Ts/call  name    
>   0.00      0.00     0.00        2     0.00     0.00  main
>   0.00      0.00     0.00        1     0.00     0.00  <ada_main__Tsec_default_sized_stacksBIP>
>   0.00      0.00     0.00        1     0.00     0.00  ada_main'Elab_Body
>   0.00      0.00     0.00        1     0.00     0.00  ada_main.finalize_library
>   0.00      0.00     0.00        1     0.00     0.00  adafinal
>   0.00      0.00     0.00        1     0.00     0.00  adainit
>   0.00      0.00     0.00        1     0.00     0.00  frame_dummy
> 
> ...
> 
> 		     Call graph (explanation follows)
> 
> 
> granularity: each sample hit covers 2 byte(s) no time propagated
> 
> index % time    self  children    called     name
>                 0.00    0.00       1/1           ada_main'Elab_Body [2]
> [1]      0.0    0.00    0.00       1         <ada_main__Tsec_default_sized_stacksBIP> [1]
> -----------------------------------------------
>                 0.00    0.00       1/1           adainit [5]
> [2]      0.0    0.00    0.00       1         ada_main'Elab_Body [2]
>                 0.00    0.00       1/1           <ada_main__Tsec_default_sized_stacksBIP> [1]
> -----------------------------------------------
>                 0.00    0.00       1/1           system.tasking.stages.finalize_global_tasks [1193]
> [3]      0.0    0.00    0.00       1         ada_main.finalize_library [3]
> -----------------------------------------------
>                 0.00    0.00       1/1           main [456]
> [4]      0.0    0.00    0.00       1         adafinal [4]
> -----------------------------------------------
>                 0.00    0.00       1/1           main [456]
> [5]      0.0    0.00    0.00       1         adainit [5]
>                 0.00    0.00       1/1           ada_main'Elab_Body [2]
> -----------------------------------------------
>                 0.00    0.00       1/1           main [1278]
> [6]      0.0    0.00    0.00       1         frame_dummy [6]
> -----------------------------------------------
>                                    4             main [1278]
>                 0.00    0.00       1/2           main [456]
>                 0.00    0.00       1/2           system.tasking.stages.task_wrapper [1196]
> [1278]   0.0    0.00    0.00       2+4       main [1278]
>                 0.00    0.00       1/1           frame_dummy [6]
>                                    4             main [1278]
> -----------------------------------------------
> 
> As one can see there is nothing that indicates that something takes around 10 seconds to execute. Is it really impossible to detect the long running entry call A.Stop?
> 
> Best regards,
> Joakim

Isn't a or missing before delay 10.0? The rendoz-vous will always take 10 sec. And then you can skip the do thing:

select 
  accept Stop;
or 
  delay 10.0;
end select;  

Regards,
Petter