From: Tom Tromey Date: Thu, 11 Apr 2019 17:26:02 +0000 (-0600) Subject: Add timestamps to "maint time" output X-Git-Url: https://git.libre-soc.org/?a=commitdiff_plain;h=3847a7bfbf6340372962c07f31187ff87b4f492c;p=binutils-gdb.git 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 * maint.h (class scoped_command_stats): Use DISABLE_COPY_AND_ASSIGN. : 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 * gdb.base/maint.exp: Expect command started/finished output. --- diff --git a/gdb/ChangeLog b/gdb/ChangeLog index ef741d7c5f9..c0cc57f102e 100644 --- a/gdb/ChangeLog +++ b/gdb/ChangeLog @@ -1,3 +1,12 @@ +2019-06-06 Tom Tromey + + * maint.h (class scoped_command_stats): Use + DISABLE_COPY_AND_ASSIGN. + : 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 * riscv-tdep.c (riscv_insn::decode): Gracefully ignore diff --git a/gdb/maint.c b/gdb/maint.c index 328d6026a34..aaabb352249 100644 --- 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 1d8d2cc5574..57f350ade8c 100644 --- 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 c3fc780620f..61affed7731 100644 --- a/gdb/testsuite/ChangeLog +++ b/gdb/testsuite/ChangeLog @@ -1,3 +1,7 @@ +2019-06-06 Tom Tromey + + * gdb.base/maint.exp: Expect command started/finished output. + 2019-06-05 Andrew Burgess * 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 38e9a1ec4b1..a7675ea215b 100644 --- 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