binutils-gdb/gdbserver/debug.cc
Simon Marchi 3ec3145c5d gdb: introduce scoped debug prints
I spent a lot of time reading infrun debug logs recently, and I think
they could be made much more readable by being indented, to clearly see
what operation is done as part of what other operation.  In the current
format, there are no visual cues to tell where things start and end,
it's just a big flat list.  It's also difficult to understand what
caused a given operation (e.g. a call to resume_1) to be done.

To help with this, I propose to add the new scoped_debug_start_end
structure, along with a bunch of macros to make it convenient to use.

The idea of scoped_debug_start_end is simply to print a start and end
message at construction and destruction.  It also increments/decrements
a depth counter in order to make debug statements printed during this
range use some indentation.  Some care is taken to handle the fact that
debug can be turned on or off in the middle of such a range.  For
example, a "set debug foo 1" command in a breakpoint command, or a
superior GDB manually changing the debug_foo variable.

Two macros are added in gdbsupport/common-debug.h, which are helpers to
define module-specific macros:

  - scoped_debug_start_end: takes a message that is printed both at
    construction / destruction, with "start: " and "end: " prefixes.
  - scoped_debug_enter_exit: prints hard-coded "enter" and "exit"
    messages, to denote the entry and exit of a function.

I added some examples in the infrun module to give an idea of how it can
be used and what the result looks like.  The macros are in capital
letters (INFRUN_SCOPED_DEBUG_START_END and
INFRUN_SCOPED_DEBUG_ENTER_EXIT) to mimic the existing SCOPE_EXIT, but
that can be changed if you prefer something else.

Here's an excerpt of the debug
statements printed when doing "continue", where a displaced step is
started:

    [infrun] proceed: enter
      [infrun] proceed: addr=0xffffffffffffffff, signal=GDB_SIGNAL_DEFAULT
      [infrun] global_thread_step_over_chain_enqueue: enqueueing thread Thread 0x7ffff75a5640 (LWP 2289301) in global step over chain
      [infrun] start_step_over: enter
        [infrun] start_step_over: stealing global queue of threads to step, length = 1
        [infrun] start_step_over: resuming [Thread 0x7ffff75a5640 (LWP 2289301)] for step-over
        [infrun] resume_1: step=1, signal=GDB_SIGNAL_0, trap_expected=1, current thread [Thread 0x7ffff75a5640 (LWP 2289301)] at 0x5555555551bd
        [displaced] displaced_step_prepare_throw: displaced-stepping Thread 0x7ffff75a5640 (LWP 2289301) now
        [displaced] prepare: selected buffer at 0x5555555550c2
        [displaced] prepare: saved 0x5555555550c2: 1e fa 31 ed 49 89 d1 5e 48 89 e2 48 83 e4 f0 50
        [displaced] amd64_displaced_step_copy_insn: copy 0x5555555551bd->0x5555555550c2: c7 45 fc 00 00 00 00 eb 13 8b 05 d4 2e 00 00 83
        [displaced] displaced_step_prepare_throw: prepared successfully thread=Thread 0x7ffff75a5640 (LWP 2289301), original_pc=0x5555555551bd, displaced_pc=0x5555555550c2
        [displaced] resume_1: run 0x5555555550c2: c7 45 fc 00
        [infrun] infrun_async: enable=1
        [infrun] prepare_to_wait: prepare_to_wait
        [infrun] start_step_over: [Thread 0x7ffff75a5640 (LWP 2289301)] was resumed.
        [infrun] operator(): step-over queue now empty
      [infrun] start_step_over: exit
      [infrun] proceed: start: resuming threads, all-stop-on-top-of-non-stop
        [infrun] proceed: resuming Thread 0x7ffff7da7740 (LWP 2289296)
        [infrun] resume_1: step=0, signal=GDB_SIGNAL_0, trap_expected=0, current thread [Thread 0x7ffff7da7740 (LWP 2289296)] at 0x7ffff7f7d9b7
        [infrun] prepare_to_wait: prepare_to_wait
        [infrun] proceed: resuming Thread 0x7ffff7da6640 (LWP 2289300)
        [infrun] resume_1: thread Thread 0x7ffff7da6640 (LWP 2289300) has pending wait status status->kind = stopped, signal = GDB_SIGNAL_TRAP (currently_stepping=0).
        [infrun] prepare_to_wait: prepare_to_wait
        [infrun] proceed: [Thread 0x7ffff75a5640 (LWP 2289301)] resumed
        [infrun] proceed: resuming Thread 0x7ffff6da4640 (LWP 2289302)
        [infrun] resume_1: thread Thread 0x7ffff6da4640 (LWP 2289302) has pending wait status status->kind = stopped, signal = GDB_SIGNAL_TRAP (currently_stepping=0).
        [infrun] prepare_to_wait: prepare_to_wait
      [infrun] proceed: end: resuming threads, all-stop-on-top-of-non-stop
    [infrun] proceed: exit

We can easily see where the call to `proceed` starts and end.  We can
also see why there are a bunch of resume_1 calls, it's because we are
resuming threads, emulating all-stop on top of a non-stop target.

We also see that debug statements nest well with other modules that have
been migrated to use the "new" debug statement helpers (because they all
use debug_prefixed_vprintf in the end.  I think this is desirable, for
example we could see the debug statements about reading the DWARF info
of a library nested under the debug statements about loading that
library.

Of course, modules that haven't been migrated to use the "new" helpers
will still print without indentations.  This will be one good reason to
migrate them.

I think the runtime cost (when debug statements are disabled) of this is
reasonable, given the improvement in readability.  There is the cost of
the conditionals (like standard debug statements), one more condition
(if (m_must_decrement_print_depth)) and the cost of constructing a stack
object, which means copying a fews pointers.

Adding the print in fetch_inferior_event breaks some tests that use "set
debug infrun", because it prints a debug statement after the prompt.  I
adapted these tests to cope with it, by using the "-prompt" switch of
gdb_test_multiple to as if this debug statement is part of the expected
prompt.  It's unfortunate that we have to do this, but I think the debug
print is useful, and I don't want a few tests to get in the way of
adding good debug output.

gdbsupport/ChangeLog:

	* common-debug.h (debug_print_depth): New.
	(struct scoped_debug_start_end): New.
	(scoped_debug_start_end): New.
	(scoped_debug_enter_exit): New.
	* common-debug.cc (debug_prefixed_vprintf): Print indentation.

gdb/ChangeLog:

	* debug.c (debug_print_depth): New.
	* infrun.h (INFRUN_SCOPED_DEBUG_START_END): New.
	(INFRUN_SCOPED_DEBUG_ENTER_EXIT): New.
	* infrun.c (start_step_over): Use
	INFRUN_SCOPED_DEBUG_ENTER_EXIT.
	(proceed): Use INFRUN_SCOPED_DEBUG_ENTER_EXIT and
	INFRUN_SCOPED_DEBUG_START_END.
	(fetch_inferior_event): Use INFRUN_SCOPED_DEBUG_ENTER_EXIT.

gdbserver/ChangeLog:

	* debug.cc (debug_print_depth): New.

gdb/testsuite/ChangeLog:

        * gdb.base/ui-redirect.exp: Expect infrun debug print after
	prompt.
        * gdb.threads/ia64-sigill.exp: Likewise.
        * gdb.threads/watchthreads-reorder.exp: Likewise.

Change-Id: I7c3805e6487807aa63a1bae318876a0c69dce949
2021-01-04 12:00:54 -05:00

145 lines
3.6 KiB
C++

/* Debugging routines for the remote server for GDB.
Copyright (C) 2014-2021 Free Software Foundation, Inc.
This file is part of GDB.
This program is free software; you can redistribute it and/or modify
it under the terms of the GNU General Public License as published by
the Free Software Foundation; either version 3 of the License, or
(at your option) any later version.
This program is distributed in the hope that it will be useful,
but WITHOUT ANY WARRANTY; without even the implied warranty of
MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
GNU General Public License for more details.
You should have received a copy of the GNU General Public License
along with this program. If not, see <http://www.gnu.org/licenses/>. */
#include "server.h"
#include <chrono>
#if !defined (IN_PROCESS_AGENT)
int remote_debug = 0;
#endif
/* Output file for debugging. Default to standard error. */
FILE *debug_file = stderr;
/* See debug.h. */
int debug_threads;
/* Include timestamps in debugging output. */
int debug_timestamp;
#if !defined (IN_PROCESS_AGENT)
/* See debug.h. */
void
debug_set_output (const char *new_debug_file)
{
/* Close any existing file and reset to standard error. */
if (debug_file != stderr)
{
fclose (debug_file);
}
debug_file = stderr;
/* Catch empty filenames. */
if (new_debug_file == nullptr || strlen (new_debug_file) == 0)
return;
FILE *fptr = fopen (new_debug_file, "w");
if (fptr == nullptr)
{
debug_printf ("Cannot open %s for writing. %s. Switching to stderr.\n",
new_debug_file, safe_strerror (errno));
return;
}
debug_file = fptr;
}
#endif
/* See gdbsupport/common-debug.h. */
int debug_print_depth = 0;
/* Print a debugging message.
If the text begins a new line it is preceded by a timestamp.
We don't get fancy with newline checking, we just check whether the
previous call ended with "\n". */
void
debug_vprintf (const char *format, va_list ap)
{
#if !defined (IN_PROCESS_AGENT)
/* N.B. Not thread safe, and can't be used, as is, with IPA. */
static int new_line = 1;
if (debug_timestamp && new_line)
{
using namespace std::chrono;
steady_clock::time_point now = steady_clock::now ();
seconds s = duration_cast<seconds> (now.time_since_epoch ());
microseconds us = duration_cast<microseconds> (now.time_since_epoch ()) - s;
fprintf (debug_file, "%ld.%06ld ", (long) s.count (), (long) us.count ());
}
#endif
vfprintf (debug_file, format, ap);
#if !defined (IN_PROCESS_AGENT)
if (*format)
new_line = format[strlen (format) - 1] == '\n';
#endif
}
/* Flush debugging output.
This is called, for example, when starting an inferior to ensure all debug
output thus far appears before any inferior output. */
void
debug_flush (void)
{
fflush (debug_file);
}
/* Notify the user that the code is entering FUNCTION_NAME.
FUNCTION_NAME is the name of the calling function, or NULL if unknown.
This is intended to be called via the debug_enter macro. */
void
do_debug_enter (const char *function_name)
{
if (function_name != NULL)
debug_printf (">>>> entering %s\n", function_name);
}
/* Notify the user that the code is exiting FUNCTION_NAME.
FUNCTION_NAME is the name of the calling function, or NULL if unknown.
This is intended to be called via the debug_exit macro. */
void
do_debug_exit (const char *function_name)
{
if (function_name != NULL)
debug_printf ("<<<< exiting %s\n", function_name);
}
/* See debug.h. */
ssize_t
debug_write (const void *buf, size_t nbyte)
{
int fd = fileno (debug_file);
return write (fd, buf, nbyte);
}