Profiling Ada applications using gprof

[joakimds@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