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.

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.

cloudinit/cmd/main.py

cloudinit/config/cc_resizefs.py

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

cloudinit/performance.py

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


Is there a good reason to enforce this?

Having a standard calling convention makes code more recognizable but I don't feel strongly about this. I recall it also made refactoring slightly more difficult that one of the calls used the form msg="", but I can drop it if you'd rather not.

I would prefer to allow kwargs here. I think the main case for positional only arguments (other than c api compatibility) is when the arguments are obvious and names really convey no extra meaning. E.g., min(5, 4) wouldn't benefit by having kwargs.

However, if we make a call like Timed(x, threshold=y, log_mode=z), there's really no context to tell us what we're actually passing as the first argument. Obviously we should have a better variable name than x, but it seems needlessly restricting to disallow the caller to add the context if it'd make the call clearer.

@TheRealFalcon that seems reasonable, I just removed that restriction

cloudinit/config/modules.py

cloudinit/atomic_helper.py

cloudinit/safeyaml.py

cloudinit/sources/__init__.py

cloudinit/performance.py

holmanb · 2024-09-23T15:29:46Z

@TheRealFalcon I think that I've addressed all of your comments. Ready for re-review (assuming tests pass).

TheRealFalcon · 2024-09-23T18:07:37Z

@holmanb , See my latest comments on the last two unresolved conversations. +1 to everything else.

holmanb · 2024-09-23T18:42:29Z

@TheRealFalcon I just pushed fixes for your last two comments

TheRealFalcon

LGTM!

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 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 5 times, most recently 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

holmanb force-pushed the holmanb/timer branch 3 times, most recently from 9f89d20 to f713d5c Compare September 23, 2024 15:27

holmanb requested a review from TheRealFalcon September 23, 2024 15:29

TheRealFalcon approved these changes Sep 23, 2024

View reviewed changes

holmanb added 2 commits September 23, 2024 12:24

chore: add timer to io and string manipulation code

47d77d4

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 force-pushed the holmanb/timer branch from 0c2b029 to 47d77d4 Compare September 23, 2024 19:24

holmanb merged commit 70d4a5c into canonical:main Sep 23, 2024
21 checks passed

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

holmanb Sep 23, 2024

TheRealFalcon Sep 23, 2024

holmanb Sep 23, 2024

holmanb commented Sep 23, 2024

TheRealFalcon commented Sep 23, 2024

holmanb commented Sep 23, 2024

TheRealFalcon left a comment

		assert should_auto_attach_value == _should_auto_attach(ua_section)
		assert (

Improve timer #5672

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

holmanb Sep 18, 2024

Choose a reason for hiding this comment

holmanb commented Sep 19, 2024

TheRealFalcon left a comment

Choose a reason for hiding this comment

TheRealFalcon Sep 20, 2024

Choose a reason for hiding this comment

holmanb Sep 23, 2024

Choose a reason for hiding this comment

TheRealFalcon Sep 23, 2024

Choose a reason for hiding this comment

holmanb Sep 23, 2024

Choose a reason for hiding this comment

holmanb commented Sep 23, 2024

TheRealFalcon commented Sep 23, 2024

holmanb commented Sep 23, 2024

TheRealFalcon left a comment

Choose a reason for hiding this comment

holmanb commented Sep 6, 2024 •

edited

Loading

TheRealFalcon Sep 9, 2024 •

edited

Loading