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
Not trimming for the benefit of alsa-devel, cc'd. Please trim replies.
On Sat, 2010-06-19 at 16:13 +0200, Hans Schou wrote:
> 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 $?
I think the answer is no, but to be sure -- are you talking directly to
the hardware device, or are you going through pulseaudio?
While rec is running, can you capture the configuration using
head -1000 /proc/asound/card0/pcm0c/sub0/*
Once you have the information, there is no need to run it all the way
out.
I think that's the right path, but I'm going from memory so you may have
to look around under /proc/asound. I'm trying to get my MicroClient up
and running again so I can try to reproduce this. This information will
help me narrow my focus to the correct area of the driver.
Can you try using arecord? You can use options to tell it how to
configure the PCM. Especially interesting will be to configure 2 periods
per buffer vs whatever rec uses. 2 periods per buffer uses the hardware
interrupts to clock out periods, where as 3+ uses a more complex
mechanism. You can also use -M to use mmap vs not.
> 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
2010/6/19 David Dillow <[email protected]>:
> Not trimming for the benefit of alsa-devel, cc'd. Please trim replies.
ok
> On Sat, 2010-06-19 at 16:13 +0200, Hans Schou wrote:
>> 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 $?
>
> I think the answer is no, but to be sure -- are you talking directly to
> the hardware device, or are you going through pulseaudio?
Eh? No to what? Alsa? I am not really sure. In strace I can see 'rec'
uses ioclt which could implies that it is talking directly to
hardware.
> While rec is running, can you capture the configuration using
> head -1000 /proc/asound/card0/pcm0c/sub0/*
Below was captured while running:
arecord -c 1 -r 44100 -f S16 arec01.wav
==> /proc/asound/card0/pcm0c/sub0/hw_params <==
access: RW_INTERLEAVED
format: S16_LE
subformat: STD
channels: 1
rate: 44100 (44100/1)
period_size: 5513
buffer_size: 22050
==> /proc/asound/card0/pcm0c/sub0/info <==
card: 0
device: 0
subdevice: 0
stream: CAPTURE
id: SiS7019
name: SiS7019
subname: subdevice #0
class: 0
subclass: 0
subdevices_count: 1
subdevices_avail: 0
==> /proc/asound/card0/pcm0c/sub0/prealloc <==
64
==> /proc/asound/card0/pcm0c/sub0/prealloc_max <==
128
==> /proc/asound/card0/pcm0c/sub0/status <==
state: RUNNING
owner_pid : 3112
trigger_time: 1277013037.939382815
tstamp : 1277013038.809174469
delay : 10640
avail : 10640
avail_max : 10920
-----
hw_ptr : 38368
appl_ptr : 27728
==> /proc/asound/card0/pcm0c/sub0/sw_params <==
tstamp_mode: NONE
period_step: 1
avail_min: 5513
start_threshold: 1
stop_threshold: 22050
silence_threshold: 0
silence_size: 0
boundary: 1944986400
I got a strange error message from arecord while recording at rate 44100:
overrun!!! (at least 0.188 ms long)
overrun!!! (at least 0.190 ms long)
overrun!!! (at least 0.191 ms long)
Could this be a clue?
The error does occur with rate 8000 8bit (the default).
> Can you try using arecord? You can use options to tell it how to
> configure the PCM. Especially interesting will be to configure 2 periods
> per buffer vs whatever rec uses. 2 periods per buffer uses the hardware
> interrupts to clock out periods, where as 3+ uses a more complex
> mechanism. You can also use -M to use mmap vs not.
Options like this?
strace -tt -o arec.log arecord -c 1 -r 44100 -f S16 -M arec.wav
best regards/hans
Please keep me on the cc list, I'll see your message sooner in my Inbox
than my mailing list folders.
On Sun, 2010-06-20 at 08:20 +0200, Hans Schou wrote:
> > On Sat, 2010-06-19 at 16:13 +0200, Hans Schou wrote:
> >> 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 $?
> >
> > I think the answer is no, but to be sure -- are you talking directly to
> > the hardware device, or are you going through pulseaudio?
>
> Eh? No to what? Alsa?
Pulseaudio.
> I am not really sure. In strace I can see 'rec'
> uses ioclt which could implies that it is talking directly to
> hardware.
Probably, but I'm not familiar enough with the library/user-space side
of alsa to know how it talks to plugins. I expect you are correct,
though.
> > While rec is running, can you capture the configuration using
> > head -1000 /proc/asound/card0/pcm0c/sub0/*
>
> Below was captured while running:
> arecord -c 1 -r 44100 -f S16 arec01.wav
You caught the correct files, yes. Did that command produce 10 second
pauses? If not, then I need to see the same information from the rec
command you were using to reproduce the issue before. It may be easier
to just run the rec command for a moment to collect the data rather than
wait the 40+ minutes to see if arecord also demonstrates the issue.
> I got a strange error message from arecord while recording at rate 44100:
> overrun!!! (at least 0.188 ms long)
> overrun!!! (at least 0.190 ms long)
> overrun!!! (at least 0.191 ms long)
>
> Could this be a clue?
Perhaps; I'm guessing that rec (sox) is using the mmap interface, and
I've not done much with that -- though perhaps there is a bug in sox's
overrun handling. You could enable SND_PCM_XRUN_DEBUG to see if overruns
are happening when sox starts taking 10 seconds.
Getting overruns on SiS 550 based devices isn't entirely surprising, as
it doesn't have a huge amount of horsepower or memory. If you have too
much going on in the background, it is very easy to not have enough time
to processes all of the captured data, especially if you are running
short period/buffer sizes.
> The error does occur with rate 8000 8bit (the default).
Do you mean 'does not occur'? That may be more expected -- 8khz/8bit has
approximately 9% of the data as 44.1khz/16bit.
> > Can you try using arecord? You can use options to tell it how to
> > configure the PCM. Especially interesting will be to configure 2 periods
> > per buffer vs whatever rec uses. 2 periods per buffer uses the hardware
> > interrupts to clock out periods, where as 3+ uses a more complex
> > mechanism. You can also use -M to use mmap vs not.
>
> Options like this?
> strace -tt -o arec.log arecord -c 1 -r 44100 -f S16 -M arec.wav
Yes, for testing if the mmap interface is the problem. You can also use
-v to have it print more information, including the source of the data
(hw vs Pulseaudio). To check 1 period vs 2, you can use the
--period-size/--buffer-size options. I seem to recall that there is a
bug lurking around there somewhere, so you should check that you got 1
period using -v or the proc files. You may have to fallback to the -F/-B
options and convert samples to microseconds.
Dave
2010/6/20 David Dillow <[email protected]>:
> You caught the correct files, yes. Did that command produce 10 second
> pauses? If not, then I need to see the same information from the rec
> command you were using to reproduce the issue before. It may be easier
> to just run the rec command for a moment to collect the data rather than
> wait the 40+ minutes to see if arecord also demonstrates the issue.
Over night I have been running arecord several times. Alle wav-files
are much below the expected size 264600000 bytes (44100*2*60s*50min).
The file size recorded
184928116
184939142
185170688
186030716
186989978
187166394
187221524
188555670
188654904
188798242
189503906
189900842
189900842/(44100*2*60) = 35.88
Only 35 minutes of recording but I was running in 50min.
It seems that arecord loses more sample than I have seen with sox-rec.
> I'm guessing that rec (sox) is using the mmap interface, and
> I've not done much with that -- though perhaps there is a bug in sox's
> overrun handling. You could enable SND_PCM_XRUN_DEBUG to see if overruns
> are happening when sox starts taking 10 seconds.
How do I enable SND_PCM_XRUN_DEBUG with sox?
> Getting overruns on SiS 550 based devices isn't entirely surprising, as
> it doesn't have a huge amount of horsepower or memory.
Well, I usually don't have problem with that. I have samba running but
I don't access the recorded files while recording, so it is not a
problem.
Right now uptime says
load average: 0.19, 0.21, 0.18
but strace and top is the bad guys, not arecord.
>> The error does occur with rate 8000 8bit (the default).
>
> Do you mean 'does not occur'? That may be more expected -- 8khz/8bit has
> approximately 9% of the data as 44.1khz/16bit.
Sorry, yes you are right.
>> > Can you try using arecord? You can use options to tell it how to
>> > configure the PCM. Especially interesting will be to configure 2 periods
>> > per buffer vs whatever rec uses. 2 periods per buffer uses the hardware
>> > interrupts to clock out periods, where as 3+ uses a more complex
>> > mechanism. You can also use -M to use mmap vs not.
>>
>> Options like this?
>> strace -tt -o arec.log arecord -c 1 -r 44100 -f S16 -M arec.wav
I tried this one:
arecord -c 1 -r 44100 -f S16 -M -D hw:0,0 -v arec.wav
but it did not change anything. Still the files are much too small.
Recording WAVE 'arec.wav' : Signed 16 bit Little Endian, Rate 44100 Hz, Mono
Hardware PCM card 0 'SiS7019' device 0 subdevice 0
Its setup is:
stream : CAPTURE
access : MMAP_INTERLEAVED
format : S16_LE
subformat : STD
channels : 1
rate : 44100
exact rate : 44100 (44100/1)
msbits : 16
buffer_size : 22050
period_size : 5513
period_time : 125011
tick_time : 0
tstamp_mode : NONE
period_step : 1
sleep_min : 0
avail_min : 5513
xfer_align : 5513
start_threshold : 1
stop_threshold : 22050
silence_threshold: 0
silence_size : 0
boundary : 1944986400
overrun!!! (at least 4.368 ms long)
Status:
state : XRUN
trigger_time: 1277092780.321430383
tstamp : 1277092780.323362792
delay : 0
avail : 27562
avail_max : 27562
# grep avail arec-stdout2.log | sort | uniq -c
6 avail : 22053
13 avail : 22055
2 avail : 22058
1 avail : 22059
10 avail : 22060
4 avail : 22062
1 avail : 22063
2 avail : 22064
10975 avail : 27562
5 avail : 33075
2 avail : 38588
6 avail_max : 22053
13 avail_max : 22055
2 avail_max : 22058
1 avail_max : 22059
10 avail_max : 22060
4 avail_max : 22062
1 avail_max : 22063
2 avail_max : 22064
10975 avail_max : 27562
5 avail_max : 33075
2 avail_max : 38588
2 avail_min : 5513
So most often 'avail' is 27562 after an overrun when running arecord.
I think it would be better to test with sox-rec but which options
should be used?
/hans
On Mon, 2010-06-21 at 07:56 +0200, Hans Schou wrote:
> 2010/6/20 David Dillow <[email protected]>:
>
> > You caught the correct files, yes. Did that command produce 10 second
> > pauses? If not, then I need to see the same information from the rec
> > command you were using to reproduce the issue before. It may be easier
> > to just run the rec command for a moment to collect the data rather than
> > wait the 40+ minutes to see if arecord also demonstrates the issue.
>
> Over night I have been running arecord several times. Alle wav-files
> are much below the expected size 264600000 bytes (44100*2*60s*50min).
> Only 35 minutes of recording but I was running in 50min.
Ok, cool, we see the problem with arecord as well, though you were
getting overrun messages as well?
> > I'm guessing that rec (sox) is using the mmap interface, and
> > I've not done much with that -- though perhaps there is a bug in sox's
> > overrun handling. You could enable SND_PCM_XRUN_DEBUG to see if overruns
> > are happening when sox starts taking 10 seconds.
>
> How do I enable SND_PCM_XRUN_DEBUG with sox?
Sorry, that should be CONFIG_SND_PCM_XRUN_DEBUG in the kernel
configuration, but if we can demonstrate this with arecord, there's no
real reason to recompile your kernel at this point.
> > Getting overruns on SiS 550 based devices isn't entirely surprising, as
> > it doesn't have a huge amount of horsepower or memory.
>
> Well, I usually don't have problem with that. I have samba running but
> I don't access the recorded files while recording, so it is not a
> problem.
>
> Right now uptime says
> load average: 0.19, 0.21, 0.18
> but strace and top is the bad guys, not arecord.
An overrun means that arecord didn't run for 500ms, and the load average
won't really tell you much about that -- latency can happen with low
loads. That said, I'm suspecting that you've found a problem in the
driver, and I'd lay odds it is in the handling of multiple periods per
buffer.
> >> > Can you try using arecord? You can use options to tell it how to
> >> > configure the PCM. Especially interesting will be to configure 2 periods
> >> > per buffer vs whatever rec uses. 2 periods per buffer uses the hardware
> >> > interrupts to clock out periods, where as 3+ uses a more complex
> >> > mechanism. You can also use -M to use mmap vs not.
> >>
> >> Options like this?
> >> strace -tt -o arec.log arecord -c 1 -r 44100 -f S16 -M arec.wav
>
> I tried this one:
> arecord -c 1 -r 44100 -f S16 -M -D hw:0,0 -v arec.wav
> but it did not change anything. Still the files are much too small.
Ok, read/write vs mmap is not a differentiating factor, good deal.
> So most often 'avail' is 27562 after an overrun when running arecord.
>
> I think it would be better to test with sox-rec but which options
> should be used?
I don't know the options available on sox, but if you can use arecord to
reproduce, then that is probably the best tool for the job. Can you set
it up to use two periods per buffer and see if you still can reproduce?
Options would look like -B 250000 -F 125000. A second test with -B
1000000 -F 500000 would be interesting, if the hw can handle buffers of
that size -- I don't recall offhand.
I will hopefully have my hardware back up and running tonight; BTW, what
distro are you using? I'm trying Fedora 13, but I'm expecting to run
into trouble with the lack of cmov support on the processor.
Thanks,
Dave
2010/6/21 David Dillow <[email protected]>:
>> Only 35 minutes of recording but I was running in 50min.
>
> Ok, cool, we see the problem with arecord as well, though you were
> getting overrun messages as well?
Yes, a lot of overrun. At least one per second.
>> How do I enable SND_PCM_XRUN_DEBUG with sox?
>
> Sorry, that should be CONFIG_SND_PCM_XRUN_DEBUG in the kernel
> configuration, but if we can demonstrate this with arecord, there's no
> real reason to recompile your kernel at this point.
OK, I'll skip that. It takes rather long time to compile.
>> Right now uptime says
>> ? ?load average: 0.19, 0.21, 0.18
>> but strace and top is the bad guys, not arecord.
>
> An overrun means that arecord didn't run for 500ms, and the load average
> won't really tell you much about that -- latency can happen with low
Well, I did not see that with sox. It was running fine for 42 min.
> loads. That said, I'm suspecting that you've found a problem in the
> driver, and I'd lay odds it is in the handling of multiple periods per
> buffer.
> I don't know the options available on sox, but if you can use arecord to
> reproduce, then that is probably the best tool for the job. Can you set
> it up to use two periods per buffer and see if you still can reproduce?
> Options would look like -B 250000 -F 125000. A second test with -B
> 1000000 -F 500000 would be interesting, if the hw can handle buffers of
> that size -- I don't recall offhand.
I have just started it with -B 250000 -F 125000 and get a lot of overrun.
I skipped using strace to make less stress.
cmdline is now:
arecord -B 250000 -F 125000 -c 1 -r 44100 -f S16 -M -D hw:0,0 -v arec.wav
overrun!!! (at least 0.201 ms long)
Status:
state : XRUN
trigger_time: 1277140527.1826705
tstamp : 1277140527.2005279
delay : 0
avail : 16537
avail_max : 16537
overrun!!! (at least 0.207 ms long)
Status:
state : XRUN
trigger_time: 1277140527.128608572
tstamp : 1277140527.128793445
delay : 0
avail : 16537
avail_max : 16537
overrun!!! (at least 0.167 ms long)
Status:
state : XRUN
trigger_time: 1277140527.256925501
tstamp : 1277140527.257071819
delay : 0
avail : 16537
avail_max : 16537
> I will hopefully have my hardware back up and running tonight; BTW, what
> distro are you using? I'm trying Fedora 13, but I'm expecting to run
> into trouble with the lack of cmov support on the processor.
Debian stable.
/hans
2010/6/21 Hans Schou <[email protected]>:
> 2010/6/21 David Dillow <[email protected]>:
>
>>> Only 35 minutes of recording but I was running in 50min.
>>
>> Ok, cool, we see the problem with arecord as well, though you were
>> getting overrun messages as well?
>
> Yes, a lot of overrun. At least one per second.
>
>>> How do I enable SND_PCM_XRUN_DEBUG with sox?
>>
>> Sorry, that should be CONFIG_SND_PCM_XRUN_DEBUG in the kernel
>> configuration, but if we can demonstrate this with arecord, there's no
>> real reason to recompile your kernel at this point.
>
> OK, I'll skip that. It takes rather long time to compile.
>
>>> Right now uptime says
>>> ? ?load average: 0.19, 0.21, 0.18
>>> but strace and top is the bad guys, not arecord.
>>
>> An overrun means that arecord didn't run for 500ms, and the load average
>> won't really tell you much about that -- latency can happen with low
>
> Well, I did not see that with sox. It was running fine for 42 min.
>
>> loads. That said, I'm suspecting that you've found a problem in the
>> driver, and I'd lay odds it is in the handling of multiple periods per
>> buffer.
>
>> I don't know the options available on sox, but if you can use arecord to
>> reproduce, then that is probably the best tool for the job. Can you set
>> it up to use two periods per buffer and see if you still can reproduce?
>> Options would look like -B 250000 -F 125000. A second test with -B
>> 1000000 -F 500000 would be interesting, if the hw can handle buffers of
>> that size -- I don't recall offhand.
>
> I have just started it with ?-B 250000 -F 125000 and get a lot of overrun.
> I skipped using strace to make less stress.
>
> cmdline is now:
> arecord -B 250000 -F 125000 -c 1 -r 44100 -f S16 -M -D hw:0,0 -v arec.wav
This gave a 191069598 bytes long file. What does this test actually
show regarding the original problem with stopping after 42 min?
I have just started:
arecord -B 1000000 -F 500000 -c 1 -r 44100 -f S16 -M -D hw:0,0 -v arec.wav
and I only got one overrun. What I did was that logged in on another
ssh console and executed "ls".
Here is a complete screen dump after running 2 minutes:
+ arecord -B 1000000 -F 500000 -c 1 -r 44100 -f S16 -M -D hw:0,0 -v arec.wav
Recording WAVE 'arec.wav' : Signed 16 bit Little Endian, Rate 44100 Hz, Mono
Hardware PCM card 0 'SiS7019' device 0 subdevice 0
Its setup is:
stream : CAPTURE
access : MMAP_INTERLEAVED
format : S16_LE
subformat : STD
channels : 1
rate : 44100
exact rate : 44100 (44100/1)
msbits : 16
buffer_size : 32768
period_size : 22050
period_time : 500000
tick_time : 0
tstamp_mode : NONE
period_step : 1
sleep_min : 0
avail_min : 22050
xfer_align : 22050
start_threshold : 1
stop_threshold : 32768
silence_threshold: 0
silence_size : 0
boundary : 1445068800
overrun!!! (at least 826.140 ms long)
Status:
state : XRUN
trigger_time: 1277144902.603264297
tstamp : 1277144903.428975238
delay : 0
avail : 44108
avail_max : 44108
overrun!!! (at least 0.077 ms long)
Status:
state : XRUN
trigger_time: 1277144938.378978657
tstamp : 1277144938.379038604
delay : 0
avail : 42344
avail_max : 42344
/hans
/hans
On Mon, 2010-06-21 at 19:42 +0200, Hans Schou wrote:
> 2010/6/21 David Dillow <[email protected]>:
> > I don't know the options available on sox, but if you can use arecord to
> > reproduce, then that is probably the best tool for the job. Can you set
> > it up to use two periods per buffer and see if you still can reproduce?
> > Options would look like -B 250000 -F 125000. A second test with -B
> > 1000000 -F 500000 would be interesting, if the hw can handle buffers of
> > that size -- I don't recall offhand.
>
> I have just started it with -B 250000 -F 125000 and get a lot of overrun.
> I skipped using strace to make less stress.
>
> cmdline is now:
> arecord -B 250000 -F 125000 -c 1 -r 44100 -f S16 -M -D hw:0,0 -v arec.wav
>
> overrun!!! (at least 0.201 ms long)
> Status:
> state : XRUN
> trigger_time: 1277140527.1826705
> tstamp : 1277140527.2005279
> delay : 0
> avail : 16537
> avail_max : 16537
This really makes me think the system just cannot keep up. Can you post
the initial output to verify that it is getting two periods per buffer,
please? If you are getting overruns and small files in that
configuration, there is not much I think I do to help -- that uses the
hardware's built-in support for generating the appropriate interrupts.
Also, does it do the same without the -M ? And you may wish to try
longer and shorter periods to see if you get so many overruns.
Also, what storage are you using? Does it support DMA? PIO modes can be
very slow...
> > I will hopefully have my hardware back up and running tonight; BTW, what
> > distro are you using? I'm trying Fedora 13, but I'm expecting to run
> > into trouble with the lack of cmov support on the processor.
>
> Debian stable.
Thanks, I'll fall back to that if getting Fedora going looks to be more
trouble than it is worth.
Dave
2010/6/21 David Dillow <[email protected]>:
> On Mon, 2010-06-21 at 19:42 +0200, Hans Schou wrote:
>> cmdline is now:
>> arecord -B 250000 -F 125000 -c 1 -r 44100 -f S16 -M -D hw:0,0 -v arec.wav
> This really makes me think the system just cannot keep up. Can you post
> the initial output to verify that it is getting two periods per buffer,
> please?
Then I have to run it again. I do not have it on the screen anymore.
I will do that after the test I'm running now - as mentioned before.
I have turned on my signal generator with 400Hz. I will give it a try
with listen to it, to hear any clicks when the overrun occur.
> Also, does it do the same without the -M ? And you may wish to try
> longer and shorter periods to see if you get so many overruns.
> Also, what storage are you using? Does it support DMA? PIO modes can be
> very slow...
On a daily basis I use USB flash memory stick and have done this more
than a year but always less than 42 min. Right now I'm using old 4GB
external hard disk connected through USB.
/hans
On Mon, 2010-06-21 at 20:49 +0200, Hans Schou wrote:
> 2010/6/21 Hans Schou <[email protected]>:
> > 2010/6/21 David Dillow <[email protected]>:
> >> An overrun means that arecord didn't run for 500ms, and the load average
> >> won't really tell you much about that -- latency can happen with low
> >
> > Well, I did not see that with sox. It was running fine for 42 min.
My thought is that you may have been somewhat fortunate and did not see
an overrun for 42 minutes. I am trying to narrow down if this is an
issue with sox's overrun handling, if there is a big with handing
anything other than two periods per buffer, or some other generic bug in
the driver.
> >> I don't know the options available on sox, but if you can use arecord to
> >> reproduce, then that is probably the best tool for the job. Can you set
> >> it up to use two periods per buffer and see if you still can reproduce?
> >> Options would look like -B 250000 -F 125000. A second test with -B
> >> 1000000 -F 500000 would be interesting, if the hw can handle buffers of
> >> that size -- I don't recall offhand.
> >
> > I have just started it with -B 250000 -F 125000 and get a lot of overrun.
> > I skipped using strace to make less stress.
> >
> > cmdline is now:
> > arecord -B 250000 -F 125000 -c 1 -r 44100 -f S16 -M -D hw:0,0 -v arec.wav
>
> This gave a 191069598 bytes long file. What does this test actually
> show regarding the original problem with stopping after 42 min?
I'm trying to have you reproduce the original problem using 2 periods
per buffer so that I can localize the likely location of a driver bug.
If it only happens when there is not 2 periods per buffer, then that
points to one set of timing code. If it also happens with 2 periods per
buffer, then that points to a more generic bug.
> I have just started:
> arecord -B 1000000 -F 500000 -c 1 -r 44100 -f S16 -M -D hw:0,0 -v arec.wav
> and I only got one overrun. What I did was that logged in on another
> ssh console and executed "ls".
That sounds like a scheduling latency issue, yes.
> Here is a complete screen dump after running 2 minutes:
> + arecord -B 1000000 -F 500000 -c 1 -r 44100 -f S16 -M -D hw:0,0 -v arec.wav
> Recording WAVE 'arec.wav' : Signed 16 bit Little Endian, Rate 44100 Hz, Mono
> Hardware PCM card 0 'SiS7019' device 0 subdevice 0
> Its setup is:
> buffer_size : 32768
> period_size : 22050
Ok, please play with the options until you can get buffer_size = 2 *
period_size. That will eliminate the alternate timing code from the
path. I expected that options you gave to do that, but apparently there
is something else keeping that from happening.
Dave
2010/6/21 Hans Schou <[email protected]>:
> I have just started:
> ?arecord -B 1000000 -F 500000 -c 1 -r 44100 -f S16 -M -D hw:0,0 -v arec.wav
It gave a file size of 258822944 bytes. Almost 50 min:
echo "258822944/(2*60*44100)" | bc -ql
48.90
This is the longest recording I have made on this hardware.
I have this running now:
+ arecord -B 200000 -F 100000 -c 1 -r 44100 -f S16 -M -D hw:0,0 -v arec.wav
Recording WAVE 'arec.wav' : Signed 16 bit Little Endian, Rate 44100 Hz, Mono
Hardware PCM card 0 'SiS7019' device 0 subdevice 0
Its setup is:
stream : CAPTURE
access : MMAP_INTERLEAVED
format : S16_LE
subformat : STD
channels : 1
rate : 44100
exact rate : 44100 (44100/1)
msbits : 16
buffer_size : 8820
period_size : 4410
period_time : 100000
tick_time : 0
tstamp_mode : NONE
period_step : 1
sleep_min : 0
avail_min : 4410
xfer_align : 4410
start_threshold : 1
stop_threshold : 8820
silence_threshold: 0
silence_size : 0
boundary : 1244678400
and no overrun within 2 min.
/hans
On Mon, 2010-06-21 at 22:10 +0200, Hans Schou wrote:
> 2010/6/21 Hans Schou <[email protected]>:
>
> > I have just started:
> > arecord -B 1000000 -F 500000 -c 1 -r 44100 -f S16 -M -D hw:0,0 -v arec.wav
>
> It gave a file size of 258822944 bytes. Almost 50 min:
> echo "258822944/(2*60*44100)" | bc -ql
> 48.90
>
> This is the longest recording I have made on this hardware.
>
> I have this running now:
> + arecord -B 200000 -F 100000 -c 1 -r 44100 -f S16 -M -D hw:0,0 -v arec.wav
Ok, it seems something is definately funky with the driver in general,
and gets worse when we're using more than 2 periods per buffer.
If I use:
strace -tt -T -o record.log arecord -f S16 -r 44100 -c 1 -d 3600 \
--buffer-size=32768 --period-size=16384 -v -t raw - > /dev/null
I don't have any overruns, nor does it go into the 10-second pause mode.
I do see an odd alternating pattern of one period taking 1.4ms to
capture, and the next taking 732ms. The period should be about 371ms, so
the lumpyness of the timing is likely making it easier to hit overruns.
Then, using:
strace -tt -T -o record.log arecord -f S16 -r 44100 -c 1 -d 3600 \
--buffer-size=32768 --period-size=8192 -v -t raw - > /dev/null
I was able to push it into the 10-second pause failure mode, without
hitting any overruns. Initially it has a similar alternating pattern of
0.6ms then 363ms capture times until it drops into a 10 second pause
just after 42 minutes.
Now that I finally got my hardware going and can reproduce this, I'll
dig into it over the next few evenings.
Thanks for the report and help narrowing down the focus area,
Dave
On Tue, 2010-06-22 at 23:00 -0400, David Dillow wrote:
> On Mon, 2010-06-21 at 22:10 +0200, Hans Schou wrote:
> > 2010/6/21 Hans Schou <[email protected]>:
> >
> > > I have just started:
> > > arecord -B 1000000 -F 500000 -c 1 -r 44100 -f S16 -M -D hw:0,0 -v arec.wav
> >
> > It gave a file size of 258822944 bytes. Almost 50 min:
> > echo "258822944/(2*60*44100)" | bc -ql
> > 48.90
> >
> > This is the longest recording I have made on this hardware.
> >
> > I have this running now:
> > + arecord -B 200000 -F 100000 -c 1 -r 44100 -f S16 -M -D hw:0,0 -v arec.wav
>
> Ok, it seems something is definately funky with the driver in general,
> and gets worse when we're using more than 2 periods per buffer.
The driver's funkiness may be limited to the more than 2 periods per
buffer/10 second pause issue.
> I don't have any overruns, nor does it go into the 10-second pause mode.
> I do see an odd alternating pattern of one period taking 1.4ms to
> capture, and the next taking 732ms. The period should be about 371ms, so
> the lumpyness of the timing is likely making it easier to hit overruns.
I can reproduce the alternating pattern of periods using a different
device, so this may be something in the core code of ALSA.
Hardware PCM card 0 'HDA Intel' device 0 subdevice 0
Its setup is:
stream : CAPTURE
access : RW_INTERLEAVED
format : S16_LE
subformat : STD
channels : 2
rate : 44100
exact rate : 44100 (44100/1)
msbits : 16
buffer_size : 32768
period_size : 16384
period_time : 371519
tstamp_mode : NONE
period_step : 1
avail_min : 16384
period_event : 0
start_threshold : 1
stop_threshold : 32768
silence_threshold: 0
silence_size : 0
boundary : 4611686018427387904
appl_ptr : 0
hw_ptr : 0
strace -T gives:
ioctl(4, 0x80184151, 0x7fff532cff70) = 0 <0.371672>
write(1, ..., 65536) = 65536 <0.000035>
ioctl(4, 0x80184151, 0x7fff532cff70) = 0 <0.742746>
write(1, ..., 65536) = 65536 <0.000013>
ioctl(4, 0x80184151, 0x7fff532cff70) = 0 <0.000027>
write(1, ..., 65536) = 65536 <0.000016>
ioctl(4, 0x80184151, 0x7fff532cff70) = 0 <0.742694>
write(1, ..., 65536) = 65536 <0.000011>
ioctl(4, 0x80184151, 0x7fff532cff70) = 0 <0.000038>
write(1, ..., 65536) = 65536 <0.000024>
ioctl(4, 0x80184151, 0x7fff532cff70) = 0 <0.742600>
The first period gets clocked out close to the expected time --
371.672ms actual vs 371.519 ms expected -- but then we're either running
almost a full buffer -- 742.746ms actual vs 743.038ms buffer -- or very,
very short at 0.027ms.
Since this problem is not related to the SiS7019 driver, I'll leave it
to later -- or for others to investigate. Using three periods per buffer
sees a similar pattern, but one has an extra period time to work
within.
Dave
2010/6/23 David Dillow <[email protected]>:
> I can reproduce the alternating pattern of periods using a different
> device, so this may be something in the core code of ALSA.
Strange? The program I am actually using is one I have written myself.
I was sure I was using the old method as I open(2). In my program I
use
int fd = open("/dev/dsp", O_RDWR);
This should not go through ALSA (I think). I gues one should use
something with "snd_pcm_open()" to use ALSA.
> Since this problem is not related to the SiS7019 driver, I'll leave it
> to later -- or for others to investigate. Using three periods per buffer
> sees a similar pattern, but one has an extra period time to work
> within.
I really don't understand why I do not see this problem on other
hardware using the same compiled code.
If the problem is ALSA, how can I then turn it off?
Thanks for your investigation.
regards/hans
2010/6/23 Hans Schou <[email protected]>:
> If the problem is ALSA, how can I then turn it off?
I am quite sure it is turned off:
# dmesg | grep -A 1 ALSA
ALSA device list:
No soundcards found.
regards/hans
On Wed, 2010-06-23 at 20:22 +0200, Hans Schou wrote:
> 2010/6/23 David Dillow <[email protected]>:
>
> > I can reproduce the alternating pattern of periods using a different
> > device, so this may be something in the core code of ALSA.
>
> Strange? The program I am actually using is one I have written myself.
> I was sure I was using the old method as I open(2). In my program I
> use
> int fd = open("/dev/dsp", O_RDWR);
>
> This should not go through ALSA (I think). I gues one should use
> something with "snd_pcm_open()" to use ALSA.
To use ALSA directly, yes. However, there is no OSS SIS7019 driver in
the kernel, only the ALSA one I wrote. There is an OSS emulation layer,
so you can use the OSS API to talk to the ALSA core. Unless you are
using a vendor (SIS/MicroJr/etc.) supplied driver, you are using ALSA in
some capacity.
> > Since this problem is not related to the SiS7019 driver, I'll leave it
> > to later -- or for others to investigate. Using three periods per buffer
> > sees a similar pattern, but one has an extra period time to work
> > within.
>
> I really don't understand why I do not see this problem on other
> hardware using the same compiled code.
You mean the 10 second pauses during recording after 42 minutes? That is
a driver bug, so it is specific to this card.
If you mean the alternating long/sort period times, then it is present
on other hardware, but you likely don't see it either due to the
defaults giving you more periods to work in so you don't see overruns,
faster hardware than the SIS550 CPU, or a combination of the two. The
bug that gives rise to the 10 second pauses can also shorten the periods
I think, making overruns more likely to occur.
Dave
2010/6/23 David Dillow <[email protected]>:
> On Wed, 2010-06-23 at 20:22 +0200, Hans Schou wrote:
>> ? ?int fd = open("/dev/dsp", ?O_RDWR);
>>
>> This should not go through ALSA (I think). I gues one should use
>> something with "snd_pcm_open()" to use ALSA.
>
> To use ALSA directly, yes. However, there is no OSS SIS7019 driver in
> the kernel, only the ALSA one I wrote. There is an OSS emulation layer,
> so you can use the OSS API to talk to the ALSA core. Unless you are
> using a vendor (SIS/MicroJr/etc.) supplied driver, you are using ALSA in
> some capacity.
OK. Thanks for clearing it out.
I guess I should have programmed against ALSA when I started.
>> I really don't understand why I do not see this problem on other
>> hardware using the same compiled code.
>
> You mean the 10 second pauses during recording after 42 minutes? That is
> a driver bug, so it is specific to this card.
OK. And 42 min is also the only problem I see. I have no problems with
the recorded sounds.
> If you mean the alternating long/sort period times, then it is present
> on other hardware, but you likely don't see it either due to the
> defaults giving you more periods to work in so you don't see overruns,
> faster hardware than the SIS550 CPU, or a combination of the two. The
> bug that gives rise to the 10 second pauses can also shorten the periods
> I think, making overruns more likely to occur.
OK.
/hans