diff options
| -rw-r--r-- | cloudinit/analyze/__main__.py | 88 | ||||
| -rw-r--r-- | cloudinit/analyze/show.py | 202 | ||||
| -rw-r--r-- | cloudinit/analyze/tests/test_boot.py | 170 | ||||
| -rw-r--r-- | doc/rtd/topics/analyze.rst | 84 | ||||
| -rw-r--r-- | doc/rtd/topics/capabilities.rst | 1 | ||||
| -rw-r--r-- | doc/rtd/topics/debugging.rst | 13 |
6 files changed, 546 insertions, 12 deletions
diff --git a/cloudinit/analyze/__main__.py b/cloudinit/analyze/__main__.py index f8613656..99e5c203 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 3e778b8b..511b808e 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 00000000..706e2cc0 --- /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 00000000..5cf38bd4 --- /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 0d8b8947..6d85a99c 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 51363ea5..e13d9151 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 --------------------------- |