#10045 HIGH 1.5-sof: XO-1.5 Record audio/video are out of sync with each other

[James Cameron]

On Sat, May 08, 2010 at 05:24:00PM +0000, Tiago Marques wrote:
> I was just looking into this and the issue with SD cards' random write
> performance intrigued me in this particular case.  Isn't recording
> being performed sequentially, hence no lag problem?

At the moment, assuming an application that opens a file, and writes to
it at _any_ speed, occasionally the write will block for a huge amount
of time.

As an example, consider this shell script:

#!/bin/sh
while true; do
        echo ok
        sleep 0.01
done

And then this command to execute it:

strace -o /tmp/k -e write -T /tmp/j > /root/file

And then after several minutes or hours of run the strace file is
analysed:

grep write k|cut -f2 -d'<'|cut -f1 -d'>'|sort -rn|more

One will find several instances of write(2) syscalls taking huge
amounts of time:

0.406725
0.347159

Now this is surprising given that the I/O rate is trivial, and that
there is ample memory for buffering the writes.

If the test is repeated with the writes directed to tmpfs, there are no
such delays.

If the test is repeated at a much faster I/O rate using dd(1), ensuring
that ample free memory is available to buffer the writes, then one still
gets huge delays.  Consider this test sequence:

a.  drop all caches,

b.  verify free memory,

c.  write 262144000 bytes in 8192 byte blocks,

d.  verify cache is used,

e.  look at the distribution of the slowest writes.

[root at xo-a7-2a-5a tmp]# echo 1 > /proc/sys/vm/drop_caches 
[root at xo-a7-2a-5a tmp]# echo 2 > /proc/sys/vm/drop_caches 
[root at xo-a7-2a-5a tmp]# echo 3 > /proc/sys/vm/drop_caches 
[root at xo-a7-2a-5a tmp]# free
             total       used       free     shared    buffers     cached
Mem:        949256      96328     852928          0         88      30304
-/+ buffers/cache:      65936     883320
Swap:            0          0          0
[root at xo-a7-2a-5a tmp]# time strace -o /tmp/k -e write -T dd if=/dev/zero of=/root/file bs=8192 count=32000
32000+0 records in
32000+0 records out
262144000 bytes (262 MB) copied, 59.8669 s, 4.4 MB/s

real    0m59.929s
user    0m1.960s
sys     0m5.350s
[root at xo-a7-2a-5a tmp]# free
             total       used       free     shared    buffers     cached
Mem:        949256     361192     588064          0        672     287568
-/+ buffers/cache:      72952     876304
Swap:            0          0          0
[root at xo-a7-2a-5a tmp]# grep write k|cut -f2 -d'<'|cut -f1 -d'>'|sort -rn|more
11.648413
8.020875
4.299857
3.282466
2.960739
2.151048
2.147674
2.090824
1.972840
1.740923
1.721511
1.674147
1.652831
1.538634
1.430747
1.417739
1.000022
0.961700
0.847079
0.009241
0.009202
0.005332

I've no explanation for this behaviour.

I don't think any different filesystem will affect the issue, but it
would probably be a good thing to try.  Let us know how it goes!

-- 
James Cameron
http://quozl.linux.org.au/