Re: code review 108700045: runtime: implement monotonic clocks on windows (issue 108700045 by alex.brainman@gmail.com)

[alex.b...@gmail.com]

On 2014/07/17 17:30:14, dvyukov wrote:

> as for the slowdown, both tests set timers for 1 ns. I see 2
possibilities: (1)
> currently the timer thread never sleeps in this test; but with this
change it
> tries to sleep for 1 ns, but OS actually suspends it to 1ms; ...

That is the case. addtimer starts timerproc on new thread. In old
version (using GetSystemTimeAsFileTime) time would change by the time
timerproc starts, so it didn't need to wait for 1 ns. New version (using
GetTickCount) time is changing slower (every 10-16 ms), so timeproc see
same time as addtime does, so it decides to wait. Minimum wait is around
15 ms on that system, so time.NewTicker(1) actually starts ticking after
15 ms, while old version worked instantaneously (no wait involved).

It seems GetTickCount is too grainy - it does not change often enough. I
looked at GetTickCount64, and it is only slightly better. I tried to use
QueryPerformanceCounter and QueryPerformanceFrequency (just a rough
initial version), and these look better then everything else:

benchmark old ns/op new ns/op delta
BenchmarkAfterFunc 5937728 9101912 +53.29%
BenchmarkAfter 1990310800 10024799 -99.50%
BenchmarkStop 643091 1540098 +139.48%
BenchmarkSimultaneousAfterFunc 832063 1679752 +101.88%
BenchmarkStartStop 321887 1117230 +247.09%
BenchmarkTicker 1953200 1952223 -0.05%
BenchmarkNow 58.4 53.3 -8.73%
BenchmarkNowUnixNano 58.3 50.2 -13.89%
BenchmarkFormat 489 499 +2.04%
BenchmarkFormatNow 495 500 +1.01%
BenchmarkParse 474 468 -1.27%
BenchmarkHour 63.7 66.8 +4.87%
BenchmarkSecond 61.0 63.8 +4.59%
BenchmarkYear 83.5 86.7 +3.83%
BenchmarkDay 94.6 97.2 +2.75%

still there are some slow downs that I don't understand, but not as
large as previous version. Maybe we should use QPC/QPF for amd64 and
GetTickCount for 386. What do you think? I still have not tried your
suggestion of just reading the clock directly ...

Alex

https://codereview.appspot.com/108700045/

[dvy...@google.com]

Humm... I am sure that I saw 1ms increments with GetTickCount (after we
bump system timer precision). Basically I run this:

package main

import (
"fmt"
"time"
"unsafe"
)

func main() {
last := time.Now()
last1 := *((*time.Duration)(unsafe.Pointer(uintptr(0x7FFE0008)))) * 100
for i := 0; i < 10000; i++ {
now := time.Now()
now1 := *((*time.Duration)(unsafe.Pointer(uintptr(0x7FFE0008)))) * 100
fmt.Printf("%v %v %v %v %v\n", now.Sub(last)-(now1-last1),
now.Sub(last), now1-last1, now, now1)
last = now
last1 = now1
}
}

and saw that time.Now() and the raw reads produce exactly the same
values.

Maybe you just have an old OS, where GetTickCount is buggy?

Hummm. DO you have any ideas as to why QPC is slower on some benchmarks?
BenchmarkNow is runs faster, and QPC has enough prevision, so... why
some benchmarks become slower?...
In either case I don't think that these benchmarks are very
representative (especially tons of successive 1ns sleeps).


https://codereview.appspot.com/108700045/

[alex.b...@gmail.com]

On 2014/07/22 07:51:46, dvyukov wrote:

> ... I am sure that I saw 1ms increments with GetTickCount (after we
bump

> system timer precision). ...

It, probably, is 1ms. But it is much longer than what we have now, and
whole logic changes because of it. Right now we just return without
wait, like I explained above, but after using GetTickCount we end up
waiting on semaphore. timerproc thread starts quickly enough (less than
1ms, I guess), so it sees the same runtime.nanotime value as timer that
is been added. So it all goes into wait for 1ns, but end up waiting
around 15ms (we wait on windows event - I don't think it waits for less
than 15ms). QPC and reading 0x7FFE0008 is similar to the current
approach, because they both change after about 100ns (much faster than
GetTickCount).

I am bit suspicious of reading 0x7FFE0008 approach. Will it work
everywhere? What about multi CPUs? It is not documented.

QPC, on the other hand, is very documented. And Microsoft recommends it
above all. But it does not work on my XP
https://code.google.com/p/go/issues/detail?id=6007#c36. Perhaps we
should use QPC on amd64, and GetTickCount on 386?

> Hummm. DO you have any ideas as to why QPC is slower on some
benchmarks?

No, I don't. Should I investigate?

> BenchmarkNow is runs faster, and QPC has enough prevision, so... why
some
> benchmarks become slower?...

I don't understand your question. Try again.

> In either case I don't think that these benchmarks are very
representative
> (especially tons of successive 1ns sleeps).

I agree, for the most of these. But I am concerned that
time.NewThread(1) becomes slow and expensive. Given that it is easily
handled on unix, it is, probably, quite common in peoples code.

Alex


https://codereview.appspot.com/108700045/

[dvy...@google.com]

On 2014/07/22 09:29:26, brainman wrote:
> On 2014/07/22 07:51:46, dvyukov wrote:
> >
> >... I am sure that I saw 1ms increments with GetTickCount (after we
bump
> > system timer precision). ...

> It, probably, is 1ms. But it is much longer than what we have now, and
whole
> logic changes because of it. Right now we just return without wait,
like I
> explained above, but after using GetTickCount we end up waiting on
semaphore.
> timerproc thread starts quickly enough (less than 1ms, I guess), so it
sees the
> same runtime.nanotime value as timer that is been added. So it all
goes into
> wait for 1ns, but end up waiting around 15ms (we wait on windows event
- I don't
> think it waits for less than 15ms). QPC and reading 0x7FFE0008 is
similar to the
> current approach, because they both change after about 100ns (much
faster than
> GetTickCount).

Now I am puzzled about difference in behavior between GetTickCount and
0x7FFE0008. GetTickCount just reads that word...
Maybe there are two variables: one is at 0x7FFE0008 and is updated every
100ns, and another is at 0x7FFE0004 and is updated every 1ms...

> I am bit suspicious of reading 0x7FFE0008 approach. Will it work
everywhere?
> What about multi CPUs? It is not documented.

Well, yes, these are all valid questions.
All I can say is that I used 0x7FFE0008 like 10 years ago on XP.

> QPC, on the other hand, is very documented. And Microsoft recommends
it above
> all. But it does not work on my XP
> https://code.google.com/p/go/issues/detail?id=6007#c36. Perhaps we
should use
> QPC on amd64, and GetTickCount on 386?

> > Hummm. DO you have any ideas as to why QPC is slower on some
benchmarks?

> No, I don't. Should I investigate?

> > BenchmarkNow is runs faster, and QPC has enough prevision, so... why
some
> > benchmarks become slower?...

> I don't understand your question. Try again.

I mean that (1) QPC is faster than what we have now (BenchmarkNow
measures that), (2) QPC has high precision (at least 100ns, or maybe
higher), so the huge slowdown due to rescheduling that we observed with
GetTickCount must not be happening. Now the question is: What else is
different between the current impl and QPC what makes some of the
benchmarks slower?
It's not very important question to answer, but it's just puzzling.

[dvy...@google.com]

QPC with fallback to GetTickCount on XP looks fine to me. I hope there
are no people running high-performance Go servers on XP :)


https://codereview.appspot.com/108700045/

[pat...@mezard.eu]

On 2014/07/22 09:39:37, dvyukov wrote:
> I mean that (1) QPC is faster than what we have now (BenchmarkNow
measures
> that), (2) QPC has high precision (at least 100ns, or maybe higher),
so the huge
> slowdown due to rescheduling that we observed with GetTickCount must
not be
> happening. Now the question is: What else is different between the
current impl
> and QPC what makes some of the benchmarks slower?
> It's not very important question to answer, but it's just puzzling.

Do the Windows hosts run on real hardware or virtual machines?

I have encountered *massive* slowdown when running code with a lot of
QPC calls in virtual machines, in particular Win7 hosts in VMWare
containers.

https://codereview.appspot.com/108700045/

[alex.b...@gmail.com]

On 2014/07/22 09:39:37, dvyukov wrote:

> Now I am puzzled about difference in behavior between GetTickCount and
> 0x7FFE0008. GetTickCount just reads that word...

0x7FFE0008 points to int64, while GetTickCount returns uint32.
GetTickCount counts in ms as per the doco.

> I mean that (1) QPC is faster than what we have now (BenchmarkNow
measures
> that), (2) QPC has high precision (at least 100ns, or maybe higher),
so the huge
> slowdown due to rescheduling that we observed with GetTickCount must
not be
> happening. Now the question is: What else is different between the
current impl
> and QPC what makes some of the benchmarks slower?
> It's not very important question to answer, but it's just puzzling.

I will try to find out.

Alex

https://codereview.appspot.com/108700045/

[Aram Hăvărneanu]

On Tue, Jul 22, 2014 at 12:51 PM, <pat...@mezard.eu> wrote:
> I have encountered *massive* slowdown when running code with a lot of
> QPC calls in virtual machines, in particular Win7 hosts in VMWare
> containers.

Yep, to be expected. QPC uses HPET, which is a scarce resource. If
every VM thinks it owns HPET, things become ugly. The QEMU used in the
KVM port to SmartOS actually has a separate embedded cyclics subsystem
implementation because of this... It should be ported to upstream QEMU
so KVM on Linux can use it too.

--
Aram Hăvărneanu

[alex.b...@gmail.com]

On 2014/07/22 09:42:48, dvyukov wrote:
> QPC with fallback to GetTickCount on XP looks fine to me.

Sounds like a plan.

> I hope there are no
> people running high-performance Go servers on XP :)

I don't run one myself. I doubt there other windows XP Go users. :-)

Alex

https://codereview.appspot.com/108700045/

[alex.b...@gmail.com]

On 2014/07/22 09:51:59, patrick2 wrote:

> Do the Windows hosts run on real hardware or virtual machines?

No. I run XP on real PC.

Alex

https://codereview.appspot.com/108700045/

[Dmitry Vyukov]

How bad can it get?
We query time on every timer setup, timer fire; and besides that
runtime queries time every time it polls network and just periodically
(the frequency is 20us, but there are sleeps in between, and I think
windows sleeps for at least 1 ms).

Alex, this can be a reason to not use QPC, because people do run
servers in VMs today.

[alex.b...@gmail.com]

On 2014/07/22 10:29:01, dvyukov wrote:

> Alex, this can be a reason to not use QPC, because people do run
> servers in VMs today.

Do you suggest we keep this CL as is. Maybe use GetTickCount64 when
available? But GetTickCount64 won't improve our time.NewTicker(1)
situation. It is marginally better precission than GettickCount, but not
enough to make time.NewTicker(1) quick. On the other hand, it returns
int64 counter, so we don't need to anything else with returned value.

Alex

https://codereview.appspot.com/108700045/

[alex.b...@gmail.com]

On 2014/07/22 07:51:46, dvyukov wrote:

> Humm... I am sure that I saw 1ms increments with GetTickCount (after
we bump

> system timer precision). Basically I run this:

> package main

> import (
> "fmt"
> "time"
> "unsafe"
> )

> func main() {
> last := time.Now()
> last1 := *((*time.Duration)(unsafe.Pointer(uintptr(0x7FFE0008)))) *
100
> for i := 0; i < 10000; i++ {
> now := time.Now()
> now1 := *((*time.Duration)(unsafe.Pointer(uintptr(0x7FFE0008)))) *
100
> fmt.Printf("%v %v %v %v %v\n", now.Sub(last)-(now1-last1),
now.Sub(last),
> now1-last1, now, now1)
> last = now
> last1 = now1
> }
> }

> and saw that time.Now() and the raw reads produce exactly the same
values.

Just for the record. I measured time difference between values (when the
value changes) returned from different Windows API in a loop like this.
Both GetTickCount and GetTickCount64 change every 15-16 millisecond,
while time.Now().UnixNano() (uses GetSystemTimeAsFileTime under covers)
and "reading 0x7FFE0008" changes every 1 millisecond. This is all on
windows/amd64.

I am not convinced that QueryPerformanceCounter is the answer either -
it is probably too expensive / might take too long to run (comparing to
all the above).

I am not sure what to do here.

Alex

https://codereview.appspot.com/108700045/

[dvy...@google.com]

Yeah...

I would go with 0x7FFE0008. It's known on the internet, so it's unlikely
that it will change (at least not in an existing OS version):
http://www.dcl.hpi.uni-potsdam.de/research/WRK/2007/08/getting-os-information-the-kuser_shared_data-structure/
http://uninformed.org/index.cgi?v=2&a=2&p=15
http://www.informit.com/articles/article.aspx?p=167857&seqNum=8
http://forum.sysinternals.com/0x7ffe0000-what-is-in-it_topic10012.html

This link also suggests that CRT depends on it:
https://github.com/sherpya/nloader/blob/master/README.md
I don't remember whether it's possible to link CRT statically in Visual
Studio. But if it is possible, then it means that existing binary
applications compiled with Visual Studio will also break, which is not
going to happen.

It's definitely the fastest option. And it can also be the simplest
option.


https://codereview.appspot.com/108700045/

[alex.b...@gmail.com]

On 2014/07/23 07:52:56, dvyukov wrote:

> I would go with 0x7FFE0008. ...

That works very well on my windows 7 pc (windows/amd64) - thanks for the
links. But now I have problem with windows xp (windows/386).
time.TestAfter (and time.Sleep) ends too early:

sleep_test.go:154: After(100ms) slept for only 93750000 ns

It appears, windows xp (unlike windows 7) have different time
precisions: counter at 0x7FFE0008 changes every 1ms, while
GetSystemTimeAsFileTime changes every 15-16ms. time.TestAfter uses both
counters: it does time.Sleep (which uses counter at 0x7FFE0008) and than
measures that sleep with GetSystemTimeAsFileTime. Obviously that will
not work - especially for small durations. For example sleeping for
43ms, then GetSystemTimeAsFileTime says we've slept for 31.25ms. It
didn't increment by the next 15ms yet.

I don't see how we could resolve that unless we relax some tests. Or
perhaps I could use GetTickCount on windows/386. GetTickCount changes
every 15ms on windows, so at least the 2 will be more in sync. Still ...

What do you think?

Alex

https://codereview.appspot.com/108700045/

[dvy...@google.com]

Oh, boy.

GetTickCount ticks every 15-16 ms. Now they question is: does
GetSystemTimeAsFileTime tick as 15-16 ms as well, or it ticks at
15.25ms? If it's the latter, can't we get the same situation when
GetSystemTimeAsFileTime is slightly behind (e.g. 0.75 ms behind)? Or
it's GetTickCount that is always behind (if they round it down)?

Since we are already using _KUSER_SHARED_DATA, maybe it will be simple
to use _KUSER_SHARED_DATA.TickCountLow (at 0x7FFE0000) on XP. I think
that it ticks at the same 15-16 ms on XP.

Another idea: can't we just round off the 0x7FFE0008 value on XP, so
that it as if ticks at the same 15-16ms? But I suspect that it can be
tricky to round it to exactly match GetSystemTimeAsFileTime...

Another observation: the test is actually incorrect, because it expects
that system time does not change. When you sleep for 1 second, system
time can be any random value after the sleep.

I don't have a good answer for you. But I would prefer good and fast
code for newer OSes, and a workaround for the XP bug.


https://codereview.appspot.com/108700045/

[dvy...@google.com]

Well, another possibility is to manually bump GetSystemTimeAsFileTime
precision on XP along the lines of:
When we query GetSystemTimeAsFileTime also query 0x7FFE0008 and remember
these values. When we next time query GetSystemTimeAsFileTime, if it
returns the same value as before, then query 0x7FFE0008, calculate the
diff and add to GetSystemTimeAsFileTime value. This way
GetSystemTimeAsFileTime will tick at 1 ms at XP.
I don't know how complex a reliable monotonic solution will be.



https://codereview.appspot.com/108700045/

[alex.b...@gmail.com]

I tested all possible candidate APIs again. This program:

package main

import (
"fmt"

"runtime"
"syscall"
"unsafe"
)

var (
modkernel32 = syscall.NewLazyDLL("kernel32.dll")
procGetTickCount64 = modkernel32.NewProc("GetTickCount64")
procGetTickCount = modkernel32.NewProc("GetTickCount")
)

func GetTickCount64() uint64 {
r, _, _ := syscall.Syscall(procGetTickCount64.Addr(), 0, 0, 0, 0)
return uint64(r)
}

func GetTickCount() uint32 {
r, _, _ := syscall.Syscall(procGetTickCount.Addr(), 0, 0, 0, 0)
return uint32(r)
}

func getSystemTimeAsFileTime() uint64 {
var ft syscall.Filetime
syscall.GetSystemTimeAsFileTime(&ft)
return uint64(ft.Nanoseconds())
}

func getTickCount() uint64 {
return uint64(GetTickCount()) * 1000000
}

func getTickCount64() uint64 {
return GetTickCount64() * 1000000
}

type KSYSTEM_TIME struct {
LowPart uint32
High1Time int32
High2Time int32
}

var (
// KUSER_SHARED_DATA
interruptTimeAddr =
(*KSYSTEM_TIME)(unsafe.Pointer(uintptr(0x7FFE0008)))
systemTimeAddr =
(*KSYSTEM_TIME)(unsafe.Pointer(uintptr(0x7FFE0014)))
)

func readUSD(addr *KSYSTEM_TIME) uint64 {
var t KSYSTEM_TIME
for i := 0; ; i++ {
t.High1Time = addr.High1Time
t.LowPart = addr.LowPart
t.High2Time = addr.High2Time
if t.High1Time == t.High2Time {
break
}
if i > 100 {
panic("should have advanced by now")
}
}
return *((*uint64)(unsafe.Pointer(&t))) * 100
}

func readInterruptTime() uint64 {
return readUSD(interruptTimeAddr)
}

func readSystemTime() uint64 {
return readUSD(systemTimeAddr)
}

func getprec(getticks func() uint64) []uint64 {
r := make([]uint64, 0)
c := getticks()
for i := 0; i < 5; {
c2 := getticks()
if c != c2 {
r = append(r, c2-c)
i++
}
}
return r
}

func main() {
fmt.Printf("getSystemTimeAsFileTime: %v\n",
getprec(getSystemTimeAsFileTime))
fmt.Printf("getTickCount : %v\n", getprec(getTickCount))
if runtime.GOARCH == "amd64" {
fmt.Printf("getTickCount64 : %v\n", getprec(getTickCount64))
}
fmt.Printf("readInterruptTime : %v\n", getprec(readInterruptTime))
fmt.Printf("readSystemTime : %v\n", getprec(readSystemTime))
}

prints

C:\>u:\test
getSystemTimeAsFileTime: [15625000 15625000 15625000 15625000 15625000]
getTickCount : [15000000 15000000 15000000 15000000 15000000]
readInterruptTime : [976600 976600 976600 976600 976600]
readSystemTime : [15625000 15625000 15625000 15625000 15625000]

on windows xp, and

C:\>u:\test
getSystemTimeAsFileTime: [977000 977000 977000 977000 977000]
getTickCount : [16000000 16000000 16000000 16000000 16000000]
getTickCount64 : [15000000 15000000 15000000 15000000 15000000]
readInterruptTime : [976500 976500 976500 976500 976500]
readSystemTime : [977000 977000 977000 977000 977000]

on windows 7.

I still haven't made my mind about what to use here, so any suggestions
are welcome.

Alex

https://codereview.appspot.com/108700045/

[Dmitry Vyukov]

Do you know if timeBeginPeriod requires admin rights? If yes, then the
numbers can be different for program running w/o admin rights...

> --
> You received this message because you are subscribed to the Google Groups
> "golang-codereviews" group.
> To unsubscribe from this group and stop receiving emails from it, send an
> email to golang-coderevi...@googlegroups.com.
> For more options, visit https://groups.google.com/d/optout.

[alex.b...@gmail.com]

On 2014/07/25 07:02:40, dvyukov wrote:
> Do you know if timeBeginPeriod requires admin rights? ...

I don't know. I suspect it does.

> ... If yes, then the

> numbers can be different for program running w/o admin rights...

It will indeed. This is Go program with timeBeginPeriod, and with
timeBeginPeriod removed:

getSystemTimeAsFileTime: [976500 976500 976500 976500 976500]

getTickCount : [15000000 15000000 15000000 15000000 15000000]

getTickCount64 : [16000000 16000000 16000000 16000000 16000000]

readInterruptTime : [976500 976500 976500 976500 976500]

readSystemTime : [976500 976500 976500 976500 976500]

getSystemTimeAsFileTime: [15625000 15625000 15625000 15625000 15625000]

getTickCount : [16000000 16000000 16000000 16000000 16000000]
getTickCount64 : [15000000 15000000 15000000 15000000 15000000]

readInterruptTime : [15625000 15625000 15625000 15625000 15625000]

readSystemTime : [15625000 15625000 15625000 15625000 15625000]

Things aren't getting better. :-(

Alex

https://codereview.appspot.com/108700045/

[dvy...@google.com]

This is getting insane. I think just need to relaxed the sleep test on
windows and give it 16ms inconsistency window.
Users should not rely on the condition that the test currently tests,
because system time is essentially a random value.

Btw, that SystemTime at 0x7FFE0014 is the same as SystemTimeAsFileTime,
right? What do you think about using it for time.Now? If we rely on
KUSER_SHARED_DATA, it does not matter whether we read one or two fields
from it.
Here are the "docs":
http://uninformed.org/index.cgi?v=2&a=2&p=20


https://codereview.appspot.com/108700045/

[alex.b...@gmail.com]

On 2014/07/25 07:42:39, dvyukov wrote:

> Btw, that SystemTime at 0x7FFE0014 is the same as
SystemTimeAsFileTime, right?

Looks that way to me.

> What do you think about using it for time.Now? If we rely on
KUSER_SHARED_DATA,
> it does not matter whether we read one or two fields from it.

I agree. Less code and faster.

Alex

https://codereview.appspot.com/108700045/