diff mbox series

[3/3] dyndbg: add source filename to prefix

Message ID 20221223-dyndbg-filename-v1-3-cbf8543009a1@weissschuh.net
State New
Headers
Series dyndbg: add source file name to prefix |

Commit Message

Thomas Weißschuh Jan. 30, 2023, 2:01 a.m. UTC 
  Printing the line number without the file is of limited usefulness.

Knowing the filename also makes it also easier to relate the logged
information to the controlfile.

Example:

    # modprobe test_dynamic_debug
    # echo 'file test_dynamic_debug.c =pfsl' > /proc/dynamic_debug/control
    # echo 1 > /sys/module/test_dynamic_debug/parameters/do_prints
    # dmesg | tail -2
    [   71.802212] do_cats:lib/test_dynamic_debug.c:103: test_dd: doing categories
    [   71.802227] do_levels:lib/test_dynamic_debug.c:123: test_dd: doing levels

Signed-off-by: Thomas Weißschuh <linux@weissschuh.net>
---
 Documentation/admin-guide/dynamic-debug-howto.rst | 5 +++--
 include/linux/dynamic_debug.h                     | 4 +++-
 lib/dynamic_debug.c                               | 4 ++++
 3 files changed, 10 insertions(+), 3 deletions(-)

Comments

Jason Baron Feb. 3, 2023, 4:45 p.m. UTC | #1 
Hi Thomas,

Thanks for this series, this series is fine with me:
Acked-by: Jason Baron <jbaron@akamai.com>

Your comment about making the output more relatable to the control file 
made me think if we should try and make the logged output look more like 
the control file:

# cat /proc/dynamic_debug/control
# filename:lineno [module]function flags format

So for your example, I think that would look like:

[   71.802212] lib/test_dynamic_debug.c:103 do_cats: test_dd: doing 
categories
[   71.802227] lib/test_dynamic_debug.c:123 do_levels: doing levels

But even if we think it looks better, there maybe too many dependencies 
on the current output format...

Thanks,

-Jason

On 1/29/23 9:01 PM, Thomas Weißschuh wrote:
> Printing the line number without the file is of limited usefulness.
> 
> Knowing the filename also makes it also easier to relate the logged
> information to the controlfile.
> 
> Example:
> 
>      # modprobe test_dynamic_debug
>      # echo 'file test_dynamic_debug.c =pfsl' > /proc/dynamic_debug/control
>      # echo 1 > /sys/module/test_dynamic_debug/parameters/do_prints
>      # dmesg | tail -2
>      [   71.802212] do_cats:lib/test_dynamic_debug.c:103: test_dd: doing categories
>      [   71.802227] do_levels:lib/test_dynamic_debug.c:123: test_dd: doing levels
> 
> Signed-off-by: Thomas Weißschuh <linux@weissschuh.net>
> ---
>   Documentation/admin-guide/dynamic-debug-howto.rst | 5 +++--
>   include/linux/dynamic_debug.h                     | 4 +++-
>   lib/dynamic_debug.c                               | 4 ++++
>   3 files changed, 10 insertions(+), 3 deletions(-)
> 
> diff --git a/Documentation/admin-guide/dynamic-debug-howto.rst b/Documentation/admin-guide/dynamic-debug-howto.rst
> index faa22f77847a..f9fa8163fba6 100644
> --- a/Documentation/admin-guide/dynamic-debug-howto.rst
> +++ b/Documentation/admin-guide/dynamic-debug-howto.rst
> @@ -216,13 +216,14 @@ The flags are::
>     t    Include thread ID, or <intr>
>     m    Include module name
>     f    Include the function name
> +  s    Include the source file name
>     l    Include line number
>   
>   For ``print_hex_dump_debug()`` and ``print_hex_dump_bytes()``, only
>   the ``p`` flag has meaning, other flags are ignored.
>   
> -Note the regexp ``^[-+=][flmpt_]+$`` matches a flags specification.
> -To clear all flags at once, use ``=_`` or ``-flmpt``.
> +Note the regexp ``^[-+=][fslmpt_]+$`` matches a flags specification.
> +To clear all flags at once, use ``=_`` or ``-fslmpt``.
>   
>   
>   Debug messages during Boot Process
> diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
> index 41682278d2e8..0c77105d583c 100644
> --- a/include/linux/dynamic_debug.h
> +++ b/include/linux/dynamic_debug.h
> @@ -37,10 +37,12 @@ struct _ddebug {
>   #define _DPRINTK_FLAGS_INCL_FUNCNAME	(1<<2)
>   #define _DPRINTK_FLAGS_INCL_LINENO	(1<<3)
>   #define _DPRINTK_FLAGS_INCL_TID		(1<<4)
> +#define _DPRINTK_FLAGS_INCL_SOURCENAME	(1<<5)
>   
>   #define _DPRINTK_FLAGS_INCL_ANY		\
>   	(_DPRINTK_FLAGS_INCL_MODNAME | _DPRINTK_FLAGS_INCL_FUNCNAME |\
> -	 _DPRINTK_FLAGS_INCL_LINENO  | _DPRINTK_FLAGS_INCL_TID)
> +	 _DPRINTK_FLAGS_INCL_LINENO  | _DPRINTK_FLAGS_INCL_TID |\
> +	 _DPRINTK_FLAGS_INCL_SOURCENAME)
>   
>   #if defined DEBUG
>   #define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINT
> diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
> index e96ea427d8af..fa7418e35197 100644
> --- a/lib/dynamic_debug.c
> +++ b/lib/dynamic_debug.c
> @@ -92,6 +92,7 @@ static const struct { unsigned flag:8; char opt_char; } opt_array[] = {
>   	{ _DPRINTK_FLAGS_PRINT, 'p' },
>   	{ _DPRINTK_FLAGS_INCL_MODNAME, 'm' },
>   	{ _DPRINTK_FLAGS_INCL_FUNCNAME, 'f' },
> +	{ _DPRINTK_FLAGS_INCL_SOURCENAME, 's' },
>   	{ _DPRINTK_FLAGS_INCL_LINENO, 'l' },
>   	{ _DPRINTK_FLAGS_INCL_TID, 't' },
>   	{ _DPRINTK_FLAGS_NONE, '_' },
> @@ -836,6 +837,9 @@ static char *__dynamic_emit_prefix(const struct _ddebug *desc, char *buf)
>   	if (desc->flags & _DPRINTK_FLAGS_INCL_FUNCNAME)
>   		pos += snprintf(buf + pos, remaining(pos), "%s:",
>   				desc->function);
> +	if (desc->flags & _DPRINTK_FLAGS_INCL_SOURCENAME)
> +		pos += snprintf(buf + pos, remaining(pos), "%s:",
> +				trim_prefix(desc->filename));
>   	if (desc->flags & _DPRINTK_FLAGS_INCL_LINENO)
>   		pos += snprintf(buf + pos, remaining(pos), "%d:",
>   				desc->lineno);
>
Thomas Weißschuh Feb. 4, 2023, 2:49 p.m. UTC | #2 
Hi Jason,


Feb 3, 2023 10:45:49 Jason Baron <jbaron@akamai.com>:

> Hi Thomas,
>
> Thanks for this series, this series is fine with me:
> Acked-by: Jason Baron <jbaron@akamai.com>

Thanks!

> Your comment about making the output more relatable to the control file made me think if we should try and make the logged output look more like the control file:
>
> # cat /proc/dynamic_debug/control
> # filename:lineno [module]function flags format
>
> So for your example, I think that would look like:
>
> [   71.802212] lib/test_dynamic_debug.c:103 do_cats: test_dd: doing categories
> [   71.802227] lib/test_dynamic_debug.c:123 do_levels: doing levels
>
> But even if we think it looks better, there maybe too many dependencies on the current output format...

I agree on both points.

An alternative could be a new flag that prints the
full format from the control file.
The control file even has a format header that
tools could use to parse out the fields, making it
extensible.

Not sure it's worth it though.
And it should be in addition to this series in my
opinion.

Thomas

> Thanks,
>
> -Jason
>
> On 1/29/23 9:01 PM, Thomas Weißschuh wrote:
>> Printing the line number without the file is of limited usefulness.
>> Knowing the filename also makes it also easier to relate the logged
>> information to the controlfile.
>> Example:
>>      # modprobe test_dynamic_debug
>>      # echo 'file test_dynamic_debug.c =pfsl' > /proc/dynamic_debug/control
>>      # echo 1 > /sys/module/test_dynamic_debug/parameters/do_prints
>>      # dmesg | tail -2
>>      [   71.802212] do_cats:lib/test_dynamic_debug.c:103: test_dd: doing categories
>>      [   71.802227] do_levels:lib/test_dynamic_debug.c:123: test_dd: doing levels
>> Signed-off-by: Thomas Weißschuh <linux@weissschuh.net>
>> ---
>>   Documentation/admin-guide/dynamic-debug-howto.rst | 5 +++--
>>   include/linux/dynamic_debug.h                     | 4 +++-
>>   lib/dynamic_debug.c                               | 4 ++++
>>   3 files changed, 10 insertions(+), 3 deletions(-)
>> diff --git a/Documentation/admin-guide/dynamic-debug-howto.rst b/Documentation/admin-guide/dynamic-debug-howto.rst
>> index faa22f77847a..f9fa8163fba6 100644
>> --- a/Documentation/admin-guide/dynamic-debug-howto.rst
>> +++ b/Documentation/admin-guide/dynamic-debug-howto.rst
>> @@ -216,13 +216,14 @@ The flags are::
>>     t    Include thread ID, or <intr>
>>     m    Include module name
>>     f    Include the function name
>> +  s    Include the source file name
>>     l    Include line number
>>     For ``print_hex_dump_debug()`` and ``print_hex_dump_bytes()``, only
>>   the ``p`` flag has meaning, other flags are ignored.
>>   -Note the regexp ``^[-+=][flmpt_]+$`` matches a flags specification.
>> -To clear all flags at once, use ``=_`` or ``-flmpt``.
>> +Note the regexp ``^[-+=][fslmpt_]+$`` matches a flags specification.
>> +To clear all flags at once, use ``=_`` or ``-fslmpt``.
>>       Debug messages during Boot Process
>> diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
>> index 41682278d2e8..0c77105d583c 100644
>> --- a/include/linux/dynamic_debug.h
>> +++ b/include/linux/dynamic_debug.h
>> @@ -37,10 +37,12 @@ struct _ddebug {
>>   #define _DPRINTK_FLAGS_INCL_FUNCNAME  (1<<2)
>>   #define _DPRINTK_FLAGS_INCL_LINENO    (1<<3)
>>   #define _DPRINTK_FLAGS_INCL_TID       (1<<4)
>> +#define _DPRINTK_FLAGS_INCL_SOURCENAME (1<<5)
>>     #define _DPRINTK_FLAGS_INCL_ANY     \
>>     (_DPRINTK_FLAGS_INCL_MODNAME | _DPRINTK_FLAGS_INCL_FUNCNAME |\
>> -    _DPRINTK_FLAGS_INCL_LINENO  | _DPRINTK_FLAGS_INCL_TID)
>> +    _DPRINTK_FLAGS_INCL_LINENO  | _DPRINTK_FLAGS_INCL_TID |\
>> +    _DPRINTK_FLAGS_INCL_SOURCENAME)
>>     #if defined DEBUG
>>   #define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINT
>> diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
>> index e96ea427d8af..fa7418e35197 100644
>> --- a/lib/dynamic_debug.c
>> +++ b/lib/dynamic_debug.c
>> @@ -92,6 +92,7 @@ static const struct { unsigned flag:8; char opt_char; } opt_array[] = {
>>     { _DPRINTK_FLAGS_PRINT, 'p' },
>>     { _DPRINTK_FLAGS_INCL_MODNAME, 'm' },
>>     { _DPRINTK_FLAGS_INCL_FUNCNAME, 'f' },
>> +   { _DPRINTK_FLAGS_INCL_SOURCENAME, 's' },
>>     { _DPRINTK_FLAGS_INCL_LINENO, 'l' },
>>     { _DPRINTK_FLAGS_INCL_TID, 't' },
>>     { _DPRINTK_FLAGS_NONE, '_' },
>> @@ -836,6 +837,9 @@ static char *__dynamic_emit_prefix(const struct _ddebug *desc, char *buf)
>>     if (desc->flags & _DPRINTK_FLAGS_INCL_FUNCNAME)
>>         pos += snprintf(buf + pos, remaining(pos), "%s:",
>>                 desc->function);
>> +   if (desc->flags & _DPRINTK_FLAGS_INCL_SOURCENAME)
>> +       pos += snprintf(buf + pos, remaining(pos), "%s:",
>> +               trim_prefix(desc->filename));
>>     if (desc->flags & _DPRINTK_FLAGS_INCL_LINENO)
>>         pos += snprintf(buf + pos, remaining(pos), "%d:",
>>                 desc->lineno);
>>
Jim Cromie March 22, 2023, 3:54 p.m. UTC | #3 
On Sat, Feb 4, 2023 at 7:49 AM <linux@weissschuh.net> wrote:
>
> Hi Jason,
>
>
> Feb 3, 2023 10:45:49 Jason Baron <jbaron@akamai.com>:
>
> > Hi Thomas,
> >
> > Thanks for this series, this series is fine with me:
> > Acked-by: Jason Baron <jbaron@akamai.com>
>
> Thanks!
>
> > Your comment about making the output more relatable to the control file made me think if we should try and make the logged output look more like the control file:
> >
> > # cat /proc/dynamic_debug/control
> > # filename:lineno [module]function flags format
> >
> > So for your example, I think that would look like:
> >
> > [   71.802212] lib/test_dynamic_debug.c:103 do_cats: test_dd: doing categories
> > [   71.802227] lib/test_dynamic_debug.c:123 do_levels: doing levels
> >
> > But even if we think it looks better, there maybe too many dependencies on the current output format...
>
> I agree on both points.
>
> An alternative could be a new flag that prints the
> full format from the control file.
> The control file even has a format header that
> tools could use to parse out the fields, making it
> extensible.
>
> Not sure it's worth it though.
> And it should be in addition to this series in my
> opinion.

Boy howdy, I was hoping you were gonna do it. :-)

I think we need the 's' flag.
it displays properly as "$src:$line"

I agree that shuffling the "$src:$line" part before the "$mod:$func"
part would be ideal
(reluctantly) its a separate patch

Acked-by: Jim Cromie <jim.cromie@gmail.com>

(resisting the urge to hijack this thread for "designing")

>
> Thomas
>
> > Thanks,
> >
> > -Jason
> >
> > On 1/29/23 9:01 PM, Thomas Weißschuh wrote:
> >> Printing the line number without the file is of limited usefulness.
> >> Knowing the filename also makes it also easier to relate the logged
> >> information to the controlfile.
> >> Example:
> >>      # modprobe test_dynamic_debug
> >>      # echo 'file test_dynamic_debug.c =pfsl' > /proc/dynamic_debug/control
> >>      # echo 1 > /sys/module/test_dynamic_debug/parameters/do_prints
> >>      # dmesg | tail -2
> >>      [   71.802212] do_cats:lib/test_dynamic_debug.c:103: test_dd: doing categories
> >>      [   71.802227] do_levels:lib/test_dynamic_debug.c:123: test_dd: doing levels
> >> Signed-off-by: Thomas Weißschuh <linux@weissschuh.net>
> >> ---
> >>   Documentation/admin-guide/dynamic-debug-howto.rst | 5 +++--
> >>   include/linux/dynamic_debug.h                     | 4 +++-
> >>   lib/dynamic_debug.c                               | 4 ++++
> >>   3 files changed, 10 insertions(+), 3 deletions(-)
> >> diff --git a/Documentation/admin-guide/dynamic-debug-howto.rst b/Documentation/admin-guide/dynamic-debug-howto.rst
> >> index faa22f77847a..f9fa8163fba6 100644
> >> --- a/Documentation/admin-guide/dynamic-debug-howto.rst
> >> +++ b/Documentation/admin-guide/dynamic-debug-howto.rst
> >> @@ -216,13 +216,14 @@ The flags are::
> >>     t    Include thread ID, or <intr>
> >>     m    Include module name
> >>     f    Include the function name
> >> +  s    Include the source file name
> >>     l    Include line number
> >>     For ``print_hex_dump_debug()`` and ``print_hex_dump_bytes()``, only
> >>   the ``p`` flag has meaning, other flags are ignored.
> >>   -Note the regexp ``^[-+=][flmpt_]+$`` matches a flags specification.
> >> -To clear all flags at once, use ``=_`` or ``-flmpt``.
> >> +Note the regexp ``^[-+=][fslmpt_]+$`` matches a flags specification.
> >> +To clear all flags at once, use ``=_`` or ``-fslmpt``.
> >>       Debug messages during Boot Process
> >> diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
> >> index 41682278d2e8..0c77105d583c 100644
> >> --- a/include/linux/dynamic_debug.h
> >> +++ b/include/linux/dynamic_debug.h
> >> @@ -37,10 +37,12 @@ struct _ddebug {
> >>   #define _DPRINTK_FLAGS_INCL_FUNCNAME  (1<<2)
> >>   #define _DPRINTK_FLAGS_INCL_LINENO    (1<<3)
> >>   #define _DPRINTK_FLAGS_INCL_TID       (1<<4)
> >> +#define _DPRINTK_FLAGS_INCL_SOURCENAME (1<<5)
> >>     #define _DPRINTK_FLAGS_INCL_ANY     \
> >>     (_DPRINTK_FLAGS_INCL_MODNAME | _DPRINTK_FLAGS_INCL_FUNCNAME |\
> >> -    _DPRINTK_FLAGS_INCL_LINENO  | _DPRINTK_FLAGS_INCL_TID)
> >> +    _DPRINTK_FLAGS_INCL_LINENO  | _DPRINTK_FLAGS_INCL_TID |\
> >> +    _DPRINTK_FLAGS_INCL_SOURCENAME)
> >>     #if defined DEBUG
> >>   #define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINT
> >> diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
> >> index e96ea427d8af..fa7418e35197 100644
> >> --- a/lib/dynamic_debug.c
> >> +++ b/lib/dynamic_debug.c
> >> @@ -92,6 +92,7 @@ static const struct { unsigned flag:8; char opt_char; } opt_array[] = {
> >>     { _DPRINTK_FLAGS_PRINT, 'p' },
> >>     { _DPRINTK_FLAGS_INCL_MODNAME, 'm' },
> >>     { _DPRINTK_FLAGS_INCL_FUNCNAME, 'f' },
> >> +   { _DPRINTK_FLAGS_INCL_SOURCENAME, 's' },
> >>     { _DPRINTK_FLAGS_INCL_LINENO, 'l' },
> >>     { _DPRINTK_FLAGS_INCL_TID, 't' },
> >>     { _DPRINTK_FLAGS_NONE, '_' },
> >> @@ -836,6 +837,9 @@ static char *__dynamic_emit_prefix(const struct _ddebug *desc, char *buf)
> >>     if (desc->flags & _DPRINTK_FLAGS_INCL_FUNCNAME)
> >>         pos += snprintf(buf + pos, remaining(pos), "%s:",
> >>                 desc->function);
> >> +   if (desc->flags & _DPRINTK_FLAGS_INCL_SOURCENAME)
> >> +       pos += snprintf(buf + pos, remaining(pos), "%s:",
> >> +               trim_prefix(desc->filename));
> >>     if (desc->flags & _DPRINTK_FLAGS_INCL_LINENO)
> >>         pos += snprintf(buf + pos, remaining(pos), "%d:",
> >>                 desc->lineno);
> >>
>
diff mbox series

Patch

diff --git a/Documentation/admin-guide/dynamic-debug-howto.rst b/Documentation/admin-guide/dynamic-debug-howto.rst
index faa22f77847a..f9fa8163fba6 100644
--- a/Documentation/admin-guide/dynamic-debug-howto.rst
+++ b/Documentation/admin-guide/dynamic-debug-howto.rst
@@ -216,13 +216,14 @@  The flags are::
   t    Include thread ID, or <intr>
   m    Include module name
   f    Include the function name
+  s    Include the source file name
   l    Include line number
 
 For ``print_hex_dump_debug()`` and ``print_hex_dump_bytes()``, only
 the ``p`` flag has meaning, other flags are ignored.
 
-Note the regexp ``^[-+=][flmpt_]+$`` matches a flags specification.
-To clear all flags at once, use ``=_`` or ``-flmpt``.
+Note the regexp ``^[-+=][fslmpt_]+$`` matches a flags specification.
+To clear all flags at once, use ``=_`` or ``-fslmpt``.
 
 
 Debug messages during Boot Process
diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index 41682278d2e8..0c77105d583c 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -37,10 +37,12 @@  struct _ddebug {
 #define _DPRINTK_FLAGS_INCL_FUNCNAME	(1<<2)
 #define _DPRINTK_FLAGS_INCL_LINENO	(1<<3)
 #define _DPRINTK_FLAGS_INCL_TID		(1<<4)
+#define _DPRINTK_FLAGS_INCL_SOURCENAME	(1<<5)
 
 #define _DPRINTK_FLAGS_INCL_ANY		\
 	(_DPRINTK_FLAGS_INCL_MODNAME | _DPRINTK_FLAGS_INCL_FUNCNAME |\
-	 _DPRINTK_FLAGS_INCL_LINENO  | _DPRINTK_FLAGS_INCL_TID)
+	 _DPRINTK_FLAGS_INCL_LINENO  | _DPRINTK_FLAGS_INCL_TID |\
+	 _DPRINTK_FLAGS_INCL_SOURCENAME)
 
 #if defined DEBUG
 #define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINT
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index e96ea427d8af..fa7418e35197 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -92,6 +92,7 @@  static const struct { unsigned flag:8; char opt_char; } opt_array[] = {
 	{ _DPRINTK_FLAGS_PRINT, 'p' },
 	{ _DPRINTK_FLAGS_INCL_MODNAME, 'm' },
 	{ _DPRINTK_FLAGS_INCL_FUNCNAME, 'f' },
+	{ _DPRINTK_FLAGS_INCL_SOURCENAME, 's' },
 	{ _DPRINTK_FLAGS_INCL_LINENO, 'l' },
 	{ _DPRINTK_FLAGS_INCL_TID, 't' },
 	{ _DPRINTK_FLAGS_NONE, '_' },
@@ -836,6 +837,9 @@  static char *__dynamic_emit_prefix(const struct _ddebug *desc, char *buf)
 	if (desc->flags & _DPRINTK_FLAGS_INCL_FUNCNAME)
 		pos += snprintf(buf + pos, remaining(pos), "%s:",
 				desc->function);
+	if (desc->flags & _DPRINTK_FLAGS_INCL_SOURCENAME)
+		pos += snprintf(buf + pos, remaining(pos), "%s:",
+				trim_prefix(desc->filename));
 	if (desc->flags & _DPRINTK_FLAGS_INCL_LINENO)
 		pos += snprintf(buf + pos, remaining(pos), "%d:",
 				desc->lineno);