Skip to content

Commit

Permalink
fix(wait_for_log_lines): fix saturating cpu when waiting for log lines
Browse files Browse the repository at this point in the history 
We missed waiting time before recreating iterator. This causes
unnecessary high cpu utilization.

refs: scylladb#8720
  • Loading branch information
@soyacz
soyacz committed Sep 19, 2024
1 parent f38ac75 commit 9f0781a
Show file tree
Hide file tree
Showing 2 changed files with 29 additions and 20 deletions.
2 changes: 2 additions & 0 deletions sdcm/wait.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -156,12 +156,14 @@ def wait_for_log_lines(node, start_line_patterns, end_line_patterns, start_timeo
started = any(start_follower)
while not started and (time.time() - start_time < start_timeout):
started = any(start_follower)
time.sleep(0.05)
if not started:
raise TimeoutError(start_ctx)
LOGGER.debug("Start line patterns %s were found.%s", start_line_patterns, error_msg_ctx)
ended = any(end_follower)
while not ended and (time.time() - start_time < end_timeout):
ended = any(end_follower)
time.sleep(0.1)
if not ended:
raise TimeoutError(end_ctx)
LOGGER.debug("End line patterns %s were found.%s", end_line_patterns, error_msg_ctx)
47 changes: 27 additions & 20 deletions unit_tests/test_wait.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -19,6 +19,7 @@
import unittest

from concurrent.futures import ThreadPoolExecutor
from unittest.mock import patch

import pytest

Expand Down Expand Up @@ -210,10 +211,11 @@ def test_can_wait_for_log_start_line_and_end_line(self, tmp_path):
write_thread = threading.Thread(target=write_to_file, args=(file_path, lines))
write_thread.daemon = True
file_path.touch()
with wait_for_log_lines(node=node, start_line_patterns=["rebuild.*started with keyspaces=", "Rebuild starts"],
end_line_patterns=["rebuild.*finished with keyspaces=", "Rebuild succeeded"],
start_timeout=3, end_timeout=5):
write_thread.start()
with patch('time.sleep', return_value=None):
with wait_for_log_lines(node=node, start_line_patterns=["rebuild.*started with keyspaces=", "Rebuild starts"],
end_line_patterns=["rebuild.*finished with keyspaces=", "Rebuild succeeded"],
start_timeout=3, end_timeout=5):
write_thread.start()

def test_wait_for_log_timeout_when_no_start_line(self, tmp_path):
file_path = tmp_path / "wait_for_log_lines_1.log"
Expand All @@ -222,9 +224,10 @@ def test_wait_for_log_timeout_when_no_start_line(self, tmp_path):
t = threading.Thread(target=write_to_file, args=(file_path, lines))
t.daemon = True
file_path.touch()
with pytest.raises(TimeoutError, match="Timeout occurred while waiting for start log line"), \
wait_for_log_lines(node=node, start_line_patterns=["start"], end_line_patterns=["end"], start_timeout=0.3, end_timeout=1):
t.start()
with patch('time.sleep', return_value=None):
with pytest.raises(TimeoutError, match="Timeout occurred while waiting for start log line"), \
wait_for_log_lines(node=node, start_line_patterns=["start"], end_line_patterns=["end"], start_timeout=0.4, end_timeout=1.2):
t.start()

def test_wait_for_log_timeout_when_no_end_line(self, tmp_path):
file_path = tmp_path / "wait_for_log_lines_1.log"
Expand All @@ -233,9 +236,10 @@ def test_wait_for_log_timeout_when_no_end_line(self, tmp_path):
t = threading.Thread(target=write_to_file, args=(file_path, lines))
t.daemon = True
file_path.touch()
with pytest.raises(TimeoutError, match="Timeout occurred while waiting for end log line"), \
wait_for_log_lines(node=node, start_line_patterns=["start"], end_line_patterns=["end"], start_timeout=0.1, end_timeout=0.3):
t.start()
with patch('time.sleep', return_value=None):
with pytest.raises(TimeoutError, match="Timeout occurred while waiting for end log line"), \
wait_for_log_lines(node=node, start_line_patterns=["start"], end_line_patterns=["end"], start_timeout=0.4, end_timeout=0.7):
t.start()

def test_wait_for_log_reraises_exception(self, tmp_path):
file_path = tmp_path / "wait_for_log_lines_1.log"
Expand All @@ -244,18 +248,20 @@ def test_wait_for_log_reraises_exception(self, tmp_path):
t = threading.Thread(target=write_to_file, args=(file_path, lines))
t.daemon = True
file_path.touch()
with pytest.raises(ValueError, match="dummy error"), \
wait_for_log_lines(node=node, start_line_patterns=["start"], end_line_patterns=["end"], start_timeout=0.1, end_timeout=0.3):
t.start()
raise ValueError('dummy error')
with patch('time.sleep', return_value=None):
with pytest.raises(ValueError, match="dummy error"), \
wait_for_log_lines(node=node, start_line_patterns=["start"], end_line_patterns=["end"], start_timeout=0.4, end_timeout=0.7):
t.start()
raise ValueError('dummy error')

def test_wait_for_log_reraises_exception_and_timeout_error(self, tmp_path):
file_path = tmp_path / "wait_for_log_lines_1.log"
node = DummyNode(log_path=file_path)
file_path.touch()
with pytest.raises(TimeoutError, match="Timeout occurred while waiting for start log line") as exc_info, \
wait_for_log_lines(node=node, start_line_patterns=["start"], end_line_patterns=["end"], start_timeout=0.1, end_timeout=0.3):
raise ValueError('dummy error')
with patch('time.sleep', return_value=None):
with pytest.raises(TimeoutError, match="Timeout occurred while waiting for start log line") as exc_info, \
wait_for_log_lines(node=node, start_line_patterns=["start"], end_line_patterns=["end"], start_timeout=0.4, end_timeout=0.7):
raise ValueError('dummy error')
assert "ValueError" in str(exc_info.getrepr())

def test_wait_for_log_reraises_timeout_error_with_error_context(self, tmp_path):
Expand All @@ -266,6 +272,7 @@ def test_wait_for_log_reraises_timeout_error_with_error_context(self, tmp_path):
t.daemon = True
file_path.touch()
expected_match = "Timeout occurred while waiting for end log line \['end'\] on node: node_1. Context: Wait end line"
with pytest.raises(TimeoutError, match=expected_match), \
wait_for_log_lines(node=node, start_line_patterns=["start"], end_line_patterns=["end"], start_timeout=0.1, end_timeout=0.3, error_msg_ctx="Wait end line"):
t.start()
with patch('time.sleep', return_value=None):
with pytest.raises(TimeoutError, match=expected_match), \
wait_for_log_lines(node=node, start_line_patterns=["start"], end_line_patterns=["end"], start_timeout=0.4, end_timeout=0.7, error_msg_ctx="Wait end line"):
t.start()

0 comments on commit 9f0781a

Please sign in to comment.