[Bug 1629797] Re: cloud-init seems to take most of yakkety slow boot time
In yakkety, a "resolve" service has been added to the hosts line in nsswitch.conf[0]. Removing this service fixes the boot time issue. [0] http://paste.ubuntu.com/23269859/ is the diff of nsswitch.conf between xenial and yakkety. ** Also affects: systemd (Ubuntu) Importance: Undecided Status: New ** Changed in: cloud-init (Ubuntu) Status: New => Invalid ** Summary changed: - cloud-init seems to take most of yakkety slow boot time + resolve service in nsswitch.conf adds 25 seconds to failed lookups before systemd-resolved is up -- You received this bug notification because you are a member of Ubuntu Bugs, which is subscribed to Ubuntu. https://bugs.launchpad.net/bugs/1629797 Title: resolve service in nsswitch.conf adds 25 seconds to failed lookups before systemd-resolved is up To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu/+source/cloud-init/+bug/1629797/+subscriptions -- ubuntu-bugs mailing list ubuntu-bugs@lists.ubuntu.com https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
[Bug 1629797] Re: cloud-init seems to take most of yakkety slow boot time
LP cuts off the conclusions in my previous comment, which were: So it definitely looks like DNS resolution failure taking 25 seconds is A Thing (TM). It's also taking 25 seconds on both EC2 and GCE, which suggests the issue is somewhere in Ubuntu. It also is extremely unlikely to be that networking isn't up at all, because the successful check takes no time at all across several runs. -- You received this bug notification because you are a member of Ubuntu Bugs, which is subscribed to Ubuntu. https://bugs.launchpad.net/bugs/1629797 Title: cloud-init seems to take most of yakkety slow boot time To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu/+source/cloud-init/+bug/1629797/+subscriptions -- ubuntu-bugs mailing list ubuntu-bugs@lists.ubuntu.com https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
[Bug 1629797] Re: cloud-init seems to take most of yakkety slow boot time
The above log and tests were on EC2.
On GCE, an instrumented xenial gives:
Oct 03 09:40:43 xenial-161003-0956 cloud-init[1318]: [CLOUDINIT]
__init__.py[DEBUG]: Seeing if we can get any data from
Oct 03 09:40:43 xenial-161003-0956 cloud-init[1318]: [CLOUDINIT]
util.py[DEBUG]: Checking DNS redirection...
Oct 03 09:40:43 xenial-161003-0956 cloud-init[1318]: [CLOUDINIT]
util.py[DEBUG]: Trying does-not-exist.example.com
Oct 03 09:40:43 xenial-161003-0956 cloud-init[1318]: [CLOUDINIT]
util.py[DEBUG]: Not redirected
Oct 03 09:40:43 xenial-161003-0956 cloud-init[1318]: [CLOUDINIT]
util.py[DEBUG]: Trying example.invalid
Oct 03 09:40:43 xenial-161003-0956 cloud-init[1318]: [CLOUDINIT]
util.py[DEBUG]: Not redirected
Oct 03 09:40:43 xenial-161003-0956 cloud-init[1318]: [CLOUDINIT]
util.py[DEBUG]: Trying KgWv29ZuRsiJoFAGfGdwRj6To1L4b44q...
Oct 03 09:40:43 xenial-161003-0956 cloud-init[1318]: [CLOUDINIT]
util.py[DEBUG]: Not redirected
Oct 03 09:40:43 xenial-161003-0956 cloud-init[1318]: [CLOUDINIT]
util.py[DEBUG]: DNS redirection checking complete.
Oct 03 09:40:43 xenial-161003-0956 cloud-init[1318]: [CLOUDINIT]
util.py[DEBUG]: Doing actual check...
Oct 03 09:40:43 xenial-161003-0956 cloud-init[1318]: [CLOUDINIT]
util.py[DEBUG]: Actual check successful.
Oct 03 09:40:43 xenial-161003-0956 cloud-init[1318]: [CLOUDINIT]
url_helper.py[DEBUG]: [0/1] open
'http://metadata.google.internal/computeMetadata/v1/instance/id' with
{'method': 'GET', 'url': 'http://metadata.google.internal
Oct 03 09:40:43 xenial-161003-0956 cloud-init[1318]: [CLOUDINIT]
url_helper.py[DEBUG]: Read from
http://metadata.google.internal/computeMetadata/v1/instance/id (200, 19b) after
1 attempts
And an instrumented yakkety gives:
Oct 03 09:41:19 yakkety-161003-0945 cloud-init[1274]: [CLOUDINIT]
__init__.py[DEBUG]: Seeing if we can get any data from
Oct 03 09:41:19 yakkety-161003-0945 cloud-init[1274]: [CLOUDINIT]
util.py[DEBUG]: Checking DNS redirection...
Oct 03 09:41:19 yakkety-161003-0945 cloud-init[1274]: [CLOUDINIT]
util.py[DEBUG]: Trying does-not-exist.example.com
Oct 03 09:41:44 yakkety-161003-0945 cloud-init[1274]: [CLOUDINIT]
util.py[DEBUG]: Not redirected
Oct 03 09:41:44 yakkety-161003-0945 cloud-init[1274]: [CLOUDINIT]
util.py[DEBUG]: Trying example.invalid
Oct 03 09:42:10 yakkety-161003-0945 cloud-init[1274]: [CLOUDINIT]
util.py[DEBUG]: Not redirected
Oct 03 09:42:10 yakkety-161003-0945 cloud-init[1274]: [CLOUDINIT]
util.py[DEBUG]: Trying DLMcOj0Uix9neTVLk3ksle1KNUDrSz5p...
Oct 03 09:42:35 yakkety-161003-0945 cloud-init[1274]: [CLOUDINIT]
util.py[DEBUG]: Not redirected
Oct 03 09:42:35 yakkety-161003-0945 cloud-init[1274]: [CLOUDINIT]
util.py[DEBUG]: DNS redirection checking complete.
Oct 03 09:42:35 yakkety-161003-0945 cloud-init[1274]: [CLOUDINIT]
util.py[DEBUG]: Doing actual check...
Oct 03 09:42:35 yakkety-161003-0945 cloud-init[1274]: [CLOUDINIT]
util.py[DEBUG]: Actual check successful.
Oct 03 09:42:35 yakkety-161003-0945 cloud-init[1274]: [CLOUDINIT]
url_helper.py[DEBUG]: [0/1] open
'http://metadata.google.internal/computeMetadata/v1/instance/id' with {'url':
'http://metadata.google.internal/computeMetadata
Oct 03 09:42:35 yakkety-161003-0945 cloud-init[1274]: [CLOUDINIT]
url_helper.py[DEBUG]: Read from
http://metadata.google.internal/computeMetadata/v1/instance/id (200, 19b) after
1 attempts
So it definitely looks like DNS resolution failure taking 25 seconds is A Thing
(TM). It's also taking 25 seconds on both EC2 and GCE, which suggests the
issue is somewhere in Ubuntu. It also is extremely unlikely to be that
networking isn't up at all, because the successful check takes no time at all
across several runs.
--
You received this bug notification because you are a member of Ubuntu
Bugs, which is subscribed to Ubuntu.
https://bugs.launchpad.net/bugs/1629797
Title:
cloud-init seems to take most of yakkety slow boot time
To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/cloud-init/+bug/1629797/+subscriptions
--
ubuntu-bugs mailing list
ubuntu-bugs@lists.ubuntu.com
https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
[Bug 1629797] Re: cloud-init seems to take most of yakkety slow boot time
It is perhaps noteworthy that each failed resolution there appears to
take exactly 25 seconds. This would also explain the GCE boot time
being lower than EC2. Not only is the GCE resolution successful on GCE
(gaining 25 seconds) but the EC2 metadata source actually checks http
://instance-data.:8773 before http://169.254.169.254 which adds another
25 seconds for resolution failure. The second EC2 boot time and the GCE
boot time are almost exactly 50 seconds apart.
Once booted, resolution seems to take a sensible amount of time:
$ time python3 -c "import socket; socket.getaddrinfo('this.does.not.exist',
None)"
Traceback (most recent call last):
File "", line 1, in
File "/usr/lib/python3.5/socket.py", line 733, in getaddrinfo
for res in _socket.getaddrinfo(host, port, family, type, proto, flags):
socket.gaierror: [Errno -2] Name or service not known
real0m0.120s
user0m0.092s
sys 0m0.008s
$ time python3 -c "import socket; socket.getaddrinfo('thisdoesnotexist', None)"
Traceback (most recent call last):
File "", line 1, in
File "/usr/lib/python3.5/socket.py", line 733, in getaddrinfo
for res in _socket.getaddrinfo(host, port, family, type, proto, flags):
socket.gaierror: [Errno -2] Name or service not known
real0m0.887s
user0m0.092s
sys 0m0.012s
--
You received this bug notification because you are a member of Ubuntu
Bugs, which is subscribed to Ubuntu.
https://bugs.launchpad.net/bugs/1629797
Title:
cloud-init seems to take most of yakkety slow boot time
To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/cloud-init/+bug/1629797/+subscriptions
--
ubuntu-bugs mailing list
ubuntu-bugs@lists.ubuntu.com
https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
[Bug 1629797] Re: cloud-init seems to take most of yakkety slow boot time
OK, my instrumented code[0] produces this, which seems to confirm my hypothesis that DNS resolution is being weirdly slow: Oct 03 09:23:06 ip-172-31-3-216 cloud-init[1041]: [CLOUDINIT] __init__.py[DEBUG]: Seeing if we can get any data from Oct 03 09:23:06 ip-172-31-3-216 cloud-init[1041]: [CLOUDINIT] util.py[DEBUG]: Checking DNS redirection... Oct 03 09:23:06 ip-172-31-3-216 cloud-init[1041]: [CLOUDINIT] util.py[DEBUG]: Trying does-not-exist.example.com Oct 03 09:23:31 ip-172-31-3-216 cloud-init[1041]: [CLOUDINIT] util.py[DEBUG]: Not redirected Oct 03 09:23:31 ip-172-31-3-216 cloud-init[1041]: [CLOUDINIT] util.py[DEBUG]: Trying example.invalid Oct 03 09:23:56 ip-172-31-3-216 cloud-init[1041]: [CLOUDINIT] util.py[DEBUG]: Not redirected Oct 03 09:23:56 ip-172-31-3-216 cloud-init[1041]: [CLOUDINIT] util.py[DEBUG]: Trying X516ZAGxJofmtsCvbLA3bHeK2o2fcfVf... Oct 03 09:23:59 ip-172-31-3-216 systemd-timesyncd[669]: Synchronized to time server 91.189.89.198:123 (ntp.ubuntu.com). Oct 03 09:24:21 ip-172-31-3-216 cloud-init[1041]: [CLOUDINIT] util.py[DEBUG]: Not redirected Oct 03 09:24:21 ip-172-31-3-216 cloud-init[1041]: [CLOUDINIT] util.py[DEBUG]: DNS redirection checking complete. Oct 03 09:24:21 ip-172-31-3-216 cloud-init[1041]: [CLOUDINIT] util.py[DEBUG]: Doing actual check... Oct 03 09:24:46 ip-172-31-3-216 kernel: random: crng init done Oct 03 09:24:46 ip-172-31-3-216 cloud-init[1041]: [CLOUDINIT] util.py[DEBUG]: Actual check failed. Oct 03 09:24:46 ip-172-31-3-216 cloud-init[1041]: [CLOUDINIT] DataSourceGCE.py[DEBUG]: http://metadata.google.internal/computeMetadata/v1/ is not resolvable [0] http://paste.ubuntu.com/23269423/ is the relevant snippet of cloudinit.util. -- You received this bug notification because you are a member of Ubuntu Bugs, which is subscribed to Ubuntu. https://bugs.launchpad.net/bugs/1629797 Title: cloud-init seems to take most of yakkety slow boot time To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu/+source/cloud-init/+bug/1629797/+subscriptions -- ubuntu-bugs mailing list ubuntu-bugs@lists.ubuntu.com https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
[Bug 1629797] Re: cloud-init seems to take most of yakkety slow boot time
(This bug seems to reproduce on every boot (not just first boot), which at least makes debugging easier.) -- You received this bug notification because you are a member of Ubuntu Bugs, which is subscribed to Ubuntu. https://bugs.launchpad.net/bugs/1629797 Title: cloud-init seems to take most of yakkety slow boot time To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu/+source/cloud-init/+bug/1629797/+subscriptions -- ubuntu-bugs mailing list ubuntu-bugs@lists.ubuntu.com https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
[Bug 1629797] Re: cloud-init seems to take most of yakkety slow boot time
Pretty much all that happens between logging "Seeing if we can get any data from " in cloudinit.sources and "http://metadata.google.internal/computeMetadata/v1/ is not resolvable" in cloudinit.sources.DataSourceGCE is that we attempt to resolve that address. So, my first guess is that something weird is happening with DNS resolution; I'm going to attempt to add some logging to check this. -- You received this bug notification because you are a member of Ubuntu Bugs, which is subscribed to Ubuntu. https://bugs.launchpad.net/bugs/1629797 Title: cloud-init seems to take most of yakkety slow boot time To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu/+source/cloud-init/+bug/1629797/+subscriptions -- ubuntu-bugs mailing list ubuntu-bugs@lists.ubuntu.com https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
[Bug 1629797] Re: cloud-init seems to take most of yakkety slow boot time
For reference, a couple of EC2 image types give: Startup finished in 9.548s (kernel) + 2min 55.205s (userspace) = 3min 4.753s Startup finished in 6.911s (kernel) + 2min 21.522s (userspace) = 2min 28.434s And GCE gives: Startup finished in 6.661s (kernel) + 1min 30.434s (userspace) = 1min 37.095s (I had a GCE xenial instance handy, and it gives: Startup finished in 6.672s (kernel) + 15.855s (userspace) = 22.528s) ** Description changed: - Seems yakkety is consistently taking 2-3 minutes to boot on EC2, + Seems yakkety is consistently taking 2-3 minutes to boot on EC2 and GCE, compared to the ~30 seconds of the first boot and ~10 seconds thereafter in xenial. -- You received this bug notification because you are a member of Ubuntu Bugs, which is subscribed to Ubuntu. https://bugs.launchpad.net/bugs/1629797 Title: cloud-init seems to take most of yakkety slow boot time To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu/+source/cloud-init/+bug/1629797/+subscriptions -- ubuntu-bugs mailing list ubuntu-bugs@lists.ubuntu.com https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
[Bug 1629797] Re: cloud-init seems to take most of yakkety slow boot time
The really time-consuming part seems to be this on EC2:
Oct 03 08:45:10 ubuntu cloud-init[1015]: [CLOUDINIT] handlers.py[DEBUG]: start:
init-network/search-GCE: searching for network data from DataSourceGCE
Oct 03 08:45:10 ubuntu cloud-init[1015]: [CLOUDINIT] __init__.py[DEBUG]: Seeing
if we can get any data from
Oct 03 08:45:49 ubuntu systemd-timesyncd[671]: Synchronized to time server
91.189.89.199:123 (ntp.ubuntu.com).
Oct 03 08:46:02 ubuntu kernel: random: crng init done
Oct 03 08:46:50 ubuntu cloud-init[1015]: [CLOUDINIT] DataSourceGCE.py[DEBUG]:
http://metadata.google.internal/computeMetadata/v1/ is not resolvable
Oct 03 08:46:50 ubuntu cloud-init[1015]: [CLOUDINIT] handlers.py[DEBUG]:
finish: init-network/search-GCE: SUCCESS: no network data found from
DataSourceGCE
And, similarly, on GCE:
Oct 03 08:46:32 ubuntu cloud-init[1244]: [CLOUDINIT] handlers.py[DEBUG]: start:
init-network/search-GCE: searching for network data from DataSourceGCE
Oct 03 08:46:32 ubuntu cloud-init[1244]: [CLOUDINIT] __init__.py[DEBUG]: Seeing
if we can get any data from
Oct 03 08:47:47 ubuntu cloud-init[1244]: [CLOUDINIT] url_helper.py[DEBUG]:
[0/1] open 'http://metadata.google.internal/computeMetadata/v1/instance/id'
with {'method': 'GET', 'url':
'http://metadata.google.internal/computeMetadata/v1/instance/id',
'allow_redirects': True, 'headers': {'X-Google-Metadata-Request': 'True',
'User-Agent': 'Cloud-Init/0.7.8'}} configuration
--
You received this bug notification because you are a member of Ubuntu
Bugs, which is subscribed to Ubuntu.
https://bugs.launchpad.net/bugs/1629797
Title:
cloud-init seems to take most of yakkety slow boot time
To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/cloud-init/+bug/1629797/+subscriptions
--
ubuntu-bugs mailing list
ubuntu-bugs@lists.ubuntu.com
https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
[Bug 1629797] Re: cloud-init seems to take most of yakkety slow boot time
** Changed in: cloud-init (Ubuntu) Assignee: (unassigned) => Dan Watkins (daniel-thewatkins) -- You received this bug notification because you are a member of Ubuntu Bugs, which is subscribed to Ubuntu. https://bugs.launchpad.net/bugs/1629797 Title: cloud-init seems to take most of yakkety slow boot time To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu/+source/cloud-init/+bug/1629797/+subscriptions -- ubuntu-bugs mailing list ubuntu-bugs@lists.ubuntu.com https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
[Bug 1629797] Re: cloud-init seems to take most of yakkety slow boot time
Document with testing details ** Attachment added: "TestingyakketybootspeedregressionvsxenialinEC2.odt" https://bugs.launchpad.net/ubuntu/+source/cloud-init/+bug/1629797/+attachment/4753367/+files/TestingyakketybootspeedregressionvsxenialinEC2.odt -- You received this bug notification because you are a member of Ubuntu Bugs, which is subscribed to Ubuntu. https://bugs.launchpad.net/bugs/1629797 Title: cloud-init seems to take most of yakkety slow boot time To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu/+source/cloud-init/+bug/1629797/+subscriptions -- ubuntu-bugs mailing list ubuntu-bugs@lists.ubuntu.com https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
