Merge ~samgilson/cloud-init:cloud-init-analyze-boot into cloud-init:master

[Sam Gilson]

Cloud-init analyze module: Added ability to analyze boot events.

This branch introduces a new command line feature for cloud-init.
Currently, the cloud-init module has the capability to analyze events in
cloud-init.log in three ways: 'show', 'blame', 'dump'.
These changes add a fourth capability, called 'boot'.
Running the command 'cloud-init analyze boot' will provide the user three
timestamps.
1) Timestamp for when the kernel starts initializing.
2) Timestamp for when the kernel finishes its initialization.
3) Timestamp for when systemd activates cloud-init.
This feature enables cloud-init users to analyze different boot phases.
This would aid in debugging performance issues related
to cloud-init startup or tracking regression.

[Chad Smith (chad.smith)]

Thank you for this branch Sam and for making cloud-init better!

A couple of notes:
 1. ^M characters present throughout:
    - cloudinit/analyze/tests/test_boot.py
    - doc/rtd/topics/analyze.rst

 2. Timestamps don't seem to be reported properly in an lxc container for me: (note that the kernel ended boot time abd cloud-init start time is in the future on my system:

root@x1:~# cloud-init analyze boot
-- Most Recent Boot Record --
   Kernel Started at: 2019-06-24 20:24:25.527606
   Kernel ended boot at: 2019-06-27 18:53:04.667329
   Kernel time to boot (seconds): 253719.139722
   Cloud-init start: 2019-06-27 18:53:05.277550
   Time between Kernel boot and Cloud-init start (seconds): 0.610222

root@x1:~# date
Mon Jun 24 20:39:25 UTC 2019

 2. timestamp reported by cloud-init boot doesn't match timestamp in cloud-init logs
  on my system. This may lead to confusing errors because you

 cloud-init analyze boot
   Cloud-init start: 2019-06-21 21:56:24.461153

YET cloud-init does startup @ 21.56:08

grep "running 'init-local" /var/log/cloud-init.log | tail -n 1
2019-06-21 21:56:09,067 - util.py[DEBUG]: Cloud-init v. 18.5-59-gb05832a5-1~bddeb running 'init-local' at Fri, 21 Jun 2019 21:56:08 +0000. Up 5.00 seconds.

Maybe we should be using ActiveEnterTimestampMonotonic or ExecMainStartTimestampMonotonic to represesent on cloud-init-local starts it's datasource discovery?

I'll continue to try to triage what might give us a better handle on cloud-init start time

[Chad Smith (chad.smith)]

Marking needs information until we have an idea of how best to align cloud-init start time to something that aligns more with the timestamp in cloud-init logs.
Currently ActiveEnterTimestamp and InactiveExitTimestamp do show matching string values with the timestampl recoreded in cloud-init.log

# cloud-init.log

2019-06-24 20:24:25,463 - util.py[DEBUG]: Cloud-init v. 19.1-11-ge44586f2-1~bddeb running 'init-local' at Mon, 24 Jun 2019 20:24:25 +0000. Up 0.00 seconds.

# systemctl properties
root@x1:~# systemctl show -p ActiveEnterTimestamp cloud-init-local
ActiveEnterTimestamp=Mon 2019-06-24 20:24:25 UTC
root@x1:~# systemctl show -p InactiveExitTimestamp cloud-init-local
InactiveExitTimestamp=Mon 2019-06-24 20:24:25 UTC

So I think that maybe the timestamp arithmetic in the branch may be suspect

review: Needs Information

[Sam Gilson (samgilson)]

This is very interesting. I created an Ubuntu 18.04:latest VM on Azure and did the same checks as you, and here is what I got.
cat /var/log/cloud-init.log | grep "running 'init-local"
2019-06-24 18:59:34,735 - util.py[DEBUG]: Cloud-init v. 19.1-1-gbaa47854-0ubuntu1~18.04.1 running 'init-local' at Mon, 24 Jun 2019 18:59:34 +0000. Up 22.97 seconds.

systemctl show -p UserspaceTimestamp
UserspaceTimestamp=Mon 2019-06-24 18:59:22 UTC

systemctl show -p ExecMainStartTimestamp cloud-init-local
ExecMainStartTimestamp=Mon 2019-06-24 19:43:33 UTC

systemctl show -p ActiveEnterTimestamp cloud-init-local
ActiveEnterTimestamp=Mon 2019-06-24 19:43:33 UTC

systemctl show -p InactiveExitTimestamp cloud-init-local
InactiveExitTimestamp=Mon 2019-06-24 18:59:30 UTC

cloud-init analyze boot
-- Most Recent Boot Record --
   Kernel Started at: 2019-06-24 18:59:11.739511
   Kernel ended boot at: 2019-06-24 18:59:22.125180
   Kernel time to boot (seconds): 10.385669
   Cloud-init start: 2019-06-24 18:59:30.426426
   Time between Kernel boot and Cloud-init start (seconds): 8.301246

In my case, the InactiveExitTimestamp and the timestamp shown in cloud-init.log are the closest together (still not correct), with the ActiveEnter and ExecMainStart timestamps being very far off the mark. I am not really certain as to why the ActiveEnter and ExecMainStart are so far off in this case.

[Sam Gilson (samgilson)]

Keep in mind I had created this VM earlier in the day, hence why all the timestamps are so far off the current time.
> This is very interesting. I created an Ubuntu 18.04:latest VM on Azure and did
> the same checks as you, and here is what I got.
> cat /var/log/cloud-init.log | grep "running 'init-local"
> 2019-06-24 18:59:34,735 - util.py[DEBUG]: Cloud-init v.
> 19.1-1-gbaa47854-0ubuntu1~18.04.1 running 'init-local' at Mon, 24 Jun 2019
> 18:59:34 +0000. Up 22.97 seconds.
>
> systemctl show -p UserspaceTimestamp
> UserspaceTimestamp=Mon 2019-06-24 18:59:22 UTC
>
> systemctl show -p ExecMainStartTimestamp cloud-init-local
> ExecMainStartTimestamp=Mon 2019-06-24 19:43:33 UTC
>
> systemctl show -p ActiveEnterTimestamp cloud-init-local
> ActiveEnterTimestamp=Mon 2019-06-24 19:43:33 UTC
>
> systemctl show -p InactiveExitTimestamp cloud-init-local
> InactiveExitTimestamp=Mon 2019-06-24 18:59:30 UTC
>
> cloud-init analyze boot
> -- Most Recent Boot Record --
> Kernel Started at: 2019-06-24 18:59:11.739511
> Kernel ended boot at: 2019-06-24 18:59:22.125180
> Kernel time to boot (seconds): 10.385669
> Cloud-init start: 2019-06-24 18:59:30.426426
> Time between Kernel boot and Cloud-init start (seconds): 8.301246
>
> In my case, the InactiveExitTimestamp and the timestamp shown in cloud-
> init.log are the closest together (still not correct), with the ActiveEnter
> and ExecMainStart timestamps being very far off the mark. I am not really
> certain as to why the ActiveEnter and ExecMainStart are so far off in this
> case.

[Sam Gilson (samgilson)]

Hey Chad, in your first comment, what did you mean by "on my system"? I have been testing this on Ubuntu 18.04:latest and have found that on all the VMs I booted and tried, the cloud-init boot analyze is always consistently 4 seconds behind the cloud-init.log reported time. However, when checking the timestamps, it seems to be that ActiveEnter and ExecMainStart are consistently never correct, often off by several factors of 10. However in your test, it seems that InactiveExit and ActiveEnter are the same.

[Sam Gilson (samgilson)]

It seems that on Azure VMs that have been pre-provisioned, the ActiveEnter and ExecMainStart timestamps are incorrect due to the waiting that the pre-provisioning must do during the cloud-init-local phase of cloud-init in order to get the necessary data from Azure. Due to this, the more consistent time stamp is the InactiveExit timestamp, as it is written before any pre-provisioning occurs. However, InactiveExit is consistently 4 seconds off of the cloud-init.log timestamp.

However, when on a VM that has not been pre-provisioned, using ActiveEnter instead of InactiveExit always nets you the correct answer.

[Sam Gilson (samgilson)]

Hey Chad, thanks for all the great help in finding these bugs. I went back through and fixed all of the ones you found, so this MP is now ready for a re-review.

review: Needs Resubmitting

[Chad Smith (chad.smith)]

looks much better Sam, one suggestion inline to drop/adapt get_ci_start_from_log to use exinst event parsing from cloud-init.log

[Chad Smith (chad.smith)]

one more on some of the formatting success/failure too

[Sam Gilson (samgilson)]

Hey Chad, thank you for the reviews. I made all the changes you specified, specifically being dropping get_ci_start_from_log and replacing it with your inline comment, and changing the constant functions to formatted strings in analyze_boot. The previous two commits represent these changes, and this merge proposal is now ready for a re-review.

[Server Team CI bot (server-team-bot)]

FAILED: Continuous integration, rev:8e6d3c9f176e18cf60d3e3281d8f87334ce72417
https://jenkins.ubuntu.com/server/job/cloud-init-ci/766/
Executed test runs:
    SUCCESS: Checkout
    SUCCESS: Unit & Style Tests
    FAILED: Ubuntu LTS: Build

Click here to trigger a rebuild:
https://jenkins.ubuntu.com/server/job/cloud-init-ci/766/rebuild

review: Needs Fixing (continuous-integration)

[Server Team CI bot (server-team-bot)]

PASSED: Continuous integration, rev:8e6d3c9f176e18cf60d3e3281d8f87334ce72417
https://jenkins.ubuntu.com/server/job/cloud-init-ci/772/
Executed test runs:
    SUCCESS: Checkout
    SUCCESS: Unit & Style Tests
    SUCCESS: Ubuntu LTS: Build
    SUCCESS: Ubuntu LTS: Integration
    IN_PROGRESS: Declarative: Post Actions

Click here to trigger a rebuild:
https://jenkins.ubuntu.com/server/job/cloud-init-ci/772/rebuild

review: Approve (continuous-integration)

[Chad Smith (chad.smith)]

One final round of review commments from me on this.
here's a pastebin of the changes if you think it'll work:

1. I think we need to document that we are currently working around an lxc issue in this code
with a comment to pointing to https://github.com/lxc/lxcfs/issues/292

2. we probably shouldn't subshell with subp to stat a file, but use python's os.stat

here's a pastebin of the changes I suggest:
https://paste.ubuntu.com/p/TYbddMbVJ2/

[Chad Smith (chad.smith)]

This looks good to me. Will talk with other upstream devs on Monday to see if we have any concerns with including this in 19.2.

review: Approve

[Dan Watkins (oddbloke)]

I haven't done a full review (because I'm on a plane and about to be interrupted), but I did find some stylistic issues as well as perhaps some functional ones.

[Sam Gilson (samgilson)]

review: Approve

[Dan Watkins (oddbloke)]

Thanks Sam!

review: Approve

[Server Team CI bot (server-team-bot)]

Commit message lints:
 - Line #0 has 26 too many characters. Line starts with: "Cloud-init analyze module:"... - Line #2 has 264 too many characters. Line starts with: "This branch introduces"... - Line #6 has 139 too many characters. Line starts with: "This feature enables"...

review: Needs Fixing

[Server Team CI bot (server-team-bot)]

review: Approve (continuous-integration)

[Server Team CI bot (server-team-bot)]

Commit message lints:
 - Line #12 has 26 too many characters. Line starts with: "This would aid in debugging"...

review: Needs Fixing

[Server Team CI bot (server-team-bot)]

review: Approve (continuous-integration)

diff --git a/cloudinit/analyze/__main__.py b/cloudinit/analyze/__main__.py
index f861365..99e5c20 100644
--- a/cloudinit/analyze/__main__.py
+++ b/cloudinit/analyze/__main__.py
@@ -7,7 +7,7 @@ import re
 import sys
 
 from cloudinit.util import json_dumps
-
+from datetime import datetime
 from . import dump
 from . import show
 
@@ -52,9 +52,93 @@ def get_parser(parser=None):
                              dest='outfile', default='-',
                              help='specify where to write output. ')
     parser_dump.set_defaults(action=('dump', analyze_dump))
+    parser_boot = subparsers.add_parser(
+        'boot', help='Print list of boot times for kernel and cloud-init')
+    parser_boot.add_argument('-i', '--infile', action='store',
+                             dest='infile', default='/var/log/cloud-init.log',
+                             help='specify where to read input. ')
+    parser_boot.add_argument('-o', '--outfile', action='store',
+                             dest='outfile', default='-',
+                             help='specify where to write output.')
+    parser_boot.set_defaults(action=('boot', analyze_boot))
     return parser
 
 
+def analyze_boot(name, args):
+    """Report a list of how long different boot operations took.
+
+    For Example:
+    -- Most Recent Boot Record --
+        Kernel Started at: <time>
+        Kernel ended boot at: <time>
+        Kernel time to boot (seconds): <time>
+        Cloud-init activated by systemd at: <time>
+        Time between Kernel end boot and Cloud-init activation (seconds):<time>
+        Cloud-init start: <time>
+    """
+    infh, outfh = configure_io(args)
+    kernel_info = show.dist_check_timestamp()
+    status_code, kernel_start, kernel_end, ci_sysd_start = \
+        kernel_info
+    kernel_start_timestamp = datetime.utcfromtimestamp(kernel_start)
+    kernel_end_timestamp = datetime.utcfromtimestamp(kernel_end)
+    ci_sysd_start_timestamp = datetime.utcfromtimestamp(ci_sysd_start)
+    try:
+        last_init_local = \
+            [e for e in _get_events(infh) if e['name'] == 'init-local' and
+                'starting search' in e['description']][-1]
+        ci_start = datetime.utcfromtimestamp(last_init_local['timestamp'])
+    except IndexError:
+        ci_start = 'Could not find init-local log-line in cloud-init.log'
+        status_code = show.FAIL_CODE
+
+    FAILURE_MSG = 'Your Linux distro or container does not support this ' \
+                  'functionality.\n' \
+                  'You must be running a Kernel Telemetry supported ' \
+                  'distro.\nPlease check ' \
+                  'https://cloudinit.readthedocs.io/en/latest' \
+                  '/topics/analyze.html for more ' \
+                  'information on supported distros.\n'
+
+    SUCCESS_MSG = '-- Most Recent Boot Record --\n' \
+                  '    Kernel Started at: {k_s_t}\n' \
+                  '    Kernel ended boot at: {k_e_t}\n' \
+                  '    Kernel time to boot (seconds): {k_r}\n' \
+                  '    Cloud-init activated by systemd at: {ci_sysd_t}\n' \
+                  '    Time between Kernel end boot and Cloud-init ' \
+                  'activation (seconds): {bt_r}\n' \
+                  '    Cloud-init start: {ci_start}\n'
+
+    CONTAINER_MSG = '-- Most Recent Container Boot Record --\n' \
+                    '    Container started at: {k_s_t}\n' \
+                    '    Cloud-init activated by systemd at: {ci_sysd_t}\n' \
+                    '    Cloud-init start: {ci_start}\n' \
+
+    status_map = {
+        show.FAIL_CODE: FAILURE_MSG,
+        show.CONTAINER_CODE: CONTAINER_MSG,
+        show.SUCCESS_CODE: SUCCESS_MSG
+    }
+
+    kernel_runtime = kernel_end - kernel_start
+    between_process_runtime = ci_sysd_start - kernel_end
+
+    kwargs = {
+        'k_s_t': kernel_start_timestamp,
+        'k_e_t': kernel_end_timestamp,
+        'k_r': kernel_runtime,
+        'bt_r': between_process_runtime,
+        'k_e': kernel_end,
+        'k_s': kernel_start,
+        'ci_sysd': ci_sysd_start,
+        'ci_sysd_t': ci_sysd_start_timestamp,
+        'ci_start': ci_start
+    }
+
+    outfh.write(status_map[status_code].format(**kwargs))
+    return status_code
+
+
 def analyze_blame(name, args):
     """Report a list of records sorted by largest time delta.
 
@@ -119,7 +203,7 @@ def analyze_dump(name, args):
 
 def _get_events(infile):
     rawdata = None
-    events, rawdata = show.load_events(infile, None)
+    events, rawdata = show.load_events_infile(infile)
     if not events:
         events, _ = dump.dump_events(rawdata=rawdata)
     return events
diff --git a/cloudinit/analyze/show.py b/cloudinit/analyze/show.py
index 3e778b8..511b808 100644
--- a/cloudinit/analyze/show.py
+++ b/cloudinit/analyze/show.py
@@ -8,8 +8,11 @@ import base64
 import datetime
 import json
 import os
+import time
+import sys
 
 from cloudinit import util
+from cloudinit.distros import uses_systemd
 
 #  An event:
 '''
@@ -49,6 +52,10 @@ format_key = {
 
 formatting_help = " ".join(["{0}: {1}".format(k.replace('%', '%%'), v)
                            for k, v in format_key.items()])
+SUCCESS_CODE = 'successful'
+FAIL_CODE = 'failure'
+CONTAINER_CODE = 'container'
+TIMESTAMP_UNKNOWN = (FAIL_CODE, -1, -1, -1)
 
 
 def format_record(msg, event):
@@ -125,9 +132,175 @@ def total_time_record(total_time):
     return 'Total Time: %3.5f seconds\n' % total_time
 
 
+class SystemctlReader(object):
+    '''
+    Class for dealing with all systemctl subp calls in a consistent manner.
+    '''
+    def __init__(self, property, parameter=None):
+        self.epoch = None
+        self.args = ['/bin/systemctl', 'show']
+        if parameter:
+            self.args.append(parameter)
+        self.args.extend(['-p', property])
+        # Don't want the init of our object to break. Instead of throwing
+        # an exception, set an error code that gets checked when data is
+        # requested from the object
+        self.failure = self.subp()
+
+    def subp(self):
+        '''
+        Make a subp call based on set args and handle errors by setting
+        failure code
+
+        :return: whether the subp call failed or not
+        '''
+        try:
+            value, err = util.subp(self.args, capture=True)
+            if err:
+                return err
+            self.epoch = value
+            return None
+        except Exception as systemctl_fail:
+            return systemctl_fail
+
+    def parse_epoch_as_float(self):
+        '''
+        If subp call succeeded, return the timestamp from subp as a float.
+
+        :return: timestamp as a float
+        '''
+        # subp has 2 ways to fail: it either fails and throws an exception,
+        # or returns an error code. Raise an exception here in order to make
+        # sure both scenarios throw exceptions
+        if self.failure:
+            raise RuntimeError('Subprocess call to systemctl has failed, '
+                               'returning error code ({})'
+                               .format(self.failure))
+        # Output from systemctl show has the format Property=Value.
+        # For example, UserspaceMonotonic=1929304
+        timestamp = self.epoch.split('=')[1]
+        # Timestamps reported by systemctl are in microseconds, converting
+        return float(timestamp) / 1000000
+
+
+def dist_check_timestamp():
+    '''
+    Determine which init system a particular linux distro is using.
+    Each init system (systemd, upstart, etc) has a different way of
+    providing timestamps.
+
+    :return: timestamps of kernelboot, kernelendboot, and cloud-initstart
+    or TIMESTAMP_UNKNOWN if the timestamps cannot be retrieved.
+    '''
+
+    if uses_systemd():
+        return gather_timestamps_using_systemd()
+
+    # Use dmesg to get timestamps if the distro does not have systemd
+    if util.is_FreeBSD() or 'gentoo' in \
+            util.system_info()['system'].lower():
+        return gather_timestamps_using_dmesg()
+
+    # this distro doesn't fit anything that is supported by cloud-init. just
+    # return error codes
+    return TIMESTAMP_UNKNOWN
+
+
+def gather_timestamps_using_dmesg():
+    '''
+    Gather timestamps that corresponds to kernel begin initialization,
+    kernel finish initialization using dmesg as opposed to systemctl
+
+    :return: the two timestamps plus a dummy timestamp to keep consistency
+    with gather_timestamps_using_systemd
+    '''
+    try:
+        data, _ = util.subp(['dmesg'], capture=True)
+        split_entries = data[0].splitlines()
+        for i in split_entries:
+            if i.decode('UTF-8').find('user') != -1:
+                splitup = i.decode('UTF-8').split()
+                stripped = splitup[1].strip(']')
+
+                # kernel timestamp from dmesg is equal to 0,
+                # with the userspace timestamp relative to it.
+                user_space_timestamp = float(stripped)
+                kernel_start = float(time.time()) - float(util.uptime())
+                kernel_end = kernel_start + user_space_timestamp
+
+                # systemd wont start cloud-init in this case,
+                # so we cannot get that timestamp
+                return SUCCESS_CODE, kernel_start, kernel_end, \
+                    kernel_end
+
+    except Exception:
+        pass
+    return TIMESTAMP_UNKNOWN
+
+
+def gather_timestamps_using_systemd():
+    '''
+    Gather timestamps that corresponds to kernel begin initialization,
+    kernel finish initialization. and cloud-init systemd unit activation
+
+    :return: the three timestamps
+    '''
+    kernel_start = float(time.time()) - float(util.uptime())
+    try:
+        delta_k_end = SystemctlReader('UserspaceTimestampMonotonic')\
+            .parse_epoch_as_float()
+        delta_ci_s = SystemctlReader('InactiveExitTimestampMonotonic',
+                                     'cloud-init-local').parse_epoch_as_float()
+        base_time = kernel_start
+        status = SUCCESS_CODE
+        # lxc based containers do not set their monotonic zero point to be when
+        # the container starts, instead keep using host boot as zero point
+        # time.CLOCK_MONOTONIC_RAW is only available in python 3.3
+        if util.is_container():
+            # clock.monotonic also uses host boot as zero point
+            if sys.version_info >= (3, 3):
+                base_time = float(time.time()) - float(time.monotonic())
+                # TODO: lxcfs automatically truncates /proc/uptime to seconds
+                # in containers when https://github.com/lxc/lxcfs/issues/292
+                # is fixed, util.uptime() should be used instead of stat on
+                try:
+                    file_stat = os.stat('/proc/1/cmdline')
+                    kernel_start = file_stat.st_atime
+                except OSError as err:
+                    raise RuntimeError('Could not determine container boot '
+                                       'time from /proc/1/cmdline. ({})'
+                                       .format(err))
+                status = CONTAINER_CODE
+            else:
+                status = FAIL_CODE
+        kernel_end = base_time + delta_k_end
+        cloudinit_sysd = base_time + delta_ci_s
+
+    except Exception as e:
+        # Except ALL exceptions as Systemctl reader can throw many different
+        # errors, but any failure in systemctl means that timestamps cannot be
+        # obtained
+        print(e)
+        return TIMESTAMP_UNKNOWN
+    return status, kernel_start, kernel_end, cloudinit_sysd
+
+
 def generate_records(events, blame_sort=False,
                      print_format="(%n) %d seconds in %I%D",
                      dump_files=False, log_datafiles=False):
+    '''
+    Take in raw events and create parent-child dependencies between events
+    in order to order events in chronological order.
+
+    :param events: JSONs from dump that represents events taken from logs
+    :param blame_sort: whether to sort by timestamp or by time taken.
+    :param print_format: formatting to represent event, time stamp,
+    and time taken by the event in one line
+    :param dump_files: whether to dump files into JSONs
+    :param log_datafiles: whether or not to log events generated
+
+    :return: boot records ordered chronologically
+    '''
 
     sorted_events = sorted(events, key=lambda x: x['timestamp'])
     records = []
@@ -189,19 +362,28 @@ def generate_records(events, blame_sort=False,
 
 
 def show_events(events, print_format):
+    '''
+    A passthrough method that makes it easier to call generate_records()
+
+    :param events: JSONs from dump that represents events taken from logs
+    :param print_format: formatting to represent event, time stamp,
+    and time taken by the event in one line
+
+    :return: boot records ordered chronologically
+    '''
     return generate_records(events, print_format=print_format)
 
 
-def load_events(infile, rawdata=None):
-    if rawdata:
-        data = rawdata.read()
-    else:
-        data = infile.read()
+def load_events_infile(infile):
+    '''
+    Takes in a log file, read it, and convert to json.
+
+    :param infile: The Log file to be read
 
-    j = None
+    :return: json version of logfile, raw file
+    '''
+    data = infile.read()
     try:
-        j = json.loads(data)
+        return json.loads(data), data
     except ValueError:
-        pass
-
-    return j, data
+        return None, data
diff --git a/cloudinit/analyze/tests/test_boot.py b/cloudinit/analyze/tests/test_boot.py
new file mode 100644
index 0000000..706e2cc
--- /dev/null
+++ b/cloudinit/analyze/tests/test_boot.py
@@ -0,0 +1,170 @@
+import os
+from cloudinit.analyze.__main__ import (analyze_boot, get_parser)
+from cloudinit.tests.helpers import CiTestCase, mock
+from cloudinit.analyze.show import dist_check_timestamp, SystemctlReader, \
+    FAIL_CODE, CONTAINER_CODE
+
+err_code = (FAIL_CODE, -1, -1, -1)
+
+
+class TestDistroChecker(CiTestCase):
+
+    @mock.patch('cloudinit.util.system_info', return_value={'dist': ('', '',
+                                                                     ''),
+                                                            'system': ''})
+    @mock.patch('platform.linux_distribution', return_value=('', '', ''))
+    @mock.patch('cloudinit.util.is_FreeBSD', return_value=False)
+    def test_blank_distro(self, m_sys_info, m_linux_distribution, m_free_bsd):
+        self.assertEqual(err_code, dist_check_timestamp())
+
+    @mock.patch('cloudinit.util.system_info', return_value={'dist': ('', '',
+                                                                     '')})
+    @mock.patch('platform.linux_distribution', return_value=('', '', ''))
+    @mock.patch('cloudinit.util.is_FreeBSD', return_value=True)
+    def test_freebsd_gentoo_cant_find(self, m_sys_info,
+                                      m_linux_distribution, m_is_FreeBSD):
+        self.assertEqual(err_code, dist_check_timestamp())
+
+    @mock.patch('cloudinit.util.subp', return_value=(0, 1))
+    def test_subp_fails(self, m_subp):
+        self.assertEqual(err_code, dist_check_timestamp())
+
+
+class TestSystemCtlReader(CiTestCase):
+
+    def test_systemctl_invalid_property(self):
+        reader = SystemctlReader('dummyProperty')
+        with self.assertRaises(RuntimeError):
+            reader.parse_epoch_as_float()
+
+    def test_systemctl_invalid_parameter(self):
+        reader = SystemctlReader('dummyProperty', 'dummyParameter')
+        with self.assertRaises(RuntimeError):
+            reader.parse_epoch_as_float()
+
+    @mock.patch('cloudinit.util.subp', return_value=('U=1000000', None))
+    def test_systemctl_works_correctly_threshold(self, m_subp):
+        reader = SystemctlReader('dummyProperty', 'dummyParameter')
+        self.assertEqual(1.0, reader.parse_epoch_as_float())
+        thresh = 1.0 - reader.parse_epoch_as_float()
+        self.assertTrue(thresh < 1e-6)
+        self.assertTrue(thresh > (-1 * 1e-6))
+
+    @mock.patch('cloudinit.util.subp', return_value=('U=0', None))
+    def test_systemctl_succeed_zero(self, m_subp):
+        reader = SystemctlReader('dummyProperty', 'dummyParameter')
+        self.assertEqual(0.0, reader.parse_epoch_as_float())
+
+    @mock.patch('cloudinit.util.subp', return_value=('U=1', None))
+    def test_systemctl_succeed_distinct(self, m_subp):
+        reader = SystemctlReader('dummyProperty', 'dummyParameter')
+        val1 = reader.parse_epoch_as_float()
+        m_subp.return_value = ('U=2', None)
+        reader2 = SystemctlReader('dummyProperty', 'dummyParameter')
+        val2 = reader2.parse_epoch_as_float()
+        self.assertNotEqual(val1, val2)
+
+    @mock.patch('cloudinit.util.subp', return_value=('100', None))
+    def test_systemctl_epoch_not_splittable(self, m_subp):
+        reader = SystemctlReader('dummyProperty', 'dummyParameter')
+        with self.assertRaises(IndexError):
+            reader.parse_epoch_as_float()
+
+    @mock.patch('cloudinit.util.subp', return_value=('U=foobar', None))
+    def test_systemctl_cannot_convert_epoch_to_float(self, m_subp):
+        reader = SystemctlReader('dummyProperty', 'dummyParameter')
+        with self.assertRaises(ValueError):
+            reader.parse_epoch_as_float()
+
+
+class TestAnalyzeBoot(CiTestCase):
+
+    def set_up_dummy_file_ci(self, path, log_path):
+        infh = open(path, 'w+')
+        infh.write('2019-07-08 17:40:49,601 - util.py[DEBUG]: Cloud-init v. '
+                   '19.1-1-gbaa47854-0ubuntu1~18.04.1 running \'init-local\' '
+                   'at Mon, 08 Jul 2019 17:40:49 +0000. Up 18.84 seconds.')
+        infh.close()
+        outfh = open(log_path, 'w+')
+        outfh.close()
+
+    def set_up_dummy_file(self, path, log_path):
+        infh = open(path, 'w+')
+        infh.write('dummy data')
+        infh.close()
+        outfh = open(log_path, 'w+')
+        outfh.close()
+
+    def remove_dummy_file(self, path, log_path):
+        if os.path.isfile(path):
+            os.remove(path)
+        if os.path.isfile(log_path):
+            os.remove(log_path)
+
+    @mock.patch('cloudinit.analyze.show.dist_check_timestamp',
+                return_value=err_code)
+    def test_boot_invalid_distro(self, m_dist_check_timestamp):
+
+        path = os.path.dirname(os.path.abspath(__file__))
+        log_path = path + '/boot-test.log'
+        path += '/dummy.log'
+        self.set_up_dummy_file(path, log_path)
+
+        parser = get_parser()
+        args = parser.parse_args(args=['boot', '-i', path, '-o',
+                                       log_path])
+        name_default = ''
+        analyze_boot(name_default, args)
+        # now args have been tested, go into outfile and make sure error
+        # message is in the outfile
+        outfh = open(args.outfile, 'r')
+        data = outfh.read()
+        err_string = 'Your Linux distro or container does not support this ' \
+                     'functionality.\nYou must be running a Kernel ' \
+                     'Telemetry supported distro.\nPlease check ' \
+                     'https://cloudinit.readthedocs.io/en/latest/topics' \
+                     '/analyze.html for more information on supported ' \
+                     'distros.\n'
+
+        self.remove_dummy_file(path, log_path)
+        self.assertEqual(err_string, data)
+
+    @mock.patch("cloudinit.util.is_container", return_value=True)
+    @mock.patch('cloudinit.util.subp', return_value=('U=1000000', None))
+    def test_container_no_ci_log_line(self, m_is_container, m_subp):
+        path = os.path.dirname(os.path.abspath(__file__))
+        log_path = path + '/boot-test.log'
+        path += '/dummy.log'
+        self.set_up_dummy_file(path, log_path)
+
+        parser = get_parser()
+        args = parser.parse_args(args=['boot', '-i', path, '-o',
+                                       log_path])
+        name_default = ''
+
+        finish_code = analyze_boot(name_default, args)
+
+        self.remove_dummy_file(path, log_path)
+        self.assertEqual(FAIL_CODE, finish_code)
+
+    @mock.patch("cloudinit.util.is_container", return_value=True)
+    @mock.patch('cloudinit.util.subp', return_value=('U=1000000', None))
+    @mock.patch('cloudinit.analyze.__main__._get_events', return_value=[{
+        'name': 'init-local', 'description': 'starting search', 'timestamp':
+        100000}])
+    @mock.patch('cloudinit.analyze.show.dist_check_timestamp',
+                return_value=(CONTAINER_CODE, 1, 1, 1))
+    def test_container_ci_log_line(self, m_is_container, m_subp, m_get, m_g):
+        path = os.path.dirname(os.path.abspath(__file__))
+        log_path = path + '/boot-test.log'
+        path += '/dummy.log'
+        self.set_up_dummy_file_ci(path, log_path)
+
+        parser = get_parser()
+        args = parser.parse_args(args=['boot', '-i', path, '-o',
+                                       log_path])
+        name_default = ''
+        finish_code = analyze_boot(name_default, args)
+
+        self.remove_dummy_file(path, log_path)
+        self.assertEqual(CONTAINER_CODE, finish_code)
diff --git a/doc/rtd/topics/analyze.rst b/doc/rtd/topics/analyze.rst
new file mode 100644
index 0000000..5cf38bd
--- /dev/null
+++ b/doc/rtd/topics/analyze.rst
@@ -0,0 +1,84 @@
+*************************
+Cloud-init Analyze Module
+*************************
+
+Overview
+========
+The analyze module was added to cloud-init in order to help analyze cloud-init boot time 
+performance. It is loosely based on systemd-analyze where there are 4 main actions: 
+show, blame, dump, and boot.
+
+The 'show' action is similar to 'systemd-analyze critical-chain' which prints a list of units, the 
+time they started and how long they took. For cloud-init, we have four stages, and within each stage
+a number of modules may run depending on configuration.  ‘cloudinit-analyze show’ will, for each 
+boot, print this information and a summary total time, per boot.
+
+The 'blame' action matches 'systemd-analyze blame' where it prints, in descending order, 
+the units that took the longest to run.  This output is highly useful for examining where cloud-init 
+is spending its time during execution.
+
+The 'dump' action simply dumps the cloud-init logs that the analyze module is performing
+the analysis on and returns a list of dictionaries that can be consumed for other reporting needs.
+
+The 'boot' action prints out kernel related timestamps that are not included in any of the
+cloud-init logs. There are three different timestamps that are presented to the user: 
+kernel start, kernel finish boot, and cloud-init start. This was added for additional
+clarity into the boot process that cloud-init does not have control over, to aid in debugging of 
+performance issues related to cloudinit startup or tracking regression.
+
+Usage
+=====
+Using each of the printing formats is as easy as running one of the following bash commands:
+
+.. code-block:: shell-session
+
+  cloud-init analyze show
+  cloud-init analyze blame
+  cloud-init analyze dump
+  cloud-init analyze boot
+
+Cloud-init analyze boot Timestamp Gathering
+===========================================
+The following boot related timestamps are gathered on demand when cloud-init analyze boot runs:
+- Kernel Startup, which is inferred from system uptime
+- Kernel Finishes Initialization, which is inferred from systemd UserSpaceMonotonicTimestamp property
+- Cloud-init activation, which is inferred from the property InactiveExitTimestamp of the cloud-init
+local systemd unit.
+
+In order to gather the necessary timestamps using systemd, running the commands
+
+.. code-block:: shell-session
+
+	systemctl show -p UserspaceTimestampMonotonic  
+	systemctl show cloud-init-local -p InactiveExitTimestampMonotonic
+
+will gather the UserspaceTimestamp and InactiveExitTimestamp. 
+The UserspaceTimestamp tracks when the init system starts, which is used as an indicator of kernel
+finishing initialization. The InactiveExitTimestamp tracks when a particular systemd unit transitions
+from the Inactive to Active state, which can be used to mark the beginning of systemd's activation
+of cloud-init.
+
+Currently this only works for distros that use systemd as the init process. We will be expanding
+support for other distros in the future and this document will be updated accordingly.
+
+If systemd is not present on the system, dmesg is used to attempt to find an event that logs the
+beginning of the init system. However, with this method only the first two timestamps are able to be found;
+dmesg does not monitor userspace processes, so no cloud-init start timestamps are emitted like when
+using systemd.
+
+List of Cloud-init analyze boot supported distros
+=================================================
+- Arch
+- CentOS
+- Debian
+- Fedora
+- OpenSuSE
+- Red Hat Enterprise Linux
+- Ubuntu
+- SUSE Linux Enterprise Server
+- CoreOS
+
+List of Cloud-init analyze boot unsupported distros
+===================================================
+- FreeBSD
+- Gentoo
\ No newline at end of file
diff --git a/doc/rtd/topics/capabilities.rst b/doc/rtd/topics/capabilities.rst
index 0d8b894..6d85a99 100644
--- a/doc/rtd/topics/capabilities.rst
+++ b/doc/rtd/topics/capabilities.rst
@@ -217,6 +217,7 @@ Get detailed reports of where cloud-init spends most of its time. See
 * **dump** Machine-readable JSON dump of all cloud-init tracked events.
 * **show** show time-ordered report of the cost of operations during each
   boot stage.
+* **boot** show timestamps from kernel initialization, kernel finish initialization, and cloud-init start.
 
 .. _cli_devel:
 
diff --git a/doc/rtd/topics/debugging.rst b/doc/rtd/topics/debugging.rst
index 51363ea..e13d915 100644
--- a/doc/rtd/topics/debugging.rst
+++ b/doc/rtd/topics/debugging.rst
@@ -68,6 +68,19 @@ subcommands default to reading /var/log/cloud-init.log.
          00.00100s (modules-final/config-rightscale_userdata)
          ...
 
+* ``analyze boot`` Make subprocess calls to the kernel in order to get relevant 
+  pre-cloud-init timestamps, such as the kernel start, kernel finish boot, and cloud-init start.
+
+.. code-block:: shell-session
+
+    $ cloud-init analyze boot 
+    -- Most Recent Boot Record --
+    	Kernel Started at: 2019-06-13 15:59:55.809385
+    	Kernel ended boot at: 2019-06-13 16:00:00.944740
+    	Kernel time to boot (seconds): 5.135355
+    	Cloud-init start: 2019-06-13 16:00:05.738396
+    	Time between Kernel boot and Cloud-init start (seconds): 4.793656
+
 
 Analyze quickstart - LXC
 ---------------------------