PROBLEM: SIS7019 stops recording after 42 min

[Hans Schou]

Hi

I have a problem with recording sound when using the sound chip
SIS7019 with both kernel 2.6.26 and 2.6.34. After recording about 42
minutes it kind a stops recording, more precisely it is taking a pause
of exactly 10 seconds between each reading.

As recorder I have tried several programs and all of them fails after
42 minutes. Some programs uses Alsa and some uses the old deprecated
method. In this example I have logged sox rec.

Recording method in a script:
  strace -tt -o strace.log rec -c 1 -r 44100 -2 sox.wav &
  sleep 3000
  kill $?

Recording start 17:41:29 and undtil 18:23:38.977278 it writes about
6-7 times per second to disk. Then it begin only writing every 10
seconds. At this point it had written 27222 times to disk and the
amount of data written so far is 28684288 bytes (including
wav-header).

WorkARound: When the recording stops, one can just exit 'rec' and
start it again and record another 42 minutes. Reboot is not necessary.
Apparently, the re-init of the sound chip fixes the problem.

On other systems with nVidia CK804 or emu10k I do not have the same problem.

I have looked at sound/pci/sis7019.c but I do not really know what I
should look for. None of the numbers in my observations is in the
power of 2 which I would expect it was. Like, I expected it stopped
recording after 64MB or so, but that is not the case.

Linux version 2.6.34-norhtec-sis (root@norh) (gcc version 4.1.2
20061115 (prerelease) (Debian 4.1.1-21)) #7 Wed Jun 16 00:32:56 CEST
2010
(the kernel used was compiled on this system.)

# scripts/ver_linux
Gnu C                  4.1.2
Gnu make               3.81
binutils               2.17
util-linux             2.12r
mount                  2.12r
module-init-tools      3.3-pre2
e2fsprogs              1.40-WIP
Linux C Library        scripts/ver_linux: line 63: /proc/self/maps: No
such file or directory
Dynamic linker (ldd)   2.3.6
Net-tools              1.60
Console-tools          0.2.3
Sh-utils               5.97
udev                   105

# lspci -vvv
00:01.4 Multimedia audio controller: Silicon Integrated Systems [SiS]
SiS7019 Audio Accelerator
        Subsystem: Silicon Integrated Systems [SiS] SiS7019 Audio
Accelerator
        Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop-
ParErr- Stepping- SERR- FastB2B- DisINTx-
        Status: Cap+ 66MHz- UDF- FastB2B+ ParErr- DEVSEL=medium
>TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
        Latency: 64 (500ns min, 6000ns max)
        Interrupt: pin B routed to IRQ 10
        Region 0: I/O ports at dc00 [size=256]
        Region 1: Memory at dfff8000 (32-bit, non-prefetchable)
[size=16K]
        Capabilities: [60] Power Management version 2
                Flags: PMEClk- DSI+ D1+ D2+ AuxCurrent=0mA
PME(D0+,D1+,D2+,D3hot+,D3cold+)
                Status: D0 PME-Enable- DSel=0 DScale=0 PME-
        Kernel driver in use: SiS7019
        Kernel modules: snd-sis7019

Here is a snip from the log file when it goes from reading 7 times per
second to every 10th second. Note two times "ioctl" within a second
and then it goes over to a delay with 10 seconds between each "ioctl":

18:23:38.611877 ioctl(4, 0x800c4151, 0xbf96b1d0) = 0
18:23:38.784635 gettimeofday({1276446218, 785207}, NULL) = 0
18:23:38.786609 write(2, "\rTime: 42:08.19 [00:00.00] of 00:"..., 78)= 78
18:23:38.789354
write(3,"p\377q\377n\377k\377l\377p\377o\377o\377k\377n\377p\377q\377n\377o\377k\377l\377p"...,4096)
= 4096
18:23:38.791590
write(3,"j\377l\377l\377j\377l\377k\377m\377k\377l\377n\377j\377l\377l\377n\377n\377g\377m"...,12288)
= 12288
18:23:38.794425 gettimeofday({1276446218, 795024}, NULL) = 0
18:23:38.795762 ioctl(4, 0x800c4151, 0xbf96b1d0) = 0
18:23:38.970451 gettimeofday({1276446218, 971018}, NULL) = 0
18:23:38.972293 write(2, "\rTime: 42:08.37 [00:00.00] of 00:"..., 78)= 78
18:23:38.975134
write(3,"k\377m\377o\377k\377i\377j\377m\377o\377o\377m\377k\377m\377o\377k\377p\377n\377o"...,4096)
= 4096
18:23:38.977278
write(3,"m\377j\377p\377n\377n\377r\377m\377o\377o\377o\377l\377h\377l\377l\377m\377o\377o"...,12288)
= 12288
18:23:38.980176 gettimeofday({1276446218, 980773}, NULL) = 0
18:23:38.981516 ioctl(4, 0x800c4151, 0xbf96b1d0) = 0
18:23:48.983347 ioctl(4, 0x800c4151, 0xbf96b1d0) = 0
18:23:48.985710 gettimeofday({1276446228, 986317}, NULL) = 0
18:23:48.987784 write(2, "\rTime: 42:08.56 [00:00.00] of 00:"..., 78) = 78
18:23:48.990733
write(3,"j\377k\377l\377l\377l\377n\377l\377q\377q\377j\377l\377m\377m\377p\377o\377o\377q"...,4096)
= 4096
18:23:48.992814
write(3,"p\377m\377k\377s\377r\377m\377o\377m\377k\377k\377j\377j\377l\377p\377o\377r\377l"...,12288)
= 12288
18:23:48.995694 gettimeofday({1276446228, 996297}, NULL) = 0
18:23:48.997046 ioctl(4, 0x800c4151, 0xbf96b1d0) = 0
18:23:48.999574 gettimeofday({1276446229, 186}, NULL) = 0
18:23:49.003421
write(3,"l\377l\377m\377o\377q\377q\377n\377m\377q\377r\377s\377p\377n\377t\377r\377m\377n"...,4096)
= 4096
18:23:49.005517
write(3,"o\377m\377l\377p\377m\377p\377o\377m\377p\377p\377q\377o\377j\377m\377r\377m\377r"...,12288)
= 12288
18:23:49.008337 gettimeofday({1276446229, 8945}, NULL) = 0
18:23:49.009699 ioctl(4, 0x800c4151, 0xbf96b1d0) = 0
18:23:59.007878 ioctl(4, 0x800c4151, 0xbf96b1d0) = 0

Version of sox: SoX v14.0.1

Full log file is 780KB compressed:
http://schou.dk/linux/sis7019/strace.sis7019.sox-rec.2010-06-13.log.bz2

Hardware system used is a Norhtec MicroClient Jr with SIS550 CPU:
http://www.norhtec.com/products/mcjrmx/index.html

best regards/hans
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/