[alsa-devel] BugReport: Dice works partially [Broken]
Hi, I am a user of TC Electronic DesktopKonnekt6 and latest kernel update 3.19.2 add partial support for my device and thus broke my usual sound workflow. So i want to make good bug report to make device usable on latest kernels.
With 3.19.2 kernel device is successfully recognized by system and even sometimes can play sound(!). But always, after some time sound is breaks (usually after 30-90 seconds) and to restore it i must restart pulseaudio(v6.0) and application. So device becomes unusable on latests kernels. Earlier i use my sound card through ffado + jackdbus + pulseaudio. Now it's impossible, so i have to downgrade kernel.
Please request any additional info that you need to fix problem and i will post it here soon. Also i can test any "bleeding edge" changes thru dkms as described here: https://github.com/takaswie/snd-firewire-improve
Related bug(not mine): https://bugs.archlinux.org/task/44258
Some useful info:
cat /proc/asound/cards 0 [DesktopKonnekt6]: DICE - DesktopKonnekt6 TC Electronic DesktopKonnekt6 (serial 12941) at fw1.0, S400
cat /proc/asound/card0/dice sections: global: offset 10, size 90 tx: offset 100, size 142 rx: offset 242, size 282 ext_sync: offset 524, size 4 unused2: offset 0, size 0 global: owner: ffc1:000100000000 notification: 00000040 nick name: DesktopKonnekt6 clock select: internal 44100 enable: 1 status: locked 44100 ext status: 00000000 sample rate: 44100 version: 1.0.4.0 clock caps: 44100 48000 88200 96000 176400 192000 arx1 arx2 internal clock source names: Unused\Unused\Unused\Unused\Unused\Unused\Unused\Unused\Unused\Unused\Unused\Unused\INTERNAL\ tx 0: iso channel: 0 audio channels: 6 midi ports: 0 speed: S400 names: ch 1\ch 2\ - \ - \ - \ - \ ac3 caps: 00000000 ac3 enable: 00000000 rx 0: iso channel: 1 sequence start: 0 audio channels: 6 midi ports: 0 names: main out 1\main out 2\phones out 1\phones out 2\ - \ - \ ac3 caps: 00000000 ac3 enable: 00000000 ext status: clock source: internal locked: 1 rate: 44100 adat user data: 0
Stanislav Sergiienko wrote:
Hi, I am a user of TC Electronic DesktopKonnekt6 and latest kernel update 3.19.2 add partial support for my device and thus broke my usual sound workflow. So i want to make good bug report to make device usable on latest kernels.
With 3.19.2 kernel device is successfully recognized by system and even sometimes can play sound(!).
What exactly happens when it cannot play sound?
But always, after some time sound is breaks (usually after 30-90 seconds) and to restore it i must restart pulseaudio(v6.0) and application.
What exactly happens when it "breaks"? Any error messages in the system log?
Regards, Clemens
Any error messages in the system log?
The problem is that i couldn't find any significant errors. All i was able to gather is:
journalctl: апр 13 13:47:56 ArchLinux pulseaudio[2115]: [pulseaudio] pid.c: Daemon already running. апр 13 13:48:03 ArchLinux pulseaudio[2098]: [alsa-sink-DICE] alsa-sink.c: ALSA woke us up to write new data to the device, but there was actually nothing to write! апр 13 13:48:03 ArchLinux pulseaudio[2098]: [alsa-sink-DICE] alsa-sink.c: Most likely this is a bug in the ALSA driver 'snd_dice'. Please report this issue to the ALSA developers. апр 13 13:48:03 ArchLinux pulseaudio[2098]: [alsa-sink-DICE] alsa-sink.c: We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail() returned 0 or another value < min_avail.
Sometimes see this: май 03 17:30:27 ArchLinux pulseaudio[657]: [alsa-sink-DICE] alsa-sink.c: Resume failed, couldn't restore original sample settings.
Sometimes after play failed i see in sysnotification area: "DesktopKonnect6 don't work, 'Default' will be used"
In dmesg i see no errors.
What exactly happens when it cannot play sound?
No errors. It's just don't play anything. For example, for video, various players handle it differently - some are just play video without any sound, some can't play video at all(stops play on first frame).
What exactly happens when it "breaks"?
Almost nothing, sometimes i can hear that music breaks with some kind of "click-sound", like someone pulled the wire from my loudspeakers. But this sound is barely noticeable. If i try to play file again i hear some kind of "initialization sound", like when device open on PC boot. It's hard to describe it in my English :)
If you send me info about how to gather more detailed logs, i try do this. P.S. Sorry for long time to answer.
Hi,
To reveal what causes this issue, please post following test and the outputs. The test consists of 8 steps.
0. Plug-out your DesktopKonnect6.
1. To prevent snd_dice from auto-loading, add an entry to configuration file. See: https://wiki.archlinux.org/index.php/Kernel_modules#Blacklisting
Perhaps: $ cat /etc/modprobe.d/blacklist.conf ... blacklist snd_dice ...
2. Reboot your system and confirm that snd_dice is not auto-loaded.
$ lsmod | grep snd_dice (nothing)
3. Plug-in your DesktopKonnect6.
4. Wait one minute without do things (I expect several bus reset occurs in IEEE 1394 bus then the bus becomes calm.)
5. Load snd_dice and check it $ modprobe snd_dice $ lsmod | grep snd_dice snd_dice (you may see.)
6. Dump module information $ cat /proc/asound/DesktopKonnekt6/dice ...(outputs)...
7. Try your playback test.
8. get logs from pulseaudio via journalctl or the other tools.
Regards
Takashi Sakamoto
On May 11 2015 07:10, Stanislav Sergiienko wrote:
Any error messages in the system log?
The problem is that i couldn't find any significant errors. All i was able to gather is:
journalctl: апр 13 13:47:56 ArchLinux pulseaudio[2115]: [pulseaudio] pid.c: Daemon already running. апр 13 13:48:03 ArchLinux pulseaudio[2098]: [alsa-sink-DICE] alsa-sink.c: ALSA woke us up to write new data to the device, but there was actually nothing to write! апр 13 13:48:03 ArchLinux pulseaudio[2098]: [alsa-sink-DICE] alsa-sink.c: Most likely this is a bug in the ALSA driver 'snd_dice'. Please report this issue to the ALSA developers. апр 13 13:48:03 ArchLinux pulseaudio[2098]: [alsa-sink-DICE] alsa-sink.c: We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail() returned 0 or another value < min_avail.
Sometimes see this: май 03 17:30:27 ArchLinux pulseaudio[657]: [alsa-sink-DICE] alsa-sink.c: Resume failed, couldn't restore original sample settings.
Sometimes after play failed i see in sysnotification area: "DesktopKonnect6 don't work, 'Default' will be used"
In dmesg i see no errors.
What exactly happens when it cannot play sound?
No errors. It's just don't play anything. For example, for video, various players handle it differently - some are just play video without any sound, some can't play video at all(stops play on first frame).
What exactly happens when it "breaks"?
Almost nothing, sometimes i can hear that music breaks with some kind of "click-sound", like someone pulled the wire from my loudspeakers. But this sound is barely noticeable. If i try to play file again i hear some kind of "initialization sound", like when device open on PC boot. It's hard to describe it in my English :)
If you send me info about how to gather more detailed logs, i try do this. P.S. Sorry for long time to answer.
Hi, I did all you asked exactly step by step, and after that, even more. Linux kernel == 4.1.4
This was printed by dmesg when I plugged card after reboot: ... [ 53.654603] cfg80211: Calling CRDA to update world regulatory domain [ 56.802735] cfg80211: Exceeded CRDA call max attempts. Not calling CRDA [ 163.474535] firewire_core 0000:0a:00.0: phy config: new root=ffc1, gap_count=5 [ 165.633183] firewire_core 0000:0a:00.0: created device fw1: GUID 000166040900328d, S400 [ 165.635721] firewire_core 0000:0a:00.0: phy config: new root=ffc1, gap_count=5 [ 165.979725] firewire_core 0000:0a:00.0: giving up on node ffc0: reading config rom failed: timeout [ 167.640492] firewire_core 0000:0a:00.0: BM lock failed (timeout), making local node (ffc0) root [ 167.640496] firewire_core 0000:0a:00.0: phy config: new root=ffc0, gap_count=5
This after modprobe (kde played notification sound on this command): cat /proc/asound/DesktopKonnekt6/dice sections: global: offset 10, size 90 tx: offset 100, size 142 rx: offset 242, size 282 ext_sync: offset 524, size 4 unused2: offset 0, size 0 global: owner: ffc1:000100000000 notification: 00000040 nick name: DesktopKonnekt6 clock select: internal 48000 enable: 0 status: locked 48000 ext status: 00000000 sample rate: 48000 version: 1.0.4.0 clock caps: 44100 48000 88200 96000 176400 192000 arx1 arx2 internal clock source names: Unused\Unused\Unused\Unused\Unused\Unused\Unused\Unused\Unused\Unused\Unused\Unused\INTERNAL\ tx 0: iso channel: -1 audio channels: 6 midi ports: 0 speed: S400 names: ch 1\ch 2\ - \ - \ - \ - \ ac3 caps: 00000000 ac3 enable: 00000000 rx 0: iso channel: -1 sequence start: 0 audio channels: 6 midi ports: 0 names: main out 1\main out 2\phones out 1\phones out 2\ - \ - \ ac3 caps: 00000000 ac3 enable: 00000000 ext status: clock source: internal locked: 1 rate: 48000 adat user data: 0
aplay -v ./test.wav Playing WAVE './test.wav' : Signed 16 bit Little Endian, Rate 44100 Hz, Stereo Plug PCM: Route conversion PCM (sformat=S16_LE) Transformation table: 0 <- 0 1 <- 1 2 <- none 3 <- none 4 <- none 5 <- none Its setup is: stream : PLAYBACK access : RW_INTERLEAVED format : S16_LE subformat : STD channels : 2 rate : 44100 exact rate : 44100 (44100/1) msbits : 16 buffer_size : 8192 period_size : 1536 period_time : 34829 tstamp_mode : NONE tstamp_type : MONOTONIC period_step : 1 avail_min : 1536 period_event : 0 start_threshold : 8192 stop_threshold : 8192 silence_threshold: 0 silence_size : 0 boundary : 4611686018427387904 Slave: Hardware PCM card 0 'DesktopKonnekt6' device 0 subdevice 0 Its setup is: stream : PLAYBACK access : MMAP_INTERLEAVED format : S16_LE subformat : STD channels : 6 rate : 44100 exact rate : 44100 (44100/1) msbits : 16 buffer_size : 8192 period_size : 1536 period_time : 34829 tstamp_mode : NONE tstamp_type : MONOTONIC period_step : 1 avail_min : 1536 period_event : 0 start_threshold : 8192 stop_threshold : 8192 silence_threshold: 0 silence_size : 0 boundary : 4611686018427387904 appl_ptr : 0 hw_ptr : 0 ^CAborted by signal Прерывание... aplay: pcm_write:1939: write error: Прерван системный вызов
aplay freezes randomly and prints NO ERRORS. Same with pulseaudio, i tried even pulseaudio -v --log-level=4 (huge output) but no errors when playing stopped. I have try to set various sample size format and clock rate, same results.
After that I even use python lib https://github.com/larsimmisch/pyalsaaudio/ to debug tiny program that plays .wav. I tried to see where exactly was error, and found that no errors is occured, program always blocked here: ... while data: y = device.write(data) # blocked here print('WRITTEN=', y) ...
That's why there is no errors in any programs.
Then I remember about strace:
strace -i -v -T -y -yy aplay ./test.wav [00007f2b604db18d] poll([{fd=4</dev/snd/pcmC0D0p>, events=POLLOUT|POLLERR|POLLNVAL}], 1, 4294967295) = 1 ([{fd=4, revents=POLLOUT}]) <0.033380> [00007f2b604dc797] ioctl(4</dev/snd/pcmC0D0p>, SNDRV_PCM_IOCTL_HWSYNC, 0x7f2b60a13cf0) = 0 <0.000056> [00007f2b607aefad] read(3</home/stas/test.wav>, "N\0\0\0024\0\31\2\306\0^\2\36\1~\2\301\0\350\1\330\0\331\1\277\0d\1$\1{\1"..., 6144) = 6144 <0.000067> [00007f2b604dc797] ioctl(4</dev/snd/pcmC0D0p>, SNDRV_PCM_IOCTL_HWSYNC, 0x7f2b60a13cf0) = 0 <0.000058> [00007f2b604db18d] poll([{fd=4</dev/snd/pcmC0D0p>, events=POLLOUT|POLLERR|POLLNVAL}], 1, 4294967295) = 1 ([{fd=4, revents=POLLOUT}]) <0.035439> [00007f2b604dc797] ioctl(4</dev/snd/pcmC0D0p>, SNDRV_PCM_IOCTL_HWSYNC, 0x7f2b60a13cf0) = 0 <0.000030> [00007f2b607aefad] read(3</home/stas/test.wav>, "\267\373\225\372\225\373Q\372U\373\342\371,\373\273\371\276\372?\371\340\3729\371\23\372\230\370\326\372F\371"..., 6144) = 6144 <0.000051> [00007f2b604dc797] ioctl(4</dev/snd/pcmC0D0p>, SNDRV_PCM_IOCTL_HWSYNC, 0x7f2b60a13cf0) = 0 <0.000066> [00007f2b604db18d] poll([{fd=4</dev/snd/pcmC0D0p>, events=POLLOUT|POLLERR|POLLNVAL}], 1, 4294967295) = 1 ([{fd=4, revents=POLLOUT}]) <0.033301> [00007f2b604dc797] ioctl(4</dev/snd/pcmC0D0p>, SNDRV_PCM_IOCTL_HWSYNC, 0x7f2b60a13cf0) = 0 <0.000079> [00007f2b607aefad] read(3</home/stas/test.wav>, "_\1\313\377_\2\230\0\36\6\212\4\270\7\234\6\360\6f\0061\6o\5\362\2q\2t\0\3\0"..., 6144) = 6144 <0.000107> [00007f2b604dc797] ioctl(4</dev/snd/pcmC0D0p>, SNDRV_PCM_IOCTL_HWSYNC, 0x7f2b60a13cf0) = 0 <0.000080> [00007f2b604db18d] poll([{fd=4</dev/snd/pcmC0D0p>, events=POLLOUT|POLLERR|POLLNVAL}], 1, 4294967295) = 1 ([{fd=4, revents=POLLOUT}]) <0.033154> [00007f2b604dc797] ioctl(4</dev/snd/pcmC0D0p>, SNDRV_PCM_IOCTL_HWSYNC, 0x7f2b60a13cf0) = 0 <0.000093> [00007f2b607aefad] read(3</home/stas/test.wav>, "\354\1W\5-\1\266\4t\377\1\3Y\376\330\1E\376\267\1\222\376\350\1<\377u\2\251\377\364\2"..., 6144) = 6144 <0.000081> [00007f2b604dc797] ioctl(4</dev/snd/pcmC0D0p>, SNDRV_PCM_IOCTL_HWSYNC, 0x7f2b60a13cf0) = 0 <0.000033> [00007f2b604db18d] poll([{fd=4</dev/snd/pcmC0D0p>, events=POLLOUT|POLLERR|POLLNVAL}], 1, 4294967295) = 1 ([{fd=4, revents=POLLOUT}]) <0.035188> [00007f2b604dc797] ioctl(4</dev/snd/pcmC0D0p>, SNDRV_PCM_IOCTL_HWSYNC, 0x7f2b60a13cf0) = 0 <0.000087> [00007f2b607aefad] read(3</home/stas/test.wav>, "\306\350\353\346>\351I\347>\351\25\347\325\350\370\346v\346\372\344\317\343\205\342(\343O\342V\343\220\342"..., 6144) = 6144 <0.000090> [00007f2b604dc797] ioctl(4</dev/snd/pcmC0D0p>, SNDRV_PCM_IOCTL_HWSYNC, 0x7f2b60a13cf0) = 0 <0.000089> [00007f2b604db18d] poll([{fd=4</dev/snd/pcmC0D0p>, events=POLLOUT|POLLERR|POLLNVAL}], 1, 4294967295) = 1 ([{fd=4, revents=POLLOUT}]) <0.034704> [00007f2b604dc797] ioctl(4</dev/snd/pcmC0D0p>, SNDRV_PCM_IOCTL_HWSYNC, 0x7f2b60a13cf0) = 0 <0.000083> [00007f2b607aefad] read(3</home/stas/test.wav>, "E\27\330\26>\32\320\31a\32F\31e\31\372\27\336\30t\27x\31\254\27\352\31\372\27\17\32)\30"..., 6144) = 6144 <0.000085> [00007f2b604dc797] ioctl(4</dev/snd/pcmC0D0p>, SNDRV_PCM_IOCTL_HWSYNC, 0x7f2b60a13cf0) = 0 <0.000049> [00007f2b604db18d] poll([{fd=4</dev/snd/pcmC0D0p>, events=POLLOUT|POLLERR|POLLNVAL}], 1, 4294967295 # sound stops play here and program blocks
Same aplay but through pulseaudio:
[00007f3f7fa56fad] read(3pipe:[76277], 0x7ffda627a910, 10) = -1 EAGAIN (Resource temporarily unavailable) [00007f3f7fa51f07] futex(0x1fd17d0, FUTEX_UNLOCK_PI_PRIVATE, 0) = 0 [00007f3f7fa56fad] read(8</home/stas/test.wav>, "i\10\200\7D\4\317\0023\4w\2\346\5/\4\307\6\373\4\177\6\344\4l\4\371\2\241\375\227\374"..., 22048) = 22048 [00007f3f7f78318d] poll([{fd=3pipe:[76277], events=POLLIN|POLLERR|POLLNVAL}], 1, 4294967295) = 1 ([{fd=3, revents=POLLIN}]) [00007f3f7fa56f4d] write(6pipe:[76278], "W", 1) = 1 [00007f3f7fa56fad] read(3pipe:[76277], "x", 10) = 1 [00007f3f7fa56fad] read(3pipe:[76277], 0x7ffda627a910, 10) = -1 EAGAIN (Resource temporarily unavailable) [00007f3f7fa51f07] futex(0x1fd17d0, FUTEX_UNLOCK_PI_PRIVATE, 0) = 0 [00007f3f7fa56fad] read(8</home/stas/test.wav>, "g\350_\350\260\350y\350\273\350\215\350\350\350\221\350\365\350\22\350\357\350\375\347\353\350\330\350\v\351\307\351"..., 22048) = 22048 [00007f3f7f78318d] poll([{fd=3pipe:[76277], events=POLLIN|POLLERR|POLLNVAL}], 1, 4294967295) = 1 ([{fd=3, revents=POLLIN}]) [00007f3f7fa56f4d] write(6pipe:[76278], "W", 1) = 1 [00007f3f7fa56fad] read(3pipe:[76277], "x", 10) = 1 [00007f3f7fa56fad] read(3pipe:[76277], 0x7ffda627a910, 10) = -1 EAGAIN (Resource temporarily unavailable) [00007f3f7fa51f07] futex(0x1fd17d0, FUTEX_UNLOCK_PI_PRIVATE, 0) = 0 [00007f3f7fa56fad] read(8</home/stas/test.wav>, "\36\355"\355Z\355_\355\212\355\232\355\277\355\345\355\33\356P\356\273\356\341\356\264\357\326\357\337\360\363\360"..., 22048) = 22048 [00007f3f7f78318d] poll([{fd=3pipe:[76277], events=POLLIN|POLLERR|POLLNVAL}], 1, 4294967295
After my tests with aplay:
cat /proc/asound/DesktopKonnekt6/dice sections: global: offset 10, size 90 tx: offset 100, size 142 rx: offset 242, size 282 ext_sync: offset 524, size 4 unused2: offset 0, size 0 global: owner: ffc1:000100000000 notification: 00000040 nick name: DesktopKonnekt6 clock select: internal 44100 enable: 0 status: locked 44100 ext status: 00000000 sample rate: 44100 version: 1.0.4.0 clock caps: 44100 48000 88200 96000 176400 192000 arx1 arx2 internal clock source names: Unused\Unused\Unused\Unused\Unused\Unused\Unused\Unused\Unused\Unused\Unused\Unused\INTERNAL\ tx 0: iso channel: -1 audio channels: 6 midi ports: 0 speed: S400 names: ch 1\ch 2\ - \ - \ - \ - \ ac3 caps: 00000000 ac3 enable: 00000000 rx 0: iso channel: -1 sequence start: 0 audio channels: 6 midi ports: 0 names: main out 1\main out 2\phones out 1\phones out 2\ - \ - \ ac3 caps: 00000000 ac3 enable: 00000000 ext status: clock source: internal locked: 1 rate: 44100 adat user data: 0
I noticed that when sound is playing "ext status: 00000040". When sound stops and program freezes then it sets to 00000000 again, even if program still works (freezed).
Hope this helps to solve the problem.
2015-05-11 4:42 GMT+03:00 Takashi Sakamoto o-takashi@sakamocchi.jp:
Hi,
To reveal what causes this issue, please post following test and the outputs. The test consists of 8 steps.
Plug-out your DesktopKonnect6.
To prevent snd_dice from auto-loading, add an entry to configuration
file. See: https://wiki.archlinux.org/index.php/Kernel_modules#Blacklisting
Perhaps: $ cat /etc/modprobe.d/blacklist.conf ... blacklist snd_dice ...
- Reboot your system and confirm that snd_dice is not auto-loaded.
$ lsmod | grep snd_dice (nothing)
Plug-in your DesktopKonnect6.
Wait one minute without do things
(I expect several bus reset occurs in IEEE 1394 bus then the bus becomes calm.)
- Load snd_dice and check it
$ modprobe snd_dice $ lsmod | grep snd_dice snd_dice (you may see.)
- Dump module information
$ cat /proc/asound/DesktopKonnekt6/dice ...(outputs)...
Try your playback test.
get logs from pulseaudio via journalctl or the other tools.
Regards
Takashi Sakamoto
On May 11 2015 07:10, Stanislav Sergiienko wrote:
Any error messages in the system log?
The problem is that i couldn't find any significant errors. All i was able to gather is:
journalctl: апр 13 13:47:56 ArchLinux pulseaudio[2115]: [pulseaudio] pid.c: Daemon already running. апр 13 13:48:03 ArchLinux pulseaudio[2098]: [alsa-sink-DICE] alsa-sink.c: ALSA woke us up to write new data to the device, but there was actually nothing to write! апр 13 13:48:03 ArchLinux pulseaudio[2098]: [alsa-sink-DICE] alsa-sink.c: Most likely this is a bug in the ALSA driver 'snd_dice'. Please report this issue to the ALSA developers. апр 13 13:48:03 ArchLinux pulseaudio[2098]: [alsa-sink-DICE] alsa-sink.c: We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail() returned 0 or another value < min_avail.
Sometimes see this: май 03 17:30:27 ArchLinux pulseaudio[657]: [alsa-sink-DICE] alsa-sink.c: Resume failed, couldn't restore original sample settings.
Sometimes after play failed i see in sysnotification area: "DesktopKonnect6 don't work, 'Default' will be used"
In dmesg i see no errors.
What exactly happens when it cannot play sound?
No errors. It's just don't play anything. For example, for video, various players handle it differently - some are just play video without any sound, some can't play video at all(stops play on first frame).
What exactly happens when it "breaks"?
Almost nothing, sometimes i can hear that music breaks with some kind of "click-sound", like someone pulled the wire from my loudspeakers. But this sound is barely noticeable. If i try to play file again i hear some kind of "initialization sound", like when device open on PC boot. It's hard to describe it in my English :)
If you send me info about how to gather more detailed logs, i try do this. P.S. Sorry for long time to answer.
participants (3)
-
Clemens Ladisch -
Stanislav Sergiienko -
Takashi Sakamoto