[PATCH] rate limit drm:radeon_cp_idle/reset errors

[PATCH] rate limit drm:radeon_cp_idle/reset errors

[Roberto Oppedisano]

When switching from kwin composite wm (KDE 4.1) to compiz I often hit the
following error:

Sep  6 10:24:31 poppero1 kernel: [  186.138203] [drm:radeon_cp_idle] *ERROR* radeon_cp_idle called without lock held, held  0 owner f726bc80 f68f6840
Sep  6 10:24:31 poppero1 kernel: [  186.138568] [drm:radeon_cp_reset] *ERROR* radeon_cp_reset called without lock held, held  0 owner f726bc80 f68f6840

probably due to broken X drivers/apps; after hitting this the error my laptop
(hp nx7010) is totally unresponsitive to keyboard/mouse, also if it can be 
shut down via the power button:

Sep  6 10:24:59 poppero1 powersave-wm_shutdown[4843]: DIAG: Process script for event button.power ID 10
Sep  6 10:24:59 poppero1 powersave-wm_shutdown[4843]: INFO: Event: BUTTON_POWER occured.
Sep  6 10:24:59 poppero1 powersave-wm_shutdown[4843]: INFO: Parameters: Event - button.power; Current Active Scheme: scheme_performance - ACPI event line: button/power PWRF 00000080
00000001
Sep  6 10:25:00 poppero1 shutdown[4852]: shutting down for system halt
...

Without the attached patch, which rate limits DRM_ERROR, the syslog is flooded
by thuosands of messages; here's the output with the patch applied.

Sep  6 10:24:31 poppero1 kernel: [  186.138774] [drm:radeon_cp_start] *ERROR* radeon_cp_start called without lock held, held  0 owner f726bc80 f68f6840
Sep  6 10:24:31 poppero1 kernel: [  186.138968] [drm:radeon_cp_idle] *ERROR* radeon_cp_idle called without lock held, held  0 owner f726bc80 f68f6840
Sep  6 10:24:31 poppero1 kernel: [  186.139214] [drm:radeon_cp_reset] *ERROR* radeon_cp_reset called without lock held, held  0 owner f726bc80 f68f6840
Sep  6 10:24:31 poppero1 kernel: [  186.139408] [drm:radeon_cp_start] *ERROR* radeon_cp_start called without lock held, held  0 owner f726bc80 f68f6840
Sep  6 10:24:31 poppero1 kernel: [  186.139601] [drm:radeon_cp_idle] *ERROR* radeon_cp_idle called without lock held, held  0 owner f726bc80 f68f6840
Sep  6 10:24:31 poppero1 kernel: [  186.139866] [drm:radeon_cp_reset] *ERROR* radeon_cp_reset called without lock held, held  0 owner f726bc80 f68f6840
Sep  6 10:24:31 poppero1 kernel: [  186.140072] [drm:radeon_cp_start] *ERROR* radeon_cp_start called without lock held, held  0 owner f726bc80 f68f6840
Sep  6 10:24:31 poppero1 kernel: [  186.140467] [drm:radeon_cp_idle] *ERROR* radeon_cp_idle called without lock held, held  0 owner f726bc80 f68f6840
Sep  6 10:24:36 poppero1 kernel: [  191.139019] __ratelimit: 253431 callbacks suppressed
Sep  6 10:24:36 poppero1 kernel: [  191.139030] [drm:radeon_cp_reset] *ERROR* radeon_cp_reset called without lock held, held  0 owner f726bc80 f68f6840
Sep  6 10:24:36 poppero1 kernel: [  191.139314] [drm:radeon_cp_start] *ERROR* radeon_cp_start called without lock held, held  0 owner f726bc80 f68f6840

Also if it doesn't solve a bug I think it may still be worth applying it. 
Patch is against current git.

Signed-off-by: Roberto Oppedisano <roberto.oppedisano@infracom.it>

diff --git a/include/drm/drmP.h b/include/drm/drmP.h
index 1c1b13e..1107361 100644
--- a/include/drm/drmP.h
+++ b/include/drm/drmP.h
@@ -162,7 +162,8 @@ struct drm_device;
  * \param arg arguments
  */
 #define DRM_ERROR(fmt, arg...) \
-	printk(KERN_ERR "[" DRM_NAME ":%s] *ERROR* " fmt , __func__ , ##arg)
+	if (printk_ratelimit()) \
+		printk(KERN_ERR "[" DRM_NAME ":%s] *ERROR* " fmt , __func__ , ##arg)
 
 /**
  * Memory error output.

Re: [PATCH] rate limit drm:radeon_cp_idle/reset errors

[Andrew Morton]

On Sat, 6 Sep 2008 11:19:19 +0200 Roberto Oppedisano <roppedisano@infracomspa.it> wrote:

> When switching from kwin composite wm (KDE 4.1) to compiz I often hit the
> following error:
> 
> Sep  6 10:24:31 poppero1 kernel: [  186.138203] [drm:radeon_cp_idle] *ERROR* radeon_cp_idle called without lock held, held  0 owner f726bc80 f68f6840
> Sep  6 10:24:31 poppero1 kernel: [  186.138568] [drm:radeon_cp_reset] *ERROR* radeon_cp_reset called without lock held, held  0 owner f726bc80 f68f6840
> 
> probably due to broken X drivers/apps; after hitting this the error my laptop
> (hp nx7010) is totally unresponsitive to keyboard/mouse, also if it can be 
> shut down via the power button:
> 
> Sep  6 10:24:59 poppero1 powersave-wm_shutdown[4843]: DIAG: Process script for event button.power ID 10
> Sep  6 10:24:59 poppero1 powersave-wm_shutdown[4843]: INFO: Event: BUTTON_POWER occured.
> Sep  6 10:24:59 poppero1 powersave-wm_shutdown[4843]: INFO: Parameters: Event - button.power; Current Active Scheme: scheme_performance - ACPI event line: button/power PWRF 00000080
> 00000001
> Sep  6 10:25:00 poppero1 shutdown[4852]: shutting down for system halt
> ...
> 
> Without the attached patch, which rate limits DRM_ERROR, the syslog is flooded
> by thuosands of messages; here's the output with the patch applied.
> 
> Sep  6 10:24:31 poppero1 kernel: [  186.138774] [drm:radeon_cp_start] *ERROR* radeon_cp_start called without lock held, held  0 owner f726bc80 f68f6840
> Sep  6 10:24:31 poppero1 kernel: [  186.138968] [drm:radeon_cp_idle] *ERROR* radeon_cp_idle called without lock held, held  0 owner f726bc80 f68f6840
> Sep  6 10:24:31 poppero1 kernel: [  186.139214] [drm:radeon_cp_reset] *ERROR* radeon_cp_reset called without lock held, held  0 owner f726bc80 f68f6840
> Sep  6 10:24:31 poppero1 kernel: [  186.139408] [drm:radeon_cp_start] *ERROR* radeon_cp_start called without lock held, held  0 owner f726bc80 f68f6840
> Sep  6 10:24:31 poppero1 kernel: [  186.139601] [drm:radeon_cp_idle] *ERROR* radeon_cp_idle called without lock held, held  0 owner f726bc80 f68f6840
> Sep  6 10:24:31 poppero1 kernel: [  186.139866] [drm:radeon_cp_reset] *ERROR* radeon_cp_reset called without lock held, held  0 owner f726bc80 f68f6840
> Sep  6 10:24:31 poppero1 kernel: [  186.140072] [drm:radeon_cp_start] *ERROR* radeon_cp_start called without lock held, held  0 owner f726bc80 f68f6840
> Sep  6 10:24:31 poppero1 kernel: [  186.140467] [drm:radeon_cp_idle] *ERROR* radeon_cp_idle called without lock held, held  0 owner f726bc80 f68f6840
> Sep  6 10:24:36 poppero1 kernel: [  191.139019] __ratelimit: 253431 callbacks suppressed
> Sep  6 10:24:36 poppero1 kernel: [  191.139030] [drm:radeon_cp_reset] *ERROR* radeon_cp_reset called without lock held, held  0 owner f726bc80 f68f6840
> Sep  6 10:24:36 poppero1 kernel: [  191.139314] [drm:radeon_cp_start] *ERROR* radeon_cp_start called without lock held, held  0 owner f726bc80 f68f6840
> 
> Also if it doesn't solve a bug I think it may still be worth applying it. 
> Patch is against current git.
> 
> Signed-off-by: Roberto Oppedisano <roberto.oppedisano@infracom.it>
> 
> diff --git a/include/drm/drmP.h b/include/drm/drmP.h
> index 1c1b13e..1107361 100644
> --- a/include/drm/drmP.h
> +++ b/include/drm/drmP.h
> @@ -162,7 +162,8 @@ struct drm_device;
>   * \param arg arguments
>   */
>  #define DRM_ERROR(fmt, arg...) \
> -	printk(KERN_ERR "[" DRM_NAME ":%s] *ERROR* " fmt , __func__ , ##arg)
> +	if (printk_ratelimit()) \
> +		printk(KERN_ERR "[" DRM_NAME ":%s] *ERROR* " fmt , __func__ , ##arg)
>  
>  /**
>   * Memory error output.
> 

Which kernel version(s)?

Re: [PATCH] rate limit drm:radeon_cp_idle/reset errors

[Roberto Oppedisano]

On Mon, Sep 08, 2008 at 09:08:36PM -0700, Andrew Morton wrote:
> On Sat, 6 Sep 2008 11:19:19 +0200 Roberto Oppedisano <roppedisano@infracomspa.it> wrote:
> 
> > When switching from kwin composite wm (KDE 4.1) to compiz I often hit the
> > following error:
> > 
> > Sep  6 10:24:31 poppero1 kernel: [  186.138203] [drm:radeon_cp_idle] *ERROR* radeon_cp_idle called without lock held, held  0 owner f726bc80 f68f6840
> > Sep  6 10:24:31 poppero1 kernel: [  186.138568] [drm:radeon_cp_reset] *ERROR* radeon_cp_reset called without lock held, held  0 owner f726bc80 f68f6840
> > 
> > probably due to broken X drivers/apps; after hitting this the error my laptop
> > (hp nx7010) is totally unresponsitive to keyboard/mouse, also if it can be 
> > shut down via the power button:
> > 
> > Sep  6 10:24:59 poppero1 powersave-wm_shutdown[4843]: DIAG: Process script for event button.power ID 10
> > Sep  6 10:24:59 poppero1 powersave-wm_shutdown[4843]: INFO: Event: BUTTON_POWER occured.
> > Sep  6 10:24:59 poppero1 powersave-wm_shutdown[4843]: INFO: Parameters: Event - button.power; Current Active Scheme: scheme_performance - ACPI event line: button/power PWRF 00000080
> > 00000001
> > Sep  6 10:25:00 poppero1 shutdown[4852]: shutting down for system halt
> > ...
> > 
> > Without the attached patch, which rate limits DRM_ERROR, the syslog is flooded
> > by thuosands of messages; here's the output with the patch applied.
> > 
> > Sep  6 10:24:31 poppero1 kernel: [  186.138774] [drm:radeon_cp_start] *ERROR* radeon_cp_start called without lock held, held  0 owner f726bc80 f68f6840
> > Sep  6 10:24:31 poppero1 kernel: [  186.138968] [drm:radeon_cp_idle] *ERROR* radeon_cp_idle called without lock held, held  0 owner f726bc80 f68f6840
> > Sep  6 10:24:31 poppero1 kernel: [  186.139214] [drm:radeon_cp_reset] *ERROR* radeon_cp_reset called without lock held, held  0 owner f726bc80 f68f6840
> > Sep  6 10:24:31 poppero1 kernel: [  186.139408] [drm:radeon_cp_start] *ERROR* radeon_cp_start called without lock held, held  0 owner f726bc80 f68f6840
> > Sep  6 10:24:31 poppero1 kernel: [  186.139601] [drm:radeon_cp_idle] *ERROR* radeon_cp_idle called without lock held, held  0 owner f726bc80 f68f6840
> > Sep  6 10:24:31 poppero1 kernel: [  186.139866] [drm:radeon_cp_reset] *ERROR* radeon_cp_reset called without lock held, held  0 owner f726bc80 f68f6840
> > Sep  6 10:24:31 poppero1 kernel: [  186.140072] [drm:radeon_cp_start] *ERROR* radeon_cp_start called without lock held, held  0 owner f726bc80 f68f6840
> > Sep  6 10:24:31 poppero1 kernel: [  186.140467] [drm:radeon_cp_idle] *ERROR* radeon_cp_idle called without lock held, held  0 owner f726bc80 f68f6840
> > Sep  6 10:24:36 poppero1 kernel: [  191.139019] __ratelimit: 253431 callbacks suppressed
> > Sep  6 10:24:36 poppero1 kernel: [  191.139030] [drm:radeon_cp_reset] *ERROR* radeon_cp_reset called without lock held, held  0 owner f726bc80 f68f6840
> > Sep  6 10:24:36 poppero1 kernel: [  191.139314] [drm:radeon_cp_start] *ERROR* radeon_cp_start called without lock held, held  0 owner f726bc80 f68f6840
> > 
> > Also if it doesn't solve a bug I think it may still be worth applying it. 
> > Patch is against current git.
> > 
> > Signed-off-by: Roberto Oppedisano <roberto.oppedisano@infracom.it>
> > 
> > diff --git a/include/drm/drmP.h b/include/drm/drmP.h
> > index 1c1b13e..1107361 100644
> > --- a/include/drm/drmP.h
> > +++ b/include/drm/drmP.h
> > @@ -162,7 +162,8 @@ struct drm_device;
> >   * \param arg arguments
> >   */
> >  #define DRM_ERROR(fmt, arg...) \
> > -	printk(KERN_ERR "[" DRM_NAME ":%s] *ERROR* " fmt , __func__ , ##arg)
> > +	if (printk_ratelimit()) \
> > +		printk(KERN_ERR "[" DRM_NAME ":%s] *ERROR* " fmt , __func__ , ##arg)
> >  
> >  /**
> >   * Memory error output.
> > 
> 
> Which kernel version(s)?

This is against vanilla current git. 

Linux poppero1 2.6.27-rc5-00000-g7686ad5-dirty #1 PREEMPT Sun Sep 7 08:47:08 CEST 2008 i686 GNU/Linux

R

Re: [PATCH] rate limit drm:radeon_cp_idle/reset errors

[Andrew Morton]

On Tue, 9 Sep 2008 09:37:32 +0200 Roberto Oppedisano <roppedisano@infracomspa.it> wrote:

> On Mon, Sep 08, 2008 at 09:08:36PM -0700, Andrew Morton wrote:
> > On Sat, 6 Sep 2008 11:19:19 +0200 Roberto Oppedisano <roppedisano@infracomspa.it> wrote:
> > 
> > > When switching from kwin composite wm (KDE 4.1) to compiz I often hit the
> > > following error:
> > > 
> > > Sep  6 10:24:31 poppero1 kernel: [  186.138203] [drm:radeon_cp_idle] *ERROR* radeon_cp_idle called without lock held, held  0 owner f726bc80 f68f6840
> > > Sep  6 10:24:31 poppero1 kernel: [  186.138568] [drm:radeon_cp_reset] *ERROR* radeon_cp_reset called without lock held, held  0 owner f726bc80 f68f6840
> > > 
> > > probably due to broken X drivers/apps; after hitting this the error my laptop
> > > (hp nx7010) is totally unresponsitive to keyboard/mouse, also if it can be 
> > > shut down via the power button:
> > > 
> > > Sep  6 10:24:59 poppero1 powersave-wm_shutdown[4843]: DIAG: Process script for event button.power ID 10
> > > Sep  6 10:24:59 poppero1 powersave-wm_shutdown[4843]: INFO: Event: BUTTON_POWER occured.
> > > Sep  6 10:24:59 poppero1 powersave-wm_shutdown[4843]: INFO: Parameters: Event - button.power; Current Active Scheme: scheme_performance - ACPI event line: button/power PWRF 00000080
> > > 00000001
> > > Sep  6 10:25:00 poppero1 shutdown[4852]: shutting down for system halt
> > > ...
> > > 
> > > Without the attached patch, which rate limits DRM_ERROR, the syslog is flooded
> > > by thuosands of messages; here's the output with the patch applied.
> > > 
> > > Sep  6 10:24:31 poppero1 kernel: [  186.138774] [drm:radeon_cp_start] *ERROR* radeon_cp_start called without lock held, held  0 owner f726bc80 f68f6840
> > > Sep  6 10:24:31 poppero1 kernel: [  186.138968] [drm:radeon_cp_idle] *ERROR* radeon_cp_idle called without lock held, held  0 owner f726bc80 f68f6840
> > > Sep  6 10:24:31 poppero1 kernel: [  186.139214] [drm:radeon_cp_reset] *ERROR* radeon_cp_reset called without lock held, held  0 owner f726bc80 f68f6840
> > > Sep  6 10:24:31 poppero1 kernel: [  186.139408] [drm:radeon_cp_start] *ERROR* radeon_cp_start called without lock held, held  0 owner f726bc80 f68f6840
> > > Sep  6 10:24:31 poppero1 kernel: [  186.139601] [drm:radeon_cp_idle] *ERROR* radeon_cp_idle called without lock held, held  0 owner f726bc80 f68f6840
> > > Sep  6 10:24:31 poppero1 kernel: [  186.139866] [drm:radeon_cp_reset] *ERROR* radeon_cp_reset called without lock held, held  0 owner f726bc80 f68f6840
> > > Sep  6 10:24:31 poppero1 kernel: [  186.140072] [drm:radeon_cp_start] *ERROR* radeon_cp_start called without lock held, held  0 owner f726bc80 f68f6840
> > > Sep  6 10:24:31 poppero1 kernel: [  186.140467] [drm:radeon_cp_idle] *ERROR* radeon_cp_idle called without lock held, held  0 owner f726bc80 f68f6840
> > > Sep  6 10:24:36 poppero1 kernel: [  191.139019] __ratelimit: 253431 callbacks suppressed
> > > Sep  6 10:24:36 poppero1 kernel: [  191.139030] [drm:radeon_cp_reset] *ERROR* radeon_cp_reset called without lock held, held  0 owner f726bc80 f68f6840
> > > Sep  6 10:24:36 poppero1 kernel: [  191.139314] [drm:radeon_cp_start] *ERROR* radeon_cp_start called without lock held, held  0 owner f726bc80 f68f6840
> > > 
> > > Also if it doesn't solve a bug I think it may still be worth applying it. 
> > > Patch is against current git.
> > > 
> > > Signed-off-by: Roberto Oppedisano <roberto.oppedisano@infracom.it>
> > > 
> > > diff --git a/include/drm/drmP.h b/include/drm/drmP.h
> > > index 1c1b13e..1107361 100644
> > > --- a/include/drm/drmP.h
> > > +++ b/include/drm/drmP.h
> > > @@ -162,7 +162,8 @@ struct drm_device;
> > >   * \param arg arguments
> > >   */
> > >  #define DRM_ERROR(fmt, arg...) \
> > > -	printk(KERN_ERR "[" DRM_NAME ":%s] *ERROR* " fmt , __func__ , ##arg)
> > > +	if (printk_ratelimit()) \
> > > +		printk(KERN_ERR "[" DRM_NAME ":%s] *ERROR* " fmt , __func__ , ##arg)
> > >  
> > >  /**
> > >   * Memory error output.
> > > 
> > 
> > Which kernel version(s)?
> 
> This is against vanilla current git. 
> 
> Linux poppero1 2.6.27-rc5-00000-g7686ad5-dirty #1 PREEMPT Sun Sep 7 08:47:08 CEST 2008 i686 GNU/Linux
> 

Thanks.  I should have asked earlier: was 2.6.26 OK?  Any other kernels
tested?

Re: [PATCH] rate limit drm:radeon_cp_idle/reset errors

[Dave Airlie]

> > > > Sep  6 10:24:31 poppero1 kernel: [  186.138774] [drm:radeon_cp_start] *ERROR* radeon_cp_start called without lock held, held  0 owner f726bc80 f68f6840
> > > > Sep  6 10:24:31 poppero1 kernel: [  186.138968] [drm:radeon_cp_idle] *ERROR* radeon_cp_idle called without lock held, held  0 owner f726bc80 f68f6840
> > > > Sep  6 10:24:31 poppero1 kernel: [  186.139214] [drm:radeon_cp_reset] *ERROR* radeon_cp_reset called without lock held, held  0 owner f726bc80 f68f6840
> > > > Sep  6 10:24:31 poppero1 kernel: [  186.139408] [drm:radeon_cp_start] *ERROR* radeon_cp_start called without lock held, held  0 owner f726bc80 f68f6840
> > > > Sep  6 10:24:31 poppero1 kernel: [  186.139601] [drm:radeon_cp_idle] *ERROR* radeon_cp_idle called without lock held, held  0 owner f726bc80 f68f6840
> > > > Sep  6 10:24:31 poppero1 kernel: [  186.139866] [drm:radeon_cp_reset] *ERROR* radeon_cp_reset called without lock held, held  0 owner f726bc80 f68f6840
> > > > Sep  6 10:24:31 poppero1 kernel: [  186.140072] [drm:radeon_cp_start] *ERROR* radeon_cp_start called without lock held, held  0 owner f726bc80 f68f6840
> > > > Sep  6 10:24:31 poppero1 kernel: [  186.140467] [drm:radeon_cp_idle] *ERROR* radeon_cp_idle called without lock held, held  0 owner f726bc80 f68f6840
> > > > Sep  6 10:24:36 poppero1 kernel: [  191.139019] __ratelimit: 253431 callbacks suppressed
> > > > Sep  6 10:24:36 poppero1 kernel: [  191.139030] [drm:radeon_cp_reset] *ERROR* radeon_cp_reset called without lock held, held  0 owner f726bc80 f68f6840
> > > > Sep  6 10:24:36 poppero1 kernel: [  191.139314] [drm:radeon_cp_start] *ERROR* radeon_cp_start called without lock held, held  0 owner f726bc80 f68f6840
> > > > 
> > > > Also if it doesn't solve a bug I think it may still be worth applying it. 
> > > > Patch is against current git.
> > > > 
> > > > Signed-off-by: Roberto Oppedisano <roberto.oppedisano@infracom.it>
> > > > 
> > > > diff --git a/include/drm/drmP.h b/include/drm/drmP.h
> > > > index 1c1b13e..1107361 100644
> > > > --- a/include/drm/drmP.h
> > > > +++ b/include/drm/drmP.h
> > > > @@ -162,7 +162,8 @@ struct drm_device;
> > > >   * \param arg arguments
> > > >   */
> > > >  #define DRM_ERROR(fmt, arg...) \
> > > > -	printk(KERN_ERR "[" DRM_NAME ":%s] *ERROR* " fmt , __func__ , ##arg)
> > > > +	if (printk_ratelimit()) \
> > > > +		printk(KERN_ERR "[" DRM_NAME ":%s] *ERROR* " fmt , __func__ , ##arg)
> > > >  
> > > >  /**
> > > >   * Memory error output.
> > > > 
> > > 
> > > Which kernel version(s)?
> > 
> > This is against vanilla current git. 
> > 
> > Linux poppero1 2.6.27-rc5-00000-g7686ad5-dirty #1 PREEMPT Sun Sep 7 08:47:08 CEST 2008 i686 GNU/Linux
> > 
> 
> Thanks.  I should have asked earlier: was 2.6.26 OK?  Any other kernels
> tested?

This looks like a userspace problem, some app is accessing the drm file 
descriptror without holding the drm lock, this is very illegal.

Its probably a race between the X server and the AIGLX driver.

Dave.

Re: [PATCH] rate limit drm:radeon_cp_idle/reset errors

[Roberto Oppedisano]

Dave Airlie ha scritto, Il 09/09/2008 10.15:
>>>>> Sep  6 10:24:31 poppero1 kernel: [  186.138774] [drm:radeon_cp_start] *ERROR* radeon_cp_start called without lock held, held  0 owner f726bc80 f68f6840
>>>>> Sep  6 10:24:31 poppero1 kernel: [  186.138968] [drm:radeon_cp_idle] *ERROR* radeon_cp_idle called without lock held, held  0 owner f726bc80 f68f6840
>>>>> Sep  6 10:24:31 poppero1 kernel: [  186.139214] [drm:radeon_cp_reset] *ERROR* radeon_cp_reset called without lock held, held  0 owner f726bc80 f68f6840
>>>>> Sep  6 10:24:31 poppero1 kernel: [  186.139408] [drm:radeon_cp_start] *ERROR* radeon_cp_start called without lock held, held  0 owner f726bc80 f68f6840
>>>>> Sep  6 10:24:31 poppero1 kernel: [  186.139601] [drm:radeon_cp_idle] *ERROR* radeon_cp_idle called without lock held, held  0 owner f726bc80 f68f6840
>>>>> Sep  6 10:24:31 poppero1 kernel: [  186.139866] [drm:radeon_cp_reset] *ERROR* radeon_cp_reset called without lock held, held  0 owner f726bc80 f68f6840
>>>>> Sep  6 10:24:31 poppero1 kernel: [  186.140072] [drm:radeon_cp_start] *ERROR* radeon_cp_start called without lock held, held  0 owner f726bc80 f68f6840
>>>>> Sep  6 10:24:31 poppero1 kernel: [  186.140467] [drm:radeon_cp_idle] *ERROR* radeon_cp_idle called without lock held, held  0 owner f726bc80 f68f6840
>>>>> Sep  6 10:24:36 poppero1 kernel: [  191.139019] __ratelimit: 253431 callbacks suppressed
>>>>> Sep  6 10:24:36 poppero1 kernel: [  191.139030] [drm:radeon_cp_reset] *ERROR* radeon_cp_reset called without lock held, held  0 owner f726bc80 f68f6840
>>>>> Sep  6 10:24:36 poppero1 kernel: [  191.139314] [drm:radeon_cp_start] *ERROR* radeon_cp_start called without lock held, held  0 owner f726bc80 f68f6840
>>>>>
>>>>> Also if it doesn't solve a bug I think it may still be worth applying it. 
>>>>> Patch is against current git.
>>>>>
>>>>> Signed-off-by: Roberto Oppedisano <roberto.oppedisano@infracom.it>
>>>>>
>>>>> diff --git a/include/drm/drmP.h b/include/drm/drmP.h
>>>>> index 1c1b13e..1107361 100644
>>>>> --- a/include/drm/drmP.h
>>>>> +++ b/include/drm/drmP.h
>>>>> @@ -162,7 +162,8 @@ struct drm_device;
>>>>>   * \param arg arguments
>>>>>   */
>>>>>  #define DRM_ERROR(fmt, arg...) \
>>>>> -	printk(KERN_ERR "[" DRM_NAME ":%s] *ERROR* " fmt , __func__ , ##arg)
>>>>> +	if (printk_ratelimit()) \
>>>>> +		printk(KERN_ERR "[" DRM_NAME ":%s] *ERROR* " fmt , __func__ , ##arg)
>>>>>  
>>>>>  /**
>>>>>   * Memory error output.
>>>>>
>>>> Which kernel version(s)?
>>> This is against vanilla current git. 
>>>
>>> Linux poppero1 2.6.27-rc5-00000-g7686ad5-dirty #1 PREEMPT Sun Sep 7 08:47:08 CEST 2008 i686 GNU/Linux
>>>
>> Thanks.  I should have asked earlier: was 2.6.26 OK?  Any other kernels
>> tested?
> 
> This looks like a userspace problem, some app is accessing the drm file 
> descriptror without holding the drm lock, this is very illegal.
> 
> Its probably a race between the X server and the AIGLX driver.
> 
> Dave.

I also think it's a userspace problem. I found it while playing with
KDE4.1 kwin/Compiz, less than a month ago, always running on a current
vanilla git kernel: I noticed the syslog storm only recently (my bad,
because judging from the disk light I think it has always been there).

If you think it's useful I can do some test with older kernels (will
take some time btw).
R

drm:radeon_cp_idle/reset error storm, console lockup (-rc4 git)

[Andreas Mohr]

Hi,

encountered this problem myself, was able to regain access only via
remote login, then saw tons of (ratelimited)

[drm:radeon_cp_start] *ERROR* radeon_cp_start called without lock held, held  0 owner dc6513c0
dc6513c0
[drm:radeon_cp_idle] *ERROR* radeon_cp_idle called without lock held,
held  0 owner dc6513c0 dc6513c0
[drm:radeon_cp_reset] *ERROR* radeon_cp_reset called without lock held,
held  0 owner dc6513c0 dc6513c0
[drm:radeon_cp_start] *ERROR* radeon_cp_start called without lock held,
held  0 owner dc6513c0 dc6513c0

dmesg output.

Did Alt-SysRq-T, related result part is:

Xorg          D 00000001     0  3867   3864 0x00400000
 dc686cb8 00003082 dfabeb70 00000001 00000003 dc66bbb0 dc66be28 00003282
 dfba0e40 dc537520 00003282 00003246 01ca5259 dfba0e00 dfba0e40 dc686ce8
 c115c4a5 00000000 dfba0e50 00000000 dc66bbb0 c1040b90 dfba0e40 dfba0e40
Call Trace:
 [<c115c4a5>] log_wait_commit+0x75/0xd0
 [<c1040b90>] ? autoremove_wake_function+0x0/0x50
 [<c115c618>] journal_force_commit_nested+0x38/0x60
 [<c110dc81>] ext3_should_retry_alloc+0x51/0x60
 [<c1114810>] ext3_write_begin+0x190/0x240
 [<c1112eb0>] ? ext3_get_block+0x0/0xf0
 [<c1079c16>] generic_file_buffered_write+0xe6/0x2a0
 [<c107a23b>] __generic_file_aio_write_nolock+0x22b/0x4e0
 [<c129d1f6>] ? radeon_cp_reset+0x76/0xf0
 [<c1283dda>] ? drm_ioctl+0x1da/0x370
 [<c107ae5b>] generic_file_aio_write+0x5b/0xd0
 [<c110f89d>] ext3_file_write+0x2d/0xc0
 [<c10a08f1>] do_sync_write+0xd1/0x110
 [<c1040b90>] ? autoremove_wake_function+0x0/0x50
 [<c10acd8a>] ? do_vfs_ioctl+0x6a/0x590
 [<c1024eaf>] ? set_next_entity+0x11f/0x1a0
 [<c10a13cc>] vfs_write+0x9c/0x160
 [<c1397f36>] ? schedule+0x376/0x4c0
 [<c10a0820>] ? do_sync_write+0x0/0x110
 [<c10a154d>] sys_write+0x3d/0x70
 [<c1002d35>] syscall_call+0x7/0xb


System: Debian testing, Athlon XP, new update to xserver-xorg-core to 2:1.6.2.901-1 from 1.6.2
(but I had desktop lockups slightly earlier already, and I'm pretty sure that was this).
ii  xserver-xorg-video-radeon                1:6.12.2-3                         X.Org X server -- ATI Radeon display driver

01:00.0 VGA compatible controller: ATI Technologies Inc Radeon RV250 If [Radeon 9000] (rev 01)

So, is there some userspace waiting to be fixed here?

And is there any way to implement damage control? It's not overly nice to have joe random
userspace app being able to FUBAR an entire desktop, by forgetting an "important" lock. :)


Xorg.0.log parts:

(II) ImPS/2 Generic Wheel Mouse: Configuring as mouse
(**) ImPS/2 Generic Wheel Mouse: YAxisMapping: buttons 4 and 5
(**) ImPS/2 Generic Wheel Mouse: EmulateWheelButton: 4, EmulateWheelInertia: 10, EmulateWheelTimeout: 200
(II) XINPUT: Adding extended input device "ImPS/2 Generic Wheel Mouse" (type: MOUSE)
(**) ImPS/2 Generic Wheel Mouse: (accel) keeping acceleration scheme 1
(**) ImPS/2 Generic Wheel Mouse: (accel) filter chain progression: 2.00
(**) ImPS/2 Generic Wheel Mouse: (accel) filter stage 0: 20.00 ms
(**) ImPS/2 Generic Wheel Mouse: (accel) set acceleration profile 0
(II) ImPS/2 Generic Wheel Mouse: Device reopened after 8 attempts.
(II) config/hal: Adding input device ImPS/2 Generic Wheel Mouse
(**) ImPS/2 Generic Wheel Mouse: always reports core events
(**) ImPS/2 Generic Wheel Mouse: Device: "/dev/input/event4"
(WW) ImPS/2 Generic Wheel Mouse: device file already in use. Ignoring.
(II) UnloadModule: "evdev"
(EE) PreInit returned NULL for "ImPS/2 Generic Wheel Mouse"
(EE) config/hal: NewInputDeviceRequest failed (8)
(II) config/hal: removing device ImPS/2 Generic Wheel Mouse
(II) ImPS/2 Generic Wheel Mouse: Close
(II) UnloadModule: "evdev"

Backtrace:
0: /usr/bin/X(xorg_backtrace+0x3b) [0x813141b]
1: /usr/bin/X(xf86SigHandler+0x51) [0x80c55d1]
2: [0xffffe400]
3: /usr/bin/X(BlockHandler+0x94) [0x8090244]
4: /usr/bin/X(WaitForSomething+0x124) [0x812edc4]
5: /usr/bin/X(Dispatch+0x7e) [0x808c4de]
6: /usr/bin/X(main+0x3aa) [0x8071ada]
7: /lib/libc.so.6(__libc_start_main+0xe5) [0xb7c45775]
8: /usr/bin/X [0x8070fa1]

Fatal server error:
Caught signal 11.  Server aborting


Please consult the The X.Org Foundation support
         at http://wiki.x.org
 for help.
Please also check the log file at "/var/log/Xorg.0.log" for additional information.

(II) AT Translated Set 2 keyboard: Close
(II) UnloadModule: "evdev"
(II) AIGLX: Suspending AIGLX clients for VT switch
(EE) RADEON(0): RADEONWaitForIdleCP: CP idle -22
(EE) RADEON(0): Idle timed out, resetting engine...
(EE) RADEON(0): RADEONWaitForIdleCP: CP reset -22
(EE) RADEON(0): RADEONWaitForIdleCP: CP start -22
(EE) RADEON(0): RADEONWaitForIdleCP: CP idle -22
(EE) RADEON(0): Idle timed out, resetting engine...
(EE) RADEON(0): RADEONWaitForIdleCP: CP reset -22
(EE) RADEON(0): RADEONWaitForIdleCP: CP start -22
(EE) RADEON(0): RADEONWaitForIdleCP: CP idle -22
(EE) RADEON(0): Idle timed out, resetting engine...
(EE) RADEON(0): RADEONWaitForIdleCP: CP reset -22
(EE) RADEON(0): RADEONWaitForIdleCP: CP start -22
(EE) RADEON(0): RADEONWaitForIdleCP: CP idle -22
(EE) RADEON(0): Idle timed out, resetting engine...
(EE) RADEON(0): RADEONWaitForIdleCP: CP reset -22
(EE) RADEON(0): RADEONWaitForIdleCP: CP start -22
(EE) RADEON(0): RADEONWaitForIdleCP: CP idle -22


[etc.etc. ad nauseam]

I'm throwing an uneducated guess that this log means that there's some locking-up drm inconsistency
during server crash shutdown (subsystem shutdown order violation?)
which is rendering my entire machine useless, including blocking tty access.

Thanks a lot,

Andreas Mohr

Re: drm:radeon_cp_idle/reset error storm, console lockup (-rc4 git)

[Andreas Mohr]

Hi,

On Thu, Jul 30, 2009 at 11:00:05AM +0200, Andreas Mohr wrote:
> Hi,
> 
> encountered this problem myself, was able to regain access only via
> remote login, then saw tons of (ratelimited)

...proceeded to kill -9 the X server to try to restart things,
and the result was a nice box taken off anything whatsoever (==> paperweight).
(it's still doing _something_ however, since there seems to be moderate disk
access, but...)

Andreas Mohr

Re: drm:radeon_cp_idle/reset error storm, console lockup (-rc4 git)

[Dave Airlie]

>
> encountered this problem myself, was able to regain access only via
> remote login, then saw tons of (ratelimited)
>
> [drm:radeon_cp_start] *ERROR* radeon_cp_start called without lock held, held  0 owner dc6513c0
> dc6513c0
> [drm:radeon_cp_idle] *ERROR* radeon_cp_idle called without lock held,
> held  0 owner dc6513c0 dc6513c0
> [drm:radeon_cp_reset] *ERROR* radeon_cp_reset called without lock held,
> held  0 owner dc6513c0 dc6513c0
> [drm:radeon_cp_start] *ERROR* radeon_cp_start called without lock held,
> held  0 owner dc6513c0 dc6513c0
>
> dmesg output.
>
> Did Alt-SysRq-T, related result part is:
>
> Xorg          D 00000001     0  3867   3864 0x00400000
>  dc686cb8 00003082 dfabeb70 00000001 00000003 dc66bbb0 dc66be28 00003282
>  dfba0e40 dc537520 00003282 00003246 01ca5259 dfba0e00 dfba0e40 dc686ce8
>  c115c4a5 00000000 dfba0e50 00000000 dc66bbb0 c1040b90 dfba0e40 dfba0e40
> Call Trace:
>  [<c115c4a5>] log_wait_commit+0x75/0xd0
>  [<c1040b90>] ? autoremove_wake_function+0x0/0x50
>  [<c115c618>] journal_force_commit_nested+0x38/0x60
>  [<c110dc81>] ext3_should_retry_alloc+0x51/0x60
>  [<c1114810>] ext3_write_begin+0x190/0x240
>  [<c1112eb0>] ? ext3_get_block+0x0/0xf0
>  [<c1079c16>] generic_file_buffered_write+0xe6/0x2a0
>  [<c107a23b>] __generic_file_aio_write_nolock+0x22b/0x4e0
>  [<c129d1f6>] ? radeon_cp_reset+0x76/0xf0
>  [<c1283dda>] ? drm_ioctl+0x1da/0x370
>  [<c107ae5b>] generic_file_aio_write+0x5b/0xd0
>  [<c110f89d>] ext3_file_write+0x2d/0xc0
>  [<c10a08f1>] do_sync_write+0xd1/0x110
>  [<c1040b90>] ? autoremove_wake_function+0x0/0x50
>  [<c10acd8a>] ? do_vfs_ioctl+0x6a/0x590
>  [<c1024eaf>] ? set_next_entity+0x11f/0x1a0
>  [<c10a13cc>] vfs_write+0x9c/0x160
>  [<c1397f36>] ? schedule+0x376/0x4c0
>  [<c10a0820>] ? do_sync_write+0x0/0x110
>  [<c10a154d>] sys_write+0x3d/0x70
>  [<c1002d35>] syscall_call+0x7/0xb
>
>
> System: Debian testing, Athlon XP, new update to xserver-xorg-core to 2:1.6.2.901-1 from 1.6.2
> (but I had desktop lockups slightly earlier already, and I'm pretty sure that was this).
> ii  xserver-xorg-video-radeon                1:6.12.2-3                         X.Org X server -- ATI Radeon display driver
>
> 01:00.0 VGA compatible controller: ATI Technologies Inc Radeon RV250 If [Radeon 9000] (rev 01)
>
> So, is there some userspace waiting to be fixed here?
>
> And is there any way to implement damage control? It's not overly nice to have joe random
> userspace app being able to FUBAR an entire desktop, by forgetting an "important" lock. :)
>
>
> Xorg.0.log parts:
>
> (II) ImPS/2 Generic Wheel Mouse: Configuring as mouse
> (**) ImPS/2 Generic Wheel Mouse: YAxisMapping: buttons 4 and 5
> (**) ImPS/2 Generic Wheel Mouse: EmulateWheelButton: 4, EmulateWheelInertia: 10, EmulateWheelTimeout: 200
> (II) XINPUT: Adding extended input device "ImPS/2 Generic Wheel Mouse" (type: MOUSE)
> (**) ImPS/2 Generic Wheel Mouse: (accel) keeping acceleration scheme 1
> (**) ImPS/2 Generic Wheel Mouse: (accel) filter chain progression: 2.00
> (**) ImPS/2 Generic Wheel Mouse: (accel) filter stage 0: 20.00 ms
> (**) ImPS/2 Generic Wheel Mouse: (accel) set acceleration profile 0
> (II) ImPS/2 Generic Wheel Mouse: Device reopened after 8 attempts.
> (II) config/hal: Adding input device ImPS/2 Generic Wheel Mouse
> (**) ImPS/2 Generic Wheel Mouse: always reports core events
> (**) ImPS/2 Generic Wheel Mouse: Device: "/dev/input/event4"
> (WW) ImPS/2 Generic Wheel Mouse: device file already in use. Ignoring.
> (II) UnloadModule: "evdev"
> (EE) PreInit returned NULL for "ImPS/2 Generic Wheel Mouse"
> (EE) config/hal: NewInputDeviceRequest failed (8)
> (II) config/hal: removing device ImPS/2 Generic Wheel Mouse
> (II) ImPS/2 Generic Wheel Mouse: Close
> (II) UnloadModule: "evdev"
>
> Backtrace:
> 0: /usr/bin/X(xorg_backtrace+0x3b) [0x813141b]
> 1: /usr/bin/X(xf86SigHandler+0x51) [0x80c55d1]
> 2: [0xffffe400]
> 3: /usr/bin/X(BlockHandler+0x94) [0x8090244]
> 4: /usr/bin/X(WaitForSomething+0x124) [0x812edc4]
> 5: /usr/bin/X(Dispatch+0x7e) [0x808c4de]
> 6: /usr/bin/X(main+0x3aa) [0x8071ada]
> 7: /lib/libc.so.6(__libc_start_main+0xe5) [0xb7c45775]
> 8: /usr/bin/X [0x8070fa1]
>
> Fatal server error:
> Caught signal 11.  Server aborting
>
>
> Please consult the The X.Org Foundation support
>         at http://wiki.x.org
>  for help.
> Please also check the log file at "/var/log/Xorg.0.log" for additional information.
>
> (II) AT Translated Set 2 keyboard: Close
> (II) UnloadModule: "evdev"
> (II) AIGLX: Suspending AIGLX clients for VT switch
> (EE) RADEON(0): RADEONWaitForIdleCP: CP idle -22
> (EE) RADEON(0): Idle timed out, resetting engine...
> (EE) RADEON(0): RADEONWaitForIdleCP: CP reset -22
> (EE) RADEON(0): RADEONWaitForIdleCP: CP start -22
> (EE) RADEON(0): RADEONWaitForIdleCP: CP idle -22
> (EE) RADEON(0): Idle timed out, resetting engine...
> (EE) RADEON(0): RADEONWaitForIdleCP: CP reset -22
> (EE) RADEON(0): RADEONWaitForIdleCP: CP start -22
> (EE) RADEON(0): RADEONWaitForIdleCP: CP idle -22
> (EE) RADEON(0): Idle timed out, resetting engine...
> (EE) RADEON(0): RADEONWaitForIdleCP: CP reset -22
> (EE) RADEON(0): RADEONWaitForIdleCP: CP start -22
> (EE) RADEON(0): RADEONWaitForIdleCP: CP idle -22
> (EE) RADEON(0): Idle timed out, resetting engine...
> (EE) RADEON(0): RADEONWaitForIdleCP: CP reset -22
> (EE) RADEON(0): RADEONWaitForIdleCP: CP start -22
> (EE) RADEON(0): RADEONWaitForIdleCP: CP idle -22
>
>
> [etc.etc. ad nauseam]
>
> I'm throwing an uneducated guess that this log means that there's some locking-up drm inconsistency
> during server crash shutdown (subsystem shutdown order violation?)
> which is rendering my entire machine useless, including blocking tty access.

Pretty much X dies, tries to get the GPU driver to go back to text
mode, this re-enters somewhere
holding the drm lock and the GPU dies. Pretty much sums up the whole
problem with graphics card
drivers on Linux, I can't say how we can fix that apart from if you
could gdb the X server and we
can fix the actual crash so we can avoid the issue.

The real fix for this sort of issues is called kernel modesetting.

Dave.

>
> Thanks a lot,
>
> Andreas Mohr
> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/
>

Re: drm:radeon_cp_idle/reset error storm, console lockup (-rc4 git)

[Andreas Mohr]

Hi,

On Thu, Jul 30, 2009 at 07:21:59PM +1000, Dave Airlie wrote:
> > I'm throwing an uneducated guess that this log means that there's some locking-up drm inconsistency
> > during server crash shutdown (subsystem shutdown order violation?)
> > which is rendering my entire machine useless, including blocking tty access.
> 
> Pretty much X dies, tries to get the GPU driver to go back to text
> mode, this re-enters somewhere
> holding the drm lock and the GPU dies. Pretty much sums up the whole
> problem with graphics card
> drivers on Linux, I can't say how we can fix that apart from if you
> could gdb the X server and we
> can fix the actual crash so we can avoid the issue.

"avoid the issue"... "in _this_ particular problem case", you wanted to say
(picture Sisyphos :).

Ah, darn, I should have kept X running for some longer, or rather
directly presented gdb stuff such as backtrace, local environment etc.
I will handle this in a more flexible manner next time, however.

> The real fix for this sort of issues is called kernel modesetting.

...and I was almost ready to migrate to it already. ;)
Now strongly pondering whether I should.

> Dave.

Thank you for the fast reply!

Andreas Mohr