Improve timer #5672

holmanb · 2024-09-06T03:56:01Z

Note to reviewers

This looks big, but it is broken into three logically separate changes. I would recommend reviewing a commit at a time.

Motivation

The recent addition of subp execution time was a huge benefit to exposing slow external commands. As we try to push performance more, more data is vital to making the biggest impact that we can. Comparing this branch against the tip of main, this change makes the total log size 1 line longer - but this will vary depending per-platform.

builtin timing instrumentation in production allows diagnosing everywhere we can get a log
reduce noise by only logging slow events
avoid the need for manual instrumentation
cloud-init analyze is neat, but it is low granularity, relies log timestamps (so is only an approximation), and it requires extra steps
standardize logging to in shared code

Description of changes

Improve on the existing timer helper by simplifying its usage and implementation
Remove obsolete functionality in the existing timer function
Eliminate irrelevant logs by only logging if a threshold is exceeded.
Update existing callsites to use context manager
Refactor logging helpers out of util.py
Replace duplicate timer implementations with timer helper
- socket.py
- subp.py
Add timer helper to shared callsites
- DataSource.get_data()
- each cloud-config module

Todo

fix unittests
bikeshed the name (I originally implemented the context handler as a function, but now it's a class so it's suddenly un-pythonic)

Merge type

Squash merge using "Proposed Commit Message"
Rebase and merge unique commits. Requires commit messages per-commit each referencing the pull request number (#<PR_NUM>)

TheRealFalcon

Thanks for this! Overall a really good change. I left some comments inline.

cloudinit/log/__init__.py

cloudinit/log/log_util.py

cloudinit/sources/DataSourceEc2.py

cloudinit/ssh_util.py

tests/unittests/config/test_cc_package_update_upgrade_install.py

TheRealFalcon · 2024-09-09T19:53:12Z

tests/unittests/config/test_cc_ubuntu_pro.py

            assert should_auto_attach_value == _should_auto_attach(ua_section)
-            assert (


Hmmm...I think this highlights a gap in functionality where we might wind up losing valuable logging messages that no longer take as much time to execute. Looking at the Pro module now, there's now no log anywhere to indicate that we're attempting to attach to Pro unless it is taking too long, and I'm assuming that's not what we want. I'm not sure I have a great solution other than looking through all of the changed call sites and using a threshold of 0 for those we think we want to log regardless of the time taken.

Good point. I reworked the context manager to support a parameter called log_mode, with three options: "always", "threshold", and "skip" (default is "threshold"). I audited the modified callsites and set "always" to those that I think need it. Let me know if there are any others that you think should also be modified.

The logic in Timed() has defaults which are designed to avoid low-value log messages. A log is only emitted when the threshold is exceeded. Additionally, the log_mode parameter allows the caller to prevent Timed() logs, so that the caller may coalesce the message into another log. - Make timer helper into a context manager. - Add new decorator for timing functions. - Simplify timer helper function, eliminate obsolete logic. - Eliminate redundant logs and timer calls.

refactors existing code to utilize timer codepaths: - replace manual timer implementations in subp.py and sockets.py - replace open() / read() calls with util.load_text_file() where appropriate

holmanb · 2024-09-19T22:53:20Z

@TheRealFalcon thanks for the review. I think that I've addressed all of your comments. Ready for re-review.

TheRealFalcon

I left a few more comments, but everything is mostly minor.

I really like the new decorator.

TheRealFalcon · 2024-09-20T14:22:26Z

cloudinit/cmd/main.py

@@ -1273,15 +1277,15 @@ def sub_main(args):
    report_on = True
    if name == "init":
        if args.local:
-            rname, rdesc = ("init-local", "searching for local datasources")
+            rname, rdesc = ("local", "searching for local datasources")


What's the impetus for these next 3 changes? Their replacements are less greppable, the first log message of each stage still uses the original name, and we have other tons of references to the original names all over the code base. I would prefer to keep the originals.

TheRealFalcon · 2024-09-20T14:26:13Z

cloudinit/cmd/main.py

-            args=(name, args),
-        )
+        with performance.Timed(f"cloud-init stage: '{rname}'"):
+            retval = functor(name, args)


get_uptime was kind of an odd kwarg to have in the old function, and it looks like here is the only place it was used. I'm not sure if/how it was useful, but do you think it makes sense to throw an uptime log as early as possible in init-local as a replacement?

TheRealFalcon · 2024-09-20T16:00:52Z

cloudinit/config/cc_resizefs.py

-            msg="backgrounded Resizing",
-            func=do_resize,
-            args=(resize_cmd,),
+            do_resize,


Is the removal here intentional?

TheRealFalcon · 2024-09-20T16:05:50Z

cloudinit/performance.py

+    def __init__(
+        self,
+        msg: str,
+        /,


Is there a good reason to enforce this?

TheRealFalcon · 2024-09-20T16:12:40Z

cloudinit/config/modules.py

-                        run_name, mod.handle, func_args, freq=freq
-                    )
+
+                    with performance.Timed("and", log_mode="skip") as timer:


This still feels a bit hard to understand at first. What do you think about having this message be "" and then later f"{run_name} ran successfully and took {timer.delta:.3f} seconds"?

Not a blocking comment if you prefer it as-is.

TheRealFalcon · 2024-09-20T18:03:46Z

cloudinit/atomic_helper.py

-    # 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}"):


Can the decorator be used here now instead?

TheRealFalcon · 2024-09-20T18:05:00Z

cloudinit/safeyaml.py

-        default_flow_style=False,
-        Dumper=(NoAliasSafeDumper if noalias else yaml.dumper.SafeDumper),
-    )
+    with performance.Timed("Dumping yaml"):


Can the new decorator work here?

TheRealFalcon · 2024-09-20T18:14:51Z

cloudinit/sources/__init__.py

@@ -475,6 +483,7 @@ def clear_cached_attrs(self, attr_defaults=()):
        if not attr_defaults:
            self._dirty_cache = False

+    @performance.timed("Getting metadata")


This should probably log always

TheRealFalcon · 2024-09-20T18:17:13Z

cloudinit/performance.py

+        /,
+        *,
+        threshold: float = 0.01,
+        log_mode: str = "threshold",


I don't love this parameter being a magic string, especially when it only takes two values. Is there a reason setting threshold to 0 isn't a valid way to signal to log always? If so, could this field be a boolean like always_log: bool = False or something similar?

holmanb force-pushed the holmanb/timer branch 4 times, most recently from 3169a13 to 86daea4 Compare September 7, 2024 00:08

holmanb marked this pull request as ready for review September 7, 2024 00:25

TheRealFalcon self-assigned this Sep 9, 2024

TheRealFalcon requested changes Sep 9, 2024

View reviewed changes

holmanb mentioned this pull request Sep 18, 2024

chore: clean up old pickle workaround #5714

Merged

2 tasks

holmanb force-pushed the holmanb/timer branch 4 times, most recently from dfa55df to 446fee4 Compare September 19, 2024 18:07

holmanb added 3 commits September 19, 2024 13:33

chore: add timer to io and string manipulation code

92ecf58

refactors existing code to utilize timer codepaths: - replace manual timer implementations in subp.py and sockets.py - replace open() / read() calls with util.load_text_file() where appropriate

chore: use stage name in cloud-init log for better clarity

aeec429

holmanb force-pushed the holmanb/timer branch from 446fee4 to aeec429 Compare September 19, 2024 20:33

holmanb requested a review from TheRealFalcon September 19, 2024 22:52

TheRealFalcon requested changes Sep 20, 2024

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Improve timer #5672

Improve timer #5672

holmanb commented Sep 6, 2024 •

edited

Loading

TheRealFalcon left a comment

TheRealFalcon Sep 9, 2024 •

edited

Loading

holmanb Sep 18, 2024

holmanb commented Sep 19, 2024

TheRealFalcon left a comment

TheRealFalcon Sep 20, 2024

TheRealFalcon Sep 20, 2024

TheRealFalcon Sep 20, 2024

TheRealFalcon Sep 20, 2024

TheRealFalcon Sep 20, 2024 •

edited

Loading

TheRealFalcon Sep 20, 2024

TheRealFalcon Sep 20, 2024

TheRealFalcon Sep 20, 2024

TheRealFalcon Sep 20, 2024 •

edited

Loading

		assert should_auto_attach_value == _should_auto_attach(ua_section)
		assert (

Improve timer #5672

Are you sure you want to change the base?

Improve timer #5672

Conversation

holmanb commented Sep 6, 2024 • edited Loading

Note to reviewers

Motivation

Description of changes

Todo

Merge type

TheRealFalcon left a comment

Choose a reason for hiding this comment

TheRealFalcon Sep 9, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

holmanb commented Sep 19, 2024

TheRealFalcon left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

TheRealFalcon Sep 20, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

TheRealFalcon Sep 20, 2024 • edited Loading

Choose a reason for hiding this comment

holmanb commented Sep 6, 2024 •

edited

Loading

TheRealFalcon Sep 9, 2024 •

edited

Loading

TheRealFalcon Sep 20, 2024 •

edited

Loading

TheRealFalcon Sep 20, 2024 •

edited

Loading