Subject: Re: [linux-audio-dev] more numbers for multichannel playback
From: Paul Barton-Davis (pbd_AT_Op.Net)
Date: Tue Apr 04 2000 - 20:35:08 EEST
First, thanks for everyone's comments and insights into this stuff.
>> This is output from a run with a 4 second track buffer size.
>
>I'm curious about how much work the butler was supposed to be doing on
>each request. You show how long it took, but not how full/empty the
>buffer queue was at the time of the request. If the "minimum work
>threshold" is reasonably small and the butler is keeping the queue
>mostly full, it looks like a minimum-work-quantum is probably the
>amount that caused the excessive lag.
The threshold for being willing to do disk I/O is set at 256kB bytes,
which as demonstrated the other day, will ensure an overall throughput
rate of at least 8MB/sec, even with the inter-file seeking. I chose
this number to account for possible 2-way traffic in the case of
recording on all 24 tracks.
So, in the general case, the butler thread is issuing about 24 x 256kB
disk i/o requests. What actually happens is shown more clearly by
these traces:
Here we are in "happy land", for example. The trace shows the target
byte for the end-of-read-ahead area, how many bytes we need to get
from the disk to satisfy this requirement, and how many msecs it took
to do it.
0: rah target 5126188 requires 294912 bytes (47.607msecs)
1: rah target 5126188 requires 262144 bytes (49.044msecs)
2: rah target 5126188 requires 262144 bytes (44.376msecs)
3: rah target 5158956 requires 294912 bytes (43.941msecs)
4: rah target 5158956 requires 294912 bytes (50.947msecs)
5: rah target 5158956 requires 262144 bytes (38.364msecs)
6: rah target 5158956 requires 262144 bytes (38.919msecs)
7: rah target 5191724 requires 262144 bytes (41.987msecs)
8: rah target 5224492 requires 262144 bytes (113.846msecs)
9: rah target 5224492 requires 262144 bytes (43.161msecs)
10: rah target 5257260 requires 294912 bytes (61.165msecs)
11: rah target 5257260 requires 294912 bytes (43.072msecs)
12: rah target 5257260 requires 262144 bytes (42.577msecs)
13: rah target 5257260 requires 262144 bytes (81.284msecs)
14: rah target 5290028 requires 262144 bytes (47.514msecs)
15: rah target 5290028 requires 262144 bytes (58.123msecs)
16: rah target 5290028 requires 262144 bytes (81.401msecs)
17: rah target 5322796 requires 262144 bytes (48.678msecs)
18: rah target 5322796 requires 262144 bytes (43.812msecs)
19: rah target 5322796 requires 262144 bytes (43.177msecs)
20: rah target 5355564 requires 294912 bytes (48.514msecs)
21: rah target 5355564 requires 262144 bytes (69.212msecs)
22: rah target 5355564 requires 262144 bytes (44.577msecs)
23: rah target 5388332 requires 294912 bytes (106.572msecs)
Excellent. But later things start to get worse:
0: rah target 5388332 requires 262144 bytes (46.147msecs)
1: rah target 5421100 requires 294912 bytes (41.467msecs)
2: rah target 5421100 requires 294912 bytes (58.935msecs)
3: rah target 5421100 requires 262144 bytes (101.688msecs)
4: rah target 5453868 requires 294912 bytes (48.352msecs)
5: rah target 5453868 requires 294912 bytes (46.394msecs)
6: rah target 5486636 requires 327680 bytes (84.197msecs)
7: rah target 5486636 requires 294912 bytes (65.517msecs)
8: rah target 5486636 requires 262144 bytes (96.208msecs)
9: rah target 5519404 requires 294912 bytes (182.217msecs)
10: rah target 5552172 requires 294912 bytes (102.100msecs)
11: rah target 5584940 requires 327680 bytes (86.519msecs)
12: rah target 5584940 requires 327680 bytes (60.348msecs)
13: rah target 5584940 requires 327680 bytes (214.142msecs)
14: rah target 5650476 requires 360448 bytes (141.156msecs)
15: rah target 5683244 requires 393216 bytes (165.175msecs)
16: rah target 5716012 requires 425984 bytes (329.143msecs)
17: rah target 5748780 requires 425984 bytes (240.222msecs)
18: rah target 5814316 requires 491520 bytes (59.614msecs)
19: rah target 5814316 requires 491520 bytes (128.623msecs)
20: rah target 5847084 requires 491520 bytes (293.053msecs)
21: rah target 5912620 requires 557056 bytes (236.032msecs)
22: rah target 5945388 requires 589824 bytes (203.362msecs)
23: rah target 5978156 requires 589824 bytes (325.902msecs)
Notice that the bytes of disk i/o we have to do is increasing. This in
turn is caused by the fact that some of the preceding disk i/o took
longer than "usual", and so now we're catching up. This becomes
cyclical, because doing more disk i/o takes longer still, and so the
process continues. We've got a positive feedback loop, and I need to
figure out how to break out of it, because soon it looks like this:
0: rah target 6043692 requires 655360 bytes (114.095msecs)
1: rah target 6076460 requires 655360 bytes (155.756msecs)
2: rah target 6109228 requires 688128 bytes (415.590msecs)
3: rah target 6174764 requires 753664 bytes (189.666msecs)
4: rah target 6174764 requires 720896 bytes (220.335msecs)
5: rah target 6207532 requires 753664 bytes (571.783msecs)
6: rah target 6207532 requires 720896 bytes (119.337msecs)
7: rah target 6207532 requires 720896 bytes (80.758msecs)
8: rah target 6240300 requires 753664 bytes (414.479msecs)
9: rah target 6273068 requires 753664 bytes (195.001msecs)
10: rah target 6305836 requires 753664 bytes (193.884msecs)
11: rah target 6305836 requires 720896 bytes (426.877msecs)
12: rah target 6338604 requires 753664 bytes (375.126msecs)
13: rah target 6338604 requires 753664 bytes (93.053msecs)
14: rah target 6338604 requires 688128 bytes (333.184msecs)
15: rah target 6371372 requires 688128 bytes (187.965msecs)
16: rah target 6371372 requires 655360 bytes (259.403msecs)
17: rah target 6371372 requires 622592 bytes (231.621msecs)
18: rah target 6404140 requires 589824 bytes (167.623msecs)
19: rah target 6436908 requires 622592 bytes (497.933msecs)
20: rah target 6535212 requires 688128 bytes (377.801msecs)
21: rah target 6600748 requires 688128 bytes (256.659msecs)
22: rah target 6633516 requires 688128 bytes (286.674msecs)
23: rah target 6699052 requires 720896 bytes (300.572msecs)
At this point, we're now reading on the order of 730kB per track, just
to play catch up, and I already know that this can't work - it takes
too long to do this, and the audio thread will catch up. It does :(
>If everything's working properly, you shouldn't have an increasing
>memory consumption during the run of the recorder. Have you watched a
>memory-usage trace while you're running?
I haven't checked it overall, but there is no malloc activity anywhere
in the program, and I am pretty confident that the mlocked() region is
definitely not growing (other debug-traces support this).
But yes, I agree with you that the behaviour is exactly what you'd
expect if we were consuming more and more memory, and so each time we
mlock a new region of the track files into the program, the kernel is
having to page out.
I'll try to check into this.
>leak somewhere that could cause this? Does C++ delete actually return
>resources to the system, or are you sucking up a monotonically
I don't believe that any implementation of malloc or new() returns
memory to the system by default. But anyway, there are no calls to
malloc/new that I know of, other than anything that might take place
in printf(3).
It feels as though the key is going to be stopping the positive
feedback loop from kicking in, but I'm not sure how to do that right
now. We sort of need to *not* try to catch up until we know that the
current round of refilling worked out just fine and that we *really*
have some slack time.
The current scheme is too bursty - we spend a long time doing nothing
in the butler thread while we wait for 256kB to be necessary, then we
go nuts pre-fetching it in. The problem is that doing i/o in smaller
sizes does not have a very good chance of meeting our bandwith
requirements, and so it could be just as dangerous to set the minimum
disk i/o size to be, say, 64kB, even though this would reduce the
amount of idle time in the butler thread.
Ideas ?
--p
This archive was generated by hypermail 2b28 : Tue Apr 04 2000 - 20:41:10 EEST