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

Doug Evans
2011-11-03T23:18:26Z

[-- 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}).