wine CPU usage and CreateWaitableTimer
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
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
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
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
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
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?
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....
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
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
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
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
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
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
participants (3)
-
andrea -
Nikolay Sivov -
Sebastian Lackner