winepulse test data review

[Maarten Lankhorst]

Op 03-12-12 15:42, Joerg-Cyril.Hoehle at t-systems.com schreef:
> Hi,
>
> Maarten Lankhorst kindly posted mmdevapi test results for render and capture
> gathered using his winepulse driver:
> http://www.winehq.org/pipermail/wine-devel/2012-October/097602.html
>
>> render.c:1199: padding 1250 position 510000/21250 slept 470ms iteration 0
> I've run your data through some MS-Excel analysis of mine.
> Here are my observations.
>
>
>> Exclusive mode tests aren't done, I disabled exclusive mode
>> because I felt tests were insufficient. 
> It's funny that you say this, because your winepulse driver behaves
> much like an exclusive mode driver, not a shared mode one ;-)
>
> More specifically,
>
> a) winepulse and exclusive mode do not decrease padding in multiples
>    of the period size.
It typically will keep it in multiples if pulseaudio is run in timer driven mode (glitchfree audio),
however if you create a buffer that's 2x period size or less it seems to be more aggressive with
updates.

> b) winepulse and exclusive mode appear to equate
>   GetPosition with released frames minus GetCurrentPadding
>  exactly like ALSA hw:0 and dmix do:
>   delay + avail_update = buffer_size (~= 8192 frames)
>
> IOW, the driver pretends that the speaker position is exactly the
> frame that just fell off the circular buffer.  This may be ok for ALSA
> hw:0 and MS-Windows exclusive mode drivers, but that's wrong for
> anything with a filter chain in the back.
>
> Hence I assume that winepulse's GetPosition is lying.
> The question is: does it matter?
Well from how I understand with winepulse pulseaudio will only add 1 more period on top of that.
I do or did have code for IAudioClock::GetPosition, winepulse v18 commit removed it entirely.
I could reinstate it, but I didn't find the mmdevapi tests strict enough to justify it.
> If using PA API calls of some sort, you manage to keep the PA-internal
> latency well below what's the human brain can perceive, I'd say that's
> ok.  Likewise, hw:0 ignores Digital->Analog and wire->LC->speaker times.
>
> Our gripe with PA is precisely that using the regular ALSA->PA path
> via the ALSA plugin, nobody found a means to keep PA's latency small.
>
> (I'll repeat myself saying that what actually matters is the sum of all
>  latencies and buffers: mmdevapi buffer, PA transformation chain, DAC etc.)
>
> The caveat is that with increasing latency, the behaviour of GCP and
> GetPosition will differ more and more from native's mixer, until
> it becomes too much for application X to bear, causing a bug report.
>
>
> That was about the relationship between GCP and GetPosition.  Now what
> about GetPosition and wall time (as seen by the HighPerformanceTimer)?
> The largest delta is 8ms, which suggests that your GetPosition is not
> particularly regular, but as it stays below one 10ms period, it's
> presumably good enough.  By contrast, native's largest delta is < 1ms.
Delta shouldn't be so high, are you using the timestamps from IAudioClock2::GetPosition ?
Those are lies, I could probably fix that by recording them in pulse_wr_callback. But you
could try testing with my tree, I enable rtkit in there which should decrease jitter regardless.
>> Sometimes up to 2 tests fail due to position updates not being regular,
> Indeed, the data reveals it.  I guess the reported GetPosition is more related to
> packet size job completion than actual sample accurate stream position.
>> I suspect this is because it's nearly done playing though, but it can get worse
>> when you use usb headphones, not much I can do about that though, except if I
>> started lying,
> What do you mean with "started lying"?  I inferred above that it's already lying.
Not directly passing the value in GetCurrentPadding through as was reported by
pulseaudio, but hide the irregular pointner advancements. I prefer to just report the
values from pulseaudio directly.
>> but it's so far been much simpler when I don't..
> The data points look very reasonable -- if audible latency is really
> low, which the tests cannot reveal.
>
>
> BTW, I'd really like to see native test results with a USB headphone.
> IF somebody has such data, pleas show them to me.
Unless I'm mistaken, because I use early requests, pulseaudio will only have 1 more
period internally than the buffer length of my sound buffer, so if the buffer is 30 ms,
period is 10 ms, and I only fill it with 10 ms data, max latency would be 20 ms at that point.
If you say jitter is 8 ms (which I find very high), you wouldn't notice that extra 10 ms..
>
> I'm not saying that it's bad that winepulse's GetCurrentPadding and
> GetPosition behave like an exclusive mode driver.  After all,
> winecoreaudio's GCP does the same.  Just be aware of the differences.
>
>
> Your capture results look good.
>> My favorite capture results (a2dp phone as "microphone"):
>> capture.c:247: Sleep.1 position -1 pad 0 flags abadcafe, amount of frames locked: 0
>> I love this one because it shows that when you have a source that's not
>> capturing, winepulse still gets the correct results.
> This is an area that needs more tests.  I've seen native machines
> behave similarly, OTOH I've read msdn blog entries mentioning that no
> event is delivered when there's nothing to capture.  So the expected
> behaviour when there's nothing to capture is unclear to me so far.
I guessed that it just has a bunch of packets that are re-used, like the way I'm
implementing capture in winepulse. See ACPacket, it's stuffed in locked_ptr,
empty ones in packet_free_head, and filled in packet_filled_head.
> I'd recommend you simply enable (non-event) exclusive mode, that'll
> yield twice as many data points per test run. ;-)
>
> BTW, I recommend that you play & increase the worst case test duration to
> last for 5, 30 or 3000 seconds and see if figures are still regular
> (e.g. with ALSA->PA, you'd see with 5 seconds that it eats too much data)
> and whether it still plays without audible glitches.
render.c:2290: Released 441441=1001x441 -441 frames at 44100 worth 10000ms in 9972ms
render.c:2290: Released 4410441=10001x441 -441 frames at 44100 worth 100000ms in 99900ms

Some interruption of the audio stream, that sleep(i % 10) is suspect... what are you really testing there?

And that test seems to be sensitive to not being run in realtime,
it seems to work slightly better if I change that to if I set THREAD_PRIORITY_TIME_CRITICAL on the thread,
Sleep(0) (for i%10 = 0) looks kind of wrong though

Oops and another bugfix[1], pulse_wr_callback can sometimes be called with no update, which can be a
contributing factor why sometimes the tests finished early..

with that fixed and no sleep:
render.c:2296: Released 4410441=10001x441 -441 frames at 44100 worth 100000ms in 99998ms

And with rt prio set, and sleep:
render.c:2291: Released 4410441=10001x441 -882 frames at 44100 worth 99990ms in 100014ms

I may also be hitting some pulseaudio bug though, if I play some music on the background when one
of those tests start the sound during the test works ok, even if I pause it after that.
Come to think of it, what is more likely is that on underrun the device is paused since nothing else is
playing, and it starts again when being fed again, that would explain why I'm getting interruptions
like the +14 ms above..

Also played skyrim for a few hours just fine, it wanted a 20 ms buffer for some reason..
Still not sure why, but who am I to object..

~Maarten

[1] winepulse don't SetEvent on no pad change..

diff --git a/dlls/winepulse.drv/mmdevdrv.c b/dlls/winepulse.drv/mmdevdrv.c
index 554a9fc..a4575d5 100644
--- a/dlls/winepulse.drv/mmdevdrv.c
+++ b/dlls/winepulse.drv/mmdevdrv.c
@@ -531,7 +531,10 @@ static void pulse_wr_callback(pa_stream *s, size_t bytes, void *userdata)
     else
         This->pad = 0;
 
-    assert(oldpad >= This->pad);
+    if (oldpad == This->pad)
+        return;
+
+    assert(oldpad > This->pad);
 
     This->clock_written += oldpad - This->pad;
     TRACE("New pad: %zu (-%zu)\n", This->pad / pa_frame_size(&This->ss), (oldpad - This->pad) / pa_frame_size(&This->ss));