Use built in queue log handlers to avoid formatting logs in the event loop

[bdraco]

Proposed change

I noticed that cameras were taking a long time to load images in the UI and realized I had pyhap in debug mode. After investigation it turned out that the event loop was being tied up by logging (mostly formatting).

Proposed solution is to use a logging QueueHandler and QueueListener to avoid formatting log messages the event loop

This also resolves a bug where the first few messages (~39 for me) includes 2020-05-15 22:06:44 INFO (MainThread) [homeassistant.bootstrap] Config directory: /config would be missing from home-assistant.log

Before (websocket_api debug on, full debug overwhelmed things):

After (full debug on):

Logging has negligible impact on the event loop. I can even turn on full debug mode with significantly less impact on the UI performance as all of the work is no longer happening in the event loop as its moved to another thread.

Type of change

• Dependency upgrade
• Bugfix (non-breaking change which fixes an issue)
• New integration (thank you!)
• New feature (which adds functionality to an existing integration)
• Breaking change (fix/feature causing existing functionality to break)
• Code quality improvements to existing code or addition of tests

Example entry for configuration.yaml:

# Example configuration.yaml

Additional information

• This PR fixes or closes issue: fixes #
• This PR is related to issue:
• Link to documentation pull request:

Checklist

• The code change is tested and works locally.
• Local tests pass. Your PR cannot be merged unless tests pass
• There is no commented out code in this PR.
• I have followed the development checklist
• The code has been formatted using Black (black --fast homeassistant tests)
• Tests have been added to verify that the new code works.

If user exposed functionality or configuration variables are added/changed:

• Documentation added/updated for www.home-assistant.io

If the code communicates with devices, web services, or third-party tools:

• The manifest file has all fields filled out correctly.
  Updated and included derived files by running: python3 -m script.hassfest.
• New or updated dependencies have been added to requirements_all.txt.
  Updated by running python3 -m script.gen_requirements_all.
• Untested files have been added to .coveragerc.

The integration reached or maintains the following Integration Quality Scale:

• No score or internal
• 🥈 Silver
• 🥇 Gold
• 🏆 Platinum

[bdraco]

need to experiment with where the filtering should go. Not sure if it should stay on incoming side of the queue or the processing side. The filtering is a bit more expensive than I expected, esp. with many logger config lines as it has to iterate all of them and do a string match

[bdraco]

I'm thinking the log filtering should come off the individual handlers and go on to the queue handler only so only the messages we care about go into the queue. Should be a bit more efficient as we only have to run the filter once and the other handlers on the other side of the queue don't have to worry about filtering

[bdraco]

It appears I'm solving the wrong problem here since this shouldn't be an issue since logging is already wrapped in homeassistant/util/logging.py

It may be holding it wrong but it looks like none of the if self._logger.isEnabledFor(logging.DEBUG) checks in the code actually do anything since handler.setLevel(logging.NOTSET) is set in logger and the log is filtered per module by the log filter.

So what I think its really happening is we are serializing the all the websocket data in the self._logger.debug("Sending %s", message) messages and than throwing it away when the filter doesn't match which is what is really showing up on the profile.

More investigation needed for sure

[bdraco]

All the new logging code in util/logging.py should be covered. codecov is highlighting the existing lack of coverage in bootstrap.py

[bdraco]

Managed to get it to 100% of diff hit

[bdraco]

Retested to make sure the name change didn't cause issues (done programmatically) but better to be safe. All good

[MartinHjelmare]

Looks good!