runtime: Windows service timeout during system startup

[kneden]

What version of Go are you using (go version)?

go version go1.9.2 windows/amd64

Does this issue reproduce with the latest release?

Yes.

What operating system and processor architecture are you using (go env)?

set GOARCH=amd64
set GOBIN=
set GOEXE=.exe
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOOS=windows
set GOPATH=C:\Users\XXXXX\d\go
set GORACE=
set GOROOT=C:\Go
set GOTOOLDIR=C:\Go\pkg\tool\windows_amd64
set GCCGO=gccgo
set CC=gcc
set GOGCCFLAGS=-m64 -mthreads -fmessage-length=0 -fdebug-prefix-map=C:\Users\XXXXX\AppData\Local\Temp\go-build933228923=/tmp/go-build -gno-record-gcc-switches
set CXX=g++
set CGO_ENABLED=1
set CGO_CFLAGS=-g -O2
set CGO_CPPFLAGS=
set CGO_CXXFLAGS=-g -O2
set CGO_FFLAGS=-g -O2
set CGO_LDFLAGS=-g -O2
set PKG_CONFIG=pkg-config

What did you do?

Configured our Go language application to start as a Windows Service, with start type of 'Automatic'. The service is expected to start when the system boots up. Sometimes the service process will not be running after the system has booted up and the 'Windows Logs / 'System' logs in Event Viewer show two logs:

Event ID: 7009
Level: Error
Text:
A timeout was reached (30000 milliseconds) while waiting for the <service name> service to connect.

Event ID: 7000
Level: Error
Text:
The <service name> service failed to start due to the following error: 
The service did not respond to the start or control request in a timely fashion.

These events do not appear in the logs when the service successfully starts.

It appears that Windows terminates the service process when the service fails to respond to the Windows Service start event within the 30 s time frame. Our application contains the Windows Service code based on the sample code from sys/windows/svc/example.

This timeout issue occurs both with 64-bit and 32-bit versions of our executable.

What did you expect to see?

The Go language Windows service start reliably every time the system boots up.

What did you see instead?

The Go language service does not start reliably on some systems on boot-up.

Some observations from systems where the service often fails to start during boot-up:

1. Manually starting the service once the system is up and running has never failed to start correctly. Timestamps from the logs show the process starting quickly (no more than a few seconds).
2. Setting the service's start type to 'Automatic (Delayed Start)', where Windows starts the service 120 s after the 'Automatic' services, works without fail. The user is able to login to the desktop well before the service has been started. It is possible to change this global Windows setting to a lower value (eg 60 s) to make it less noticeable to the user, but because it will affect all delayed start services, it is not an acceptable solution. Some search results claim a per-service delay value can be specified, but we were not able to make this work.
3. Changing the 30000 ms (30 s) Windows service timeout value to larger values (60 s or 90 s) allowed the service to startup. However, this is a global Windows setting and it is not possible to set the timeout per-service. Again, this is not an acceptable solution.
4. We experimented with using the Windows Service "Recovery" settings to restart our service in an attempt to mitigate this problem. However, it appears that these recovery settings have no effect for services that fail to start in time.
5. We instrumented our service with timestamped logs when the first imported package is initialized and when main() starts. We found that main() was often not reached when the timeout occurred. Sometimes even the first imported package's initialization was not reached.
6. A stripped-down Windows service that just logged would often fail to start, but it was less likely to happen compared to our full-fledged service.
7. Using a simple C++ Windows Service (code here) modified to launch our executable (running as a 'normal' application, not as a Windows Service) always launched without fail (no timeouts) during boot-up. Logs within our executable, as well as in the C++ service (just prior to the CreateProcess() call that started our executable) often showed large time deltas. The logs indicated it often took a long time for the Go executable to get launched, and also to reach the main().

While we have some systems (VirtualBox VMs) that reliably show these startup problems, the issue is harder to reproduce on other systems. We have VirtualBox VMs where the problem occurs only occasionally and we have yet to see the timeout occur on non-virtual Windows 10 installations. Timestamp-instrumented loads on those systems sometimes show time deltas of up to 10 s during startup. While this is not long enough to trigger the 30 s timeout on a powerful real system, the concern is that in virtualized environments and/or slower systems the timeout will be reached and the service will not start.

Sample Programs

Sample code can be found in this GitHub repository, including instructions for building and installing (README.md).

Both the launchserv.exe and winserv.exe programs contain the Go Windows Service code (again, based one the sample code). The Go Windows Service sample code was combined into a single file in both cases in order to 'flatten' the main package for tracking imported package initialization.

It is intended that only one of the two should run as a Windows Service. The recommended configuration is to install launchserv.exe as a Windows Service ("my service"), and it will in turn launch winserv.exe as a child process (winserv.exe will run as a 'normal' program, not a service). launchserv.exe writes a timestamped log just prior to starting winserv.exe, which allows measuring the time it takes for winserv.exe to start.

winserv.exe contains a large number of standard package imports, to mimic a real program. These imports are marked as 'unused' and as such only their initializations run (variable initialization and init()).

The VirtualBox version of the Win10 MSEdge test VM can be downloaded from Microsoft here to run these test programs. The following changes may help to increase the likelihood of seeing the issue with this, or other systems:

• Increase the number of CPU cores from 1 (to say 2 or 4). This might increase the concurrent activity when the system is starting up.
• Install the Guest Additions.
• Install other software that starts services when the system boots. For example, one VM that shows the issue very reliably has two VNC server packages, OpenVPN client and an SSL VPN client (Array Networks) (as well as other software) installed.

Multiple boot-ups of the system may be required to see the problem. In many cases, a VM may sometimes demonstrate the problem, but then not do so at other times. YMMV.

When delays are seen, the two most common places are:

1. Launching winserv.exe; that is, between the last launchserv.exe log and the first winserv.exe log. Time deltas as high as 26 s have been seen (and as low as less than 400 ms) have been seen on an Win10/MSEdge VM.
2. The 'lots of imports' in winserv.exe main.go, between the 'b' and 'c' logs. These are the large number of unused standard package imports. Times as high as 9 s (and less than 100 ms on the low end) have been seen on the same Win10/MSEdge VM.

This service is an important component of our product; we are adding more functionality all the time. As the amount of code increases, it seems even more likely that this problem will occur. If there is anything else we can do to help resolve this issue (experiments, measurements, debugging, etc), please let us know.

[rasky]

Thanks for the report. Can you try instrumenting the runtime with timestamped logs, following the code being executed before main?

Just compile Go from source, and use the produced binary to compile your application. Then put print calls in the runtime code and just recompile your software and test. Within the runtime, you can use println() to print without going through fmt, and nanotime() or walltime() to get a timer reading to print. Start from runtime.main() and runtime.init() and check if you can find where time is being lost.

[alexbrainman]

I cannot reproduce it here (I am running it on my WIndows 10 computer) - your service starts and stops fine. I do not have any bright ideas.

Alex

When delays are seen, the two most common places are:
...
The 'lots of imports' in winserv.exe main.go, between the 'b' and 'c' logs.

Maybe some code that runs during std packages init functions is broken when running as a service. We don't test code you import to run as a service. Maybe try removing some imports and see if it improve your situation.

Alex

[alexbrainman]

@kneden

and you are not checking for errors here

https://github.com/Openera/winserv/blob/bdc3a73826f0b7e5d32838f8981aa7a67e2b1d65/cmd/launchserv/launchserv.go#L257

and when you Kill and Wait for process to exit. Not that it matter for your problem.

Alex

[kneden]

I rebuilt 1.9.2 from source with instrumentation in the main() in src/runtime/proc.go, using time_now() (wallclock() calls failed to compile) to get the epoch time and println() to output the values to stdout (in seconds and milliseconds). The winserv.exe Go executable was modified to send all of its timestamped logs to stdout and rebuilt it using this instrumented Go runtime.

I also reduced the number of unused standard package imports in winserv.exe from the original number to those that our Go language service uses throughout our code base. In the future, we expect this list of imports to grow, not shrink, but it does reflect our application's current usage. The updated code can be found on the stdout branch in the GitHub repo.

The simple C++ Windows service (mentioned previously) was modified to do the following:

1. Open the log file.
2. Write a timestamped log to the log file.
3. Start winserv.exe in 'nonservice' mode, using CreateProcess(). stdout & stderr for this child process were set to the log file.

The C++ service was used instead of the Go launchserv.exe to remove the effects of a second Go runtime in these measurements.

There are thus three types of timestamped logs in the log file when the C++ service starts and launches the Go application:

• Simple C++ service log immediately before starting winserve.exe child process.
• Go runtime main() logs at the following points:
  • main() entry (runtime/proc.go, not the application's main()).
  • Just before and after runtime_init() call.
  • Just before and after main_init() call.
  • Just before main_main() call.
• winserv.exe logs as before, mostly delineating the progress through the main package (imports, start of main(), etc). As mentioned, the unused standard package imports (between 'b' and 'c') was reduced to match what our service currently uses.

The results of a set of runs can be found in the following Google Sheet. There is one manual start of the service (ie system already running), followed by 15 boot-ups. The fourth column is the time delta between that log and the previous one, in seconds. It has been conditionally formatted to highlight any value >= 1 second.

For the manual start, there were no significant delays. A separate set of 10 manual service starts on a running system (data not shown) also showed no significant delays between any of the logs.

For the boot-up runs, there are cases where there was no significant delays (such as boot 2 & 7) and others where there were noticeable delays. These delays tend to be seen in several places:

• Between CreateProcess() and entry point of runtime main() (boot 1 & 3).
• Within the winserv.exe package imports, especially the unused standard packages.
• Only once (boot 5) was there a noticeable delay within the runtime main(): between runtime_init() done and the main_init() start logs, though there were many other delays in this run.

There are runs where there was only one significant delay and others where there were many.

For the delay between the CreateProcess() and the runtime main() entry logs, it isn't clear where the time is lost. Is it possible to instrument the Go runtime even earlier than this point?

The current hypothesis is that when Windows is starting services during boot-up, there are often times when resources available to the processes (possibly disk and/or CPU?) are limited. These resource constraints might affect a Go application more than others due to its size, as a larger executable requires more disk I/O and CPU time to load into memory. launchserv.exe is 2.5M vs. C++ service at 21K, for two programs with similar functionality. winserv.exe is 5.6M in its current form (and was 7M when it had more imports).

If the application doesn't hit any significant resource constraints, it starts without delay. If it does, the delay(s) depend when the constraints occur.

[alexbrainman]

For the delay between the CreateProcess() and the runtime main() entry logs, it isn't clear where the time is lost. Is it possible to instrument the Go runtime even earlier than this point?

I do not know. Maybe @aclements knows. Austin, can you suggest something here to understand why it is so slow to start?

The current hypothesis is that when Windows is starting services during boot-up, there are often times when resources available to the processes (possibly disk and/or CPU?) are limited.

It sounds reasonable to me. Windows is trying to get system up and running as soon as possible. It would delay anything that it consider might affect that goal.

These resource constraints might affect a Go application more than others due to its size, as a larger executable requires more disk I/O and CPU time to load into memory. launchserv.exe is 2.5M vs. C++ service at 21K, for two programs with similar functionality. winserv.exe is 5.6M in its current form (and was 7M when it had more imports).

I don't think executable size maters here. Maybe memory allocations affect things. Go reserves large amount of address space upfront, but it is not expensive for a normal process. And, as you have discovered, simple Go service does not suffers delays. Have you tried to build simple Go service with many inits (not starting Go executable with many inits from a service)?

I really don't have any good ideas. Sorry.

Alex

[kneden]

@alexbrainman:

We have seen simple Go service experience delays during startup, though the probability of it happening seem to be less compared to one with one with many imports.

A Go service with many imports behaves similar to one that runs as a 'normal' executable launched by a service, often suffering start-up delays. In fact, we started debugging with this first and moved to having the Go executable (in 'non-service' mode) launched by a service (C++ or Go) to get a measure of the time for the program to be launched. When the delay issues occur during Windows start-up, it doesn't seem to make much difference whether the Go executable is running as the service itself, or launched by the another service.

[alexbrainman]

When the delay issues occur during Windows start-up, it doesn't seem to make much difference whether the Go executable is running as the service itself, or launched by the another service.

Thank you for explaining.

Just an idea - I believe Docker is running as a Windows service. If that service executable is written in Go, how come they don't have problems like yours?

Alex

[kneden]

Just an idea - I believe Docker is running as a Windows service. If that service executable is written in Go, how come they don't have problems like yours?

Good point. When I get a chance, I'll try installing Docker on a problematic VM and see how it behaves.

[aclements]

For the delay between the CreateProcess() and the runtime main() entry logs, it isn't clear where the time is lost. Is it possible to instrument the Go runtime even earlier than this point?

It is. Runtime initialization calls a few functions before runtime.main. You can see the CALLs instructions in rt0_go in asm_amd64.s, but here are the ones you can practically annotate: check and args in runtime1.go, osinit in os_windows.go, and schedinit in proc.go. Quite a bit happens in osinit and schedinit, so it would be interesting to see if the time goes there.

[kneden]

I instrumented the earlier runtime initialization calls, with more focus on the middle of schedinit as some preliminary runs pointed to there. Since calls to println didn't work in the earlier calls, all of the timestamps up to and including those in schedinit are output together at the end of that function (after the schedinit exit timestamp is recorded). The 'schedinit() print time' captures how long it takes for these 15 println calls, in case that introduced any significant delay.

The results are in the second tab of the Google Sheets spreadsheet. Six of the boot-ups had significant times in the newly instrumented code:

• boot 5: osinit, schedinit/mcommoninit, & schedinit/itabsinit
• boot 6: schedinit/itabsinit
• boot 18: schedinit after gcinit (until end of function)
• boot 23: schedinit/itabsinit
• boot 31: schedinit/mcommoninit
• boot 35: schedinit/mcommoninit, schedinit/modulesinit, & schedinit/itabsinit

Other boot-ups either had delays elsewhere, or none of significance.

Seems similar to the previous results, with there being locations in the code where delays are more likely to happen than others, but they don't happen in these places all the time.

[alexbrainman]

Seems similar to the previous results

Indeed.

I have nothing else that helps you. Sorry.

Alex