x/build/env/windows-amd64: optimize Windows start-up time

[bradfitz]

I've been looking into Windows buildlet VM start-up latency and reliability.

I wrote a little tool to create an instance and log what's happening.

Will post details here.

/cc @johnsonj

[gopherbot]

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

[bradfitz]

@johnsonj, you can patch in https://go-review.googlesource.com/51030

[bradfitz]

Seems like network is often the slow and/or flaky thing, even for the 10.* addresses.

I've seen (based on serial) that the buildlet can be downloaded and listening even before the 10.* address is pingable.

If inbound networking takes a long time to come up, perhaps we need to move to a model where the new VMs connect out only and register themselves with the coordinator to have the coordinator reverse the TCP connection like our other non-VM builders.

[bradfitz]

Here's a run where I see nothing from the buildlet.exe process on serial:

But the network changes behavior. Is the network coming up at 07:02:22 and that's why conns are refused? Maybe stage0 already gave up waiting on the network by then?

$ go install ./debugnewvm/ && debugnewvm -serial
2017/07/25 07:00:53 Creating debug-brad-windows-1500966053
2017/07/25 07:00:54 instance requested
2017/07/25 07:01:22 instance created
2017/07/25 07:01:22 got instance info
2017/07/25 07:01:22 Trying http://10.240.0.14 ...
2017/07/25 07:01:22 SERIAL: SeaBIOS (version 1.8.2-20170419_170401-google)
                            Total RAM Size = 0x00000000e6600000 = 3686 MiB
                            CPUs found: 4     Max CPUs supported: 4
                            found virtio-scsi at 0:3
                            virtio-scsi vendor='Google' product='PersistentDisk' rev='1' type=0 removable=0
                            virtio-scsi blksize=512 sectors=104857600 = 51200 MiB
                            drive 0x000f31a0: PCHS=0/0/0 translation=lba LCHS=1024/255/63 s=104857600
                            Booting from Hard Disk 0...
2017/07/25 07:01:27 Trying http://10.240.0.14: <nil>, Get http://10.240.0.14: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
2017/07/25 07:01:28 Trying http://10.240.0.14 ...
2017/07/25 07:01:28 SERIAL: 7/25/2017 7:01:27 AM UTC: GCE Agent started (version 3.5.1.0).
2017/07/25 07:01:30 SERIAL: 7/25/2017 7:01:29 AM UTC: Starting startup scripts (version 3.5.1.0).
2017/07/25 07:01:33 Trying http://10.240.0.14: <nil>, Get http://10.240.0.14: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
2017/07/25 07:01:34 Trying http://10.240.0.14 ...
2017/07/25 07:01:36 SERIAL: 7/25/2017 7:01:36 AM UTC: Finished running startup scripts.
2017/07/25 07:01:39 Trying http://10.240.0.14: <nil>, Get http://10.240.0.14: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
2017/07/25 07:01:40 Trying http://10.240.0.14 ...
2017/07/25 07:01:45 Trying http://10.240.0.14: <nil>, Get http://10.240.0.14: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
2017/07/25 07:01:46 Trying http://10.240.0.14 ...
2017/07/25 07:01:51 Trying http://10.240.0.14: <nil>, Get http://10.240.0.14: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
2017/07/25 07:01:52 Trying http://10.240.0.14 ...
2017/07/25 07:01:57 Trying http://10.240.0.14: <nil>, Get http://10.240.0.14: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
2017/07/25 07:01:58 Trying http://10.240.0.14 ...
2017/07/25 07:02:03 Trying http://10.240.0.14: <nil>, Get http://10.240.0.14: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
2017/07/25 07:02:04 Trying http://10.240.0.14 ...
2017/07/25 07:02:09 Trying http://10.240.0.14: <nil>, Get http://10.240.0.14: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
2017/07/25 07:02:10 Trying http://10.240.0.14 ...
2017/07/25 07:02:15 Trying http://10.240.0.14: <nil>, Get http://10.240.0.14: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
2017/07/25 07:02:16 Trying http://10.240.0.14 ...
2017/07/25 07:02:21 Trying http://10.240.0.14: <nil>, Get http://10.240.0.14: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
2017/07/25 07:02:22 Trying http://10.240.0.14 ...
2017/07/25 07:02:22 Trying http://10.240.0.14: <nil>, Get http://10.240.0.14: dial tcp 10.240.0.14:80: getsockopt: connection refused
2017/07/25 07:02:23 Trying http://10.240.0.14 ...
2017/07/25 07:02:23 Trying http://10.240.0.14: <nil>, Get http://10.240.0.14: dial tcp 10.240.0.14:80: getsockopt: connection refused
2017/07/25 07:02:24 Trying http://10.240.0.14 ...
2017/07/25 07:02:24 Trying http://10.240.0.14: <nil>, Get http://10.240.0.14: dial tcp 10.240.0.14:80: getsockopt: connection refused
2017/07/25 07:02:25 Trying http://10.240.0.14 ...
2017/07/25 07:02:25 Trying http://10.240.0.14: <nil>, Get http://10.240.0.14: dial tcp 10.240.0.14:80: getsockopt: connection refused
2017/07/25 07:02:26 Trying http://10.240.0.14 ...
2017/07/25 07:02:26 Trying http://10.240.0.14: <nil>, Get http://10.240.0.14: dial tcp 10.240.0.14:80: getsockopt: connection refused
2017/07/25 07:02:27 Trying http://10.240.0.14 ...
2017/07/25 07:02:27 Trying http://10.240.0.14: <nil>, Get http://10.240.0.14: dial tcp 10.240.0.14:80: getsockopt: connection refused
2017/07/25 07:02:28 Trying http://10.240.0.14 ...
...
2017/07/25 07:04:51 Trying http://10.240.0.14 ...
2017/07/25 07:04:51 Trying http://10.240.0.14: <nil>, Get http://10.240.0.14: dial tcp 10.240.0.14:80: getsockopt: connection refused
2017/07/25 07:04:52 Trying http://10.240.0.14 ...
2017/07/25 07:04:52 Trying http://10.240.0.14: <nil>, Get http://10.240.0.14: dial tcp 10.240.0.14:80: getsockopt: connection refused
2017/07/25 07:04:53 Trying http://10.240.0.14 ...
2017/07/25 07:04:53 Trying http://10.240.0.14: <nil>, Get http://10.240.0.14: dial tcp 10.240.0.14:80: getsockopt: connection refused
2017/07/25 07:04:54 Trying http://10.240.0.14 ...
2017/07/25 07:04:54 Trying http://10.240.0.14: <nil>, Get http://10.240.0.14: dial tcp 10.240.0.14:80: getsockopt: connection refused
2017/07/25 07:04:55 Trying http://10.240.0.14 ...
2017/07/25 07:04:55 Trying http://10.240.0.14: <nil>, Get http://10.240.0.14: dial tcp 10.240.0.14:80: getsockopt: connection refused

[bradfitz]

Okay, I caught the weird case again:

Here the buildlet comes up and is listening at 07:06:19, but the TCP is dead & 10.240.0.22 doesn't ping until 07:07:08. We have outbound Internet 1 minute before inbound 10.* network!?

$ go install ./debugnewvm/ && debugnewvm -serial
2017/07/25 07:05:38 Creating debug-brad-windows-1500966338
2017/07/25 07:05:40 instance requested
2017/07/25 07:05:46 instance created
2017/07/25 07:05:46 got instance info
2017/07/25 07:05:46 Trying http://10.240.0.22 ...
2017/07/25 07:05:46 SERIAL: SeaBIOS (version 1.8.2-20170419_170401-google)
                            Total RAM Size = 0x00000000e6600000 = 3686 MiB
                            CPUs found: 4     Max CPUs supported: 4
                            found virtio-scsi at 0:3
                            virtio-scsi vendor='Google' product='PersistentDisk' rev='1' type=0 removable=0
                            virtio-scsi blksize=512 sectors=104857600 = 51200 MiB
                            drive 0x000f31a0: PCHS=0/0/0 translation=lba LCHS=1024/255/63 s=104857600
                            Booting from Hard Disk 0...
2017/07/25 07:05:51 Trying http://10.240.0.22: <nil>, Get http://10.240.0.22: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
2017/07/25 07:05:52 Trying http://10.240.0.22 ...
2017/07/25 07:05:54 SERIAL: 7/25/2017 7:05:53 AM UTC: GCE Agent started (version 3.5.1.0).
2017/07/25 07:05:55 SERIAL: 7/25/2017 7:05:55 AM UTC: Starting startup scripts (version 3.5.1.0).
2017/07/25 07:05:57 Trying http://10.240.0.22: <nil>, Get http://10.240.0.22: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
2017/07/25 07:05:58 Trying http://10.240.0.22 ...
2017/07/25 07:06:01 SERIAL: 7/25/2017 7:06:01 AM UTC: Finished running startup scripts.
2017/07/25 07:06:03 Trying http://10.240.0.22: <nil>, Get http://10.240.0.22: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
2017/07/25 07:06:04 Trying http://10.240.0.22 ...
2017/07/25 07:06:09 Trying http://10.240.0.22: <nil>, Get http://10.240.0.22: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
2017/07/25 07:06:10 Trying http://10.240.0.22 ...
2017/07/25 07:06:15 Trying http://10.240.0.22: <nil>, Get http://10.240.0.22: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
2017/07/25 07:06:16 Trying http://10.240.0.22 ...
2017/07/25 07:06:19 SERIAL: 2017/07/25 07:06:19 buildlet starting.
2017/07/25 07:06:19 Will listen on :80
2017/07/25 07:06:19 Listening on :80 ...
2017/07/25 07:06:21 Trying http://10.240.0.22: <nil>, Get http://10.240.0.22: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
2017/07/25 07:06:22 Trying http://10.240.0.22 ...
2017/07/25 07:06:27 Trying http://10.240.0.22: <nil>, Get http://10.240.0.22: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
2017/07/25 07:06:28 Trying http://10.240.0.22 ...
2017/07/25 07:06:33 Trying http://10.240.0.22: <nil>, Get http://10.240.0.22: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
2017/07/25 07:06:34 Trying http://10.240.0.22 ...
2017/07/25 07:06:39 Trying http://10.240.0.22: <nil>, Get http://10.240.0.22: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
2017/07/25 07:06:40 Trying http://10.240.0.22 ...
2017/07/25 07:06:45 Trying http://10.240.0.22: <nil>, Get http://10.240.0.22: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
2017/07/25 07:06:46 Trying http://10.240.0.22 ...
2017/07/25 07:06:51 Trying http://10.240.0.22: <nil>, Get http://10.240.0.22: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
2017/07/25 07:06:52 Trying http://10.240.0.22 ...
2017/07/25 07:06:57 Trying http://10.240.0.22: <nil>, Get http://10.240.0.22: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
^Z
[1]+  Stopped                 debugnewvm -serial
bradfitz@gdev:~/src/golang.org/x/build/cmd$ ping 10.240.0.22
PING 10.240.0.22 (10.240.0.22) 56(84) bytes of data.
(nothing)

But later:

2017/07/25 07:07:08 Trying http://10.240.0.22 ...
2017/07/25 07:07:08 Trying http://10.240.0.22: &{200 OK 200 HTTP/1.1 1 1 map[Date:[Tue, 25 Jul 2017 07:07:08 GMT] Content-Length:[34] Content-Type:[text/plain; charset=utf-8]] 0xc4203a04c0 34 [] true false map[] 0xc420275400 <nil>}, <nil>
2017/07/25 07:07:08 WorkDir: C:\workdir, <nil>
2017/07/25 07:07:08 done.
2017/07/25 07:07:09 SERIAL: 2017/07/25 07:07:08 Halting in 1 second.
2017/07/25 07:07:10 SERIAL: 2017/07/25 07:07:09 Halting machine.
2017/07/25 07:07:09 Shutdown: No system-specific halt command run; will just end buildlet process.
2017/07/25 07:07:09 Ending buildlet process post-halt

[bradfitz]

Here it's only 10 seconds from outbound network to inbound network:

2017/07/25 07:08:43 Creating debug-brad-windows-1500966523
2017/07/25 07:08:44 instance requested
2017/07/25 07:08:57 instance created
2017/07/25 07:08:57 got instance info
2017/07/25 07:08:57 Trying http://10.240.0.23 ...
2017/07/25 07:08:57 SERIAL: SeaBIOS (version 1.8.2-20170419_170401-google)
                            Total RAM Size = 0x00000000e6600000 = 3686 MiB
                            CPUs found: 4     Max CPUs supported: 4
                            found virtio-scsi at 0:3
                            virtio-scsi vendor='Google' product='PersistentDisk' rev='1' type=0 removable=0
                            virtio-scsi blksize=512 sectors=104857600 = 51200 MiB
                            drive 0x000f31a0: PCHS=0/0/0 translation=lba LCHS=1024/255/63 s=104857600
                            Booting from Hard Disk 0...
2017/07/25 07:09:02 Trying http://10.240.0.23: <nil>, Get http://10.240.0.23: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
2017/07/25 07:09:02 SERIAL: 7/25/2017 7:09:02 AM UTC: GCE Agent started (version 3.5.1.0).
2017/07/25 07:09:03 Trying http://10.240.0.23 ...
2017/07/25 07:09:04 SERIAL: 7/25/2017 7:09:04 AM UTC: Starting startup scripts (version 3.5.1.0).
2017/07/25 07:09:08 Trying http://10.240.0.23: <nil>, Get http://10.240.0.23: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
2017/07/25 07:09:09 Trying http://10.240.0.23 ...
2017/07/25 07:09:11 SERIAL: 7/25/2017 7:09:10 AM UTC: Finished running startup scripts.
2017/07/25 07:09:14 Trying http://10.240.0.23: <nil>, Get http://10.240.0.23: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
2017/07/25 07:09:15 Trying http://10.240.0.23 ...
2017/07/25 07:09:20 Trying http://10.240.0.23: <nil>, Get http://10.240.0.23: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
2017/07/25 07:09:21 Trying http://10.240.0.23 ...
2017/07/25 07:09:26 Trying http://10.240.0.23: <nil>, Get http://10.240.0.23: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
2017/07/25 07:09:27 Trying http://10.240.0.23 ...
2017/07/25 07:09:32 Trying http://10.240.0.23: <nil>, Get http://10.240.0.23: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
2017/07/25 07:09:33 Trying http://10.240.0.23 ...
2017/07/25 07:09:38 Trying http://10.240.0.23: <nil>, Get http://10.240.0.23: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
2017/07/25 07:09:39 Trying http://10.240.0.23 ...
2017/07/25 07:09:42 SERIAL: 2017/07/25 07:09:42 buildlet starting.
2017/07/25 07:09:42 Will listen on :80
2017/07/25 07:09:42 Listening on :80 ...
2017/07/25 07:09:44 Trying http://10.240.0.23: <nil>, Get http://10.240.0.23: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
2017/07/25 07:09:45 Trying http://10.240.0.23 ...
2017/07/25 07:09:50 Trying http://10.240.0.23: <nil>, Get http://10.240.0.23: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
2017/07/25 07:09:51 Trying http://10.240.0.23 ...
2017/07/25 07:09:54 Trying http://10.240.0.23: &{200 OK 200 HTTP/1.1 1 1 map[Date:[Tue, 25 Jul 2017 07:09:54 GMT] Content-Length:[34] Content-Type:[text/plain; charset=utf-8]] 0xc420383060 34 [] true false map[] 0xc420467800 <nil>}, <nil>
2017/07/25 07:09:54 WorkDir: C:\workdir, <nil>
2017/07/25 07:09:54 done.
2017/07/25 07:09:55 SERIAL: 2017/07/25 07:09:54 Halting in 1 second.
2017/07/25 07:09:56 SERIAL: 2017/07/25 07:09:55 Halting machine.
2017/07/25 07:09:55 Shutdown: No system-specific halt command run; will just end buildlet process.
2017/07/25 07:09:55 Ending buildlet process post-halt

[johnsonj]

In the delayed run it looks like the network isn't coming up for a while. GCE doesn't provide two NICs for the different IPs. The machine gets an internal IP and the external IP is an address that forwards to the machine. So it seems very strange that it could download the buildlet but not be pinged.

Could we add a write to serial port for stage0 or is that too heavy for stage0?

[bradfitz]

So it seems very strange that it could download the buildlet but not be pinged.

I guess there are networking fast paths from VMs to Google services like GCS, in that the routes are already known or something?

Could we add a write to serial port for stage0 or is that too heavy for stage0?

Great idea.

Before you rebuild the images, let me add that and also clean up the network-waiting code and make sure it's enabled for Windows.

[johnsonj]

SGTM!

[gopherbot]

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

[johnsonj]

@bradfitz I'm getting a panic on launching the new stage0:

fatal error: unexpected signal during runtime execution
[signal 0xc0000005 code=0x0 addr=0xffffffffffffffff pc=0x427c12]

runtime stack:
runtime.throw(0x695d84, 0x2a)
        /home/bradfitz/go/src/runtime/panic.go:605 +0x9c
runtime.sigpanic()
        /home/bradfitz/go/src/runtime/signal_windows.go:155 +0x184
runtime.netpoll(0xc042016000, 0x0)
        /home/bradfitz/go/src/runtime/netpoll_windows.go:105 +0x332
runtime.findrunnable(0xc042016000, 0x0)
        /home/bradfitz/go/src/runtime/proc.go:1966 +0x90f
runtime.schedule()
        /home/bradfitz/go/src/runtime/proc.go:2245 +0x13a
runtime.mstart1()
        /home/bradfitz/go/src/runtime/proc.go:1182 +0xcd
runtime.mstart()
        /home/bradfitz/go/src/runtime/proc.go:1142 +0x6b

goroutine 1 [runnable]:
net/http.(*Transport).RoundTrip(0xc0420f0000, 0xc0420f4100, 0xc0420f0000, 0xbe56
069a33e72c04, 0x13197476c)
        /home/bradfitz/go/src/net/http/transport.go:341 +0xf86
net/http.send(0xc0420f4000, 0x7aaac0, 0xc0420f0000, 0xbe56069a33e72c04, 0x131974
76c, 0x7e0260, 0xc04206a048, 0xbe56069a33e72c04, 0xc042067ac8, 0x1)
        /home/bradfitz/go/src/net/http/client.go:249 +0x1b0
net/http.(*Client).send(0xc0420748d0, 0xc0420f4000, 0xbe56069a33e72c04, 0x131974
76c, 0x7e0260, 0xc04206a048, 0x0, 0x1, 0xc042067b50)
        /home/bradfitz/go/src/net/http/client.go:173 +0x104
net/http.(*Client).Do(0xc0420748d0, 0xc0420f4000, 0x693570, 0x21, 0x0)
        /home/bradfitz/go/src/net/http/client.go:602 +0x294
net/http.(*Client).Get(0xc0420748d0, 0x693570, 0x21, 0xc04204a3e0, 0x48a76d, 0x5
977a2e3)
        /home/bradfitz/go/src/net/http/client.go:393 +0xae
main.isNetworkUp(0xbe560698f3e72c04)
        /home/bradfitz/src/golang.org/x/build/cmd/buildlet/stage0/stage0.go:204
+0xab
main.awaitNetwork(0x690700)
        /home/bradfitz/src/golang.org/x/build/cmd/buildlet/stage0/stage0.go:181
+0x16a
main.main()
        /home/bradfitz/src/golang.org/x/build/cmd/buildlet/stage0/stage0.go:82 +
0xd2

goroutine 19 [runnable]:
net/http.setRequestCancel.func3(0x0, 0xc0420749c0, 0xc0420482c0, 0xc04204c42c, 0
xc04203e240)
        /home/bradfitz/go/src/net/http/client.go:319
created by net/http.setRequestCancel
        /home/bradfitz/go/src/net/http/client.go:319 +0x2c6

C:\golang>

[bradfitz]

Well that's disturbing. Will look after my late lunch here.