* Profiling Ada applications using gprof
@ 2018-12-04 15:04 joakimds
2018-12-04 19:41 ` Dennis Lee Bieber
2018-12-05 14:13 ` Petter Fryklund
0 siblings, 2 replies; 7+ messages in thread
From: joakimds @ 2018-12-04 15:04 UTC (permalink / raw)
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
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Profiling Ada applications using gprof
2018-12-04 15:04 Profiling Ada applications using gprof joakimds
@ 2018-12-04 19:41 ` Dennis Lee Bieber
2018-12-05 14:13 ` Petter Fryklund
1 sibling, 0 replies; 7+ messages in thread
From: Dennis Lee Bieber @ 2018-12-04 19:41 UTC (permalink / raw)
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/
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Profiling Ada applications using gprof
2018-12-04 15:04 Profiling Ada applications using gprof joakimds
2018-12-04 19:41 ` Dennis Lee Bieber
@ 2018-12-05 14:13 ` Petter Fryklund
2018-12-05 15:32 ` joakimds
2018-12-05 20:11 ` Dennis Lee Bieber
1 sibling, 2 replies; 7+ messages in thread
From: Petter Fryklund @ 2018-12-05 14:13 UTC (permalink / raw)
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
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Profiling Ada applications using gprof
2018-12-05 14:13 ` Petter Fryklund
@ 2018-12-05 15:32 ` joakimds
2018-12-05 16:05 ` joakimds
2018-12-05 20:11 ` Dennis Lee Bieber
1 sibling, 1 reply; 7+ messages in thread
From: joakimds @ 2018-12-05 15:32 UTC (permalink / raw)
> 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?
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Profiling Ada applications using gprof
2018-12-05 15:32 ` joakimds
@ 2018-12-05 16:05 ` joakimds
2018-12-05 17:27 ` Dmitry A. Kazakov
0 siblings, 1 reply; 7+ messages in thread
From: joakimds @ 2018-12-05 16:05 UTC (permalink / raw)
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).
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Profiling Ada applications using gprof
2018-12-05 16:05 ` joakimds
@ 2018-12-05 17:27 ` Dmitry A. Kazakov
0 siblings, 0 replies; 7+ messages in thread
From: Dmitry A. Kazakov @ 2018-12-05 17:27 UTC (permalink / raw)
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
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Profiling Ada applications using gprof
2018-12-05 14:13 ` Petter Fryklund
2018-12-05 15:32 ` joakimds
@ 2018-12-05 20:11 ` Dennis Lee Bieber
1 sibling, 0 replies; 7+ messages in thread
From: Dennis Lee Bieber @ 2018-12-05 20:11 UTC (permalink / raw)
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/
^ permalink raw reply [flat|nested] 7+ messages in thread
end of thread, other threads:[~2018-12-05 20:11 UTC | newest]
Thread overview: 7+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2018-12-04 15:04 Profiling Ada applications using gprof joakimds
2018-12-04 19:41 ` Dennis Lee Bieber
2018-12-05 14:13 ` Petter Fryklund
2018-12-05 15:32 ` joakimds
2018-12-05 16:05 ` joakimds
2018-12-05 17:27 ` Dmitry A. Kazakov
2018-12-05 20:11 ` Dennis Lee Bieber
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox