From 36cf156500c0f421546fdb9df97b99db16300e35 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Adri=C3=A1n=20Chaves?= Date: Tue, 9 Jul 2024 14:04:16 +0200 Subject: [PATCH] Record backout seconds instead of call counts --- scrapy/core/downloader/__init__.py | 21 +++++++++---- scrapy/extensions/corestats.py | 8 ----- tests/test_downloader.py | 47 ++++++++++++------------------ 3 files changed, 35 insertions(+), 41 deletions(-) diff --git a/scrapy/core/downloader/__init__.py b/scrapy/core/downloader/__init__.py index 4199ed4e2..79c2846e1 100644 --- a/scrapy/core/downloader/__init__.py +++ b/scrapy/core/downloader/__init__.py @@ -134,6 +134,7 @@ class Downloader: "DOWNLOAD_SLOTS", {} ) self._stats = crawler.stats + self._last_backout = (None, None) deprecated_setting_priority = self.settings.getpriority( "SCRAPER_SLOT_MAX_ACTIVE_SIZE" @@ -172,13 +173,22 @@ class Downloader: ) return dfd.addBoth(_deactivate) - def _count_backout(self, reason): - self._stats.inc_value("request_backouts/total") - self._stats.inc_value(f"request_backouts/{reason}") + def _record_backout(self, reason): + last_reason, last_reason_start_time = self._last_backout + if last_reason == reason: + return + current_time = time() + if last_reason is not None: + last_reason_seconds = current_time - last_reason_start_time + self._stats.inc_value("request_backout_seconds/total", last_reason_seconds) + self._stats.inc_value( + f"request_backout_seconds/{last_reason}", last_reason_seconds + ) + self._last_backout = (reason, current_time) def needs_backout(self) -> bool: if len(self.active) >= self.total_concurrency: - self._count_backout("concurrency") + self._record_backout("concurrency") return True if ( self._response_max_active_size @@ -207,11 +217,12 @@ class Downloader: f"during a crawl for this reason, see the " f"request_backouts/response_max_active_size stat." ) - self._count_backout("response_max_active_size") + self._record_backout("response_max_active_size") # Force the garbage collection of response objects. Necessary for # PyPy, which is lazier when it comes to garbage collection. gc.collect() return True + self._record_backout(None) return False def _get_slot(self, request: Request, spider: Spider) -> Tuple[str, Slot]: diff --git a/scrapy/extensions/corestats.py b/scrapy/extensions/corestats.py index d8b285ca3..6ef2d0382 100644 --- a/scrapy/extensions/corestats.py +++ b/scrapy/extensions/corestats.py @@ -47,14 +47,6 @@ class CoreStats: ) self.stats.set_value("finish_time", finish_time, spider=spider) self.stats.set_value("finish_reason", reason, spider=spider) - if elapsed_time_seconds > 0: - request_backouts = self.stats.get_value("request_backouts/total", 0) - if request_backouts: - self.stats.set_value( - "request_backouts/total_per_second", - request_backouts / elapsed_time_seconds, - spider=spider, - ) def item_scraped(self, item: Any, spider: Spider) -> None: self.stats.inc_value("item_scraped_count", spider=spider) diff --git a/tests/test_downloader.py b/tests/test_downloader.py index 39ac15870..c6de213a6 100644 --- a/tests/test_downloader.py +++ b/tests/test_downloader.py @@ -195,7 +195,7 @@ class RequestBackoutTest(unittest.TestCase): stats = { k: v for k, v in crawler.stats.get_stats().items() - if k.startswith("request_backouts/") + if k.startswith("request_backout_seconds/") } self.assertEqual(stats, {}) @@ -241,14 +241,13 @@ class RequestBackoutTest(unittest.TestCase): self.assertEqual(matching_log_count, 0) expected_stats = { - "request_backouts/concurrency": gt(0), - "request_backouts/total": gt(0), - "request_backouts/total_per_second": gt(0), + "request_backout_seconds/concurrency": gt(0), + "request_backout_seconds/total": gt(0), } actual_stats = { k: v for k, v in crawler.stats.get_stats().items() - if k.startswith("request_backouts/") + if k.startswith("request_backout_seconds/") } self.assertEqual(expected_stats, actual_stats) @@ -280,17 +279,13 @@ class RequestBackoutTest(unittest.TestCase): self.assertEqual(matching_log_count, 1) expected_stats = { - # Test > 1, if 1 then we are not really making sure that the INFO - # message above is logged only once in a scenario where active size - # is checked more than once. - "request_backouts/response_max_active_size": gt(1), - "request_backouts/total": gt(0), - "request_backouts/total_per_second": gt(0), + "request_backout_seconds/response_max_active_size": gt(0), + "request_backout_seconds/total": gt(0), } actual_stats = { k: v for k, v in crawler.stats.get_stats().items() - if k.startswith("request_backouts/") + if k.startswith("request_backout_seconds/") } self.assertEqual(expected_stats, actual_stats) @@ -328,14 +323,13 @@ class RequestBackoutTest(unittest.TestCase): self.assertEqual(matching_log_count, 1) expected_stats = { - "request_backouts/response_max_active_size": gt(0), - "request_backouts/total": gt(0), - "request_backouts/total_per_second": gt(0), + "request_backout_seconds/response_max_active_size": gt(0), + "request_backout_seconds/total": gt(0), } actual_stats = { k: v for k, v in crawler.stats.get_stats().items() - if k.startswith("request_backouts/") + if k.startswith("request_backout_seconds/") } self.assertEqual(expected_stats, actual_stats) @@ -373,14 +367,13 @@ class RequestBackoutTest(unittest.TestCase): self.assertEqual(matching_log_count, 1) expected_stats = { - "request_backouts/response_max_active_size": gt(0), - "request_backouts/total": gt(0), - "request_backouts/total_per_second": gt(0), + "request_backout_seconds/response_max_active_size": gt(0), + "request_backout_seconds/total": gt(0), } actual_stats = { k: v for k, v in crawler.stats.get_stats().items() - if k.startswith("request_backouts/") + if k.startswith("request_backout_seconds/") } self.assertEqual(expected_stats, actual_stats) @@ -426,14 +419,13 @@ class RequestBackoutTest(unittest.TestCase): self.assertEqual(matching_log_count, 1) expected_stats = { - "request_backouts/response_max_active_size": gt(0), - "request_backouts/total": gt(0), - "request_backouts/total_per_second": gt(0), + "request_backout_seconds/response_max_active_size": gt(0), + "request_backout_seconds/total": gt(0), } actual_stats = { k: v for k, v in crawler.stats.get_stats().items() - if k.startswith("request_backouts/") + if k.startswith("request_backout_seconds/") } self.assertEqual(expected_stats, actual_stats) @@ -481,13 +473,12 @@ class RequestBackoutTest(unittest.TestCase): self.assertEqual(matching_log_count, 1) expected_stats = { - "request_backouts/response_max_active_size": gt(0), - "request_backouts/total": gt(0), - "request_backouts/total_per_second": gt(0), + "request_backout_seconds/response_max_active_size": gt(0), + "request_backout_seconds/total": gt(0), } actual_stats = { k: v for k, v in crawler.stats.get_stats().items() - if k.startswith("request_backouts/") + if k.startswith("request_backout_seconds/") } self.assertEqual(expected_stats, actual_stats)