Skip to content
This repository has been archived by the owner on Apr 26, 2024. It is now read-only.

Avoid incrementing bg process utime/stime counters by negative durations #14323

Merged
merged 6 commits into from
Oct 31, 2022
Merged
Show file tree
Hide file tree
Changes from 5 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions changelog.d/14323.bugfix
Original file line number Diff line number Diff line change
@@ -0,0 +1 @@
Fix a bug introduced in Synapse 0.34.0rc2 where logs could include error spam when background processes are measured as taking a negative amount of time.
4 changes: 3 additions & 1 deletion mypy.ini
Original file line number Diff line number Diff line change
Expand Up @@ -56,7 +56,6 @@ exclude = (?x)
|tests/rest/media/v1/test_media_storage.py
|tests/server.py
|tests/server_notices/test_resource_limits_server_notices.py
|tests/test_metrics.py
|tests/test_state.py
|tests/test_terms_auth.py
|tests/util/caches/test_cached_call.py
Expand Down Expand Up @@ -106,6 +105,9 @@ disallow_untyped_defs = False
[mypy-tests.handlers.test_user_directory]
disallow_untyped_defs = True

[mypy-tests.metrics.test_background_process_metrics]
disallow_untyped_defs = True

[mypy-tests.push.test_bulk_push_rule_evaluator]
disallow_untyped_defs = True

Expand Down
6 changes: 4 additions & 2 deletions synapse/metrics/background_process_metrics.py
Original file line number Diff line number Diff line change
Expand Up @@ -174,8 +174,10 @@ def update_metrics(self) -> None:
diff = new_stats - self._reported_stats
self._reported_stats = new_stats

_background_process_ru_utime.labels(self.desc).inc(diff.ru_utime)
_background_process_ru_stime.labels(self.desc).inc(diff.ru_stime)
# For unknown reasons, the difference in times can be negative. See comment in
# synapse.http.request_metrics.RequestMetrics.update_metrics.
_background_process_ru_utime.labels(self.desc).inc(max(diff.ru_utime, 0))
_background_process_ru_stime.labels(self.desc).inc(max(diff.ru_stime, 0))
_background_process_db_txn_count.labels(self.desc).inc(diff.db_txn_count)
_background_process_db_txn_duration.labels(self.desc).inc(
diff.db_txn_duration_sec
Expand Down
Empty file added tests/metrics/__init__.py
Empty file.
19 changes: 19 additions & 0 deletions tests/metrics/test_background_process_metrics.py
Original file line number Diff line number Diff line change
@@ -0,0 +1,19 @@
from unittest import TestCase as StdlibTestCase
from unittest.mock import Mock

from synapse.logging.context import ContextResourceUsage, LoggingContext
from synapse.metrics.background_process_metrics import _BackgroundProcess


class TestBackgroundProcessMetrics(StdlibTestCase):
def test_update_metrics_with_negative_time_diff(self) -> None:
"""We should ignore negative reported utime and stime differences"""
usage = ContextResourceUsage()
usage.ru_stime = usage.ru_utime = -1.0

mock_logging_context = Mock(spec=LoggingContext)
mock_logging_context.get_resource_usage.return_value = usage

process = _BackgroundProcess("test process", mock_logging_context)
# Should not raise
process.update_metrics()
10 changes: 8 additions & 2 deletions tests/test_metrics.py → tests/metrics/test_metrics.py
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,8 @@
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
# See the License for the specific language governing permissions and
# limitations under the License.
from typing import Protocol

try:
from importlib import metadata
except ImportError:
Expand Down Expand Up @@ -52,7 +54,11 @@ def get_sample_labels_value(sample):

class TestMauLimit(unittest.TestCase):
def test_basic(self):
gauge = InFlightGauge(
class MetricEntry(Protocol):
foo: int
bar: int

gauge: InFlightGauge[MetricEntry] = InFlightGauge(
"test1", "", labels=["test_label"], sub_metrics=["foo", "bar"]
)

Expand Down Expand Up @@ -146,7 +152,7 @@ def test_cache_metric(self):
Caches produce metrics reflecting their state when scraped.
"""
CACHE_NAME = "cache_metrics_test_fgjkbdfg"
cache = DeferredCache(CACHE_NAME, max_entries=777)
cache: DeferredCache[str, str] = DeferredCache(CACHE_NAME, max_entries=777)

items = {
x.split(b"{")[0].decode("ascii"): x.split(b" ")[1].decode("ascii")
Expand Down