PROBLEM: SIS7019 stops recording after 42 min
in [Kernel]
|
Prev: ~~Hi~~
Next: MMC: Add JZ4740 mmc driver
From: David Dillow on 21 Jun 2010 15:10 On Mon, 2010-06-21 at 20:49 +0200, Hans Schou wrote: > 2010/6/21 Hans Schou <linux(a)schou.dk>: > > 2010/6/21 David Dillow <dave(a)thedillows.org>: > >> 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 -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo(a)vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
From: Hans Schou on 21 Jun 2010 16:20 2010/6/21 Hans Schou <linux(a)schou.dk>: > 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 -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo(a)vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
From: David Dillow on 22 Jun 2010 23:10 On Mon, 2010-06-21 at 22:10 +0200, Hans Schou wrote: > 2010/6/21 Hans Schou <linux(a)schou.dk>: > > > 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 -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo(a)vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
From: David Dillow on 23 Jun 2010 01:40 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 <linux(a)schou.dk>: > > > > > 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 -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo(a)vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
From: Hans Schou on 23 Jun 2010 14:30
2010/6/23 Hans Schou <linux(a)schou.dk>: > 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 -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo(a)vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/ |