Timeout Select errors by up to 1s to avoid callers pinning CPU and filling /var/log - #1231
Timeout Select errors by up to 1s to avoid callers pinning CPU and filling /var/log#1231mdhoff-ms wants to merge 7 commits into
Conversation
Signed-off-by: Matt Hoffman <matthoffman@microsoft.com>
|
/azp run |
|
Azure Pipelines: There may be pipelines that require an authorized user to comment /azp run to run. |
|
Azure Pipelines: Successfully started running 1 pipeline(s). |
There was a problem hiding this comment.
Pull request overview
This PR updates the core swss::Select event loop implementation to throttle repeated Select::ERROR returns, reducing CPU pinning and runaway log growth when underlying selectables (e.g., Redis-backed ones) repeatedly fail to readData().
Changes:
- Adds a 1-second backoff when
Select::select()returnsSelect::ERROR. - Refactors the early-return logic in
Select::select()to make return conditions more explicit. - Adds
<chrono>/<thread>includes to support the new throttling sleep.
Signed-off-by: Matt Hoffman <matthoffman@microsoft.com>
|
/azp run |
|
Azure Pipelines: Successfully started running 1 pipeline(s). |
|
/azp run |
|
Azure Pipelines: Successfully started running 1 pipeline(s). |
Signed-off-by: Matt Hoffman <matthoffman@microsoft.com>
111179b to
d538530
Compare
|
maybe a good idea is to sleep only for the timeout that's passed in, then add a separate backoff (equal to 1s) to the actual logging statement. This would preserve the exact contract the caller is expecting while also mitigating the log spam. |
anti-spin timeout capped at 1s. Additional 1s rate limiting for logging. Signed-off-by: Matt Hoffman <matthoffman@microsoft.com>
|
/azp run |
|
Azure Pipelines: Successfully started running 1 pipeline(s). |
|
Azure Pipelines: There may be pipelines that require an authorized user to comment /azp run to run. |
| ret = poll_descriptors(c, timeout, interrupt_on_signal); | ||
| } else if (ret == Select::ERROR) | ||
| { | ||
| // ERROR returns immediately, so a tight caller loop pins the CPU. |
There was a problem hiding this comment.
This is caller's responsibility to handle ERROR gracefully, not to burn CPU.
| // the partition from callers in a tight loop. | ||
| constexpr auto kErrorLogInterval = std::chrono::seconds(1); | ||
| static thread_local std::chrono::steady_clock::time_point lastErrorLog; | ||
| auto now = std::chrono::steady_clock::now(); |
There was a problem hiding this comment.
Suggest not to add clock check. This function is critical to object sync performance.
There was a problem hiding this comment.
I have swapped this to a cap on total consecutive failure logs. After thinking about it, I actually prefer this to the clock method also.
readData error logging Signed-off-by: Matt Hoffman <matthoffman@microsoft.com>
There was a problem hiding this comment.
Pull request overview
Copilot reviewed 2 out of 2 changed files in this pull request and generated no new comments.
Comments suppressed due to low confidence (2)
common/select.cpp:205
- Select::select() only applies the error backoff when the initial non-blocking poll_descriptors(..., 0) returns ERROR. If the first poll returns TIMEOUT and the subsequent poll_descriptors(..., timeout, ...) returns ERROR (e.g., readData throws after epoll_wait wakes), the function returns immediately with ERROR and callers can still spin in a tight loop, which defeats the PR’s goal.
} else if (ret == Select::TIMEOUT)
{
ret = poll_descriptors(c, timeout, interrupt_on_signal);
} else if (ret == Select::ERROR)
{
common/select.cpp:147
- The PR description says the readData error log should be rate-limited to once per second, but this implementation instead logs up to 10 consecutive errors and then suppresses all further errors until any successful read occurs. Also, because the suppression counter is thread_local and not keyed per Select/Selectable, errors from one failing selectable can suppress logging for unrelated selectables in the same thread.
This issue also appears on line 201 of the same file.
if (s_consecutiveErrors < kMaxConsecutiveErrorLogs)
{
s_consecutiveErrors++;
SWSS_LOG_ERROR("readData error: %s%s", ex.what(),
s_consecutiveErrors == kMaxConsecutiveErrorLogs
Signed-off-by: Matt Hoffman <matthoffman@microsoft.com>
|
/azp run |
|
Azure Pipelines: Successfully started running 1 pipeline(s). |
There was a problem hiding this comment.
Pull request overview
Copilot reviewed 2 out of 2 changed files in this pull request and generated no new comments.
Comments suppressed due to low confidence (2)
common/select.cpp:149
- PR description says the readData error log should be rate-limited (once per second), but the implementation here permanently suppresses all further logs after 10 consecutive errors until a successful read occurs. On a long-lived outage this can hide the ongoing failure entirely after the first 10 messages, which is materially different behavior than rate limiting.
Consider implementing a time-based throttle (e.g., thread_local last-log timestamp; log at most once per second, optionally with a suppressed-count summary), or update the PR description/tests to match the intended ‘cap then silence’ semantics.
if (s_consecutiveErrors < kMaxConsecutiveErrorLogs)
{
s_consecutiveErrors++;
SWSS_LOG_ERROR("readData error: %s%s", ex.what(),
s_consecutiveErrors == kMaxConsecutiveErrorLogs
common/select.cpp:217
- The new ERROR-path backoff (sleep_for) is the main behavioral change intended to prevent tight loops from pinning CPU, but the added unit tests only validate log suppression. A regression here (e.g., removing/shortening the sleep) would not be caught.
Consider adding a unit test that measures elapsed time for repeated ERROR returns with a non-zero timeout and asserts there is a minimum backoff (with some slack to avoid flakiness).
// ERROR returns immediately, so a tight caller loop pins the CPU. Back off
// by the timeout capped at 1s; INFINITE (< 0) counts as the largest timeout.
constexpr int kMaxErrorBackoffMs = 1000;
int backoffMs = (timeout < 0 || timeout > kMaxErrorBackoffMs) ? kMaxErrorBackoffMs : timeout;
std::this_thread::sleep_for(std::chrono::milliseconds(backoffMs));
to others Signed-off-by: Matt Hoffman <matthoffman@microsoft.com>
|
/azp run |
|
Azure Pipelines: Successfully started running 1 pipeline(s). |
There was a problem hiding this comment.
Pull request overview
Copilot reviewed 2 out of 2 changed files in this pull request and generated no new comments.
Comments suppressed due to low confidence (2)
common/select.cpp:218
select()sleeps onSelect::ERRORbefore returning, butpoll_descriptors()may already have queued other healthy selectables intom_readyearlier in the same epoll batch. Sleeping unconditionally here can delay processing of already-ready data by up to the backoff amount. Consider only applying the backoff sleep when there is no queued ready work (m_ready.empty()).
// ERROR returns immediately, so a tight caller loop pins the CPU. Back off
// by the timeout capped at 1s; INFINITE (< 0) counts as the largest timeout.
constexpr int kMaxErrorBackoffMs = 1000;
int backoffMs = (timeout < 0 || timeout > kMaxErrorBackoffMs) ? kMaxErrorBackoffMs : timeout;
std::this_thread::sleep_for(std::chrono::milliseconds(backoffMs));
common/select.cpp:147
- The log-suppression state only tracks the last failing fd. If multiple selectables are failing and epoll returns different fds across iterations,
s_consecutiveErrorsis reset on each fd switch, so suppression may never reachkMaxConsecutiveErrorLogsand the process can still flood logs in a tight loop (especially when failures alternate across fds). This also doesn’t match the PR description’s “once per second” rate-limiting behavior.
Consider tracking suppression per-fd (e.g., thread-local map keyed by fd) and/or implementing a time-based rate limiter so alternating failures can’t bypass suppression.
if (fd != s_lastFailedFd)
{
s_lastFailedFd = fd;
s_consecutiveErrors = 0;
}
I have noticed two instances of filled /var/log on DUTs with many repeated lines:
these repeat immediately, leading to /var/log partition being filled very quickly. It seems that the error case of
common/select.cpp(e.g. if redis is down) returns immediately, leading to callers who call in loops spinning indefinitely and filling the log partition.To fix this I propose the following change:
On the
Select::ERRORpath, we should enforce the timeout requested by the caller (often 1ms, 100ms, etc) up to a cap of 1 second, to avoid pinning the CPU in a hot loop. Additionally the readData error log should be rate limited to once per second, to avoid flooding /var/log/syslog and filling the partition.