wine CPU usage and CreateWaitableTimer

[andrea]

Hi,

I'm trying to understand why AppleWin uses 100% CPU when running in wine vs ~1% in Windows.

my case is wine 1.7.43 vs Windows 7

https://appdb.winehq.org/objectManager.php?sClass=version&iId=29403
https://bugs.winehq.org/show_bug.cgi?id=34945

basically 97% time is spent in a WaitForSingleObject on a semaphore signalled by a DirectSound 
IReferenceClock via AdvisePeriodic.
The timer period is set to 1 millisecond.

I have tried an other Windows call to create the timer: CreateWaitableTimer
The latter uses about 50% CPU, so it is much better, but still not very good.

This is true even on a simple app that does nothing other than waiting for this timer all the time.

Does anybody know

1) is this normal? should these waits be almost free like they are in Windows?
2) what is the best implemented timer in wine that can be used for a periodic event (~1ms)?

Thanks

[andrea]

On 01/06/15 20:43, andrea wrote:
> Hi,
>
> I'm trying to understand why AppleWin uses 100% CPU when running in wine vs ~1% in Windows.
>
> my case is wine 1.7.43 vs Windows 7
>
> https://appdb.winehq.org/objectManager.php?sClass=version&iId=29403
> https://bugs.winehq.org/show_bug.cgi?id=34945
>
> basically 97% time is spent in a WaitForSingleObject on a semaphore signalled by a DirectSound
> IReferenceClock via AdvisePeriodic.
> The timer period is set to 1 millisecond.
>
> I have tried an other Windows call to create the timer: CreateWaitableTimer
> The latter uses about 50% CPU, so it is much better, but still not very good.
>
> This is true even on a simple app that does nothing other than waiting for this timer all the time.
>
> Does anybody know
>
> 1) is this normal? should these waits be almost free like they are in Windows?
> 2) what is the best implemented timer in wine that can be used for a periodic event (~1ms)?
>
> Thanks

I've tried 4 different function to create a period timer

http://pastebin.com/wt4iTL78

you can compiler it as

// winegcc -g timers.cpp -lwinmm -lole32 -lstrmiids

and then run it as

./a.out X Y

where X is the period of wait in ms, and Y the method
it will wait till 10 seconds and print some statistics
(you can use "time" to time it)

1 - CreateWaitableTimer
2 - IReferenceClock->AdvisePeriodic
3 - CreateTimerQueueTimer
4 - timeSetEvent

if the wait is 1 ms each time I get the following system times (out of ~10 sec of execution, compute 
with "time")

1 - 0.33s
2 - 4.05s
3 - 0.57s
4 - 0.54s

if I wait every 5 ms I get

1 - 0.15s
2 - 3.95s
3 - 0.28s
4 - 0.20s

It feels like option 2 (IReferenceClock) is implemented as a sort of spin lock, its system time does 
not decrease with longer waits.

What do you think?

Andrea

[Sebastian Lackner]

Hello andrea,

good catch, its actually a bug in SystemClockAdviseThread. A patch like:

--- snip ---
diff --git a/dlls/quartz/systemclock.c b/dlls/quartz/systemclock.c
index 043299b..ac41a49 100644
--- a/dlls/quartz/systemclock.c
+++ b/dlls/quartz/systemclock.c
@@ -127,6 +127,7 @@ static DWORD WINAPI SystemClockAdviseThread(LPVOID lpParam) {
       it = nextit;
     }
     if (NULL != it) timeOut = (DWORD) ((it->rtBaseTime + it->rtIntervalTime) - curTime) / (REFERENCE_TIME)10000;
+    else timeOut = INFINITE;
 
     /** Now Periodics Advice: semi sorted list (sort cannot be used) */
     for (it = This->pPeriodicAdvise; NULL != it; it = it->next) {
--- snip ---

Seems to be sufficient to fix it. I will review the code for other errors one more time,
and then submit the patch.

Regarding your second question, the best timer (when using for events) is
CreateWaitableTimer in my opinion. All other timers need separate threads, and need an
additional wineserver call for event handling.

Regards,
Sebastian

On 06.06.2015 16:28, andrea wrote:
> On 01/06/15 20:43, andrea wrote:
> > Hi,
> >
> > I'm trying to understand why AppleWin uses 100% CPU when running in wine vs ~1% in Windows.
> >
> > my case is wine 1.7.43 vs Windows 7
> >
> > https://appdb.winehq.org/objectManager.php?sClass=version&iId=29403
> > https://bugs.winehq.org/show_bug.cgi?id=34945
> >
> > basically 97% time is spent in a WaitForSingleObject on a semaphore signalled by a DirectSound
> > IReferenceClock via AdvisePeriodic.
> > The timer period is set to 1 millisecond.
> >
> > I have tried an other Windows call to create the timer: CreateWaitableTimer
> > The latter uses about 50% CPU, so it is much better, but still not very good.
> >
> > This is true even on a simple app that does nothing other than waiting for this timer all the time.
> >
> > Does anybody know
> >
> > 1) is this normal? should these waits be almost free like they are in Windows?
> > 2) what is the best implemented timer in wine that can be used for a periodic event (~1ms)?
> >
> > Thanks
>
> I've tried 4 different function to create a period timer
>
> http://pastebin.com/wt4iTL78
>
> you can compiler it as
>
> // winegcc -g timers.cpp -lwinmm -lole32 -lstrmiids
>
> and then run it as
>
> ./a.out X Y
>
> where X is the period of wait in ms, and Y the method
> it will wait till 10 seconds and print some statistics
> (you can use "time" to time it)
>
> 1 - CreateWaitableTimer
> 2 - IReferenceClock->AdvisePeriodic
> 3 - CreateTimerQueueTimer
> 4 - timeSetEvent
>
> if the wait is 1 ms each time I get the following system times (out of ~10 sec of execution, compute with "time")
>
> 1 - 0.33s
> 2 - 4.05s
> 3 - 0.57s
> 4 - 0.54s
>
> if I wait every 5 ms I get
>
> 1 - 0.15s
> 2 - 3.95s
> 3 - 0.28s
> 4 - 0.20s
>
> It feels like option 2 (IReferenceClock) is implemented as a sort of spin lock, its system time does not decrease with longer waits.
>
> What do you think?
>
> Andrea

[andrea]

On 07/06/15 19:08, Sebastian Lackner wrote:
> Hello andrea,
>
> good catch, its actually a bug in SystemClockAdviseThread. A patch like:
>
> --- snip ---
> diff --git a/dlls/quartz/systemclock.c b/dlls/quartz/systemclock.c
> index 043299b..ac41a49 100644
> --- a/dlls/quartz/systemclock.c
> +++ b/dlls/quartz/systemclock.c
> @@ -127,6 +127,7 @@ static DWORD WINAPI SystemClockAdviseThread(LPVOID lpParam) {
>         it = nextit;
>       }
>       if (NULL != it) timeOut = (DWORD) ((it->rtBaseTime + it->rtIntervalTime) - curTime) / (REFERENCE_TIME)10000;
> +    else timeOut = INFINITE;
>
> /** Now Periodics Advice: semi sorted list (sort cannot be used) */
>       for (it = This->pPeriodicAdvise; NULL != it; it = it->next) {
> --- snip ---
>
> Seems to be sufficient to fix it. I will review the code for other errors one more time,
> and then submit the patch.
>
> Regarding your second question, the best timer (when using for events) is
> CreateWaitableTimer in my opinion. All other timers need separate threads, and need an
> additional wineserver call for event handling.
>
> Regards,
> Sebastian

very nice.
I don't think I will be able to test it before it is released, but I will give it a go to build wine 
from source.

Thank you

[andrea]

On 07/06/15 19:08, Sebastian Lackner wrote:
> Hello andrea,
>
> good catch, its actually a bug in SystemClockAdviseThread. A patch like:
>
> --- snip ---
> diff --git a/dlls/quartz/systemclock.c b/dlls/quartz/systemclock.c
> index 043299b..ac41a49 100644
> --- a/dlls/quartz/systemclock.c
> +++ b/dlls/quartz/systemclock.c
> @@ -127,6 +127,7 @@ static DWORD WINAPI SystemClockAdviseThread(LPVOID lpParam) {
>         it = nextit;
>       }
>       if (NULL != it) timeOut = (DWORD) ((it->rtBaseTime + it->rtIntervalTime) - curTime) / (REFERENCE_TIME)10000;
> +    else timeOut = INFINITE;
>
> /** Now Periodics Advice: semi sorted list (sort cannot be used) */
>       for (it = This->pPeriodicAdvise; NULL != it; it = it->next) {
> --- snip ---
>
> Seems to be sufficient to fix it. I will review the code for other errors one more time,
> and then submit the patch.
>
> Regarding your second question, the best timer (when using for events) is
> CreateWaitableTimer in my opinion. All other timers need separate threads, and need an
> additional wineserver call for event handling.
>
> Regards,
> Sebastian

Did you manage to check if the patch you proposed is the good one?

[Nikolay Sivov]

On 06/25/2015 10:47 PM, andrea wrote:
> On 07/06/15 19:08, Sebastian Lackner wrote:
> > Hello andrea,
> >
> > good catch, its actually a bug in SystemClockAdviseThread. A patch like:
> >
> > --- snip ---
> > diff --git a/dlls/quartz/systemclock.c b/dlls/quartz/systemclock.c
> > index 043299b..ac41a49 100644
> > --- a/dlls/quartz/systemclock.c
> > +++ b/dlls/quartz/systemclock.c
> > @@ -127,6 +127,7 @@ static DWORD WINAPI SystemClockAdviseThread(LPVOID
> > lpParam) {
> >         it = nextit;
> >       }
> >       if (NULL != it) timeOut = (DWORD) ((it->rtBaseTime +
> > it->rtIntervalTime) - curTime) / (REFERENCE_TIME)10000;
> > +    else timeOut = INFINITE;
> >
> > /** Now Periodics Advice: semi sorted list (sort cannot be used) */
> >       for (it = This->pPeriodicAdvise; NULL != it; it = it->next) {
> > --- snip ---
> >
> > Seems to be sufficient to fix it. I will review the code for other
> > errors one more time,
> > and then submit the patch.
> >
> > Regarding your second question, the best timer (when using for events) is
> > CreateWaitableTimer in my opinion. All other timers need separate
> > threads, and need an
> > additional wineserver call for event handling.
> >
> > Regards,
> > Sebastian
>
> Did you manage to check if the patch you proposed is the good one?

This particular patch is already in wine, 
http://source.winehq.org/git/wine.git/commit/b513e07c55504f623baf8d838d00ac6....

[andrea]

On 07/06/15 19:08, Sebastian Lackner wrote:
> Hello andrea,
>
> good catch, its actually a bug in SystemClockAdviseThread. A patch like:
>
> --- snip ---
> diff --git a/dlls/quartz/systemclock.c b/dlls/quartz/systemclock.c
> index 043299b..ac41a49 100644
> --- a/dlls/quartz/systemclock.c
> +++ b/dlls/quartz/systemclock.c
> @@ -127,6 +127,7 @@ static DWORD WINAPI SystemClockAdviseThread(LPVOID lpParam) {
>         it = nextit;
>       }
>       if (NULL != it) timeOut = (DWORD) ((it->rtBaseTime + it->rtIntervalTime) - curTime) / (REFERENCE_TIME)10000;
> +    else timeOut = INFINITE;
>
> /** Now Periodics Advice: semi sorted list (sort cannot be used) */
>       for (it = This->pPeriodicAdvise; NULL != it; it = it->next) {
> --- snip ---
>
> Seems to be sufficient to fix it. I will review the code for other errors one more time,
> and then submit the patch.

Hi,

I've just tried wine 1.7.45 and things have changed.

Better: the system time has been reduced and it is comparable to CreateWaitableTimer

http://pastebin.com/K55znWFQ

this code check the 4 implementations


time ./a.out 2 2

this does a wait every 2 ms for a total of 5 with IReferenceClock

results

real	0m5.090s
user	0m0.160s
sys	0m0.214s


time ./a.out 2 1

this does a wait every 2 ms for a total of 5 with CreateWaitableTimer

results

real	0m5.157s
user	0m0.040s
sys	0m0.115s



Worse: is the wait is low (guess it depends on CPU speed as well) the actual average wait gets bigger.
So if I wait for 5 seconds every 1 ms, with CreateWaitableTimer I actually do 5000 waits and on 
average they are 1.00006 apart (it is ok as I asked to do 1 ms wait)

On the other had with IReferenceClock I get an average of 1.30225 ms (it should have been 1)


You can use the source code I linked above and compare

./a.out 1 1		// 1ms wait with CreateWaitableTimer (5 sec total)
./a.out 1 2             // 1ms wait with IReferenceClock     (5 sec total)

On an other PC (probably slower) things started getting bad at 2ms wait (which results 2.5ms 
average) and terrible with 1ms wait (9ms on average).


So the patch is very good for bigger periods, but not so good for very small periods.

Regards

Andrea

[andrea]

On 01/07/15 20:43, andrea wrote:
> On 07/06/15 19:08, Sebastian Lackner wrote:
>
> Hi,
>
> I've just tried wine 1.7.45 and things have changed.
>
> Better: the system time has been reduced and it is comparable to CreateWaitableTimer
>
> http://pastebin.com/K55znWFQ
>
> this code check the 4 implementations
>
> time ./a.out 2 2
>
> this does a wait every 2 ms for a total of 5 with IReferenceClock
>
> results
>
> real    0m5.090s
> user    0m0.160s
> sys    0m0.214s
>
> time ./a.out 2 1
>
> this does a wait every 2 ms for a total of 5 with CreateWaitableTimer
>
> results
>
> real    0m5.157s
> user    0m0.040s
> sys    0m0.115s
>
> Worse: is the wait is low (guess it depends on CPU speed as well) the actual average wait gets bigger.
> So if I wait for 5 seconds every 1 ms, with CreateWaitableTimer I actually do 5000 waits and on
> average they are 1.00006 apart (it is ok as I asked to do 1 ms wait)
>
> On the other had with IReferenceClock I get an average of 1.30225 ms (it should have been 1)
>
> You can use the source code I linked above and compare
>
> ./a.out 1 1        // 1ms wait with CreateWaitableTimer (5 sec total)
> ./a.out 1 2             // 1ms wait with IReferenceClock     (5 sec total)
>
> On an other PC (probably slower) things started getting bad at 2ms wait (which results 2.5ms
> average) and terrible with 1ms wait (9ms on average).
>
> So the patch is very good for bigger periods, but not so good for very small periods.

Re reading myself, I might have not been very clear.

This patch resolves the issue of the spin lock in IReferenceClock->AdvisePeriodic,

but for small periods the function does not do what it is supposed to do

PC 1:

request wait of 3ms -> get 3ms
request wait of 2ms -> get 2.5ms
request wait of 1ms -> get 8ms

PC 2:

request wait of 3ms -> get 3ms
request wait of 2ms -> get 2ms
request wait of 1ms -> get 1.3ms

while before the patch the actual wait was always the requested
(we are talking about averages over 5 or 10 seconds, of an app that does not do anything else)

Andrea

[andrea]

On 07/06/15 19:08, Sebastian Lackner wrote:
> Hello andrea,
>
> good catch, its actually a bug in SystemClockAdviseThread. A patch like:
>
> --- snip ---
> diff --git a/dlls/quartz/systemclock.c b/dlls/quartz/systemclock.c
> index 043299b..ac41a49 100644
> --- a/dlls/quartz/systemclock.c
> +++ b/dlls/quartz/systemclock.c
> @@ -127,6 +127,7 @@ static DWORD WINAPI SystemClockAdviseThread(LPVOID lpParam) {
>         it = nextit;
>       }
>       if (NULL != it) timeOut = (DWORD) ((it->rtBaseTime + it->rtIntervalTime) - curTime) / (REFERENCE_TIME)10000;
> +    else timeOut = INFINITE;
>
> /** Now Periodics Advice: semi sorted list (sort cannot be used) */
>       for (it = This->pPeriodicAdvise; NULL != it; it = it->next) {
> --- snip ---
>
> Seems to be sufficient to fix it. I will review the code for other errors one more time,
> and then submit the patch.
>
> Regarding your second question, the best timer (when using for events) is
> CreateWaitableTimer in my opinion. All other timers need separate threads, and need an
> additional wineserver call for event handling.
>
> Regards,
> Sebastian

Hi,

I just wanted to check with you, if you have an idea why this patch works well for long-ish periods 
(>3 ms), while for 1 or 2 ms (according to the pc/situation) produces actual waits that can be much 
longer than requested.

on a machine I got 8ms average realised vs 1ms period requested.

thanks

[Sebastian Lackner]

On 07.07.2015 21:49, andrea wrote:
> On 07/06/15 19:08, Sebastian Lackner wrote:
> > Hello andrea,
> >
> > good catch, its actually a bug in SystemClockAdviseThread. A patch like:
> >
> > --- snip ---
> > diff --git a/dlls/quartz/systemclock.c b/dlls/quartz/systemclock.c
> > index 043299b..ac41a49 100644
> > --- a/dlls/quartz/systemclock.c
> > +++ b/dlls/quartz/systemclock.c
> > @@ -127,6 +127,7 @@ static DWORD WINAPI SystemClockAdviseThread(LPVOID lpParam) {
> >         it = nextit;
> >       }
> >       if (NULL != it) timeOut = (DWORD) ((it->rtBaseTime + it->rtIntervalTime) - curTime) / (REFERENCE_TIME)10000;
> > +    else timeOut = INFINITE;
> >
> > /** Now Periodics Advice: semi sorted list (sort cannot be used) */
> >       for (it = This->pPeriodicAdvise; NULL != it; it = it->next) {
> > --- snip ---
> >
> > Seems to be sufficient to fix it. I will review the code for other errors one more time,
> > and then submit the patch.
> >
> > Regarding your second question, the best timer (when using for events) is
> > CreateWaitableTimer in my opinion. All other timers need separate threads, and need an
> > additional wineserver call for event handling.
> >
> > Regards,
> > Sebastian
>
> Hi,
>
> I just wanted to check with you, if you have an idea why this patch works well for long-ish periods (>3 ms), while for 1 or 2 ms (according to the pc/situation) produces actual waits that can be much longer than requested.
>
> on a machine I got 8ms average realised vs 1ms period requested.
>
> thanks

Hello andrea,

I just saw by pure accident that you already wrote a couple of mails before this one, they all landed in my spam folder somehow (?!).

Regarding your question:

The whole implementation of the clock is not really very efficient (separate thread, message loops, events, ...).
Before the patch, as soon as timeOut reached a value of zero (or just a very small value), the thread was busy-looping
all the time, no matter if timers were queued or not. After the patch, the thread sleeps in the meantime, as expected.
The patch itself was definitely correct, but the code was written over 10 years ago, there might be lot of opportunities
to do things more efficient.

Is there any app which explicitly uses such a small delay (and doesn't work well when there is too much overhead)? If
yes, please open a new bug report and add me as CC. You can also add your code as testcase there.

Regards,
Sebastian

[andrea]

On 08/07/15 14:43, Sebastian Lackner wrote:
> Hello andrea,
>
> I just saw by pure accident that you already wrote a couple of mails before this one, they all landed in my spam folder somehow (?!).
>
> Regarding your question:
>
> The whole implementation of the clock is not really very efficient (separate thread, message loops, events, ...).
> Before the patch, as soon as timeOut reached a value of zero (or just a very small value), the thread was busy-looping
> all the time, no matter if timers were queued or not. After the patch, the thread sleeps in the meantime, as expected.
> The patch itself was definitely correct, but the code was written over 10 years ago, there might be lot of opportunities
> to do things more efficient.
>
> Is there any app which explicitly uses such a small delay (and doesn't work well when there is too much overhead)? If
> yes, please open a new bug report and add me as CC. You can also add your code as testcase there.

done

here it is

https://bugs.wine-staging.com/show_bug.cgi?id=442