Bug#656196: [2.6.39 -> 3.0 regression] kernel stalls every few days (rcu_sched_state detected stall on CPU x)

To: Jonathan Nieder <jrnieder@gmail.com>
Cc: 656196@bugs.debian.org
Subject: Bug#656196: [2.6.39 -> 3.0 regression] kernel stalls every few days (rcu_sched_state detected stall on CPU x)
From: Michael Below <below@judiz.de>
Date: Thu, 23 Aug 2012 15:58:36 +0200
Message-id: <[🔎] 1345730316.5337.25.camel@ossietzky>
Reply-to: Michael Below <below@judiz.de>, 656196@bugs.debian.org
In-reply-to: <[🔎] 1345567994.4665.16.camel@ossietzky>
References: <1343724921.5402.6.camel@ossietzky> <[🔎] 20120803004116.GB30701@copier> <[🔎] 1345567994.4665.16.camel@ossietzky>

Am Dienstag, den 21.08.2012, 18:53 +0200 schrieb Michael Below:

> Am Donnerstag, den 02.08.2012, 17:41 -0700 schrieb Jonathan Nieder:
> 
> > Could you bisect through the kernels at
> > 
> >   http://snapshot.debian.org/package/linux-2.6/
> > 
> > to find which is the first fixed one?  That would help a lot in
> > isolating what change is likely to have fixed this, so we can apply
> > that change to wheezy and make sure it is applied to the upstream
> > 3.2.y tree for other distributors, too.
> 
> I have been running 3.3 rc6 for a couple of days now, no problems so
> far.

Maybe related, maybe not. I am not reporting this as an ALSA bug since I
am still running 3.3rc6 from experimental, still without stalls, but
maybe this points to a reason for those 3.2 stalls: I have seen this
"canary starving" message with the stalls as well:

Aug 23 15:17:01 ossietzky /USR/SBIN/CRON[13837]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 23 15:32:20 ossietzky rtkit-daemon[3096]: The canary thread is apparently starving. Taking action.
Aug 23 15:32:20 ossietzky rtkit-daemon[3096]: Demoting known real-time threads.
Aug 23 15:32:20 ossietzky rtkit-daemon[3096]: Successfully demoted thread 4886 of process 4886 (/usr/bin/pulseaudio).
Aug 23 15:32:20 ossietzky rtkit-daemon[3096]: Demoted 1 threads.
Aug 23 15:32:21 ossietzky dbus[1962]: [system] Activating service name='org.freedesktop.PackageKit' (using servicehelper)
Aug 23 15:32:25 ossietzky dbus[1962]: [system] Successfully activated service 'org.freedesktop.PackageKit'
Aug 23 15:39:01 ossietzky /USR/SBIN/CRON[14045]: (root) CMD (  [ -x /usr/lib/php5/maxlifetime ] && [ -d /var/lib/php5 ] && find /var/lib/php5/ -depth -mindepth 1 -maxdepth 1 -type f -ignore_readdir_race -cmin +$(/usr/lib/php5/maxlifetime) ! -execdir fuser -s {} 2>/dev/null \; -delete)
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c: snd_pcm_avail() gibt einen Wert zurück, der ausserordentlich gross ist: 2131660 bytes (12084 ms).
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c: Dies ist wahrscheinlich ein Fehler im ALSA-Treiber 'snd_hda_intel'. Bitte melden Sie dieses Problem den ALSA-Entwicklern.
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c: snd_pcm_dump():
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c: Hardware PCM card 0 'HDA ATI SB' device 0 subdevice 0
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c: Its setup is:
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   stream       : PLAYBACK
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   access       : MMAP_INTERLEAVED
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   format       : S16_LE
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   subformat    : STD
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   channels     : 2
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   rate         : 44100
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   exact rate   : 44100 (44100/1)
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   msbits       : 16
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   buffer_size  : 16384
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   period_size  : 8192
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   period_time  : 185759
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   tstamp_mode  : ENABLE
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   period_step  : 1
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   avail_min    : 15503
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   period_event : 0
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   start_threshold  : -1
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   stop_threshold   : 4611686018427387904
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   silence_threshold: 0
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   silence_size : 0
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   boundary     : 4611686018427387904
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   appl_ptr     : 30407
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   hw_ptr       : 546938
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c: snd_pcm_delay() gibt einen Wert zurück, der ausserordentlich gross ist: -2024588 bytes (-11477 ms).
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c: Dies ist wahrscheinlich ein Fehler im ALSA-Treiber 'snd_hda_intel'. Bitte melden Sie dieses Problem den ALSA-Entwicklern.
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c: snd_pcm_dump():
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c: Hardware PCM card 0 'HDA ATI SB' device 0 subdevice 0
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c: Its setup is:
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   stream       : PLAYBACK
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   access       : MMAP_INTERLEAVED
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   format       : S16_LE
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   subformat    : STD
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   channels     : 2
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   rate         : 44100
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   exact rate   : 44100 (44100/1)
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   msbits       : 16
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   buffer_size  : 16384
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   period_size  : 8192
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   period_time  : 185759
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   tstamp_mode  : ENABLE
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   period_step  : 1
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   avail_min    : 15503
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   period_event : 0
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   start_threshold  : -1
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   stop_threshold   : 4611686018427387904
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   silence_threshold: 0
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   silence_size : 0
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   boundary     : 4611686018427387904
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   appl_ptr     : 62087
Aug 23 15:47:18 ossietzky pulseaudio[4886]: [alsa-sink] alsa-util.c:   hw_ptr       : 568234

Reply to:

References:
- Bug#656196: [2.6.39 -> 3.0 regression] kernel stalls every few days (rcu_sched_state detected stall on CPU x)
  - From: Jonathan Nieder <jrnieder@gmail.com>
- Bug#656196: [2.6.39 -> 3.0 regression] kernel stalls every few days (rcu_sched_state detected stall on CPU x)
  - From: Michael Below <below@judiz.de>

Prev by Date: Bug#656899: http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=656899
Next by Date: Bug#656899: http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=656899
Previous by thread: Bug#656196: [2.6.39 -> 3.0 regression] kernel stalls every few days (rcu_sched_state detected stall on CPU x)
Next by thread: Processed: tagging 675493
Index(es):
- Date
- Thread