Profiling Ada applications using gprof

Profiling Ada applications using gprof

[joakimds]

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

Re: Profiling Ada applications using gprof

[Dennis Lee Bieber]

On Tue, 4 Dec 2018 07:04:40 -0800 (PST), joakimds@kth.se declaimed the
following:

>
>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?
>

	Hypothesis: your profiling is showing CPU time consumed by the program,
not wall-clock time -- but your 10 second DELAY statement could be a
blocking call depending upon how the run-time interface was created (ie:
block waiting for some timer to expire) and consumes no CPU while blocked.
(And your 0.17s could be the time the system takes to load the executable.)

	Change the DELAY to something that actually consumes CPU time and see
what happens.

		Start_T := ada.real_time.clock;
		while (Start_T + 10.0) > ada.real_time.clock loop
			null;
		end loop;


-- 
	Wulfraed                 Dennis Lee Bieber         AF6VN
	wlfraed@ix.netcom.com    HTTP://wlfraed.home.netcom.com/ 

Re: Profiling Ada applications using gprof

[Petter Fryklund]

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

Re: Profiling Ada applications using gprof

[joakimds]

> 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:

That's correct but consider the following thought experiment: Imagine being new in an Ada project with a mature code base which has been worked on for 20+ years and is around 2 million lines of Ada code. Imagine it takes a long time to shut down the application and the question is how to quickly find out why. Maybe somebody has put a long running calculation by mistake inside an entry call like in the example above where a delay statement has been used instead to simulate work being done. How is there any hope to find out quickly in the huge code base if it isn't possible in the tiny example code I have provided in the original post? How can one avoid manual inspection/review?

Re: Profiling Ada applications using gprof

[joakimds]

When Writing code oneself one could use select-statements to discover long running entry calls like:

   procedure Work is
   begin
      select
         delay 1.0;
         Ada.Text_IO.Put_Line ("Calling A.Stop takes too long time!");
      then abort
         A.Stop;
      end select;
   end Work;

But again, it would be cool if there was a way to discover long running entry calls by profiling (for example gprof).

Re: Profiling Ada applications using gprof

[Dmitry A. Kazakov]

On 2018-12-05 17:05, joakimds@kth.se wrote:
> When Writing code oneself one could use select-statements to discover long running entry calls like:
> 
>     procedure Work is
>     begin
>        select
>           delay 1.0;
>           Ada.Text_IO.Put_Line ("Calling A.Stop takes too long time!");
>        then abort
>           A.Stop;
>        end select;
>     end Work;
> 
> But again, it would be cool if there was a way to discover long running entry calls by profiling (for example gprof).

This is not an entry call, it is asynchronous transfer of control (RM 
9.7.4).

Regarding entry calls, a long running call of a protected entry is a 
bug, protected actions must be instant, nothing to profile. For a task 
entry, it is maybe not a quite bug, but suspicious nonetheless. Though, 
I presume that both must be detectable by the profiler.

I guess you mean something completely different - times spent by a task 
in a queue of an entry, multiple entries if requeue happens. That would 
be a quite cool feature indeed.

The total time of an entry call as observed by the caller is

    time spent in the queues + execution time of the entry body

-- 
Regards,
Dmitry A. Kazakov
http://www.dmitry-kazakov.de

Re: Profiling Ada applications using gprof

[Dennis Lee Bieber]

On Wed, 5 Dec 2018 06:13:12 -0800 (PST), Petter Fryklund
<petter.fryklund@atero.se> declaimed the following:


>
>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:
>

	Since the OP put "the problem" in quotes, my interpretation is that
this was deliberate (done to simulate a long-running operation) and that
they expected to see the rendezvous consuming 10 seconds of time when
profiled.


-- 
	Wulfraed                 Dennis Lee Bieber         AF6VN
	wlfraed@ix.netcom.com    HTTP://wlfraed.home.netcom.com/