[sdk/python] Reduce log.debug calls for improved performance
#7295
Conversation
`log.debug` messages are part of an update and get sent to the service. Reducing the number of `log.debug` calls can significantly improve the performance of a program. This commit changes the debug logging in the Python SDK to be similar to the debug logging in the Node.js SDK. - An `excessive_debug_output` variable has been added (that can be set to `True` during debugging), but otherwise will avoid a large number of `log.debug` calls. - Some unhelpful/redundant `log.debug` calls have been deleted.
| @@ -81,7 +81,6 @@ async def prepare_resource(res: 'Resource', | |||
| opts: Optional['ResourceOptions'], | |||
| typ: Optional[type] = None) -> ResourceResolverOperations: | |||
| from .. import Output # pylint: disable=import-outside-toplevel | |||
| log.debug(f"resource {props} preparing to wait for dependencies") | |||
There was a problem hiding this comment.
Deleting the log.debug calls at the beginning/end of this function, because we don't do it in the Node.js SDK
| @@ -311,7 +309,6 @@ def read_resource(res: 'CustomResource', | |||
| # that we are populating the Resource object with properties associated with an already-live resource. | |||
| # | |||
| # Same as below, we initialize the URN property on the resource, which will always be resolved. | |||
| log.debug("preparing read resource for RPC") | |||
There was a problem hiding this comment.
Redundant with the earlier log.debug call at the beginning of the function.
| @@ -328,7 +325,6 @@ def read_resource(res: 'CustomResource', | |||
|
|
|||
| async def do_read(): | |||
| try: | |||
| log.debug(f"preparing read: ty={ty}, name={name}, id={opts.id}") | |||
There was a problem hiding this comment.
Doesn't really add much new information beyond what was logged at the beginning of the function, and Node.js doesn't have this additional logging.
| @@ -419,7 +415,6 @@ def register_resource(res: 'Resource', | |||
| # Simply initialize the URN property and get prepared to resolve it later on. | |||
| # Note: a resource urn will always get a value, and thus the output property | |||
| # for it can always run .apply calls. | |||
| log.debug("preparing resource for RPC") | |||
There was a problem hiding this comment.
Redundant with the debug.log call at the beginning of the function.
| @@ -434,7 +429,6 @@ def register_resource(res: 'Resource', | |||
|
|
|||
| async def do_register(): | |||
| try: | |||
| log.debug(f"preparing resource registration: ty={ty}, name={name}") | |||
There was a problem hiding this comment.
Similarly redundant with the earlier log.debug call -- and Node.js doesn't have this additional log call.
| # excessive_debug_output enables, well, pretty excessive debug output pertaining to resources and properties. | ||
| excessive_debug_output = False |
There was a problem hiding this comment.
This is equivalent to what we have in the Node.js SDK:
pulumi/sdk/nodejs/runtime/settings.ts
Lines 32 to 35 in 7820d2c
There was a problem hiding this comment.
an env var might be easier for users, but this is what we do in node 🤷
| # excessive_debug_output enables, well, pretty excessive debug output pertaining to resources and properties. | ||
| excessive_debug_output = False |
There was a problem hiding this comment.
an env var might be easier for users, but this is what we do in node 🤷
|
@justinvp TIL we log synchronously. Makes sense -- don't want to lose messages -- but the same way we coordinate synchronous execution and shutdown with other RPCs, etc, we could do the same here and possibly bank even more. |
log.debugmessages are part of an update and get sent to the service. Reducing the number oflog.debugcalls can significantly improve the performance of a program. This commit changes the debug logging in the Python SDK to be similar to the debug logging in the Node.js SDK.excessive_debug_outputvariable has been added (that can be set toTrueduring debugging), but otherwise will avoid a large number oflog.debugcalls.log.debugcalls have been deleted.Fixes #7292
The following program run with
pulumi preview(plus the fix from #7293):Duration Before: 35.8 seconds
Duration After: 6.35 seconds
29.45 second improvement!
Before
After