runtime: time is not correctly updated under wine #18537

bioothod · 2017-01-06T10:06:11Z

After golang had changed its clocks to monotonic, windows port started to use slightly unofficial memory mapping hack to get current time: https://codereview.appspot.com/108700045/patch/120001/130001

Unfortunately wine (as of jan 2016 neither hack was committed) does not update that page, this ends up with time.Sleep() taking forever on wine (checked with GOOS=windows and go 1.7.4)

It seems that hack to read mapped memory containing interrupt time works for all systems but wine, are there any plans to add a check into magic systime() call at https://github.com/golang/go/blob/master/src/runtime/os_windows.go#L594 to fallback to query performance counter syscall for example if mapped memory is not being updated?

The text was updated successfully, but these errors were encountered:

bioothod · 2017-01-06T10:06:41Z

@dvyukov Dmitry please comment on this issue

dvyukov · 2017-01-06T10:18:06Z

@alexbrainman
Is it possible to detect that we are running under wine?

bioothod · 2017-01-06T11:27:15Z

This should work

#include <windows.h>
#include <stdio.h>

int main(void)
{
	static const char * (CDECL *pwine_get_version)(void);
	HMODULE hntdll = GetModuleHandle("ntdll.dll");
	if(!hntdll) {
		printf("Not running on NT.\n");
		return -1;
	}
	pwine_get_version = (const char* (*)())(void *)GetProcAddress(hntdll, "wine_get_version");
	if(pwine_get_version) {
		printf("Running on Wine... %s\n",pwine_get_version());
	} else {
		printf("did not detect Wine.\n");
	}
	return 0;
}

$ x86_64-w64-mingw32-gcc /tmp/wine.cpp -o /tmp/wine
$ /tmp/wine
fixme:winediag:start_process Wine Staging 2.0-rc2 is a testing version containing experimental patches.
...
Running on Wine... 2.0-rc2

bioothod · 2017-01-06T11:32:29Z

But I believe that detecting that interrupt time is not updated rather than application runs under wine is a better idea - one problem, one local fix. Who knows, maybe wine will eventually port this memory feature, although so far there are only workarounds which use dedicated thread which updates this page once in 15.6 ms to mimic only system time.

alexbrainman · 2017-01-08T02:04:22Z

@bioothod

Sure, we can change runtime to allow for Wine.

Searching for wine_get_version functoin in ntdll.dll on startup sounds good to me. I am not clear about your alternative proposal - how are you going to detect that "interrupt time is not updated"?

Also, once we know that we are running on Wine, how should runtime.unixnano and runtime.nanotime be implemented? Alternatively fill free to send your own proposal (https://golang.org/doc/contribute.html).

Thank you.

Alex

bioothod · 2017-01-08T02:17:23Z

Detecting that time is not updated is rather simple - just run this interrupt time checking loop in osinit() and if time doesn't change, set a flag/callback which uses modkernel32.NewProc("Sleep"). This will not be monotonic though, so this fallback can use QueryPerformanceCounter/QueryPerformanceFrequency instead.

alexbrainman · 2017-01-08T02:26:34Z

run this interrupt time checking loop in osinit() and if time doesn't change, set a flag/callback which uses modkernel32.NewProc("Sleep")

I do not understand your proposal. Do you suggest we check if runtime._KSYSTEM_TIME at runtime._INTERRUPT_TIME address changes in a loop? How many time should we run the loop before giving up? This should be fast - we don't want every Go program pay for this too much.

Alex

bioothod · 2017-01-08T03:03:31Z

Interrupt time precision is about 10 updates per microsecond, so calling something like code below at every start will not ever slow down any go program, getting that windows starting code already calls things like LoadLibrary()

It could be even better than what I wrote if using a systime()-like loop directly instead of calling systime() which synchronizes timer update with timer interrupt. There should be a new term for this kind of optimization though - a nanooptimization!

I would not mind calling this with the loop duration specified via some environment variable or anything else, which will be zero by default and only wine users would specify it. Although imo it looks a bit ugly ~~like hell~~, it is up to the maintainers who believes what is best for the project.

// 1 usec at worst
func time_check() bool {
t1 := systime()
for i := 0; i<10; i++ {
    t2 := systime()
    if t2 != t1 {
        return true
    }
}
return false
}

osinit() {
...
if time_check() != true {
    set new time callback
}
}

alexbrainman · 2017-01-12T00:24:21Z

Interrupt time precision is about 10 updates per microsecond, so calling something like code below at every start will not ever slow down any go program

Fair enough. We could, probably, do that. Or search for wine_get_version in ntdll.dll.

You didn't say how runtime.unixnano and runtime.nanotime should be implemented for Wine.

Alex

minux · 2017-01-12T00:45:05Z

I'm still not convinced. Say, if ReactOS requires special cases, should we add them? Why wine is different? Wine is supposed to emulate Windows faithfully. Just because we generally don't add special case for qemu-user, I don't think we should add special case for wine too. It's definitely possible to implement the system page under wine.

alexbrainman · 2017-01-12T00:52:38Z

Why wine is
different?

The way runtime.unixnano and runtime.nanotime are implemented is not documented by Microsoft. I think it is fare we implement them in a documented way.

Personally I am happy to support whatever OS users use.

Alex

bioothod · 2017-01-12T01:34:15Z

To implement nanotime in a correct fashion I would recommend using QueryPerformanceCounter/QueryPerformanceFrequency syscalls, dividing one by another should produce incrementing counter with fixed frequency: https://msdn.microsoft.com/en-us/library/windows/desktop/dn553408(v=vs.85).aspx

Wine is a bit different, because it is not really a windows, it tries its best to emulate it, but it quite frequently fails. It is up to the wine user to convince wine core team to fix it, and frankly saying I seriously doubt wine can ever fix this particular bug for at least 1ms resolution. This bug exists in wine bugzilla for at least 2 years, the only solution I saw uses dedicated thread to update the mapping, it emulates system time with 15.6 ms resulution, which is not enough for go (although its ok for me and most of the users I believe). This is really an ugly and expensive solution for most of the users out there (for everyone who doesn't need monotonic clocks).

Quite contrary syscall behaviour is a standard, if QPC breaks there will be no hpet timers, and I'm pretty sure wine needs it. It has quite a serious performance overhead compared to reading 3 times from mapped memory, so it is not default.

As of ReactOS - it doesn't really matter. It looks really feasible for me that some reactos user will eventually come here and say, that in version X.Y.Z of branch N something had stopped working. If golang can fix it easily without overhead, what's the problem? If you are an insane purist who fights for the absolute code and design perfection, you probably would not go in IT anyway. And fixing some issue for some users with a trivial check is a good way to go. Otherwise you can tell that time subsystem (and I question whether things like GC work) virtually doesn't work on one of the most popular crossover platform in the world.

And after all this memory reading feature IS NOT OFFICIALLY DOCUMENTED. It exists in winapi headers quite for a while and starting from w2k there are some helpers which work with it (like is-debugger-present and similar), but yet again, if you fight for the purification, you should argue to change code to official syscalls.

alexbrainman · 2017-01-12T01:59:43Z

To implement nanotime in a correct fashion I would recommend using QueryPerformanceCounter/QueryPerformanceFrequency syscalls

Sounds like a plan. Would you like to send a change? Here https://golang.org/doc/contribute.html is how to contribute.

Maybe wait for a week to make sure no objections here. @minux might come around too.

Alex

minux · 2017-01-12T02:23:44Z

The hard part of wine is implementing the undocumented side effects. If wine just implements documented interfaces, I doubt it can run any major Windows applications at all.

minux · 2017-01-12T02:25:40Z

Changing our implementation to use documented interfaces (provided the performance doesn't suffer too much) SGTM. But detecting wine and then act differently is not ok from me.

bioothod · 2017-01-13T17:53:07Z

I've cooked up a patch, which kind of works but raises an error when calling time.Sleep(): fatal error: runtime: stack split at bad time
It happens 100% when time.Sleep() is invoked and never when just time.Now() or friends (which are different now compared to the same startup value previously).

If there anything with signals which messes up between time.Sleep() and QueryPerformanceCounter()?

Here is a patch, its quite straightforward
wine.time.use.qpc.diff.txt

Here is a tracedump:

$ GOTRACEBACK=2 /tmp/sleep
fixme:process:SetProcessPriorityBoost (0xffffffff,1): stub
t1: 2017-01-14 09:32:54.4705399 +0300 AST [1484375574470539900]
t2: 2017-01-14 09:32:54.4705495 +0300 AST [1484375574470549500]
2017-01-14 09:32:54.4705519 +0300 AST [1484375574470551900]: going to sleep at start for 1s
runtime: newstack sp=0x5b411f1c stack=[0x5b411000, 0x5b412000]
	morebuf={pc:0x421aad sp:0x5b411f20 lr:0x0}
	sched={pc:0x43ffa1 sp:0x5b411f1c lr:0x0 ctxt:0x0}
runtime.systime_qpc_syscall(0x7ffe0008, 0x0, 0x1)
	/home/zbr/awork/gosrc/src/runtime/os_windows.go:657 +0x7d fp=0x5b411f4c sp=0x5b411f20
runtime.nanotime(0x4ee13c, 0x0)
	/home/zbr/awork/gosrc/src/runtime/os_windows.go:667 +0x14 fp=0x5b411f5c sp=0x5b411f4c
runtime.notetsleep_internal(0x4ee13c, 0x3b9abe48, 0x0, 0x5b42e1e0, 0x0, 0x0, 0x5b42e1e0)
	/home/zbr/awork/gosrc/src/runtime/lock_sema.go:194 +0x6e fp=0x5b411f74 sp=0x5b411f5c
runtime.notetsleepg(0x4ee13c, 0x3b9abe48, 0x0, 0x0)
	/home/zbr/awork/gosrc/src/runtime/lock_sema.go:258 +0x77 fp=0x5b411f98 sp=0x5b411f74
runtime.timerproc()
	/home/zbr/awork/gosrc/src/runtime/time.go:209 +0x39b fp=0x5b411ff0 sp=0x5b411f98
runtime.goexit()
	/home/zbr/awork/gosrc/src/runtime/asm_386.s:1629 +0x1 fp=0x5b411ff4 sp=0x5b411ff0
created by runtime.addtimerLocked
	/home/zbr/awork/gosrc/src/runtime/time.go:116 +0xe0
fatal error: runtime: stack split at bad time

runtime stack:
runtime.throw(0x4a465a, 0x20)
	/home/zbr/awork/gosrc/src/runtime/panic.go:596 +0x7c fp=0x33fcbc sp=0x33fcb0
runtime.newstack(0x0)
	/home/zbr/awork/gosrc/src/runtime/stack.go:989 +0x9cd fp=0x33fd74 sp=0x33fcbc
runtime.morestack()
	/home/zbr/awork/gosrc/src/runtime/asm_386.s:409 +0x77 fp=0x33fd7c sp=0x33fd74

goroutine 18 [syscall]:
runtime.systime_qpc_syscall(0x7ffe0008, 0x0, 0x1)
	/home/zbr/awork/gosrc/src/runtime/os_windows.go:657 +0x7d fp=0x5b411f4c sp=0x5b411f20
runtime.nanotime(0x4ee13c, 0x0)
	/home/zbr/awork/gosrc/src/runtime/os_windows.go:667 +0x14 fp=0x5b411f5c sp=0x5b411f4c
runtime.notetsleep_internal(0x4ee13c, 0x3b9abe48, 0x0, 0x5b42e1e0, 0x0, 0x0, 0x5b42e1e0)
	/home/zbr/awork/gosrc/src/runtime/lock_sema.go:194 +0x6e fp=0x5b411f74 sp=0x5b411f5c
runtime.notetsleepg(0x4ee13c, 0x3b9abe48, 0x0, 0x0)
	/home/zbr/awork/gosrc/src/runtime/lock_sema.go:258 +0x77 fp=0x5b411f98 sp=0x5b411f74
runtime.timerproc()
	/home/zbr/awork/gosrc/src/runtime/time.go:209 +0x39b fp=0x5b411ff0 sp=0x5b411f98
runtime.goexit()
	/home/zbr/awork/gosrc/src/runtime/asm_386.s:1629 +0x1 fp=0x5b411ff4 sp=0x5b411ff0
created by runtime.addtimerLocked
	/home/zbr/awork/gosrc/src/runtime/time.go:116 +0xe0

goroutine 1 [sleep]:
runtime.gopark(0x4a6d40, 0x4ee130, 0x49f53a, 0x5, 0x13, 0x2)
	/home/zbr/awork/gosrc/src/runtime/proc.go:261 +0x109 fp=0x5b429ea0 sp=0x5b429e8c
runtime.goparkunlock(0x4ee130, 0x49f53a, 0x5, 0x13, 0x2)
	/home/zbr/awork/gosrc/src/runtime/proc.go:267 +0x4c fp=0x5b429ebc sp=0x5b429ea0
time.Sleep(0x3b9aca00, 0x0)
	/home/zbr/awork/gosrc/src/runtime/time.go:59 +0xfb fp=0x5b429ed8 sp=0x5b429ebc
main.main()
	/tmp/sleep.go:18 +0x466 fp=0x5b429fc8 sp=0x5b429ed8
runtime.main()
	/home/zbr/awork/gosrc/src/runtime/proc.go:185 +0x1d6 fp=0x5b429ff0 sp=0x5b429fc8
runtime.goexit()
	/home/zbr/awork/gosrc/src/runtime/asm_386.s:1629 +0x1 fp=0x5b429ff4 sp=0x5b429ff0

goroutine 2 [force gc (idle)]:
runtime.gopark(0x4a6d40, 0x4edfe8, 0x4a08de, 0xf, 0x2914, 0x1)
	/home/zbr/awork/gosrc/src/runtime/proc.go:261 +0x109 fp=0x5b414fbc sp=0x5b414fa8
runtime.goparkunlock(0x4edfe8, 0x4a08de, 0xf, 0x5b40e014, 0x1)
	/home/zbr/awork/gosrc/src/runtime/proc.go:267 +0x4c fp=0x5b414fd8 sp=0x5b414fbc
runtime.forcegchelper()
	/home/zbr/awork/gosrc/src/runtime/proc.go:226 +0x99 fp=0x5b414ff0 sp=0x5b414fd8
runtime.goexit()
	/home/zbr/awork/gosrc/src/runtime/asm_386.s:1629 +0x1 fp=0x5b414ff4 sp=0x5b414ff0
created by runtime.init.3
	/home/zbr/awork/gosrc/src/runtime/proc.go:215 +0x2b

goroutine 3 [GC sweep wait]:
runtime.gopark(0x4a6d40, 0x4ee090, 0x4a030a, 0xd, 0x419014, 0x1)
	/home/zbr/awork/gosrc/src/runtime/proc.go:261 +0x109 fp=0x5b415fb0 sp=0x5b415f9c
runtime.goparkunlock(0x4ee090, 0x4a030a, 0xd, 0x14, 0x1)
	/home/zbr/awork/gosrc/src/runtime/proc.go:267 +0x4c fp=0x5b415fcc sp=0x5b415fb0
runtime.bgsweep(0x5b4041c0)
	/home/zbr/awork/gosrc/src/runtime/mgcsweep.go:56 +0xa2 fp=0x5b415fe8 sp=0x5b415fcc
runtime.goexit()
	/home/zbr/awork/gosrc/src/runtime/asm_386.s:1629 +0x1 fp=0x5b415fec sp=0x5b415fe8
created by runtime.gcenable
	/home/zbr/awork/gosrc/src/runtime/mgc.go:212 +0x55

goroutine 17 [finalizer wait]:
runtime.gopark(0x4a6d40, 0x4fde30, 0x4a0628, 0xe, 0x14, 0x1)
	/home/zbr/awork/gosrc/src/runtime/proc.go:261 +0x109 fp=0x5b410f94 sp=0x5b410f80
runtime.goparkunlock(0x4fde30, 0x4a0628, 0xe, 0x14, 0x1)
	/home/zbr/awork/gosrc/src/runtime/proc.go:267 +0x4c fp=0x5b410fb0 sp=0x5b410f94
runtime.runfinq()
	/home/zbr/awork/gosrc/src/runtime/mfinal.go:161 +0x9c fp=0x5b410ff0 sp=0x5b410fb0
runtime.goexit()
	/home/zbr/awork/gosrc/src/runtime/asm_386.s:1629 +0x1 fp=0x5b410ff4 sp=0x5b410ff0
created by runtime.createfing
	/home/zbr/awork/gosrc/src/runtime/mfinal.go:142 +0x62

Application is rather trivial: https://play.golang.org/p/0ZUCNggw7e

bioothod · 2017-01-13T19:58:49Z

Patch for online review:

diff --git a/src/runtime/os_windows.go b/src/runtime/os_windows.go
index 75b8acd..cc001ce 100644
--- a/src/runtime/os_windows.go
+++ b/src/runtime/os_windows.go
@@ -33,6 +33,8 @@ const (
 //go:cgo_import_dynamic runtime._GetThreadContext GetThreadContext%2 "kernel32.dll"
 //go:cgo_import_dynamic runtime._LoadLibraryW LoadLibraryW%1 "kernel32.dll"
 //go:cgo_import_dynamic runtime._LoadLibraryA LoadLibraryA%1 "kernel32.dll"
+//go:cgo_import_dynamic runtime._QueryPerformanceCounter QueryPerformanceCounter%1 "kernel32.dll"
+//go:cgo_import_dynamic runtime._QueryPerformanceFrequency QueryPerformanceFrequency%1 "kernel32.dll"
 //go:cgo_import_dynamic runtime._ResumeThread ResumeThread%1 "kernel32.dll"
 //go:cgo_import_dynamic runtime._SetConsoleCtrlHandler SetConsoleCtrlHandler%2 "kernel32.dll"
 //go:cgo_import_dynamic runtime._SetErrorMode SetErrorMode%1 "kernel32.dll"
@@ -76,6 +78,8 @@ var (
 	_GetThreadContext,
 	_LoadLibraryW,
 	_LoadLibraryA,
+	_QueryPerformanceCounter,
+	_QueryPerformanceFrequency,
 	_ResumeThread,
 	_SetConsoleCtrlHandler,
 	_SetErrorMode,
@@ -290,6 +294,32 @@ func osinit() {
 	// equivalent threads that all do a mix of GUI, IO, computations, etc.
 	// In such context dynamic priority boosting does nothing but harm, so we turn it off.
 	stdcall2(_SetProcessPriorityBoost, currentProcess, 1)
+
+	check_timers()
+}
+
+//go:nosplit
+var systime func(addr uintptr) int64
+var systime_qpc_frequency int64
+
+//go:nosplit
+func check_timers() {
+	systime = systime_memory_mapping
+	t1 := nanotime()
+
+	// wine users will wait for at most 10 usecs at start to detect that wine
+	// doesn't update page containg INTERRUPT_TIME, which means fast time is not supported on wine
+	// we can not simply fallback to Sleep() syscall, since its time is not monotonic,
+	// instead we use QueryPerformanceCounter family of syscalls to implement monotonic timer
+	// https://msdn.microsoft.com/en-us/library/windows/desktop/dn553408(v=vs.85).aspx
+	for i := 0; i < 100; i++ {
+		if nanotime() != t1 {
+			return
+		}
+	}
+
+	systime = systime_qpc_syscall
+	stdcall1(_QueryPerformanceFrequency, uintptr(unsafe.Pointer(&systime_qpc_frequency)))
 }
 
 //go:nosplit
@@ -591,7 +621,7 @@ const (
 )
 
 //go:nosplit
-func systime(addr uintptr) int64 {
+func systime_memory_mapping(addr uintptr) int64 {
 	timeaddr := (*_KSYSTEM_TIME)(unsafe.Pointer(addr))
 
 	var t _KSYSTEM_TIME
@@ -607,6 +637,8 @@ func systime(addr uintptr) int64 {
 			osyield()
 		}
 	}
+
+	// this recursively enters systime() call
 	systemstack(func() {
 		throw("interrupt/system time is changing too fast")
 	})
@@ -614,6 +646,18 @@ func systime(addr uintptr) int64 {
 }
 
 //go:nosplit
+func systime_qpc_syscall(addr uintptr) int64 {
+	// QPC timing is called when memory mapping is not updated, but it still contains the correct initial time
+	// we use this as a base and apply QPC bias
+	base_time := systime_memory_mapping(addr)
+
+	var counter int64
+	stdcall1(_QueryPerformanceCounter, uintptr(unsafe.Pointer(&counter)))
+
+	return base_time + counter * 1000000 / systime_qpc_frequency
+}
+
+//go:nosplit
 func unixnano() int64 {
 	return (systime(_SYSTEM_TIME) - 116444736000000000) * 100
 }

bradfitz · 2017-01-13T20:04:18Z

@bioothod, we can't accept or review patches on the bug tracker. They have to be in Gerrit.

minux · 2017-01-13T20:04:57Z

Again, wine specific code is not ok as the windows builder won't test them. And I highly doubt we would add a wine builder (I'm pretty sure all.bat won't pass on wine.)

bioothod · 2017-01-13T20:17:01Z

This is not a request for inclusion, this is a demonstration of the idea @bradfitz

There is no need to test it at build time since it doesn't work yet - it crashes probably because of signal mess, that's why I asked above what could be a reason for fatal error: runtime: stack split at bad time in this code. Testing it at build time is trivial, just call systime_qpc_syscall() directly right after plain systime() has been tested @minux

alexbrainman · 2017-01-14T05:48:57Z

This is not a request for inclusion, this is a demonstration of the idea

Some won't look at your code for legal reason. For Gerrit access, you must have completed one of the contributor license agreements. Not everything sent via Gerrit is reviewed or submitted.

what could be a reason for fatal error: runtime: stack split at bad time in this code

I am, probably, wrong, but I think you cannot call stdcall1 from systime. stdcall1 function does a lot, and expects runtime to be in a consistent state. But systime (or nanotime) is called from everywhere. We already have osyield and usleep functions that are in a similar situation, perhaps you can do the same in systime.

Alex

bioothod · 2017-01-14T11:48:15Z

Wow, assembler in the high-level language to call a function and save the stack!
I thought it had hidden in the debris like in 90th or something.

Ok, I will dust off my wizard hat, recover the ancient manuscripts and try to cook up a patch.

bioothod · 2017-01-14T11:56:23Z

I wonder how did it work previously, since just 2.5 years ago it was as simple as

int64 runtime·nanotime(void)
 {
    int64 filetime;
    runtime·stdcall(runtime·GetSystemTimeAsFileTime, 1, &filetime)

is there any high-level document describing runtime changes which forced time code to go into hand crafted assembly?

bioothod · 2017-01-14T20:17:30Z

It happens to be much simpler than I thought, no need to switch stacks, problem is in division.

Running 10000000 / 10000000 in NOSPLIT function ends up with panic, since it invokes quite a bit of division functions from runtime.int64div().

By simpler I mean that I do not have to write asm code to invoke QPC syscalls, which for instance requires changing signature of onosstack() to accept uintptr instead of uint32, since otherwise there is no way to get back 64-bit data, with uintptr I can use a pointer at least, although return value is missing.

Code works on i386 if I mark a bunch of division functions in src/runtime/vlrt.go with go://nosplit, what do you think? Something tells me that it may affect runtime by panicing in the middle of the production code if stack has been suddenly exhausted.

bioothod · 2017-01-14T20:20:17Z

For the reference, discussions about stack usage and why some functions had been changed to OS stack:
#4955
https://codereview.appspot.com/7563043

dvyukov · 2017-01-15T09:25:00Z

@bioothod timediv function may help with division.

bioothod · 2017-01-15T15:34:19Z

@dvyukov yeah, timediv() does the trick, thank you

I've made the patch, added QPC test into src/runtime/syscall_windows_test.go, but guys, you force people to use google account with gerrit, and that's a crap, it can not verify newly created account. Either because of russian phone number or whatever else, and sorry, I can not dig into google QA to find out the reason (phone number in screenshot has been changed obviously) @bradfitz @alexbrainman

So I post a patch here, please comment and merge, it works both for i386 and amd64 builds tested on wine, I will run it on real windows machine a bit later.

Patch:
qpc.time.diff.txt

Online:

diff --git a/src/runtime/os_windows.go b/src/runtime/os_windows.go
index 75b8acd..15506da 100644
--- a/src/runtime/os_windows.go
+++ b/src/runtime/os_windows.go
@@ -33,6 +33,8 @@ const (
 //go:cgo_import_dynamic runtime._GetThreadContext GetThreadContext%2 "kernel32.dll"
 //go:cgo_import_dynamic runtime._LoadLibraryW LoadLibraryW%1 "kernel32.dll"
 //go:cgo_import_dynamic runtime._LoadLibraryA LoadLibraryA%1 "kernel32.dll"
+//go:cgo_import_dynamic runtime._QueryPerformanceCounter QueryPerformanceCounter%1 "kernel32.dll"
+//go:cgo_import_dynamic runtime._QueryPerformanceFrequency QueryPerformanceFrequency%1 "kernel32.dll"
 //go:cgo_import_dynamic runtime._ResumeThread ResumeThread%1 "kernel32.dll"
 //go:cgo_import_dynamic runtime._SetConsoleCtrlHandler SetConsoleCtrlHandler%2 "kernel32.dll"
 //go:cgo_import_dynamic runtime._SetErrorMode SetErrorMode%1 "kernel32.dll"
@@ -76,6 +78,8 @@ var (
        _GetThreadContext,
        _LoadLibraryW,
        _LoadLibraryA,
+       _QueryPerformanceCounter,
+       _QueryPerformanceFrequency,
        _ResumeThread,
        _SetConsoleCtrlHandler,
        _SetErrorMode,
@@ -290,6 +294,45 @@ func osinit() {
        // equivalent threads that all do a mix of GUI, IO, computations, etc.
[zbr@odin src]$ cat /tmp/qpc.time.diff.txt
diff --git a/src/runtime/os_windows.go b/src/runtime/os_windows.go
index 75b8acd..15506da 100644
--- a/src/runtime/os_windows.go
+++ b/src/runtime/os_windows.go
@@ -33,6 +33,8 @@ const (
 //go:cgo_import_dynamic runtime._GetThreadContext GetThreadContext%2 "kernel32.dll"
 //go:cgo_import_dynamic runtime._LoadLibraryW LoadLibraryW%1 "kernel32.dll"
 //go:cgo_import_dynamic runtime._LoadLibraryA LoadLibraryA%1 "kernel32.dll"
+//go:cgo_import_dynamic runtime._QueryPerformanceCounter QueryPerformanceCounter%1 "kernel32.dll"
+//go:cgo_import_dynamic runtime._QueryPerformanceFrequency QueryPerformanceFrequency%1 "kernel32.dll"
 //go:cgo_import_dynamic runtime._ResumeThread ResumeThread%1 "kernel32.dll"
 //go:cgo_import_dynamic runtime._SetConsoleCtrlHandler SetConsoleCtrlHandler%2 "kernel32.dll"
 //go:cgo_import_dynamic runtime._SetErrorMode SetErrorMode%1 "kernel32.dll"
@@ -76,6 +78,8 @@ var (
 	_GetThreadContext,
 	_LoadLibraryW,
 	_LoadLibraryA,
+	_QueryPerformanceCounter,
+	_QueryPerformanceFrequency,
 	_ResumeThread,
 	_SetConsoleCtrlHandler,
 	_SetErrorMode,
@@ -290,6 +294,45 @@ func osinit() {
 	// equivalent threads that all do a mix of GUI, IO, computations, etc.
 	// In such context dynamic priority boosting does nothing but harm, so we turn it off.
 	stdcall2(_SetProcessPriorityBoost, currentProcess, 1)
+
+	check_timers()
+}
+
+//go:nosplit
+var systime func(addr uintptr) int64
+var systime_qpc_frequency int32
+var systime_qpc_counter_start int64
+
+//go:nosplit
+func check_timers() {
+	systime = systime_memory_mapping
+
+	var tmp int64
+	stdcall1(_QueryPerformanceFrequency, uintptr(unsafe.Pointer(&tmp)))
+	// this should not overflow, it is a number of ticks of the performance counter per second
+	// panic if overflow
+	if tmp == 0 {
+		panic("QueryPerformanceFrequency syscall returned zero, running on unsupported hardware")
+	}
+	if tmp > (1<<31 - 1) {
+		panic("QueryPerformanceFrequency overflow 32 bit divider, check nosplit discussion to proceed")
+	}
+	systime_qpc_frequency = int32(tmp)
+	stdcall1(_QueryPerformanceCounter, uintptr(unsafe.Pointer(&systime_qpc_counter_start)))
+
+	// wine users will wait for at most 10 usecs at start to detect that wine
+	// doesn't update page containg INTERRUPT_TIME, which means fast time is not supported on wine
+	// we can not simply fallback to Sleep() syscall, since its time is not monotonic,
+	// instead we use QueryPerformanceCounter family of syscalls to implement monotonic timer
+	// https://msdn.microsoft.com/en-us/library/windows/desktop/dn553408(v=vs.85).aspx
+	t1 := nanotime()
+	for i := 0; i < 100; i++ {
+		if nanotime() != t1 {
+			return
+		}
+	}
+
+	systime = systime_qpc_syscall
 }
 
 //go:nosplit
@@ -591,7 +634,7 @@ const (
 )
 
 //go:nosplit
-func systime(addr uintptr) int64 {
+func systime_memory_mapping(addr uintptr) int64 {
 	timeaddr := (*_KSYSTEM_TIME)(unsafe.Pointer(addr))
 
 	var t _KSYSTEM_TIME
@@ -607,6 +650,8 @@ func systime(addr uintptr) int64 {
 			osyield()
 		}
 	}
+
+	// NB this recursively enters systime() call
 	systemstack(func() {
 		throw("interrupt/system time is changing too fast")
 	})
@@ -614,6 +659,27 @@ func systime(addr uintptr) int64 {
 }
 
 //go:nosplit
+func systime_qpc_syscall(addr uintptr) int64 {
+	// QPC timing is called when memory mapping is not updated, but it still contains the correct initial time
+	// we use this as a base and apply QPC bias
+
+	var counter int64 = 0
+	stdcall1(_QueryPerformanceCounter, uintptr(unsafe.Pointer(&counter)))
+
+	return systime_memory_mapping(addr) + int64(timediv((counter - systime_qpc_counter_start) * 10000000, systime_qpc_frequency, nil))
+}
+func SystimeQPCTest() bool {
+	t1 := systime_qpc_syscall(_INTERRUPT_TIME)
+	for i := 0; i < 1000; i++ {
+		t2 := systime_qpc_syscall(_INTERRUPT_TIME)
+		if t2 != t1 {
+			return true
+		}
+	}
+	return false
+}
+
+//go:nosplit
 func unixnano() int64 {
 	return (systime(_SYSTEM_TIME) - 116444736000000000) * 100
 }
diff --git a/src/runtime/syscall_windows_test.go b/src/runtime/syscall_windows_test.go
index 11e67df..82dabea 100644
--- a/src/runtime/syscall_windows_test.go
+++ b/src/runtime/syscall_windows_test.go
@@ -933,6 +933,12 @@ func TestLoadLibraryEx(t *testing.T) {
 		have, flags)
 }
 
+func TimeSystimeTest(t *testing.T) {
+	if !runtime.SystimeQPCTest() {
+		t.Fatal("runtime.systime_qpc_syscall() has stalled")
+	}
+}
+
 var (
 	modwinmm    = syscall.NewLazyDLL("winmm.dll")
 	modkernel32 = syscall.NewLazyDLL("kernel32.dll")

bradfitz · 2017-01-15T18:25:37Z

@bioothod, sorry, for legal reasons we can't accept a patch here on the bug tracker.

bioothod · 2017-01-15T23:28:15Z

OMG, are you serious? You do allow proprietary binary crap in the executable and can not accept several lines diff which fixes real bug basically rendering system unusable in the most popular crossplatform environment on the world without shitty bureaucracy, which involves registering new google account, which virtually refuses to verify new user (probably because this phone number is already used in a completely irrelevant setup)?

Guys, are you aware of the 21 century auth technologies? OAuth maybe, did you hear this word? Do you know about github? Maybe words 'signed-off-by' highlight something - those beardy guys in linux-kernel use it. Or maybe code of conduct, facebook requires to sign a special page to accept patches...

What's wrong with you? You create a good language for its purpose, and you add so much crap around it.

Someone, please copy this patch into review system or rewrite it the way you like, I've shown the basic idea, implementation fixes time bug in wine environment and works without overhead for common windows users.

minux · 2017-01-15T23:51:55Z

On Sun, Jan 15, 2017 at 6:28 PM, Evgeniy Polyakov ***@***.***> wrote: You do allow proprietary binary crap in the executable and

Please elaborate on this. Where are the proprietary binary blobs in Go?

alexbrainman · 2017-01-15T23:52:40Z

it can not verify newly created account. Either because of russian phone number or whatever else, and sorry, I can not dig into google QA to find out the reason (phone number in screenshot has been changed obviously) @bradfitz @alexbrainman

I do not work for Google, and have no special contacts there. Sorry.

Alex

bioothod · 2017-01-16T00:16:54Z

@minux I talked about binaries distributed via vendoring feature

bradfitz · 2017-01-16T00:19:16Z

@bioothod, I'm sorry you're upset, but we can't make legal exceptions just because you're upset.

The bureaucracy has pros and cons. You've hit a con. The pros are that we have a very clean contribution history and legal story. Users of Go appreciate that.

If you manage to create a Google account we can start a code review for you. Until then, we'll just have to wait.

bioothod · 2017-01-16T00:22:46Z

@alexbrainman I'm not insisting on fixing google account bugs of course, I'm just pointing that code review process is flawed at best imo, and I would describe it in more colourful details actually...

I've shown the idea of how to fix it, I would gladly submit it for review and fix this bug, but I believe we have a show stopper so far, I will try to resolve it, but hardly see what can be done except finding another phone number.
If you think that this implementation is correct, consider pushing it (rewritten, rethought or whatever else) upstream

minux · 2017-01-16T00:24:36Z

On Sun, Jan 15, 2017 at 7:16 PM, Evgeniy Polyakov ***@***.***> wrote: @minux <https://github.com/minux> I talked about binaries distributed via vendoring feature

The vendoring feature is about source codes. Go does have support for binary only packages (//go:binary-only-package), but we intentionally makes it impossible to distribute them using regular "go get". And there is a little-known feature of *.syso files, but there is no proprietary binary syso blobs in the Go repos.

bioothod · 2017-01-16T00:25:38Z

@bradfitz flawed google account requirement has virtually zero correlation with go users who appreciate clean contribution. Your words imply that facebook or linux-kernel contribution history and legal story are not clean enough, are you sure that requiring flawed google account is strong enough for such words?

bradfitz · 2017-01-16T00:27:28Z

@bioothod, I'm not going to debate our CLA requirements in this forum. If you're looking for an argument, look elsewhere.

bioothod · 2017-01-16T00:30:23Z

@minux I didn't tell about golang repos per se, but legal greyarea of the binary packages combined with vendoring feature. This was a reply to claims that bugfix like above is not clear enough from legal point of view. But that's irrelevant you are correct.

bioothod · 2017-01-16T00:34:37Z

@bradfitz I'm curious, whether I need to have posts in google+ social network and how many, apparently this might be a requirement too like using google account.

Apart from the size of google drive had to be used to review the patch, is it ok from technical point of view? I.e. does it break something, or highlight some issue with stalled time detection, or maybe incorrect syscall usage?

bioothod · 2017-01-16T19:25:57Z

Updated QPC fallback time implementation. On the real hardware 100 loop iterations are actually either too quick (which is unlikely), or windows updates those mappings on some other events which are not happening in go.

Anyway, running a following loop on the real hardware ended up with unchanged times:

+       t1 := nanotime()
+       for i := 0; i < 100; i++ {
+               if nanotime() != t1 {
+                       return
+               }
+       }

so I updated test to actually perform a sleep, I call usleep(2), which can take a while, it is 1-2 ms on wine. What do you think, is it an acceptable delay or not?

If it is not, there is plan B.
Interrupt time is a time since boot, and I can not tell whether this memory mapping is ever updated on wine, but at least at osinit() time it is zero (which sounds logically since process has just booted) and can be used to check whether timing calls should be updated or not.

Embedded patch for review. If you are still afraid of letters and believe that commenting patch on github causes legal issues, headache and baldness, @noxiouz will push it into gerrit on my behalf

diff --git a/src/runtime/os_windows.go b/src/runtime/os_windows.go
index 75b8acd..6e34b04 100644
--- a/src/runtime/os_windows.go
+++ b/src/runtime/os_windows.go
@@ -33,6 +33,8 @@ const (
 //go:cgo_import_dynamic runtime._GetThreadContext GetThreadContext%2 "kernel32.dll"
 //go:cgo_import_dynamic runtime._LoadLibraryW LoadLibraryW%1 "kernel32.dll"
 //go:cgo_import_dynamic runtime._LoadLibraryA LoadLibraryA%1 "kernel32.dll"
+//go:cgo_import_dynamic runtime._QueryPerformanceCounter QueryPerformanceCounter%1 "kernel32.dll"
+//go:cgo_import_dynamic runtime._QueryPerformanceFrequency QueryPerformanceFrequency%1 "kernel32.dll"
 //go:cgo_import_dynamic runtime._ResumeThread ResumeThread%1 "kernel32.dll"
 //go:cgo_import_dynamic runtime._SetConsoleCtrlHandler SetConsoleCtrlHandler%2 "kernel32.dll"
 //go:cgo_import_dynamic runtime._SetErrorMode SetErrorMode%1 "kernel32.dll"
@@ -76,6 +78,8 @@ var (
 	_GetThreadContext,
 	_LoadLibraryW,
 	_LoadLibraryA,
+	_QueryPerformanceCounter,
+	_QueryPerformanceFrequency,
 	_ResumeThread,
 	_SetConsoleCtrlHandler,
 	_SetErrorMode,
@@ -290,6 +294,68 @@ func osinit() {
 	// equivalent threads that all do a mix of GUI, IO, computations, etc.
 	// In such context dynamic priority boosting does nothing but harm, so we turn it off.
 	stdcall2(_SetProcessPriorityBoost, currentProcess, 1)
+
+	check_timers()
+}
+
+//go:nosplit
+var _unixnano func() int64
+//go:nosplit
+var _nanotime func() int64
+
+//go:nosplit
+func unixnano() int64 {
+	return _unixnano()
+}
+
+//go:nosplit
+func nanotime() int64 {
+	return _nanotime()
+}
+
+var systime_qpc_frequency int32
+var systime_qpc_counter_start int64
+var qpc_base_nano_system, qpc_base_nano_interrupt int64
+
+//go:nosplit
+func check_timers() {
+	_unixnano = unixnano_mm
+	_nanotime = nanotime_mm
+
+	// wine will actually have a zero nanotime, since it is a time since boot, and starting the process is actually a boot
+	if unixnano() != 0 && nanotime() != 0 {
+		// users will wait for 2 usecs at start to detect that system doesn't update page containg INTERRUPT_TIME,
+		// which means fast time is not supported on wine
+		// we can not simply fallback to Sleep() syscall, since its time is not monotonic,
+		// instead we use QueryPerformanceCounter family of syscalls to implement monotonic timer
+		// https://msdn.microsoft.com/en-us/library/windows/desktop/dn553408(v=vs.85).aspx
+		t1 := nanotime()
+		usleep(2)
+		t2 := nanotime()
+		if t1 != t2 {
+			return
+		}
+	}
+
+	qpc_base_nano_system = unixnano_mm()
+	qpc_base_nano_interrupt = nanotime_mm()
+
+	_unixnano = unixnano_qpc
+	_nanotime = nanotime_qpc
+
+	var tmp int64
+	stdcall1(_QueryPerformanceFrequency, uintptr(unsafe.Pointer(&tmp)))
+	// this should not overflow, it is a number of ticks of the performance counter per second,
+	// its resolution is at most 10 per usecond (on wine, even smaller on real hardware), so it will be at most 10 millions here,
+	// panic if overflows
+	if tmp == 0 {
+		panic("QueryPerformanceFrequency syscall returned zero, running on unsupported hardware")
+	}
+	if tmp > (1<<31 - 1) {
+		panic("QueryPerformanceFrequency overflow 32 bit divider, check nosplit discussion to proceed")
+	}
+	systime_qpc_frequency = int32(tmp)
+	stdcall1(_QueryPerformanceCounter, uintptr(unsafe.Pointer(&systime_qpc_counter_start)))
 }
 
 //go:nosplit
@@ -607,6 +673,8 @@ func systime(addr uintptr) int64 {
 			osyield()
 		}
 	}
+
+	// NB this recursively enters systime() call
 	systemstack(func() {
 		throw("interrupt/system time is changing too fast")
 	})
@@ -614,15 +682,44 @@ func systime(addr uintptr) int64 {
 }
 
 //go:nosplit
-func unixnano() int64 {
+func unixnano_mm() int64 {
 	return (systime(_SYSTEM_TIME) - 116444736000000000) * 100
 }
 
 //go:nosplit
-func nanotime() int64 {
+func nanotime_mm() int64 {
 	return systime(_INTERRUPT_TIME) * 100
 }
 
+//go:nosplit
+func systime_qpc() int64 {
+	var counter int64 = 0
+	stdcall1(_QueryPerformanceCounter, uintptr(unsafe.Pointer(&counter)))
+
+	// returns number of nanoseconds
+	return int64(timediv((counter - systime_qpc_counter_start) * 1000000000, systime_qpc_frequency, nil))
+}
+
+//go:nosplit
+func unixnano_qpc() int64 {
+	// returns number of nanoseconds since Unix Epoch
+	return qpc_base_nano_system + systime_qpc()
+}
+
+//go:nosplit
+func nanotime_qpc() int64 {
+	// returns number of nanoseconds since boot
+	return qpc_base_nano_interrupt + systime_qpc()
+}
+
+func SystimeQPCTest() bool {
+	t1 := unixnano_qpc()
+	usleep(5)
+	t2 := unixnano_qpc()
+	return t1 != t2
+}
+
+
 // Calling stdcall on os stack.
 // May run during STW, so write barriers are not allowed.
 //go:nowritebarrier
diff --git a/src/runtime/syscall_windows_test.go b/src/runtime/syscall_windows_test.go
index 11e67df..82dabea 100644
--- a/src/runtime/syscall_windows_test.go
+++ b/src/runtime/syscall_windows_test.go
@@ -933,6 +933,12 @@ func TestLoadLibraryEx(t *testing.T) {
 		have, flags)
 }
 
+func TimeSystimeTest(t *testing.T) {
+	if !runtime.SystimeQPCTest() {
+		t.Fatal("runtime.systime_qpc_syscall() has stalled")
+	}
+}
+
 var (
 	modwinmm    = syscall.NewLazyDLL("winmm.dll")
 	modkernel32 = syscall.NewLazyDLL("kernel32.dll")

bradfitz · 2017-01-16T20:33:25Z

Embedded patch for review.

Again, please stop putting patches here. Nobody is allowed to review this code unless it comes via Gerrit.

If I see any further patches or any code reviews in this thread I will unfortunately be forced to lock this thread.

alnsn · 2017-01-16T23:57:46Z

@bioothod, I'm sorry you're upset, but we can't make legal exceptions just because you're upset.

If laywers dictate how you accept patches, well, one day they will come after you. Run away from the project before they do.

alexbrainman · 2017-01-17T01:11:27Z

I updated test to actually perform a sleep, I call usleep(2), which can take a while, it is 1-2 ms on wine. What do you think, is it an acceptable delay or not?

I think we want to do as little as possible on startup. What happened to "searching for wine_get_version function in ntdll.dll" idea? We already search ntdll.dll for other things, so you would need to add just a couple of lines.

If you are still afraid of letters and believe that commenting patch on github causes legal issues, headache and baldness

I have been bold for years. And have no problems with headache. But I wouldn't want legal troubles for the Go Team. I think we all want them to be happy and write code and do code review and ... instead of wasting their time with legal matters. So if @noxiouz wants to send this change, that would be good. I would do it myself, but my TODO list is very long, and you would have to wait awhile.

Alex

bioothod · 2017-01-25T14:27:12Z

Patch has been submitted into gerrit, please comment (preferably here) and merge
https://go-review.googlesource.com/#/c/35710/

bioothod · 2017-01-25T14:28:14Z

Kudos to Anton Tiurin @noxiouz for this

gopherbot · 2017-01-25T14:30:53Z

CL https://golang.org/cl/35710 mentions this issue.

alexbrainman · 2017-02-02T05:02:28Z

Kudos to Anton Tiurin @noxiouz for this

You should note that https://go-review.googlesource.com/#/c/35710/ will not progress (Brad set -2 there) until CLA is cleared.

Alex

rakyll changed the title ~~time is not correctly updated under wine~~ runtime: time is not correctly updated under wine Jan 6, 2017

rakyll added this to the Go1.9 milestone Jan 6, 2017

bioothod mentioned this issue Jan 23, 2017

grpc: Server.Serve failed to create ServerTransport: connection error: desc = "transport: short write" grpc/grpc-go#1054

Closed

bradfitz mentioned this issue Feb 1, 2017

net: ExecIO invalid number of bytes written #18887

Closed

dividedmind mentioned this issue Apr 12, 2017

Doesn't work on Windows cyberark/summon#40

Closed

gopherbot closed this as completed in 9f98e49 Apr 25, 2017

golang locked and limited conversation to collaborators Apr 25, 2018

gopherbot added the FrozenDueToAge label Apr 25, 2018

runtime: time is not correctly updated under wine #18537

runtime: time is not correctly updated under wine #18537

Comments

bioothod commented Jan 6, 2017

bioothod commented Jan 6, 2017

dvyukov commented Jan 6, 2017

bioothod commented Jan 6, 2017

bioothod commented Jan 6, 2017

alexbrainman commented Jan 8, 2017

bioothod commented Jan 8, 2017

alexbrainman commented Jan 8, 2017

bioothod commented Jan 8, 2017

alexbrainman commented Jan 12, 2017

minux commented Jan 12, 2017 via email

alexbrainman commented Jan 12, 2017

bioothod commented Jan 12, 2017

alexbrainman commented Jan 12, 2017

minux commented Jan 12, 2017 via email

minux commented Jan 12, 2017 via email

bioothod commented Jan 13, 2017

bioothod commented Jan 13, 2017

bradfitz commented Jan 13, 2017

minux commented Jan 13, 2017 via email

bioothod commented Jan 13, 2017 • edited

alexbrainman commented Jan 14, 2017

bioothod commented Jan 14, 2017

bioothod commented Jan 14, 2017

bioothod commented Jan 14, 2017

bioothod commented Jan 14, 2017

dvyukov commented Jan 15, 2017

bioothod commented Jan 15, 2017

bradfitz commented Jan 15, 2017

bioothod commented Jan 15, 2017 • edited

minux commented Jan 15, 2017 via email

alexbrainman commented Jan 15, 2017

bioothod commented Jan 16, 2017

bradfitz commented Jan 16, 2017

bioothod commented Jan 16, 2017

minux commented Jan 16, 2017 via email

bioothod commented Jan 16, 2017

bradfitz commented Jan 16, 2017

bioothod commented Jan 16, 2017 • edited

bioothod commented Jan 16, 2017

bioothod commented Jan 16, 2017 • edited

bradfitz commented Jan 16, 2017

alnsn commented Jan 16, 2017

alexbrainman commented Jan 17, 2017

bioothod commented Jan 25, 2017

bioothod commented Jan 25, 2017

gopherbot commented Jan 25, 2017

alexbrainman commented Feb 2, 2017

bioothod commented Jan 13, 2017 •

edited

bioothod commented Jan 15, 2017 •

edited

bioothod commented Jan 16, 2017 •

edited

bioothod commented Jan 16, 2017 •

edited