Bug 109411

Summary: Huge scheduling delays
Product: Other Reporter: Artiom (a.mv)
Component: OtherAssignee: other_other
Status: NEW ---    
Severity: normal CC: aaron.lu, patrakov, superquad.vortex2
Priority: P1    
Hardware: All   
OS: Linux   
See Also: https://bugs.freedesktop.org/show_bug.cgi?id=93363
Kernel Version: 4.2.5 Subsystem:
Regression: No Bisected commit-id:
Attachments: Kernel config

Description Artiom 2015-12-15 14:51:06 UTC
Using pulsaudio when letting my PC turn off the screen while playing music at the precise moment of "go to sleep" sound is repeating during few seconds. While screen is off sound repeating continue to happen from time to time. 
After waking up playback returns to normal.

During the issue pulse is writing following messages to the log:

Dec 15 12:01:56 neptun pulseaudio[24525]: Scheduling delay of 1763.10 ms > 20.00 ms, you might want to investigate this to improve latency...
Dec 15 12:01:56 neptun pulseaudio[24525]: 9 events suppressed
Dec 15 12:01:56 neptun pulseaudio[24525]: Underrun!
Dec 15 12:01:56 neptun pulseaudio[24525]: Increasing wakeup watermark to 30.00 ms
Dec 15 12:02:03 neptun pulseaudio[24525]: Scheduling delay of 5837.30 ms > 30.00 ms, you might want to investigate this to improve latency...
Dec 15 12:02:03 neptun pulseaudio[24525]: Underrun!
Dec 15 12:02:03 neptun pulseaudio[24525]: Increasing wakeup watermark to 40.00 ms
Dec 15 12:02:18 neptun pulseaudio[24525]: Scheduling delay of 4529.77 ms > 40.00 ms, you might want to investigate this to improve latency...
Dec 15 12:02:18 neptun pulseaudio[24525]: Underrun!
Dec 15 12:02:18 neptun pulseaudio[24525]: Increasing wakeup watermark to 50.00 ms

*** many Scheduling delay messages skipped ***

Dec 15 12:22:40 neptun pulseaudio[24525]: Scheduling delay of 2668.43 ms > 115.99 ms, you might want to investigate this to improve latency...
Dec 15 12:22:40 neptun pulseaudio[24525]: Increasing wakeup watermark to 125.99 ms
Dec 15 12:23:16 neptun pulseaudio[24525]: Scheduling delay of 32812.77 ms > 125.99 ms, you might want to investigate this to improve latency...
Dec 15 12:23:16 neptun pulseaudio[24525]: Increasing minimal latency to 146.00 ms
Dec 15 12:23:18 neptun pulseaudio[24525]: Scheduling delay of 753.87 ms > 125.99 ms, you might want to investigate this to improve latency...
Dec 15 12:23:18 neptun pulseaudio[24525]: Increasing wakeup watermark to 135.99 ms
Dec 15 12:23:41 neptun pulseaudio[24525]: Scheduling delay of 10551.70 ms > 135.99 ms, you might want to investigate this to improve latency...
Dec 15 12:23:41 neptun pulseaudio[24525]: Underrun!
Dec 15 12:23:41 neptun pulseaudio[24525]: Increasing minimal latency to 156.00 ms
Dec 15 12:23:56 neptun pulseaudio[24525]: Scheduling delay of 7982.65 ms > 135.99 ms, you might want to investigate this to improve latency...
Dec 15 12:23:56 neptun pulseaudio[24525]: Underrun!
Dec 15 12:23:56 neptun pulseaudio[24525]: Increasing wakeup watermark to 145.99 ms
Dec 15 12:24:18 neptun pulseaudio[24525]: Scheduling delay of 17635.40 ms > 145.99 ms, you might want to investigate this to improve latency...
Comment 1 Artiom 2015-12-15 14:51:59 UTC
Created attachment 197411 [details]
Kernel config
Comment 2 Alexander E. Patrakov 2015-12-15 15:02:06 UTC
It would be nice if you provided some more details about your PC. Please see https://wiki.ubuntu.com/Audio/AlsaInfo for instructions - even if you are not on Ubuntu.

Do I understand correctly that it is a stock Debian kernel?

Could you please try an updated (4.2 or ideally 4.3) kernel, e.g. from backports or experimental? Ask me if you need instructions.
Comment 3 Artiom 2015-12-15 15:06:41 UTC
So AlsaInfo is here:
http://www.alsa-project.org/db/?f=db471e68b0614f94859966225f86eee4aa02f8af
I am using stock debian kernel and I am ready to try a newer kernel and need instructions.
Comment 4 Alexander E. Patrakov 2015-12-15 15:17:04 UTC
First, uninstall fglrx, as the kernel update will definitely break it. In other words, switch (temporarily) to open-source drivers. Reboot. At this point, it makes sense to retest whether the problem disappeared. If it did - please complain to AMD. If it didn't, read on.

Please write this line to /etc/apt/sources.list.d/backports.list

deb http://http.debian.net/debian jessie-backports main

Run as root: apt-get update
Run as root: apt-get install linux-image-4.2.0-0.bpo.1-amd64

After the reboot, the new kernel should appear in the boot menu.
Comment 5 Artiom 2015-12-15 18:35:13 UTC
I tried 4.2.0 kernel from backports (I managed to build fgrlx via dkms):

On kernel boot it stops until I press <Enter> after what it throws an error 'rcu_sched self-detected stall on CPU { 0}'

I managed to boot it flawlessly with clocksource=hpet but still see the rcu_sched message in the log. I also discovered that this message was before with 3.1 kernel.

Sound issue still reproducible exactly the same way.

Now I will try without fgrlx.
Comment 6 Artiom 2015-12-15 19:43:13 UTC
Tested with radeon driver. Exactly the same result.
Comment 7 Alexander E. Patrakov 2015-12-15 21:38:44 UTC
Please attach the full "dmesg" output with the radeon driver, including any messages that the kernel produces during such huge-delay event.
Comment 8 Artiom 2015-12-16 08:25:37 UTC
There is no messages at all except from pulse (if I start it with -vvv) during the event. Sometimes there is a normal message from USB subsystem (connecting/disconnecting device) which happens also during normal run time.
I have already removed 4.2 kernel and trying to install 4.3 from sources.
Then I will send you dmesg.
Comment 9 Raymond 2015-12-17 05:37:32 UTC
Do it mean that timer scheduling does not work when hda-intel need to use bdl_pos_adj? 

snd_hda_intel: enable_msi=1 
!!Loaded sound module options 
!!--------------------------- 
!!Module: snd_hda_intel 

align_buffer_size : -1 
bdl_pos_adj : 32,32,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1 
beep_mode : Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y enable : Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y,Y enable_msi : 1
Comment 10 Raymond 2015-12-17 05:47:01 UTC
https://git.kernel.org/cgit/linux/kernel/git/tiwai/sound.git/plain/Documentation/sound/alsa/HD-Audio.txt

Timer scheduling requite accurate dma position,  are there any differences between different position fix?
Comment 11 Aaron Lu 2015-12-23 02:05:47 UTC
I don't quite follow it here, it seems to be sound/schedule related, can someone suggest a better component for this bug? Thanks.
Comment 12 Alexander E. Patrakov 2015-12-23 07:18:38 UTC
This is some scheduling issue here, sound is just a victim. It is also related to a DPMSed monitor somehow, both on radeon and fglrx.
Comment 13 Aaron Lu 2015-12-23 07:22:15 UTC
Thanks for the info. It doesn't seem we have a scheduling category in kernel bugzilla, only other...So I'll move the bug there.
Comment 14 Raymond 2015-12-23 16:20:17 UTC
http://cgit.freedesktop.org/pulseaudio/pulseaudio/commit/src/modules/alsa?id=3bb0b88bebb1c54280d5bfe02c64e5107b125fa5

Message seem different if there is scheduled delay
Comment 15 Raymond 2015-12-23 16:37:42 UTC
+#define DEFAULT_TSCHED_BUFFER_USEC (2*PA_USEC_PER_SEC)            /* 2s   -- Overall buffer size */
+#define DEFAULT_TSCHED_WATERMARK_USEC (20*PA_USEC_PER_MSEC)       /* 20ms -- Fill up when only this much is left in the buffer */

http://cgit.freedesktop.org/pulseaudio/pulseaudio/commit/src/modules/alsa?id=1c86267e1fabd2f6eb7349bfd47e4556dd779edf

If it only fill buffer when 20ms left in the buffer, latency should be always larger than 20ms
Comment 16 Raymond 2015-12-24 04:15:58 UTC
Is it normal that schedule delay increase when pulseaudiio left to play is zero ?

If scheduke is delayed, pulseaudio clients still send data, left to play will not be zero
Comment 17 Artiom 2016-03-03 08:47:15 UTC
Looks like it is pulse bug:
https://bugs.freedesktop.org/show_bug.cgi?id=93363
Comment 18 Artiom 2016-03-03 08:48:56 UTC
Tested with kernel 4.2.5 - exactly the same issue.