newtestbot timings

Hi,

I've looked at some of newtestbot timing results.
http://newtestbot.winehq.org/JobDetails.pl?Key=256
It's not too bad, but it's not superb either.
> render.c:633: event after Stop.4 average 40.000ms deviation 0.06 from 100 samples

That's exactly the expected 40ms, great!
> render.c:618: Test failed: Wait iteration 40 gave 102
> render.c:633: event after Stop.1 average 10.925ms deviation 0.36 from 40 samples

That's funny.  I recently discovered that the Vista-w7 machines
downgrade their event rate from 10 to 40.0ms exactly 2 seconds
following IAC_Stop.  Newtestbot's w8 results indicate that w8
continues sending 10ms events for 400ms after IAC_Stop, then ceases.
Current wine*.drv immediately stop sending events after IAC_Stop, so
Wine almost implemented w8 behaviour before it existed :-)
> render.c:189: Returned periods: 10.1587 ms 3.0000 ms
> render.c:633: event after Start.2 average 10.955ms deviation 0.16 from 100 samples
> render.c:2200: Released 44800=100x448 -448 frames at 44100 worth 1006ms in 1087ms
> render.c:2206: event average 10.878ms deviation 0.16 from 100 samples

So the machines do not manage to deliver the expected 10.1587ms period.
Well, 10.9 is not that far away.

By comparison, a native box meets the average:
< event after Start.4 average 10.159ms deviation 0.01 from 100 samples
< Released 44800=100x448 -896 frames at 44100 worth 996ms in 1018ms
< event average 10.161ms deviation 0.03 from 100 samples

The exclusive mode test shows some degradation:
> render.c:928: Testing exclusive mode at 44100
> render.c:948: Latency: 15.0113 ms
> render.c:967: BufferSize 22528 estimated fragment 662 x 33 = 21846
> render.c:991: Clock Frequency 44100
> render.c:1060: Test failed: Position 5696 too far after stop 100ms -- 129ms

30% off, quite a lot.
> render.c:1070: padding 0 past sleep #2
> render.c:1089: padding 0 position 22528 past stop #2

This is worrying.  Padding 0 means that within 200ms, the driver
emptied its whole half second buffer.  That's not physical.  Do you
have PulseAudio running on the UNIX VM host?  It's known from winealsa
to eat lots of samples when starting up.

By contrast, a native box yields:
< padding 13308 past sleep #2
< padding 13251 position 9277 past stop #2 -- 210ms
> render.c:1148: position 6208 past 100ms sleep #3 -- 141ms
> render.c:1152: Test failed: Position 6208 too far after playing 100ms
> render.c:1168: padding 16256 position 6272 past stop #3 -- 142ms
> render.c:1173: Test failed: Position 6272 too far after stop 100ms

Again, a native box yields values fully in range:
< position 4757 past 100ms sleep #3 -- 108ms
< padding 17706 position 4822 past stop #3 -- 109ms

Interestingly, only exclusive mode is affected by huge deviations, upto 50%.
Regarding shared mode, oddly w8 machines exhibit some failures.
They are quite small (I think we should raise the margins to fit):
render.c:1060: Test failed: Position 39424 too far after stop 100ms -- 111ms
render.c:1060: Test failed: Position 43008 too far after stop 100ms -- 121ms
render.c:1094: Test failed: Position 78848 too far after playing 200ms --223ms

One machine stalled for 44 seconds:
> render.c:633: event after Stop.2 average 444.809ms deviation 4294.73 from 100 samples

That would have caused a test failure if it had happened at another location
within the tests.

Regards,
    Jörg Höhle