Add timestamps to "maint time" output

Currently "maint time" will print the amount of time a command took.
Sometimes, though, it's useful to have a timestamp as well -- for
example if one is correlating a gdb log with some other log.

This patch adds a timestamp to the start and end of each command when
this setting is in effect.

This also removes a "//" comment and changes scoped_command_stats to
use DISABLE_COPY_AND_ASSIGN; two minor things I noticed while working
on the patch.

Tested on x86-64 Fedora 29.

gdb/ChangeLog
2019-06-06  Tom Tromey  <tromey@adacore.com>

	* maint.h (class scoped_command_stats): Use
	DISABLE_COPY_AND_ASSIGN.
	<print_time>: New method.
	* maint.c (scoped_command_stats, ~scoped_command_stats): Call
	print_time.
	(scoped_command_stats::print_time): New method.

gdb/testsuite/ChangeLog
2019-06-06  Tom Tromey  <tromey@adacore.com>

	* gdb.base/maint.exp: Expect command started/finished output.

diff --git a/gdb/ChangeLog b/gdb/ChangeLog
index ef741d7c5f9bb845daec81291facccc019d6394a..c0cc57f102eeeb19a58b8d34a25d36f90c4b9b99 100644 (file)
--- a/gdb/ChangeLog
+++ b/gdb/ChangeLog
@@ -1,3 +1,12 @@
+2019-06-06  Tom Tromey  <tromey@adacore.com>
+
+       * maint.h (class scoped_command_stats): Use
+       DISABLE_COPY_AND_ASSIGN.
+       <print_time>: New method.
+       * maint.c (scoped_command_stats, ~scoped_command_stats): Call
+       print_time.
+       (scoped_command_stats::print_time): New method.
+
 2019-06-05  Andrew Burgess  <andrew.burgess@embecosm.com>
 
        * riscv-tdep.c (riscv_insn::decode): Gracefully ignore

diff --git a/gdb/maint.c b/gdb/maint.c
index 328d6026a341c95798d295f786812b279e7e3c98..aaabb3522497550e057f1141164890eeca7c14cd 100644 (file)
--- a/gdb/maint.c
+++ b/gdb/maint.c
@@ -794,6 +794,8 @@ scoped_command_stats::~scoped_command_stats ()
 
   if (m_time_enabled && per_command_time)
     {
+      print_time (_("command finished"));
+
       using namespace std::chrono;
 
       run_time_clock::duration cmd_time
@@ -867,6 +869,9 @@ scoped_command_stats::scoped_command_stats (bool msg_type)
       m_start_cpu_time = run_time_clock::now ();
       m_start_wall_time = steady_clock::now ();
       m_time_enabled = 1;
+
+      if (per_command_time)
+       print_time (_("command started"));
     }
   else
     m_time_enabled = 0;
@@ -888,6 +893,26 @@ scoped_command_stats::scoped_command_stats (bool msg_type)
   reset_prompt_for_continue_wait_time ();
 }
 
+/* See maint.h.  */
+
+void
+scoped_command_stats::print_time (const char *msg)
+{
+  using namespace std::chrono;
+
+  auto now = system_clock::now ();
+  auto ticks = now.time_since_epoch ().count () / (1000 * 1000);
+  auto millis = ticks % 1000;
+
+  std::time_t as_time = system_clock::to_time_t (now);
+  struct tm *tm = localtime (&as_time);
+
+  char out[100];
+  strftime (out, sizeof (out), "%F %H:%M:%S", tm);
+
+  printf_unfiltered ("%s.%03d - %s\n", out, (int) millis, msg);
+}
+
 /* Handle unknown "mt set per-command" arguments.
    In this case have "mt set per-command on|off" affect every setting.  */
 

diff --git a/gdb/maint.h b/gdb/maint.h
index 1d8d2cc5574918aa8ef98ea06163615b5bbdb86c..57f350ade8c69c7d2dc3c7d8c56f62f8ca0bc85d 100644 (file)
--- a/gdb/maint.h
+++ b/gdb/maint.h
@@ -38,9 +38,10 @@ class scoped_command_stats
 
  private:
 
-  // No need for these.  They are intentionally not defined anywhere.
-  scoped_command_stats &operator= (const scoped_command_stats &);
-  scoped_command_stats (const scoped_command_stats &);
+  DISABLE_COPY_AND_ASSIGN (scoped_command_stats);
+
+  /* Print the time, along with a string.  */
+  void print_time (const char *msg);
 
   /* Zero if the saved time is from the beginning of GDB execution.
      One if from the beginning of an individual command execution.  */

diff --git a/gdb/testsuite/ChangeLog b/gdb/testsuite/ChangeLog
index c3fc780620fb6443e9c4801b98ea104c2766c16d..61affed773150f8bf484c46c1057ea6edd864d5a 100644 (file)
--- a/gdb/testsuite/ChangeLog
+++ b/gdb/testsuite/ChangeLog
@@ -1,3 +1,7 @@
+2019-06-06  Tom Tromey  <tromey@adacore.com>
+
+       * gdb.base/maint.exp: Expect command started/finished output.
+
 2019-06-05  Andrew Burgess  <andrew.burgess@embecosm.com>
 
        * gdb.arch/riscv-unwind-long-insn-6.s: Remove use of 'I' in

diff --git a/gdb/testsuite/gdb.base/maint.exp b/gdb/testsuite/gdb.base/maint.exp
index 38e9a1ec4b114ca43d8c463a3575f2c653c9379b..a7675ea215b592941dfe2740a9dbaffb975d037a 100644 (file)
--- a/gdb/testsuite/gdb.base/maint.exp
+++ b/gdb/testsuite/gdb.base/maint.exp
@@ -177,9 +177,12 @@ gdb_test_no_output "maint check-symtabs"
 
 # Test per-command stats.
 gdb_test_no_output "maint set per-command on"
+set decimal "\[0-9\]+"
+set time_fmt "${decimal}-${decimal}-${decimal} ${decimal}:${decimal}:${decimal}\\.${decimal}"
 gdb_test "pwd" \
-    "Command execution time: \[0-9.\]+ \\(cpu\\), \[0-9.\]+ \\(wall\\)\[\r\n\]+Space used: $decimal \\(\\+$decimal for this command\\)\[\r\n\]+#symtabs: $decimal \\(\\+$decimal\\), #compunits: $decimal \\(\\+$decimal\\), #blocks: $decimal \\(\\+$decimal\\)"
-gdb_test_no_output "maint set per-command off"
+    "${time_fmt} - command started\r\n.*\r\n${time_fmt} - command finished\r\nCommand execution time: \[0-9.\]+ \\(cpu\\), \[0-9.\]+ \\(wall\\)\[\r\n\]+Space used: $decimal \\(\\+$decimal for this command\\)\[\r\n\]+#symtabs: $decimal \\(\\+$decimal\\), #compunits: $decimal \\(\\+$decimal\\), #blocks: $decimal \\(\\+$decimal\\)"
+gdb_test "maint set per-command off" \
+    "${time_fmt} - command started"
 
 # The timeout value is raised, because printing all the symbols and
 # statistical information about Cygwin and Windows libraries takes a lot