Improve timer

cloudinit/atomic_helper.py

@@ -7,25 +7,33 @@
 import tempfile
 from base64 import b64decode, b64encode
 
-from cloudinit import util
+from cloudinit import performance, util
 
 _DEF_PERMS = 0o644
 LOG = logging.getLogger(__name__)
 
 
+@performance.timed("Base64 decoding")
 def b64d(source):
-    # Base64 decode some data, accepting bytes or unicode/str, and returning
-    # str/unicode if the result is utf-8 compatible, otherwise returning bytes.
+    """base64 decode data
+
+    :param source: a bytes or str to decode
+    :return: base64 as a decoded str if utf-8 encoded, otherwise bytes
+    """
     decoded = b64decode(source)
     try:
         return decoded.decode("utf-8")
     except UnicodeDecodeError:
         return decoded
 
 
+@performance.timed("Base64 encoding")
 def b64e(source):
-    # Base64 encode some data, accepting bytes or unicode/str, and returning
-    # str/unicode if the result is utf-8 compatible, otherwise returning bytes.
+    """base64 encode data
+
+    :param source: a bytes or str to decode
+    :return: base64 encoded str
+    """
     if not isinstance(source, bytes):
         source = source.encode("utf-8")
     return b64encode(source).decode("utf-8")
@@ -34,8 +42,15 @@ def b64e(source):
 def write_file(
     filename, content, mode=_DEF_PERMS, omode="wb", preserve_mode=False
 ):
-    # open filename in mode 'omode', write content, set permissions to 'mode'
+    """open filename in mode omode, write content, set permissions to mode"""
+
+    with performance.Timed(f"Writing {filename}"):
+        return _write_file(filename, content, mode, omode, preserve_mode)
 
+
+def _write_file(
+    filename, content, mode=_DEF_PERMS, omode="wb", preserve_mode=False
+):
     if preserve_mode:
         try:
             file_stat = os.stat(filename)
@@ -75,6 +90,7 @@ def json_serialize_default(_obj):
         return "Warning: redacted unserializable type {0}".format(type(_obj))
 
 
+@performance.timed("Dumping json")
 def json_dumps(data):
     """Return data in nicely formatted json."""
     return json.dumps(

cloudinit/cmd/clean.py

@@ -13,13 +13,13 @@
 
 from cloudinit import settings
 from cloudinit.distros import uses_systemd
+from cloudinit.log import log_util
 from cloudinit.net.netplan import CLOUDINIT_NETPLAN_FILE
 from cloudinit.stages import Init
 from cloudinit.subp import ProcessExecutionError, runparts, subp
 from cloudinit.util import (
     del_dir,
     del_file,
-    error,
     get_config_logfiles,
     is_link,
     write_file,
@@ -144,12 +144,12 @@ def remove_artifacts(init, remove_logs, remove_seed=False, remove_config=None):
             else:
                 del_file(path)
         except OSError as e:
-            error("Could not remove {0}: {1}".format(path, str(e)))
+            log_util.error("Could not remove {0}: {1}".format(path, str(e)))
             return 1
     try:
         runparts(settings.CLEAN_RUNPARTS_DIR)
     except Exception as e:
-        error(
+        log_util.error(
             f"Failure during run-parts of {settings.CLEAN_RUNPARTS_DIR}: {e}"
         )
         return 1
@@ -176,7 +176,7 @@ def handle_clean_args(name, args):
         try:
             subp(cmd, capture=False)
         except ProcessExecutionError as e:
-            error(
+            log_util.error(
                 'Could not reboot this system using "{0}": {1}'.format(
                     cmd, str(e)
                 )

cloudinit/cmd/cloud_id.py

@@ -10,8 +10,8 @@
 
 from cloudinit.cmd.devel import read_cfg_paths
 from cloudinit.cmd.status import RunningStatus, get_status_details
+from cloudinit.log import log_util
 from cloudinit.sources import METADATA_UNKNOWN, canonical_cloud_id
-from cloudinit.util import error
 
 NAME = "cloud-id"
 
@@ -77,12 +77,12 @@ def handle_args(name, args):
         with open(args.instance_data) as file:
             instance_data = json.load(file)
     except IOError:
-        return error(
+        return log_util.error(
             "File not found '%s'. Provide a path to instance data json file"
             " using --instance-data" % args.instance_data
         )
     except ValueError as e:
-        return error(
+        return log_util.error(
             "File '%s' is not valid json. %s" % (args.instance_data, e)
         )
     v1 = instance_data.get("v1", {})

cloudinit/cmd/devel/hotplug_hook.py

@@ -10,9 +10,10 @@
 import sys
 import time
 
-from cloudinit import log, reporting, stages, util
+from cloudinit import reporting, stages, util
 from cloudinit.config.cc_install_hotplug import install_hotplug
 from cloudinit.event import EventScope, EventType
+from cloudinit.log import loggers
 from cloudinit.net import read_sys_net_safe
 from cloudinit.net.network_state import parse_net_config_data
 from cloudinit.reporting import events
@@ -288,7 +289,7 @@ def handle_args(name, args):
     hotplug_init = Init(ds_deps=[], reporter=hotplug_reporter)
     hotplug_init.read_cfg()
 
-    log.setup_logging(hotplug_init.cfg)
+    loggers.setup_logging(hotplug_init.cfg)
     if "reporting" in hotplug_init.cfg:
         reporting.update_configuration(hotplug_init.cfg.get("reporting"))
     # Logging isn't going to be setup until now

cloudinit/cmd/devel/logs.py

@@ -17,13 +17,13 @@
 from datetime import datetime, timezone
 from typing import Any, Dict, Iterator, List, NamedTuple, Optional, cast
 
-from cloudinit import log
+from cloudinit.log import loggers
 from cloudinit.stages import Init
 from cloudinit.subp import ProcessExecutionError, subp
 from cloudinit.temp_utils import tempdir
 from cloudinit.util import copy, get_config_logfiles, write_file
 
-LOG = cast(log.CustomLoggerType, logging.getLogger(__name__))
+LOG = cast(loggers.CustomLoggerType, logging.getLogger(__name__))
 
 
 class ApportFile(NamedTuple):
@@ -378,13 +378,13 @@ def _setup_logger(verbosity: int) -> None:
     The verbosity controls which level gets printed to stderr. By default,
     DEBUG and TRACE are hidden.
     """
-    log.reset_logging()
+    loggers.reset_logging()
     if verbosity == 0:
         level = logging.INFO
     elif verbosity == 1:
         level = logging.DEBUG
     else:
-        level = log.TRACE
+        level = loggers.TRACE
     LOG.setLevel(level)
     handler = logging.StreamHandler()
     handler.setFormatter(logging.Formatter("%(message)s"))

cloudinit/cmd/devel/net_convert.py

@@ -10,7 +10,8 @@
 
 import yaml
 
-from cloudinit import distros, log, safeyaml
+from cloudinit import distros, safeyaml
+from cloudinit.log import loggers
 from cloudinit.net import (
     eni,
     netplan,
@@ -100,9 +101,9 @@ def handle_args(name, args):
         os.makedirs(args.directory)
 
     if args.debug:
-        log.setup_basic_logging(level=logging.DEBUG)
+        loggers.setup_basic_logging(level=logging.DEBUG)
     else:
-        log.setup_basic_logging(level=logging.WARN)
+        loggers.setup_basic_logging(level=logging.WARN)
     if args.mac:
         known_macs = {}
         for item in args.mac:

cloudinit/cmd/main.py

@@ -28,16 +28,17 @@
 from cloudinit import stages
 from cloudinit import url_helper
 from cloudinit import util
+from cloudinit import performance
 from cloudinit import version
 from cloudinit import warnings
 from cloudinit import reporting
 from cloudinit import atomic_helper
 from cloudinit import lifecycle
+from cloudinit.log import log_util, loggers
 from cloudinit.cmd.devel import read_cfg_paths
 from cloudinit.config import cc_set_hostname
 from cloudinit.config.modules import Modules
 from cloudinit.config.schema import validate_cloudconfig_schema
-from cloudinit import log
 from cloudinit.reporting import events
 from cloudinit.settings import (
     PER_INSTANCE,
@@ -115,7 +116,7 @@ def log_ppid(distro, bootstage_name):
 def welcome(action, msg=None):
     if not msg:
         msg = welcome_format(action)
-    util.multi_log("%s\n" % (msg), console=False, stderr=True, log=LOG)
+    log_util.multi_log("%s\n" % (msg), console=False, stderr=True, log=LOG)
     return msg
 
 
@@ -128,6 +129,7 @@ def welcome_format(action):
     )
 
 
+@performance.timed("Closing stdin")
 def close_stdin(logger: Callable[[str], None] = LOG.debug):
     """
     reopen stdin as /dev/null to ensure no side effects
@@ -310,7 +312,7 @@ def purge_cache_on_python_version_change(init):
         init.paths.get_cpath("data"), "python-version"
     )
     if os.path.exists(python_version_path):
-        cached_python_version = open(python_version_path).read()
+        cached_python_version = util.load_text_file(python_version_path)
         # The Python version has changed out from under us, anything that was
         # pickled previously is likely useless due to API changes.
         if cached_python_version != current_python_version:
@@ -383,9 +385,9 @@ def main_init(name, args):
         LOG.debug(
             "Logging being reset, this logger may no longer be active shortly"
         )
-        log.reset_logging()
+        loggers.reset_logging()
     if not args.skip_log_setup:
-        log.setup_logging(init.cfg)
+        loggers.setup_logging(init.cfg)
         apply_reporting_cfg(init.cfg)
 
     # Any log usage prior to setup_logging above did not have local user log
@@ -547,7 +549,7 @@ def main_init(name, args):
             (outfmt, errfmt) = util.fixup_output(mods.cfg, name)
     except Exception:
         util.logexc(LOG, "Failed to re-adjust output redirection!")
-    log.setup_logging(mods.cfg)
+    loggers.setup_logging(mods.cfg)
 
     # give the activated datasource a chance to adjust
     init.activate_datasource()
@@ -653,9 +655,9 @@ def main_modules(action_name, args):
         LOG.debug(
             "Logging being reset, this logger may no longer be active shortly"
         )
-        log.reset_logging()
+        loggers.reset_logging()
     if not args.skip_log_setup:
-        log.setup_logging(mods.cfg)
+        loggers.setup_logging(mods.cfg)
         apply_reporting_cfg(init.cfg)
 
     # now that logging is setup and stdout redirected, send welcome
@@ -723,8 +725,8 @@ def main_single(name, args):
         LOG.debug(
             "Logging being reset, this logger may no longer be active shortly"
         )
-        log.reset_logging()
-    log.setup_logging(mods.cfg)
+        loggers.reset_logging()
+    loggers.setup_logging(mods.cfg)
     apply_reporting_cfg(init.cfg)
 
     # now that logging is setup and stdout redirected, send welcome
@@ -817,7 +819,9 @@ def status_wrapper(name, args):
 
     v1[mode]["start"] = float(util.uptime())
     handler = next(
-        filter(lambda h: isinstance(h, log.LogExporter), root_logger.handlers)
+        filter(
+            lambda h: isinstance(h, loggers.LogExporter), root_logger.handlers
+        )
     )
     preexisting_recoverable_errors = handler.export_logs()
 
@@ -932,7 +936,7 @@ def main_features(name, args):
 
 
 def main(sysv_args=None):
-    log.configure_root_logger()
+    loggers.configure_root_logger()
     if not sysv_args:
         sysv_args = sys.argv
     parser = argparse.ArgumentParser(prog=sysv_args.pop(0))
@@ -1254,11 +1258,11 @@ def sub_main(args):
     #   - if --debug is passed, logging.DEBUG
     #   - if --debug is not passed, logging.WARNING
     if name not in ("init", "modules"):
-        log.setup_basic_logging(
+        loggers.setup_basic_logging(
             logging.DEBUG if args.debug else logging.WARNING
         )
     elif args.debug:
-        log.setup_basic_logging()
+        loggers.setup_basic_logging()
 
     # Setup signal handlers before running
     signal_handler.attach_handlers()
@@ -1300,13 +1304,8 @@ def sub_main(args):
     )
 
     with args.reporter:
-        retval = util.log_time(
-            logfunc=LOG.debug,
-            msg="cloud-init mode '%s'" % name,
-            get_uptime=True,
-            func=functor,
-            args=(name, args),
-        )
+        with performance.Timed(f"cloud-init stage: '{rname}'"):
+            retval = functor(name, args)
     reporting.flush_events()
 
     # handle return code for main_modules, as it is not wrapped by

cloudinit/config/cc_disk_setup.py

@@ -12,7 +12,7 @@
 import shlex
 from pathlib import Path
 
-from cloudinit import subp, util
+from cloudinit import performance, subp, util
 from cloudinit.cloud import Cloud
 from cloudinit.config import Config
 from cloudinit.config.schema import MetaSchema
@@ -51,13 +51,10 @@ def alias_to_device(cand):
                 continue
 
             try:
-                LOG.debug("Creating new partition table/disk")
-                util.log_time(
-                    logfunc=LOG.debug,
-                    msg="Creating partition on %s" % disk,
-                    func=mkpart,
-                    args=(disk, definition),
-                )
+                with performance.Timed(
+                    f"Creating partition on {disk}",
+                ):
+                    mkpart(disk, definition)
             except Exception as e:
                 util.logexc(LOG, "Failed partitioning operation\n%s" % e)
 
@@ -71,14 +68,8 @@ def alias_to_device(cand):
                 continue
 
             try:
-                LOG.debug("Creating new filesystem.")
-                device = definition.get("device")
-                util.log_time(
-                    logfunc=LOG.debug,
-                    msg="Creating fs for %s" % device,
-                    func=mkfs,
-                    args=(definition,),
-                )
+                with performance.Timed("Creating new filesystem"):
+                    mkfs(definition)
             except Exception as e:
                 util.logexc(LOG, "Failed during filesystem operation\n%s" % e)
 
@@ -983,7 +974,6 @@ def mkfs(fs_cfg):
         fs_cmd.append(device)
 
     LOG.debug("Creating file system %s on %s", label, device)
-    LOG.debug("     Using cmd: %s", str(fs_cmd))
     try:
         subp.subp(fs_cmd, shell=shell)
     except Exception as e: