[RFC] gdb: add linux_nat_debug_printf macro

Message ID 20200702193034.22279-1-simon.marchi@efficios.com
State New
Headers show
Series
  • [RFC] gdb: add linux_nat_debug_printf macro
Related show

Commit Message

Mike Frysinger via Gdb-patches July 2, 2020, 7:30 p.m.
From: Simon Marchi <simon.marchi@polymtl.ca>


The debug prints inside linux-nat.c almost all have a prefix that
indicate in which function they are located.  This prefix is an
abbreviation of the function name.  For example, this print is in the
`linux_nat_post_attach_wait` function:

    if (debug_linux_nat)
      fprintf_unfiltered (gdb_stdlog,
                          "LNPAW: Attaching to a stopped process\n");

Over time, the code has changed, things were moved, and many of these
prefixes are not accurate anymore.  Also, unless you know the
linux-nat.c file by heart, it's a bit cryptic what LLR, LNW, RSRL, etc,
all mean.

To address both of these issues, I suggest adding this macro for
printing debug statements, which automatically includes the function
name.  It also includes the `[linux-nat]` prefix to clarify which part
of GDB printed this (I think that ideally, all debug prints would
include such a tag).

The `__func__` magic symbol is used to get the function name.
Unfortunately, in the case of methods, it only contains the method name,
not the class name.  So we'll get "wait", where I would have liked to
get "linux_nat_target::wait".  But at least with the `[linux-nat]` tag
in the front, it's not really ambiguous.

I've made the macro automatically include the trailing newline, because
it wouldn't make sense to call it twice to print two parts of one line,
because the `[linux-nat]` tag would be printed in the middle.

An advantage of this (IMO) is that it's less verbose, we don't have to
check for `if (debug_linux_nat)` everywhere.

Another advantage is that it's easier to customize the output later,
without having to touch all call sites.

I've changed just a few call sites, if this is deemed a good idea I'll
do the rest.  It's just that there are a lot of them, so I don't want to
do the work if the idea gets rejected in the end.

Here's an example of what it looks like in the end:

    [linux-nat] linux_nat_wait_1: enter
    [linux-nat] wait: [process -1], [TARGET_WNOHANG]

Change-Id: Ifcea3255b91400d3ad093cd0b75d3fac241cb998
---
 gdb/linux-nat.c | 37 +++++++++++++++++++++++--------------
 1 file changed, 23 insertions(+), 14 deletions(-)

-- 
2.27.0

Comments

Joel Brobecker July 3, 2020, 5:33 p.m. | #1
Hi Simon,

On Thu, Jul 02, 2020 at 03:30:34PM -0400, Simon Marchi via Gdb-patches wrote:
> From: Simon Marchi <simon.marchi@polymtl.ca>

> 

> The debug prints inside linux-nat.c almost all have a prefix that

> indicate in which function they are located.  This prefix is an

> abbreviation of the function name.  For example, this print is in the

> `linux_nat_post_attach_wait` function:

> 

>     if (debug_linux_nat)

>       fprintf_unfiltered (gdb_stdlog,

>                           "LNPAW: Attaching to a stopped process\n");

> 

> Over time, the code has changed, things were moved, and many of these

> prefixes are not accurate anymore.  Also, unless you know the

> linux-nat.c file by heart, it's a bit cryptic what LLR, LNW, RSRL, etc,

> all mean.

> 

> To address both of these issues, I suggest adding this macro for

> printing debug statements, which automatically includes the function

> name.  It also includes the `[linux-nat]` prefix to clarify which part

> of GDB printed this (I think that ideally, all debug prints would

> include such a tag).

> 

> The `__func__` magic symbol is used to get the function name.

> Unfortunately, in the case of methods, it only contains the method name,

> not the class name.  So we'll get "wait", where I would have liked to

> get "linux_nat_target::wait".  But at least with the `[linux-nat]` tag

> in the front, it's not really ambiguous.

> 

> I've made the macro automatically include the trailing newline, because

> it wouldn't make sense to call it twice to print two parts of one line,

> because the `[linux-nat]` tag would be printed in the middle.

> 

> An advantage of this (IMO) is that it's less verbose, we don't have to

> check for `if (debug_linux_nat)` everywhere.

> 

> Another advantage is that it's easier to customize the output later,

> without having to touch all call sites.

> 

> I've changed just a few call sites, if this is deemed a good idea I'll

> do the rest.  It's just that there are a lot of them, so I don't want to

> do the work if the idea gets rejected in the end.

> 

> Here's an example of what it looks like in the end:

> 

>     [linux-nat] linux_nat_wait_1: enter

>     [linux-nat] wait: [process -1], [TARGET_WNOHANG]


FWIW, this looks pretty nice to me :).

-- 
Joel
Tom Tromey July 12, 2020, 5:11 p.m. | #2
>>>>> "Simon" == Simon Marchi via Gdb-patches <gdb-patches@sourceware.org> writes:


Simon> To address both of these issues, I suggest adding this macro for
Simon> printing debug statements, which automatically includes the function
Simon> name.  It also includes the `[linux-nat]` prefix to clarify which part
Simon> of GDB printed this (I think that ideally, all debug prints would
Simon> include such a tag).

Yeah.  After seeing your patch I think all the debug prints should be
done this way.

Simon> The `__func__` magic symbol is used to get the function name.
Simon> Unfortunately, in the case of methods, it only contains the method name,

We could check for GCC and use __PRETTY_FUNCTION__, though that is the
full signature, so it might be pretty long.

Tom
Simon Marchi Aug. 19, 2020, 2:56 a.m. | #3
On 2020-07-12 1:11 p.m., Tom Tromey wrote:
>>>>>> "Simon" == Simon Marchi via Gdb-patches <gdb-patches@sourceware.org> writes:

> 

> Simon> To address both of these issues, I suggest adding this macro for

> Simon> printing debug statements, which automatically includes the function

> Simon> name.  It also includes the `[linux-nat]` prefix to clarify which part

> Simon> of GDB printed this (I think that ideally, all debug prints would

> Simon> include such a tag).

> 

> Yeah.  After seeing your patch I think all the debug prints should be

> done this way.

> 

> Simon> The `__func__` magic symbol is used to get the function name.

> Simon> Unfortunately, in the case of methods, it only contains the method name,

> 

> We could check for GCC and use __PRETTY_FUNCTION__, though that is the

> full signature, so it might be pretty long.


I remember I tried it and didn't like it much.  Printing longer identifiers didn't
help readability.  And usually we have enough context to know what the debug
statement is about, especially with the [linux-nat] prefix.

I pushed the patch, since the feedback was positive.

Simon
Simon Marchi Aug. 19, 2020, 3:39 a.m. | #4
On 2020-08-18 10:56 p.m., Simon Marchi wrote:
> I remember I tried it and didn't like it much.  Printing longer identifiers didn't

> help readability.  And usually we have enough context to know what the debug

> statement is about, especially with the [linux-nat] prefix.


Although when dealing with lambdas (which includes SCOPE_EXIT), it can be quite unhelpful:

  [infrun] operator(): ...

With __PRETTY_FUNCTION__ it's a bit better:

  [infrun] stop_all_threads()::<lambda()>: ...

For that reason, we should maybe consider using __PRETTY_FUNCTION__.

Simon
Mike Frysinger via Gdb-patches Aug. 19, 2020, 3:44 a.m. | #5
On 2020-08-18 11:39 p.m., Simon Marchi wrote:
> On 2020-08-18 10:56 p.m., Simon Marchi wrote:

>> I remember I tried it and didn't like it much.  Printing longer identifiers didn't

>> help readability.  And usually we have enough context to know what the debug

>> statement is about, especially with the [linux-nat] prefix.

> 

> Although when dealing with lambdas (which includes SCOPE_EXIT), it can be quite unhelpful:

> 

>   [infrun] operator(): ...

> 

> With __PRETTY_FUNCTION__ it's a bit better:

> 

>   [infrun] stop_all_threads()::<lambda()>: ...

> 

> For that reason, we should maybe consider using __PRETTY_FUNCTION__.


Ah, now I remember why I didn't like it.  It puts the full prototype of the function:

  [infrun] void handle_inferior_event(execution_control_state*): status->kind = stopped, signal = GDB_SIGNAL_TRAP

You can imagine that it can be quite long, so it adds quite a lot of noise.  We would
need something in between, like __PRETTY_FUNCTION__ but without the parameters.

Simon

Patch

diff --git a/gdb/linux-nat.c b/gdb/linux-nat.c
index fde360f5080..bbe2fcb859b 100644
--- a/gdb/linux-nat.c
+++ b/gdb/linux-nat.c
@@ -198,6 +198,25 @@  show_debug_linux_nat (struct ui_file *file, int from_tty,
 		    value);
 }
 
+static void ATTRIBUTE_PRINTF (2, 3)
+linux_nat_debug_printf_1 (const char *func_name, const char *fmt, ...)
+{
+  fprintf_unfiltered (gdb_stdlog, "[linux-nat] %s: ", func_name);
+
+  va_list ap;
+  va_start (ap, fmt);
+  vfprintf_unfiltered (gdb_stdlog, fmt, ap);
+  va_end (ap);
+
+  fprintf_unfiltered (gdb_stdlog, "\n");
+}
+
+#define linux_nat_debug_printf(fmt, ...) \
+  do { \
+    if (debug_linux_nat) \
+      linux_nat_debug_printf_1 (__func__, fmt, ##__VA_ARGS__); \
+  } while (0)
+
 struct simple_pid_list
 {
   int pid;
@@ -2961,10 +2980,7 @@  linux_nat_filter_event (int lwpid, int status)
       && (WSTOPSIG (status) == SIGTRAP && event == PTRACE_EVENT_EXEC))
     {
       /* A multi-thread exec after we had seen the leader exiting.  */
-      if (debug_linux_nat)
-	fprintf_unfiltered (gdb_stdlog,
-			    "LLW: Re-adding thread group leader LWP %d.\n",
-			    lwpid);
+      linux_nat_debug_printf ("Re-adding thread group leader LWP %d.", lwpid);
 
       lp = add_lwp (ptid_t (lwpid, lwpid, 0));
       lp->stopped = 1;
@@ -3271,8 +3287,7 @@  linux_nat_wait_1 (ptid_t ptid, struct target_waitstatus *ourstatus,
   struct lwp_info *lp;
   int status;
 
-  if (debug_linux_nat)
-    fprintf_unfiltered (gdb_stdlog, "LLW: enter\n");
+  linux_nat_debug_printf ("enter");
 
   /* The first time we get here after starting a new inferior, we may
      not have added it to the LWP list yet - this is the earliest
@@ -3571,14 +3586,8 @@  linux_nat_target::wait (ptid_t ptid, struct target_waitstatus *ourstatus,
 {
   ptid_t event_ptid;
 
-  if (debug_linux_nat)
-    {
-      std::string options_string = target_options_to_string (target_options);
-      fprintf_unfiltered (gdb_stdlog,
-			  "linux_nat_wait: [%s], [%s]\n",
-			  target_pid_to_str (ptid).c_str (),
-			  options_string.c_str ());
-    }
+  linux_nat_debug_printf ("[%s], [%s]", target_pid_to_str (ptid).c_str (),
+			  target_options_to_string (target_options).c_str ());
 
   /* Flush the async file first.  */
   if (target_is_async_p ())