Author Topic: QueryPerformanceCounter: Sleep slows down my code  (Read 2879 times)

jj2007

  • Member
  • *****
  • Posts: 8893
  • Assembler is fun ;-)
    • MasmBasic
QueryPerformanceCounter: Sleep slows down my code
« on: November 30, 2017, 10:48:25 PM »
A simple loop using NanoTimer aka QueryPerformanceCounter:
Code: [Select]
  For_ ecx=0 To loops-1
push ecx
  invoke Sleep, 0    ; <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
  pop ecx
NanoTimer() ; start the QueryPerformanceCounter timer
void GetHash("Just a little test of the hash function")
add total, NanoTimer(us) ; add time for calculating the average, end QueryPerformanceCounter
mov ms(ecx), eax ; mov time into array
  Next

One would expect that most timings are near the physical limit, but a few are much higher because of interrupts. Here is the distribution:


What I don't understand is the result for invoke Sleep, 1:


Suddenly, timings increase drastically, with a few exceptions to the left. We always used Sleep to improve the accuracy of timings, but here it seems to have the opposite effect...

Executables and source attached.

Siekmanski

  • Member
  • *****
  • Posts: 1709
Re: QueryPerformanceCounter: Sleep slows down my code
« Reply #1 on: December 01, 2017, 02:50:53 AM »
Timers in windows are really a pain in the ass..
Especially when you need to poll a message at a fixed interval with a timer interrupt within 1 millisecond.  :(


Sleep,0


Sleep,1
Creative coders use backward thinking techniques as a strategy.

AW

  • Member
  • *****
  • Posts: 1606
  • Let's Make ASM Great Again!
Re: QueryPerformanceCounter: Sleep slows down my code
« Reply #2 on: December 01, 2017, 05:55:48 AM »
Probably you should not consider the first measurements, they will take longer because there is nothing in the cache.

jj2007

  • Member
  • *****
  • Posts: 8893
  • Assembler is fun ;-)
    • MasmBasic
Re: QueryPerformanceCounter: Sleep slows down my code
« Reply #3 on: December 01, 2017, 06:12:22 AM »
Probably you should not consider the first measurements, they will take longer because there is nothing in the cache.

Interesting idea: ; ArraySort ms() ; no sorting, show timings in their original sequence

Doesn't solve the Sleep(0) vs Sleep(1) mystery, but you are absolutely right about the first timings being much higher :t

AW

  • Member
  • *****
  • Posts: 1606
  • Let's Make ASM Great Again!
Re: QueryPerformanceCounter: Sleep slows down my code
« Reply #4 on: December 01, 2017, 08:54:33 AM »
Quote
Doesn't solve the Sleep(0) vs Sleep(1) mystery,
I think it solves. The longer the thread sleeps the more chances has the same CPU thread of being reused elsewhere, either in the same process or in another process.  This means that the cache will be invalidated shortly after that.

jj2007

  • Member
  • *****
  • Posts: 8893
  • Assembler is fun ;-)
    • MasmBasic
Re: QueryPerformanceCounter: Sleep slows down my code
« Reply #5 on: December 01, 2017, 10:52:25 AM »
Good point, José :t

hutch--

  • Administrator
  • Member
  • ******
  • Posts: 5944
  • Mnemonic Driven API Grinder
    • The MASM32 SDK
Re: QueryPerformanceCounter: Sleep slows down my code
« Reply #6 on: December 01, 2017, 11:52:30 AM »
You know roughly what SleepEx does, it suspends the thread, waits a duration then returns in the next time slice. It will garrantee slow down your code which is close to what its designed to do.
hutch at movsd dot com
http://www.masm32.com    :biggrin:  :biggrin:

jj2007

  • Member
  • *****
  • Posts: 8893
  • Assembler is fun ;-)
    • MasmBasic
Re: QueryPerformanceCounter: Sleep slows down my code
« Reply #7 on: December 01, 2017, 12:17:25 PM »
You know roughly what SleepEx does, it suspends the thread, waits a duration then returns in the next time slice. It will garrantee slow down your code which is close to what its designed to do.

The timing starts after the return from Sleep. Check José's argument, it's more convincing.

hutch--

  • Administrator
  • Member
  • ******
  • Posts: 5944
  • Mnemonic Driven API Grinder
    • The MASM32 SDK
Re: QueryPerformanceCounter: Sleep slows down my code
« Reply #8 on: December 01, 2017, 11:33:42 PM »
What Jose said is fine, what I gather is you are running timings and in that context I would imagine the you would want to avoid cache effects. Make the SleepEx duration longer so that you DO lose any cache effects and the accuracy of the timing should improve. You are still at the mercy of ring0 interference and there is likely to be some degree of wandering in the next time slice available after SleepEx gives control back to the timing thread. This is why I avoid short intense timing methods, there are too many variables that are either difficult or impossible to control.
hutch at movsd dot com
http://www.masm32.com    :biggrin:  :biggrin:

AW

  • Member
  • *****
  • Posts: 1606
  • Let's Make ASM Great Again!
Re: QueryPerformanceCounter: Sleep slows down my code
« Reply #9 on: December 01, 2017, 11:48:50 PM »
You can also increase the Process Priority and the Thread Priority (The normal Thread Priority is the Process Priority). No thread is interrupted by a lower priority thread and a higher priority interrupts lower priority. This may have side effects in the Sleep behaviour, though.  :icon_rolleyes:

jj2007

  • Member
  • *****
  • Posts: 8893
  • Assembler is fun ;-)
    • MasmBasic
Re: QueryPerformanceCounter: Sleep slows down my code
« Reply #10 on: December 02, 2017, 12:50:30 AM »
Make the SleepEx duration longer so that you DO lose any cache effects and the accuracy of the timing should improve.

That is what I would expect, too. But the evidence tells a different story - this is Sleep(100) before the timing starts. Much worse than before, and a number of "negative" outliers. And the median is about 5x higher than it should be.

Compare that to the lower graph: Sleep(0), realtimepriority, unsorted = sequential. It's the cache and nothing else. Which opens the question whether we want to time algos with or without cache ::)

Siekmanski

  • Member
  • *****
  • Posts: 1709
Re: QueryPerformanceCounter: Sleep slows down my code
« Reply #11 on: December 02, 2017, 02:15:55 AM »
You can also increase the Process Priority and the Thread Priority (The normal Thread Priority is the Process Priority). No thread is interrupted by a lower priority thread and a higher priority interrupts lower priority. This may have side effects in the Sleep behaviour, though.  :icon_rolleyes:

It works very well.

I have used "Sleep,1" in a multimedia interrupt timer thread with THREAD_PRIORITY_TIME_CRITICAL.
The timer is running 200 nanoseconds slower as the interrupt time I want.
When it slowly drifts below the interrupt time, I pause it with "Sleep,1" and reset the timer.
It stays "stable" within 1 millisecond and it keeps the processor load very small.

I needed this because I had to synchronize with the per 10 millisecond write/play cursor message from DirectSound which is jittery as hell and would not spend another 10 milliseconds waiting for the next message and lose track of the buffer positions. Now I have the lowest latency possible with DirectSound streaming buffers.
Creative coders use backward thinking techniques as a strategy.

AW

  • Member
  • *****
  • Posts: 1606
  • Let's Make ASM Great Again!
Re: QueryPerformanceCounter: Sleep slows down my code
« Reply #12 on: December 02, 2017, 04:00:33 AM »
I have used "Sleep,1" in a multimedia interrupt timer thread with THREAD_PRIORITY_TIME_CRITICAL.
For very short runs it may work very well as you confirmed.  :t

hutch--

  • Administrator
  • Member
  • ******
  • Posts: 5944
  • Mnemonic Driven API Grinder
    • The MASM32 SDK
Re: QueryPerformanceCounter: Sleep slows down my code
« Reply #13 on: December 02, 2017, 08:59:45 AM »
Something else that helps to stabilise the timings is to use a serialised instruction before it, CPUID is one that will do that, clear the cache before the timing. As you would be aware, modern x86/64 hardware is a lot messier when it comes to timing code. This Haswell E/EP I am using sleeps in "noddy mode" at about 1.2 gig until you load it where it comes up close to the 3.3 gig it tops out at.

Power saving, variable clock rates, out of order instruction sequencing etc etc etc .... are all designed to make your life more miserable so I personally test with long duration test pieces to try and get some idea if an algo is faster than another. To test attack (how quick and algo is started and run) you make a short test and run it many times so you get a duration of a second or so. For long linear tests I use the massive amount of memory available in win64 to test linear speed so if you have to process massive log files or large videos you can clock how fast a long single read/write takes.

Just a note with SleepEx, the granularity is about 20ms so SleepEx,1,0 is no faster than SleepEx,20,0. From memory it is a hardware based interrupt.
hutch at movsd dot com
http://www.masm32.com    :biggrin:  :biggrin:

jj2007

  • Member
  • *****
  • Posts: 8893
  • Assembler is fun ;-)
    • MasmBasic
Re: QueryPerformanceCounter: Sleep slows down my code
« Reply #14 on: December 02, 2017, 01:47:05 PM »
the granularity is about 20ms so SleepEx,1,0 is no faster than SleepEx,20,0

Right. Under the hood, it calls NtDelayExecution, exactly like Sleep(delay), which saves two bytes compared to the identical SleepEx, delay, 0:
Code: [Select]
SleepEx         Ú$  8BFF              mov edi, edi                            ; STATUS_X kernel32.SleepEx(Time,Alertable)
75811217        ³.  55                push ebp
75811218        ³.  8BEC              mov ebp, esp
7581121A        ³.  5D                pop ebp
7581121B        À. EB ED             jmp short <jmp.&API-MS-Win-Core-Synch-L ; Jump to KERNELBASE.SleepEx
... ->NtDelayExecution

Guess what are the values of edi, ebp and esp after the first four lines have been executed - C compilers at work :P

Below the distributions (serial, not sorted) for:
- Sleep(100), no CPUID
- Sleep(100), with CPUID
- Sleep(0), no CPUID
- Sleep(100), with CPUID

Note the average of 780 ms for the upper 2 graphs: Remember the Sleep(100) comes before the timings starts.
In contrast, the lower 2 Sleep(0) runs (with 500 elements) show spikes at regular intervals; but even those, at about 200 microsecs, are far below the 780ms average of the Sleep(100) runs.