Add reporting events and log_time around early source of blocking time

In looking at some boot time for Xenial, Artful and Bionic, we noticed
some long amounts of time that appeared to be part of the DataSource but
we related to resolving URLs. In Artful and Bionic, there was an issue
(bug: #1739672) that resulted in slow getaddrinfo() calls when
systemd-resolved was in use. This patch adds two events that track time
for datasource.setup_datasource() and datasource.activate_datasource()
Additionally use log_time() to wrapper util.is_resolvable_url() which
leaves info in cloud-init.log about how much time was spent.

2 files changed, 17 insertions, 9 deletions

diff --git a/cloudinit/stages.py b/cloudinit/stages.py
index bc4ebc85..3998cf68 100644
--- a/cloudinit/stages.py
+++ b/cloudinit/stages.py
@@ -362,16 +362,22 @@ class Init(object):
         self._store_vendordata()
 
     def setup_datasource(self):
-        if self.datasource is None:
-            raise RuntimeError("Datasource is None, cannot setup.")
-        self.datasource.setup(is_new_instance=self.is_new_instance())
+        with events.ReportEventStack("setup-datasource",
+                                     "setting up datasource",
+                                     parent=self.reporter):
+            if self.datasource is None:
+                raise RuntimeError("Datasource is None, cannot setup.")
+            self.datasource.setup(is_new_instance=self.is_new_instance())
 
     def activate_datasource(self):
-        if self.datasource is None:
-            raise RuntimeError("Datasource is None, cannot activate.")
-        self.datasource.activate(cfg=self.cfg,
-                                 is_new_instance=self.is_new_instance())
-        self._write_to_cache()
+        with events.ReportEventStack("activate-datasource",
+                                     "activating datasource",
+                                     parent=self.reporter):
+            if self.datasource is None:
+                raise RuntimeError("Datasource is None, cannot activate.")
+            self.datasource.activate(cfg=self.cfg,
+                                     is_new_instance=self.is_new_instance())
+            self._write_to_cache()
 
     def _store_userdata(self):
         raw_ud = self.datasource.get_userdata_raw()
diff --git a/cloudinit/util.py b/cloudinit/util.py
index 2828ca38..fc30018c 100644
--- a/cloudinit/util.py
+++ b/cloudinit/util.py
@@ -1154,7 +1154,9 @@ def gethostbyaddr(ip):
 
 def is_resolvable_url(url):
     """determine if this url is resolvable (existing or ip)."""
-    return is_resolvable(urlparse.urlparse(url).hostname)
+    return log_time(logfunc=LOG.debug, msg="Resolving URL: " + url,
+                    func=is_resolvable,
+                    args=(urlparse.urlparse(url).hostname,))
 
 
 def search_for_mirror(candidates):