From a69a456611689807ee08fb0acba08cad1fe375da Mon Sep 17 00:00:00 2001 From: David Robertson Date: Fri, 28 Oct 2022 23:21:40 +0100 Subject: [PATCH 1/6] Introduce tests/metrics to mirror synapse/metrics --- tests/metrics/__init__.py | 0 tests/{ => metrics}/test_metrics.py | 0 2 files changed, 0 insertions(+), 0 deletions(-) create mode 100644 tests/metrics/__init__.py rename tests/{ => metrics}/test_metrics.py (100%) diff --git a/tests/metrics/__init__.py b/tests/metrics/__init__.py new file mode 100644 index 000000000000..e69de29bb2d1 diff --git a/tests/test_metrics.py b/tests/metrics/test_metrics.py similarity index 100% rename from tests/test_metrics.py rename to tests/metrics/test_metrics.py From 94293b4e8031b22e1b3e5dc3886f1794274745e3 Mon Sep 17 00:00:00 2001 From: David Robertson Date: Fri, 28 Oct 2022 23:45:38 +0100 Subject: [PATCH 2/6] Test case --- .../test_background_process_metrics.py | 19 +++++++++++++++++++ 1 file changed, 19 insertions(+) create mode 100644 tests/metrics/test_background_process_metrics.py diff --git a/tests/metrics/test_background_process_metrics.py b/tests/metrics/test_background_process_metrics.py new file mode 100644 index 000000000000..f0f6cb291280 --- /dev/null +++ b/tests/metrics/test_background_process_metrics.py @@ -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() From 19add6f44279faaf233b16a8b4172f4e435f1fc8 Mon Sep 17 00:00:00 2001 From: David Robertson Date: Fri, 28 Oct 2022 23:45:51 +0100 Subject: [PATCH 3/6] Clamp time diferences to at least 0 --- synapse/metrics/background_process_metrics.py | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/synapse/metrics/background_process_metrics.py b/synapse/metrics/background_process_metrics.py index 7a1516d3a89c..9ea4e23b3107 100644 --- a/synapse/metrics/background_process_metrics.py +++ b/synapse/metrics/background_process_metrics.py @@ -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 From 66157a476336d7b719f951f0209105d0a9a39c54 Mon Sep 17 00:00:00 2001 From: David Robertson Date: Sat, 29 Oct 2022 00:02:27 +0100 Subject: [PATCH 4/6] Changelog --- changelog.d/14323.bugfix | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/14323.bugfix diff --git a/changelog.d/14323.bugfix b/changelog.d/14323.bugfix new file mode 100644 index 000000000000..da39bc020c15 --- /dev/null +++ b/changelog.d/14323.bugfix @@ -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. From e592162c3d6018ddd4e4c036bd4eb82a086bce49 Mon Sep 17 00:00:00 2001 From: David Robertson Date: Sat, 29 Oct 2022 00:26:27 +0100 Subject: [PATCH 5/6] Fix typechecking --- mypy.ini | 4 +++- tests/metrics/test_metrics.py | 10 ++++++++-- 2 files changed, 11 insertions(+), 3 deletions(-) diff --git a/mypy.ini b/mypy.ini index 34b4523e007e..8f1141a23905 100644 --- a/mypy.ini +++ b/mypy.ini @@ -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 @@ -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 diff --git a/tests/metrics/test_metrics.py b/tests/metrics/test_metrics.py index 1a70eddc9bbf..90d8f5de44ab 100644 --- a/tests/metrics/test_metrics.py +++ b/tests/metrics/test_metrics.py @@ -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: @@ -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"] ) @@ -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") From 0ad4b5d78bca1275d8394e3ef13a09e24600ffe1 Mon Sep 17 00:00:00 2001 From: David Robertson Date: Mon, 31 Oct 2022 12:25:38 +0000 Subject: [PATCH 6/6] No, really, fix typechecking --- tests/metrics/test_metrics.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/metrics/test_metrics.py b/tests/metrics/test_metrics.py index 90d8f5de44ab..bddc4228bc92 100644 --- a/tests/metrics/test_metrics.py +++ b/tests/metrics/test_metrics.py @@ -12,7 +12,7 @@ # 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 +from typing_extensions import Protocol try: from importlib import metadata