[PATCH v2] drm: use trace_printk rather than printk in drm_dbg.

[PATCH v2] drm: use trace_printk rather than printk in drm_dbg.

[Fuqian Huang]

In drivers/gpu/drm/amd/amdgpu/amdgpu_ih.c,
amdgpu_ih_process calls DRM_DEBUG which calls drm_dbg and
finally calls printk.
As amdgpu_ih_process is called from an interrupt handler,
and interrupt handler should be short as possible.

As printk may lead to bogging down the system or can even
create a live lock. printk should not be used in IRQ context.
Instead, trace_printk is recommended in IRQ context.
Link: https://lwn.net/Articles/365835

Reviewed-by: Joe Perches <joe@perches.com> 
Signed-off-by: Fuqian Huang <huangfq.daxian@gmail.com>
---
Changes in v2:
  - Only make the interrupt uses the trace_printk to avoid
    all 4000+ drm_dbg/DRM_DEBUG uses emitting a trace_printk.

 drivers/gpu/drm/drm_print.c | 10 +++++++---
 1 file changed, 7 insertions(+), 3 deletions(-)

diff --git a/drivers/gpu/drm/drm_print.c b/drivers/gpu/drm/drm_print.c
index a17c8a14dba4..747835d16fa6 100644
--- a/drivers/gpu/drm/drm_print.c
+++ b/drivers/gpu/drm/drm_print.c
@@ -236,9 +236,13 @@ void drm_dbg(unsigned int category, const char *format, ...)
 	vaf.fmt = format;
 	vaf.va = &args;
 
-	printk(KERN_DEBUG "[" DRM_NAME ":%ps] %pV",
-	       __builtin_return_address(0), &vaf);
-
+	if (in_interrupt()) {
+		trace_printk(KERN_DEBUG "[" DRM_NAME ":%ps] %pV",
+		       __builtin_return_address(0), &vaf);
+	} else {
+		printk(KERN_DEBUG "[" DRM_NAME ":%ps] %pV",
+		       __builtin_return_address(0), &vaf);
+	}
 	va_end(args);
 }
 EXPORT_SYMBOL(drm_dbg);
-- 
2.11.0

[PATCH v2] drm: use trace_printk rather than printk in drm_dbg.

[Fuqian Huang]

In drivers/gpu/drm/amd/amdgpu/amdgpu_ih.c,
amdgpu_ih_process calls DRM_DEBUG which calls drm_dbg and
finally calls printk.
As amdgpu_ih_process is called from an interrupt handler,
and interrupt handler should be short as possible.

As printk may lead to bogging down the system or can even
create a live lock. printk should not be used in IRQ context.
Instead, trace_printk is recommended in IRQ context.
Link: https://lwn.net/Articles/365835

Reviewed-by: Joe Perches <joe@perches.com> 
Signed-off-by: Fuqian Huang <huangfq.daxian@gmail.com>
---
Changes in v2:
  - Only make the interrupt uses the trace_printk to avoid
    all 4000+ drm_dbg/DRM_DEBUG uses emitting a trace_printk.

 drivers/gpu/drm/drm_print.c | 10 +++++++---
 1 file changed, 7 insertions(+), 3 deletions(-)

diff --git a/drivers/gpu/drm/drm_print.c b/drivers/gpu/drm/drm_print.c
index a17c8a14dba4..747835d16fa6 100644
--- a/drivers/gpu/drm/drm_print.c
+++ b/drivers/gpu/drm/drm_print.c
@@ -236,9 +236,13 @@ void drm_dbg(unsigned int category, const char *format, ...)
 	vaf.fmt = format;
 	vaf.va = &args;
 
-	printk(KERN_DEBUG "[" DRM_NAME ":%ps] %pV",
-	       __builtin_return_address(0), &vaf);
-
+	if (in_interrupt()) {
+		trace_printk(KERN_DEBUG "[" DRM_NAME ":%ps] %pV",
+		       __builtin_return_address(0), &vaf);
+	} else {
+		printk(KERN_DEBUG "[" DRM_NAME ":%ps] %pV",
+		       __builtin_return_address(0), &vaf);
+	}
 	va_end(args);
 }
 EXPORT_SYMBOL(drm_dbg);
-- 
2.11.0

Re: [PATCH v2] drm: use trace_printk rather than printk in drm_dbg.

[Joe Perches]

On Wed, 2019-07-31 at 14:24 +0800, Fuqian Huang wrote:
> In drivers/gpu/drm/amd/amdgpu/amdgpu_ih.c,
> amdgpu_ih_process calls DRM_DEBUG which calls drm_dbg and
> finally calls printk.
> As amdgpu_ih_process is called from an interrupt handler,
> and interrupt handler should be short as possible.
> 
> As printk may lead to bogging down the system or can even
> create a live lock. printk should not be used in IRQ context.
> Instead, trace_printk is recommended in IRQ context.
> Link: https://lwn.net/Articles/365835
> 
> Reviewed-by: Joe Perches <joe@perches.com> 

I made a suggestion.  I did not review this.

Please do not add signatures like this if
not specifically given by someone.


> Signed-off-by: Fuqian Huang <huangfq.daxian@gmail.com>
> ---
> Changes in v2:
>   - Only make the interrupt uses the trace_printk to avoid
>     all 4000+ drm_dbg/DRM_DEBUG uses emitting a trace_printk.
> 
>  drivers/gpu/drm/drm_print.c | 10 +++++++---
>  1 file changed, 7 insertions(+), 3 deletions(-)
> 
> diff --git a/drivers/gpu/drm/drm_print.c b/drivers/gpu/drm/drm_print.c
> index a17c8a14dba4..747835d16fa6 100644
> --- a/drivers/gpu/drm/drm_print.c
> +++ b/drivers/gpu/drm/drm_print.c
> @@ -236,9 +236,13 @@ void drm_dbg(unsigned int category, const char *format, ...)
>  	vaf.fmt = format;
>  	vaf.va = &args;
>  
> -	printk(KERN_DEBUG "[" DRM_NAME ":%ps] %pV",
> -	       __builtin_return_address(0), &vaf);
> -
> +	if (in_interrupt()) {
> +		trace_printk(KERN_DEBUG "[" DRM_NAME ":%ps] %pV",
> +		       __builtin_return_address(0), &vaf);
> +	} else {
> +		printk(KERN_DEBUG "[" DRM_NAME ":%ps] %pV",
> +		       __builtin_return_address(0), &vaf);
> +	}
>  	va_end(args);
>  }
>  EXPORT_SYMBOL(drm_dbg);

Re: [PATCH v2] drm: use trace_printk rather than printk in drm_dbg.

[Daniel Vetter]

On Tue, Jul 30, 2019 at 11:26:32PM -0700, Joe Perches wrote:
> On Wed, 2019-07-31 at 14:24 +0800, Fuqian Huang wrote:
> > In drivers/gpu/drm/amd/amdgpu/amdgpu_ih.c,
> > amdgpu_ih_process calls DRM_DEBUG which calls drm_dbg and
> > finally calls printk.
> > As amdgpu_ih_process is called from an interrupt handler,
> > and interrupt handler should be short as possible.
> > 
> > As printk may lead to bogging down the system or can even
> > create a live lock. printk should not be used in IRQ context.
> > Instead, trace_printk is recommended in IRQ context.
> > Link: https://lwn.net/Articles/365835
> > 
> > Reviewed-by: Joe Perches <joe@perches.com> 
> 
> I made a suggestion.  I did not review this.
> 
> Please do not add signatures like this if
> not specifically given by someone.

+1

> > Signed-off-by: Fuqian Huang <huangfq.daxian@gmail.com>
> > ---
> > Changes in v2:
> >   - Only make the interrupt uses the trace_printk to avoid
> >     all 4000+ drm_dbg/DRM_DEBUG uses emitting a trace_printk.
> > 
> >  drivers/gpu/drm/drm_print.c | 10 +++++++---
> >  1 file changed, 7 insertions(+), 3 deletions(-)
> > 
> > diff --git a/drivers/gpu/drm/drm_print.c b/drivers/gpu/drm/drm_print.c
> > index a17c8a14dba4..747835d16fa6 100644
> > --- a/drivers/gpu/drm/drm_print.c
> > +++ b/drivers/gpu/drm/drm_print.c
> > @@ -236,9 +236,13 @@ void drm_dbg(unsigned int category, const char *format, ...)

Right above here is a check for drm_debug, which defaults to off, so in
production this all has 0 impact. But changing all the debug output from
dmesg to tracing is sure to break everyone's CI and test setups.

I'm all for cleaning up the drm logging stuff (it's a real mess), but it's
a very delicate house of cards and with thousands of users, not easy to
change. Unfortunately I don't really have a solid recommendation for what
the ideal drm logging should look like. Plus we already have a pile of
competing approaches ...
-Daniel

> >  	vaf.fmt = format;
> >  	vaf.va = &args;
> >  
> > -	printk(KERN_DEBUG "[" DRM_NAME ":%ps] %pV",
> > -	       __builtin_return_address(0), &vaf);
> > -
> > +	if (in_interrupt()) {
> > +		trace_printk(KERN_DEBUG "[" DRM_NAME ":%ps] %pV",
> > +		       __builtin_return_address(0), &vaf);
> > +	} else {
> > +		printk(KERN_DEBUG "[" DRM_NAME ":%ps] %pV",
> > +		       __builtin_return_address(0), &vaf);
> > +	}
> >  	va_end(args);
> >  }
> >  EXPORT_SYMBOL(drm_dbg);
> 

-- 
Daniel Vetter
Software Engineer, Intel Corporation
http://blog.ffwll.ch