Bugzilla – Bug 13129
Audio playback skips / slows down on SomaFM after a while
Last modified: 2010-04-08 17:25:35 UTC
Reproduced this twice today: When connected directly to SN and playing SomaFM stations (seen on Groove Salad, Secret Agent), after a while (perhaps hours), the audio playback starts skipping and slowing down in a really bad way. Fab4 UI becomes less responsive, and any attempt to switch stations (to another SomaFM station) results in an infinite loop of the track info popup window you normally see once at start, with no audio. Both during the initial skipping/slowness problem and the later track info spam, /var/log/messages is filled with tons of this (log rotates very quickly): Jul 29 21:27:07 squeezeplay: audio_thread_execute:719 COMMIT took too long inf ms Jul 29 21:27:07 squeezeplay: audio_thread_execute:655 WAIT took too long inf ms Jul 29 21:27:07 squeezeplay: audio_thread_execute:594 OPEN took too long inf ms Jul 29 21:27:07 squeezeplay: audio_thread_execute:674 BEGIN took too long inf ms Jul 29 21:27:07 squeezeplay: audio_thread_execute:633 STATE took too long inf ms Jul 29 21:27:32 squeezeplay: audio_thread_execute:594 OPEN took too long inf ms Jul 29 21:27:32 squeezeplay: audio_thread_execute:695 PLAYBACK took too long inf ms Jul 29 21:27:32 squeezeplay: audio_thread_execute:633 STATE took too long inf ms Jul 29 21:27:32 squeezeplay: audio_thread_execute:708 EFFECTS took too long inf ms Jul 29 21:27:32 squeezeplay: audio_thread_execute:655 WAIT took too long inf ms Jul 29 21:27:32 squeezeplay: audio_thread_execute:719 COMMIT took too long inf ms Jul 29 21:27:32 squeezeplay: audio_thread_execute:674 BEGIN took too long inf ms Jul 29 21:27:32 squeezeplay: audio_thread_execute:594 OPEN took too long inf ms Jul 29 21:27:32 squeezeplay: audio_thread_execute:680 LOCK took too long inf ms Jul 29 21:27:32 squeezeplay: audio_thread_execute:633 STATE took too long inf ms Jul 29 21:27:32 squeezeplay: audio_thread_execute:695 PLAYBACK took too long inf ms Jul 29 21:27:32 squeezeplay: audio_thread_execute:655 WAIT took too long inf ms Jul 29 21:27:32 squeezeplay: audio_thread_execute:708 EFFECTS took too long inf ms Jul 29 21:27:32 squeezeplay: audio_thread_execute:674 BEGIN took too long inf ms
Were you running TinySC on fab4 too? If you can reproduce again, what's top show?
There was no TinySC running at the time, and top was showing the two jive_alsa procs at the top when I looked before. I'm playing the same station again today and I have an ssh open already, so hopefully I'll get it again in a while.
It's doing it now again, after ~45 mins uptime on SomaFM Groove Salad. I was tailing the log, there was nothing unusual preceding the "took inf ms" spam. I did spot this one oddball line somewhere in the middle of it though: Jul 30 11:19:36 squeezeplay: audio_thread_execute:633 STATE took too long inf ms Jul 30 11:19:36 squeezeplay: audio_thread_execute:655 WAIT took too long inf ms Jul 30 11:19:36 squeezeplay: audio_thread_execute:674 BEGIN took too long inf ms Jul 30 11:19:36 squeezeplay: audio_thread_execute:680 LOCK took too long inf ms Jul 30 11:19:36 squeezeplay: audio_thread_execute:695 PLAYBACK took too long inf ms Jul 30 11:19:36 squeezeplay: audio_thread_execute:708 EFFECTS took too long inf ms Jul 30 11:19:36 squeezeplay: audio_thread_execute:712 xrun (snd_pcm_mmap_commit) err=-32 Jul 30 11:19:36 squeezeplay: audio_thread_execute:719 COMMIT took too long inf ms Jul 30 11:19:36 squeezeplay: audio_thread_execute:594 OPEN took too long inf ms Jul 30 11:19:36 squeezeplay: audio_thread_execute:633 STATE took too long inf ms Jul 30 11:19:36 squeezeplay: audio_thread_execute:655 WAIT took too long inf ms Jul 30 11:19:36 squeezeplay: audio_thread_execute:674 BEGIN took too long inf ms Jul 30 11:19:36 squeezeplay: audio_thread_execute:680 LOCK took too long inf ms I think this broken state will pretty much persistent until I reboot or pull the plug, I'll leave it this way for now so I can try to dig up more details
top info: mem: 63140K used, 62656K free, 0K shrd, 8504K buff, 18100K cached CPU: 41% usr 53% sys 0% nic 0% idle 0% io 2% irq 1% sirq Load average: 1.83 1.94 1.91 3/76 1591 PID PPID USER STAT VSZ %MEM %CPU COMMAND 715 680 root S 6976 6% 26% jive_alsa -d default -b 30000 -p 3 -f 1 713 680 root S 6960 6% 24% jive_alsa -d plughw:2,0 -b 30000 -p 3 -f 2 680 1 root S 34876 28% 20% /usr/bin/jive 548 1 root R 2692 2% 19% /sbin/syslogd -S 9 2 root SW< 0 0% 3% [sirq-tasklet/0] 644 2 root SW< 0 0% 2% [wlan_main_servi] 355 2 root SW< 0 0% 1% [IRQ-7] 7 2 root SW< 0 0% 1% [sirq-net-rx/0] 1585 818 root R 2696 2% 1% top 49 2 root SW< 0 0% 1% [IRQ-34]
Created attachment 5536 [details] strace of jive process
Created attachment 5537 [details] strace of jive_alsa -d plughw:2,0 -b 30000 -p 3 -f 2
Created attachment 5538 [details] strace of jive_alsa -d default -b 30000 -p 3 -f 1
Apparently this doesn't have much to do with the stream being played. I haven't touched my fab4 since the firmware update/reboot this morning 5 hours ago (r6858), and it's already exhibiting the same symptoms now when I went to use it. UI slow, beeps are skippy, and logfile is spewing "took too long inf ms" spam. I haven't even attempted to play any audio yet.
I think this is generic fab4 problem with recent builds which is probably the cause of the forum thread: http://forums.slimdevices.com/showthread.php?t=66124 It doesn't take hours if you repeatly restart streams to get into this condition.
Brandon, I think this is fixed now. Could you confirm, and close.
I suspect it is fixed, but I can't really confirm anything on fab4+SN lately, my fab4 is kinda just stuck with a 3-item home menu and totally unresponsive touch screen every time I boot it up. Gonna try with SC trunk I guess and see if that gets anywhere.
This bug has been marked fixed in a released version of Squeezebox Server or the accompanying firmware or mysqueezebox.com release. If you are still seeing this issue, please let us know!