Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Disable serial logs by default to improve performance #2993

Open
j9brown opened this issue Dec 18, 2024 · 2 comments
Open

Disable serial logs by default to improve performance #2993

j9brown opened this issue Dec 18, 2024 · 2 comments

Comments

@j9brown
Copy link

j9brown commented Dec 18, 2024

Describe the problem you have/What new integration you would like

Logging to the serial port stalls the event loop for the time it takes to write messages. It noticeably affects overall performance and it's quite likely that no one is even watching the output since esphome devices are typically administered over wifi once deployed.

With the default logging level set to DEBUG, every state change results in several dozen or a few hundred bytes of logs. At the default 115200 baud rate, writing a 100 byte log message to the UART takes about 9 ms. That's a significant fraction of the 30 ms recommendation for blocking the event loop and it adds up very quickly.

I think we should do one or more of the following things:

  1. Disable serial logs by default in the default esphome yaml templates used when setting up new devices (non-breaking change)
  2. Disable serial logs by default in the yaml schema (a breaking change)
  3. Write serial logs using buffered I/O without blocking
  4. Lower the default logging level (although I find DEBUG logs useful)
  5. Somehow determine when serial logs are actually needed and only enable them then (perhaps watch for an attention sequence from the host)
  6. Increase the default baud rate

Please describe your use case for this integration and alternatives you've tried:

I was curious why I was seeing warnings about my components taking so long to update considering how little work they did.

For example, I have an interval component that updates 4 resistance sensors associated with NTC thermistors. It was taking over 150 ms to do the work which seemed ridiculous. After disabling serial logs, it's down to about 70 ms while observing it over wifi. So a whopping 80 ms was spent writing several hundred bytes of sensor state change logs.

Ironically, the warning message about slow components exacerbates the problem. This message is 165 bytes long and takes about 15 ms to output.

[12:52:40][W][component:237]: Component interval took a long time for an operation (66 ms).
[12:52:40][W][component:238]: Components should block for at most 30 ms.

Additional context

For anyone following along, here's how you disable serial logs:

logger:
  level: DEBUG
  baud_rate: 0
@nagyrobi
Copy link
Member

nagyrobi commented Dec 18, 2024

Moreover, log level is by default at debug. I always manually set it to info on production devices for exactly the same reason.

@j9brown
Copy link
Author

j9brown commented Dec 18, 2024

Incidentally, I found the documentation for tx_buffer_size a bit misleading. It sounds like an option to control the size of a transmit buffer for non-blocking writes to the serial port but it's really just the memory allocated for formatting a single log message. Log messages longer than this get truncated.

I might suggest a new name such as max_log_message_length or similar to distinguish it's about formatting not really about transmission.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants