[RFA, doc RFA] Include wallclock time in "maint time" output.

[RFA, doc RFA] Include wallclock time in "maint time" output.

[Doug Evans]

Hi.

It is often useful to see the wallclock time of commands.
This patch adds wallclock time to the output from "maint time 1".

This patch depends on a patch for libiberty, pending approval.
http://gcc.gnu.org/ml/gcc-patches/2011-09/msg01118.html
I'll revise this as appropriate, but can I get an RFA on the
addition of wallclock time to the output?

[Other bits of gdb can make use of timeval-utils.h,
that's another patch.]

2011-09-19  Doug Evans  <dje@google.com>

	* utils.c: #include "timeval-utils.h".
	(cmd_stats): Rename start_time to start_cpu_time.
	New member start_wall_time.
	(report_command_stats): Report wall time.
	(make_command_stats_cleanup): Record start wall time.

	doc/
	* gdb.texinfo (Maintenance Commands): Update docs of "maint time".

Index: utils.c
===================================================================
RCS file: /cvs/src/src/gdb/utils.c,v
retrieving revision 1.261
diff -u -p -r1.261 utils.c
--- utils.c	9 Sep 2011 19:41:14 -0000	1.261
+++ utils.c	20 Sep 2011 03:42:22 -0000
@@ -44,6 +44,7 @@
 #endif
 
 #include <signal.h>
+#include "timeval-utils.h"
 #include "gdbcmd.h"
 #include "serial.h"
 #include "bfd.h"
@@ -641,7 +642,8 @@ static int display_space;
 struct cmd_stats 
 {
   int msg_type;
-  long start_time;
+  struct timeval start_wall_time;
+  long start_cpu_time;
   long start_space;
 };
 
@@ -673,12 +675,18 @@ report_command_stats (void *arg)
 
   if (display_time)
     {
-      long cmd_time = get_run_time () - start_stats->start_time;
+      long cmd_time = get_run_time () - start_stats->start_cpu_time;
+      struct timeval now_wall_time, delta_wall_time;
+
+      gettimeofday (&now_wall_time, NULL);
+      timeval_sub (&delta_wall_time,
+		   &now_wall_time, &start_stats->start_wall_time);
 
       printf_unfiltered (msg_type == 0
-			 ? _("Startup time: %ld.%06ld\n")
-			 : _("Command execution time: %ld.%06ld\n"),
-			 cmd_time / 1000000, cmd_time % 1000000);
+			 ? _("Startup time: %ld.%06ld (cpu), %ld.%06ld (wall)\n")
+			 : _("Command execution time: %ld.%06ld (cpu), %ld.%06ld (wall)\n"),
+			 cmd_time / 1000000, cmd_time % 1000000,
+			 delta_wall_time.tv_sec, delta_wall_time.tv_usec);
     }
 
   if (display_space)
@@ -714,7 +722,8 @@ make_command_stats_cleanup (int msg_type
 #endif
 
   new_stat->msg_type = msg_type;
-  new_stat->start_time = get_run_time ();
+  gettimeofday (&new_stat->start_wall_time, NULL);
+  new_stat->start_cpu_time = get_run_time ();
 
   return make_cleanup_dtor (report_command_stats, new_stat, xfree);
 }
Index: doc/gdb.texinfo
===================================================================
RCS file: /cvs/src/src/gdb/doc/gdb.texinfo,v
retrieving revision 1.862
diff -u -p -r1.862 gdb.texinfo
--- doc/gdb.texinfo	16 Sep 2011 09:07:01 -0000	1.862
+++ doc/gdb.texinfo	20 Sep 2011 04:02:07 -0000
@@ -32240,13 +32240,12 @@ switch (@pxref{Mode Options}).
 @kindex maint time
 @cindex time of command execution
 @item maint time
-Control whether to display the execution time for each command.  If
-set to a nonzero value, @value{GDBN} will display how much time it
+Control whether to display the execution time of @value{GDBN} for each command.
+If set to a nonzero value, @value{GDBN} will display how much time it
 took to execute each command, following the command's own output.
-The time is not printed for the commands that run the target, since
-there's no mechanism currently to compute how much time was spend
-by @value{GDBN} and how much time was spend by the program been debugged.
-it's not possibly currently 
+Both cpu time and wallclock time are printed.
+Note that the cpu time printed is for @value{GDBN} only, it does not include
+the execution time of the inferior.
 This can also be requested by invoking @value{GDBN} with the
 @option{--statistics} command-line switch (@pxref{Mode Options}).
 

Re: [RFA, doc RFA] Include wallclock time in "maint time" output.

[Eli Zaretskii]

> Date: Mon, 19 Sep 2011 21:11:37 -0700 (PDT)
> From: dje@google.com (Doug Evans)
> 
> It is often useful to see the wallclock time of commands.

Actually, it would be much more useful to display time it took the
inferior between two points where GDB gets control.  Are you trying to
approximate that missing feature, or is there some other use case
where wallclock time would be useful?

> This patch adds wallclock time to the output from "maint time 1".
> 
> This patch depends on a patch for libiberty, pending approval.
> http://gcc.gnu.org/ml/gcc-patches/2011-09/msg01118.html
> I'll revise this as appropriate, but can I get an RFA on the
> addition of wallclock time to the output?
> 
> [Other bits of gdb can make use of timeval-utils.h,
> that's another patch.]

IMO, it would be better to add to libiberty a couple of functions to
measure interval times.  What you suggest is to call gettimeofday
twice and then subtract the values.  But that assumes the resolution
of gettimeofday is high enough to be useful in this paradigm, which
might be true on Posix platforms (specifically GNU/Linux), but is not
at all guaranteed elsewhere.  For example, Windows lacks gettimeofday
altogether and the emulation we use (from libiberty) has 1-sec(!)
resolution.  By contrast, it _is_ possible on Windows to measure
intervals with sub-millisecond resolution.

IOW, if we want an interval timing abstraction, let's have an API for
that, instead of exposing the implementation which might make no sense
on some platforms.

> +If set to a nonzero value, @value{GDBN} will display how much time it
>  took to execute each command, following the command's own output.
> -The time is not printed for the commands that run the target, since
> -there's no mechanism currently to compute how much time was spend
> -by @value{GDBN} and how much time was spend by the program been debugged.
> -it's not possibly currently 

I'm not sure we should remove that remark, because what it says is
still true, even after your changes.

> +Both cpu time and wallclock time are printed.

"CPU" in caps, or maybe "@sc{cpu}" (look at the PDF to decide which
one you like best).

> +Note that the cpu time printed is for @value{GDBN} only, it does not include
> +the execution time of the inferior.

Ditto.

Thanks.

Re: [RFA, doc RFA] Include wallclock time in "maint time" output.

[Doug Evans]

On Mon, Sep 19, 2011 at 10:31 PM, Eli Zaretskii <eliz@gnu.org> wrote:
>> Date: Mon, 19 Sep 2011 21:11:37 -0700 (PDT)
>> From: dje@google.com (Doug Evans)
>>
>> It is often useful to see the wallclock time of commands.
>
> Actually, it would be much more useful to display time it took the
> inferior between two points where GDB gets control.  Are you trying to
> approximate that missing feature, or is there some other use case
> where wallclock time would be useful?

It's not always the case that the inferior is running when wanting to
see wallclock time.  E.g., remote protocol operations, excessive nfs
latency, etc.
[For reference sake, MI already supports this feature for monitoring
slow operations.]

>> This patch adds wallclock time to the output from "maint time 1".
>>
>> This patch depends on a patch for libiberty, pending approval.
>> http://gcc.gnu.org/ml/gcc-patches/2011-09/msg01118.html
>> I'll revise this as appropriate, but can I get an RFA on the
>> addition of wallclock time to the output?
>>
>> [Other bits of gdb can make use of timeval-utils.h,
>> that's another patch.]
>
> IMO, it would be better to add to libiberty a couple of functions to
> measure interval times.  What you suggest is to call gettimeofday
> twice and then subtract the values.  But that assumes the resolution
> of gettimeofday is high enough to be useful in this paradigm, which
> might be true on Posix platforms (specifically GNU/Linux), but is not
> at all guaranteed elsewhere.  For example, Windows lacks gettimeofday
> altogether and the emulation we use (from libiberty) has 1-sec(!)
> resolution.  By contrast, it _is_ possible on Windows to measure
> intervals with sub-millisecond resolution.
>
> IOW, if we want an interval timing abstraction, let's have an API for
> that, instead of exposing the implementation which might make no sense
> on some platforms.

It's not possible to implement gettimeofday on windows with better
accuracy?  A quick search suggests it is possible.
gettimeofday is pretty simple and standard,
inventing something new has its own disadvantages.

>
>> +If set to a nonzero value, @value{GDBN} will display how much time it
>>  took to execute each command, following the command's own output.
>> -The time is not printed for the commands that run the target, since
>> -there's no mechanism currently to compute how much time was spend
>> -by @value{GDBN} and how much time was spend by the program been debugged.
>> -it's not possibly currently
>
> I'm not sure we should remove that remark, because what it says is
> still true, even after your changes.

The part about time not being printed for commands that run the target
is not true.
Does the part about there being no mechanism to compute how much time
was spent by the inferior really add anything of value?
[Plus it may be true for some configurations and not true for others.
It doesn't really add anything useful so I've opted for KISS and not
making a claim that isn't necessarily true.]
The last part is an incomplete sentence (and bad grammer to boot :-)).

>> +Both cpu time and wallclock time are printed.
>
> "CPU" in caps, or maybe "@sc{cpu}" (look at the PDF to decide which
> one you like best).
>
>> +Note that the cpu time printed is for @value{GDBN} only, it does not include
>> +the execution time of the inferior.
>
> Ditto.
>
> Thanks.
>

Re: [RFA, doc RFA] Include wallclock time in "maint time" output.

[Eli Zaretskii]

> Date: Mon, 19 Sep 2011 23:08:52 -0700
> From: Doug Evans <dje@google.com>
> Cc: gdb-patches@sourceware.org
> 
> > Actually, it would be much more useful to display time it took the
> > inferior between two points where GDB gets control.  Are you trying to
> > approximate that missing feature, or is there some other use case
> > where wallclock time would be useful?
> 
> It's not always the case that the inferior is running when wanting to
> see wallclock time.  E.g., remote protocol operations, excessive nfs
> latency, etc.
> [For reference sake, MI already supports this feature for monitoring
> slow operations.]

It sounds like it would be a good idea to mention these use cases in
the manual.

> It's not possible to implement gettimeofday on windows with better
> accuracy?

It is easy to do that with 10ms resolution, but not below that.  Below
that, AFAIK only interval measurements are "easy" on Windows.

> gettimeofday is pretty simple and standard,
> inventing something new has its own disadvantages.

I disagree, but I can live with that.

> >> +If set to a nonzero value, @value{GDBN} will display how much time it
> >>  took to execute each command, following the command's own output.
> >> -The time is not printed for the commands that run the target, since
> >> -there's no mechanism currently to compute how much time was spend
> >> -by @value{GDBN} and how much time was spend by the program been debugged.
> >> -it's not possibly currently
> >
> > I'm not sure we should remove that remark, because what it says is
> > still true, even after your changes.
> 
> The part about time not being printed for commands that run the target
> is not true.

The CPU time still accounts for GDB only, right?  It sounds like we
interpret this sentence differently, so perhaps it should be reworded
rather than being deleted.

> Does the part about there being no mechanism to compute how much time
> was spent by the inferior really add anything of value?

It explains the meaning of the times we print, IMO.  If someone saw
the need to tell that at some point, I tend to honor that.

Re: [RFA, doc RFA] Include wallclock time in "maint time" output.

[Eli Zaretskii]

> Date: Tue, 20 Sep 2011 03:09:17 -0400
> From: Eli Zaretskii <eliz@gnu.org>
> CC: gdb-patches@sourceware.org
> Reply-to: Eli Zaretskii <eliz@gnu.org>
> 
> > gettimeofday is pretty simple and standard,
> > inventing something new has its own disadvantages.
> 
> I disagree

With the second part, obviously.

Re: [RFA, doc RFA] Include wallclock time in "maint time" output.

[Tom Tromey]

>>>>> "Doug" == Doug Evans <dje@google.com> writes:

Doug> It is often useful to see the wallclock time of commands.
Doug> This patch adds wallclock time to the output from "maint time 1".

Doug> This patch depends on a patch for libiberty, pending approval.
Doug> http://gcc.gnu.org/ml/gcc-patches/2011-09/msg01118.html
Doug> I'll revise this as appropriate, but can I get an RFA on the
Doug> addition of wallclock time to the output?

It is fine by me.  In general I think that "maint" commands should
reflect what is useful to today's gdb developers, and we shouldn't feel
constrained in changing them.

Tom

Re: [RFA, doc RFA] Include wallclock time in "maint time" output.

[Doug Evans]

[-- Attachment #1: Type: text/plain, Size: 2814 bytes --]

On Tue, Sep 20, 2011 at 12:09 AM, Eli Zaretskii <eliz@gnu.org> wrote:
>> Date: Mon, 19 Sep 2011 23:08:52 -0700
>> From: Doug Evans <dje@google.com>
>> Cc: gdb-patches@sourceware.org
>>
>> > Actually, it would be much more useful to display time it took the
>> > inferior between two points where GDB gets control.  Are you trying to
>> > approximate that missing feature, or is there some other use case
>> > where wallclock time would be useful?
>>
>> It's not always the case that the inferior is running when wanting to
>> see wallclock time.  E.g., remote protocol operations, excessive nfs
>> latency, etc.
>> [For reference sake, MI already supports this feature for monitoring
>> slow operations.]
>
> It sounds like it would be a good idea to mention these use cases in
> the manual.
>
>> It's not possible to implement gettimeofday on windows with better
>> accuracy?
>
> It is easy to do that with 10ms resolution, but not below that.  Below
> that, AFAIK only interval measurements are "easy" on Windows.
>
>> gettimeofday is pretty simple and standard,
>> inventing something new has its own disadvantages.
>
> I disagree, but I can live with that.
>
>> >> +If set to a nonzero value, @value{GDBN} will display how much time it
>> >>  took to execute each command, following the command's own output.
>> >> -The time is not printed for the commands that run the target, since
>> >> -there's no mechanism currently to compute how much time was spend
>> >> -by @value{GDBN} and how much time was spend by the program been debugged.
>> >> -it's not possibly currently
>> >
>> > I'm not sure we should remove that remark, because what it says is
>> > still true, even after your changes.
>>
>> The part about time not being printed for commands that run the target
>> is not true.
>
> The CPU time still accounts for GDB only, right?  It sounds like we
> interpret this sentence differently, so perhaps it should be reworded
> rather than being deleted.

You'll need to tell me how you interpret it.
Note that my docs do say that the time printed does not include
inferior time.

>> Does the part about there being no mechanism to compute how much time
>> was spent by the inferior really add anything of value?
>
> It explains the meaning of the times we print, IMO.  If someone saw
> the need to tell that at some point, I tend to honor that.

PTAL.

2011-11-03  Doug Evans  <dje@google.com>

        * utils.c: #include "timeval-utils.h".
        (cmd_stats): Rename start_time to start_cpu_time.
        New member start_wall_time.
        (report_command_stats): Report wall time.
        (make_command_stats_cleanup): Record start wall time.

        doc/
        * gdb.texinfo (Maintenance Commands): Update docs of "maint time".

[-- Attachment #2: gdb-111103-wallclock-time-2.patch.txt --]
[-- Type: text/plain, Size: 3663 bytes --]

2011-11-03  Doug Evans  <dje@google.com>

	* utils.c: #include "timeval-utils.h".
	(cmd_stats): Rename start_time to start_cpu_time.
	New member start_wall_time.
	(report_command_stats): Report wall time.
	(make_command_stats_cleanup): Record start wall time.

	doc/
	* gdb.texinfo (Maintenance Commands): Update docs of "maint time".

Index: utils.c
===================================================================
RCS file: /cvs/src/src/gdb/utils.c,v
retrieving revision 1.264
diff -u -p -r1.264 utils.c
--- utils.c	14 Oct 2011 07:55:26 -0000	1.264
+++ utils.c	3 Nov 2011 22:46:13 -0000
@@ -45,6 +45,7 @@
 #endif
 
 #include <signal.h>
+#include "timeval-utils.h"
 #include "gdbcmd.h"
 #include "serial.h"
 #include "bfd.h"
@@ -691,7 +692,8 @@ static int display_space;
 struct cmd_stats 
 {
   int msg_type;
-  long start_time;
+  long start_cpu_time;
+  struct timeval start_wall_time;
   long start_space;
 };
 
@@ -723,12 +725,18 @@ report_command_stats (void *arg)
 
   if (display_time)
     {
-      long cmd_time = get_run_time () - start_stats->start_time;
+      long cmd_time = get_run_time () - start_stats->start_cpu_time;
+      struct timeval now_wall_time, delta_wall_time;
+
+      gettimeofday (&now_wall_time, NULL);
+      timeval_sub (&delta_wall_time,
+		   &now_wall_time, &start_stats->start_wall_time);
 
       printf_unfiltered (msg_type == 0
-			 ? _("Startup time: %ld.%06ld\n")
-			 : _("Command execution time: %ld.%06ld\n"),
-			 cmd_time / 1000000, cmd_time % 1000000);
+			 ? _("Startup time: %ld.%06ld (cpu), %ld.%06ld (wall)\n")
+			 : _("Command execution time: %ld.%06ld (cpu), %ld.%06ld (wall)\n"),
+			 cmd_time / 1000000, cmd_time % 1000000,
+			 delta_wall_time.tv_sec, delta_wall_time.tv_usec);
     }
 
   if (display_space)
@@ -764,7 +772,8 @@ make_command_stats_cleanup (int msg_type
 #endif
 
   new_stat->msg_type = msg_type;
-  new_stat->start_time = get_run_time ();
+  new_stat->start_cpu_time = get_run_time ();
+  gettimeofday (&new_stat->start_wall_time, NULL);
 
   return make_cleanup_dtor (report_command_stats, new_stat, xfree);
 }
Index: doc/gdb.texinfo
===================================================================
RCS file: /cvs/src/src/gdb/doc/gdb.texinfo,v
retrieving revision 1.888
diff -u -p -r1.888 gdb.texinfo
--- doc/gdb.texinfo	3 Nov 2011 14:32:49 -0000	1.888
+++ doc/gdb.texinfo	3 Nov 2011 23:16:16 -0000
@@ -32991,13 +32991,16 @@ switch (@pxref{Mode Options}).
 @kindex maint time
 @cindex time of command execution
 @item maint time
-Control whether to display the execution time for each command.  If
-set to a nonzero value, @value{GDBN} will display how much time it
+Control whether to display the execution time of @value{GDBN} for each command.
+If set to a nonzero value, @value{GDBN} will display how much time it
 took to execute each command, following the command's own output.
-The time is not printed for the commands that run the target, since
-there's no mechanism currently to compute how much time was spend
-by @value{GDBN} and how much time was spend by the program been debugged.
-it's not possibly currently 
+Both cpu time and wallclock time are printed.
+Printing both is useful when trying to determine whether the cost is
+cpu or, e.g., disk/network, latency.
+Note that the cpu time printed is for @value{GDBN} only, it does not include
+the execution time of the inferior because there's no mechanism currently
+to compute how much time was spent by @value{GDBN} and how much time was
+spent by the program been debugged.
 This can also be requested by invoking @value{GDBN} with the
 @option{--statistics} command-line switch (@pxref{Mode Options}).
 

Re: [RFA, doc RFA] Include wallclock time in "maint time" output.

[Eli Zaretskii]

> Date: Thu, 3 Nov 2011 16:17:08 -0700
> From: Doug Evans <dje@google.com>
> Cc: gdb-patches@sourceware.org
> 
> >> The part about time not being printed for commands that run the target
> >> is not true.
> >
> > The CPU time still accounts for GDB only, right?  It sounds like we
> > interpret this sentence differently, so perhaps it should be reworded
> > rather than being deleted.
> 
> You'll need to tell me how you interpret it.

The text of the patch you attached is fine with me, but I would
suggest to use "@sc{cpu}" instead of just "cpu", I think the former
looks better in print.

Thanks.

Re: [RFA, doc RFA] Include wallclock time in "maint time" output.

[Doug Evans]

On Fri, Nov 4, 2011 at 2:01 AM, Eli Zaretskii <eliz@gnu.org> wrote:
>> Date: Thu, 3 Nov 2011 16:17:08 -0700
>> From: Doug Evans <dje@google.com>
>> Cc: gdb-patches@sourceware.org
>>
>> >> The part about time not being printed for commands that run the target
>> >> is not true.
>> >
>> > The CPU time still accounts for GDB only, right?  It sounds like we
>> > interpret this sentence differently, so perhaps it should be reworded
>> > rather than being deleted.
>>
>> You'll need to tell me how you interpret it.
>
> The text of the patch you attached is fine with me, but I would
> suggest to use "@sc{cpu}" instead of just "cpu", I think the former
> looks better in print.

Ah, righto.  That reminded me that gdb.texinfo uses CPU (all caps) throughout,
so that's what I checked in.