feat: build log messages lazily

- Create 3643.performance.rst
- chore: black .
- fix: linter errors

Author: BobTheBuidler

docs/filters.rst

@@ -654,7 +654,7 @@ The script can be run with: ``python ./eventscanner.py <your JSON-RPC API URL>``
                     # from our in-memory cache
                     block_when = get_block_when(block_number)
 
-                    logger.debug(f"Processing event {evt['event']}, block: {evt['blockNumber']} count: {evt['blockNumber']}")
+                    logger.debug("Processing event %s, block: %s count: %s", evt['event'], block_number, block_number)
                     processed = self.state.process_event(block_when, evt)
                     all_processed.append(processed)
 
@@ -726,7 +726,8 @@ The script can be run with: ``python ./eventscanner.py <your JSON-RPC API URL>``
                 # Print some diagnostics to logs to try to fiddle with real world JSON-RPC API performance
                 estimated_end_block = min(current_block + chunk_size, end_block)
                 logger.debug(
-                    f"Scanning token transfers for blocks: {current_block} - {estimated_end_block}, chunk size {chunk_size}, last chunk scan took {last_scan_duration}, last logs found {last_logs_found}"
+                    "Scanning token transfers for blocks: %s - %s, chunk size %s, last chunk scan took %s, last logs found %s",
+                    current_block, estimated_end_block, chunk_size, last_scan_duration, last_logs_found,
                 )
 
                 start = time.time()
@@ -778,7 +779,9 @@ The script can be run with: ``python ./eventscanner.py <your JSON-RPC API URL>``
                 if i < retries - 1:
                     # Give some more verbose info than the default middleware
                     logger.warning(
-                        f"Retrying events for block range {start_block} - {end_block} ({end_block-start_block}) failed with {e} , retrying in {delay} seconds")
+                        "Retrying events for block range %s - %s (%s) failed with %s , retrying in %s seconds",
+                        start_block, end_block, end_block-start_block, e, delay,
+                    )
                     # Decrease the `eth_getBlocks` range
                     end_block = start_block + ((end_block - start_block) // 2)
                     # Let the JSON-RPC to recover e.g. from restart
@@ -832,7 +835,7 @@ The script can be run with: ``python ./eventscanner.py <your JSON-RPC API URL>``
             to_block=to_block
         )
 
-        logger.debug(f"Querying eth_getLogs with the following parameters: {event_filter_params}")
+        logger.debug("Querying eth_getLogs with the following parameters: %s", event_filter_params)
 
         # Call JSON-RPC API on your Ethereum node.
         # get_logs() returns raw AttributedDict entries

newsfragments/3643.performance.rst

@@ -0,0 +1 @@
+optimize message formatting for logging

web3/_utils/caching/request_caching_validation.py

@@ -73,7 +73,8 @@ def is_beyond_validation_threshold(
         else:
             provider.logger.error(
                 "Invalid request_cache_validation_threshold value. This should not "
-                f"have happened. Request not cached.\n    threshold: {threshold}"
+                "have happened. Request not cached.\n    threshold: %s",
+                threshold,
             )
             return False
     except Exception as e:
@@ -128,7 +129,8 @@ def validate_from_blocknum_in_result(
         else:
             provider.logger.error(
                 "Could not find block number in result. This should not have happened. "
-                f"Request not cached.\n    result: {result}",
+                "Request not cached.\n    result: %s",
+                result,
             )
             return False
     except Exception as e:
@@ -198,7 +200,8 @@ async def async_is_beyond_validation_threshold(
         else:
             provider.logger.error(
                 "Invalid request_cache_validation_threshold value. This should not "
-                f"have happened. Request not cached.\n    threshold: {threshold}"
+                "have happened. Request not cached.\n    threshold: %s",
+                threshold,
             )
             return False
     except Exception as e:
@@ -253,7 +256,8 @@ async def async_validate_from_blocknum_in_result(
         else:
             provider.logger.error(
                 "Could not find block number in result. This should not have happened. "
-                f"Request not cached.\n    result: {result}",
+                "Request not cached.\n    result: %s",
+                result,
             )
             return False
     except Exception as e:

web3/_utils/http_session_manager.py

@@ -81,14 +81,14 @@ def cache_and_return_session(
 
         with self._lock:
             cached_session, evicted_items = self.session_cache.cache(cache_key, session)
-            self.logger.debug(f"Session cached: {endpoint_uri}, {cached_session}")
+            self.logger.debug("Session cached: %s, %s", endpoint_uri, cached_session)
 
         if evicted_items is not None:
             evicted_sessions = evicted_items.values()
             for evicted_session in evicted_sessions:
                 self.logger.debug(
-                    "Session cache full. Session evicted from cache: "
-                    f"{evicted_session}",
+                    "Session cache full. Session evicted from cache: %s",
+                    evicted_session,
                 )
             threading.Timer(
                 # If `request_timeout` is `None`, don't wait forever for the closing
@@ -167,7 +167,7 @@ def _handle_streaming_response(
     def _close_evicted_sessions(self, evicted_sessions: List[requests.Session]) -> None:
         for evicted_session in evicted_sessions:
             evicted_session.close()
-            self.logger.debug(f"Closed evicted session: {evicted_session}")
+            self.logger.debug("Closed evicted session: %s", evicted_session)
 
     # -- async -- #
 
@@ -195,7 +195,7 @@ async def async_cache_and_return_session(
                     cache_key, session
                 )
                 self.logger.debug(
-                    f"Async session cached: {endpoint_uri}, {cached_session}"
+                    "Async session cached: %s, %s", endpoint_uri, cached_session
                 )
 
             else:
@@ -215,16 +215,19 @@ async def async_cache_and_return_session(
                 )
                 if warning:
                     self.logger.debug(
-                        f"{warning}: {endpoint_uri}, {cached_session}. "
-                        f"Creating and caching a new async session for uri."
+                        "%s: %s, %s. Creating and caching a new async session for uri.",
+                        warning,
+                        endpoint_uri,
+                        cached_session,
                     )
 
                     self.session_cache._data.pop(cache_key)
                     if not session_is_closed:
                         # if loop was closed but not the session, close the session
                         await cached_session.close()
                     self.logger.debug(
-                        f"Async session closed and evicted from cache: {cached_session}"
+                        "Async session closed and evicted from cache: %s",
+                        cached_session,
                     )
 
                     # replace stale session with a new session at the cache key
@@ -238,7 +241,7 @@ async def async_cache_and_return_session(
                         cache_key, _session
                     )
                     self.logger.debug(
-                        f"Async session cached: {endpoint_uri}, {cached_session}"
+                        "Async session cached: %s, %s", endpoint_uri, cached_session
                     )
 
         if evicted_items is not None:
@@ -248,8 +251,8 @@ async def async_cache_and_return_session(
             evicted_sessions = list(evicted_items.values())
             for evicted_session in evicted_sessions:
                 self.logger.debug(
-                    "Async session cache full. Session evicted from cache: "
-                    f"{evicted_session}",
+                    "Async session cache full. Session evicted from cache: %s",
+                    evicted_session,
                 )
             # Kick off an asyncio `Task` to close the evicted sessions. In the case
             # that the cache filled very quickly and some sessions have been evicted
@@ -323,10 +326,10 @@ async def _async_close_evicted_sessions(
 
         for evicted_session in evicted_sessions:
             await evicted_session.close()
-            self.logger.debug(f"Closed evicted async session: {evicted_session}")
+            self.logger.debug("Closed evicted async session: %s", evicted_session)
 
         if any(not evicted_session.closed for evicted_session in evicted_sessions):
             self.logger.warning(
-                "Some evicted async sessions were not properly closed: "
-                f"{evicted_sessions}"
+                "Some evicted async sessions were not properly closed: %s",
+                evicted_sessions,
             )

web3/_utils/validation.py

@@ -396,7 +396,7 @@ def validate_rpc_response_and_raise_if_error(
 
         response = apply_error_formatters(error_formatters, response)
         if logger is not None:
-            logger.debug(f"RPC error response: {response}")
+            logger.debug("RPC error response: %s", response)
 
         raise web3_rpc_error
 

web3/manager.py

@@ -159,7 +159,7 @@ def _make_request(
         request_func = provider.request_func(
             cast("Web3", self.w3), cast("MiddlewareOnion", self.middleware_onion)
         )
-        self.logger.debug(f"Making request. Method: {method}")
+        self.logger.debug("Making request. Method: %s", method)
         return request_func(method, params)
 
     async def _coro_make_request(
@@ -169,7 +169,7 @@ async def _coro_make_request(
         request_func = await provider.request_func(
             cast("AsyncWeb3", self.w3), cast("MiddlewareOnion", self.middleware_onion)
         )
-        self.logger.debug(f"Making request. Method: {method}")
+        self.logger.debug("Making request. Method: %s", method)
         return await request_func(method, params)
 
     #
@@ -366,9 +366,12 @@ async def socket_request(
     ) -> RPCResponse:
         provider = cast(PersistentConnectionProvider, self._provider)
         self.logger.debug(
-            "Making request to open socket connection and waiting for response: "
-            f"{provider.get_endpoint_uri_or_ipc_path()},\n    method: {method},\n"
-            f"    params: {params}"
+            "Making request to open socket connection and waiting for response: %s,\n"
+            "    method: %s,\n"
+            "    params: %s",
+            provider.get_endpoint_uri_or_ipc_path(),
+            method,
+            params,
         )
         rpc_request = await self.send(method, params)
         provider._request_processor.cache_request_information(
@@ -388,9 +391,12 @@ async def send(self, method: RPCEndpoint, params: Any) -> RPCRequest:
             middleware_onion,
         )
         self.logger.debug(
-            "Sending request to open socket connection: "
-            f"{provider.get_endpoint_uri_or_ipc_path()},\n    method: {method},\n"
-            f"    params: {params}"
+            "Sending request to open socket connection: %s,\n"
+            "    method: %s,\n"
+            "    params: %s",
+            provider.get_endpoint_uri_or_ipc_path(),
+            method,
+            params,
         )
         return await send_func(method, params)
 
@@ -404,7 +410,8 @@ async def recv_for_request(self, rpc_request: RPCRequest) -> RPCResponse:
         )
         self.logger.debug(
             "Getting response for request from open socket connection:\n"
-            f"    request: {rpc_request}"
+            "    request: %s",
+            rpc_request,
         )
         response = await recv_func(rpc_request)
         try:
@@ -417,8 +424,8 @@ async def recv_for_request(self, rpc_request: RPCRequest) -> RPCResponse:
     async def recv(self) -> Union[RPCResponse, FormattedEthSubscriptionResponse]:
         provider = cast(PersistentConnectionProvider, self._provider)
         self.logger.debug(
-            "Getting next response from open socket connection: "
-            f"{provider.get_endpoint_uri_or_ipc_path()}"
+            "Getting next response from open socket connection: %s",
+            provider.get_endpoint_uri_or_ipc_path(),
         )
         # pop from the queue since the listener task is responsible for reading
         # directly from the socket
@@ -501,9 +508,11 @@ async def _process_response(
                     # subscription as it comes in
                     request_info.subscription_id = subscription_id
                     provider.logger.debug(
-                        "Caching eth_subscription info:\n    "
-                        f"cache_key={cache_key},\n    "
-                        f"request_info={request_info.__dict__}"
+                        "Caching eth_subscription info:\n"
+                        "    cache_key=%s,\n"
+                        "    request_info=%s",
+                        cache_key,
+                        request_info.__dict__,
                     )
                     self._request_processor._request_information_cache.cache(
                         cache_key, request_info

web3/providers/ipc.py

@@ -197,7 +197,7 @@ def _make_request(self, request: bytes) -> RPCResponse:
     @handle_request_caching
     def make_request(self, method: RPCEndpoint, params: Any) -> RPCResponse:
         self.logger.debug(
-            f"Making request IPC. Path: {self.ipc_path}, Method: {method}"
+            "Making request IPC. Path: %s, Method: %s", self.ipc_path, method
         )
         request = self.encode_rpc_request(method, params)
         return self._make_request(request)
@@ -206,7 +206,7 @@ def make_request(self, method: RPCEndpoint, params: Any) -> RPCResponse:
     def make_batch_request(
         self, requests: List[Tuple[RPCEndpoint, Any]]
     ) -> List[RPCResponse]:
-        self.logger.debug(f"Making batch request IPC. Path: {self.ipc_path}")
+        self.logger.debug("Making batch request IPC. Path: %s", self.ipc_path)
         request_data = self.encode_batch_rpc_request(requests)
         response = cast(List[RPCResponse], self._make_request(request_data))
         return sort_batch_response_by_response_ids(response)

web3/providers/legacy_websocket.py

@@ -136,7 +136,7 @@ async def coro_make_request(self, request_data: bytes) -> RPCResponse:
     @handle_request_caching
     def make_request(self, method: RPCEndpoint, params: Any) -> RPCResponse:
         self.logger.debug(
-            f"Making request WebSocket. URI: {self.endpoint_uri}, " f"Method: {method}"
+            "Making request WebSocket. URI: %s, Method: %s", self.endpoint_uri, method
         )
         request_data = self.encode_rpc_request(method, params)
         future = asyncio.run_coroutine_threadsafe(
@@ -149,8 +149,9 @@ def make_batch_request(
         self, requests: List[Tuple[RPCEndpoint, Any]]
     ) -> List[RPCResponse]:
         self.logger.debug(
-            f"Making batch request WebSocket. URI: {self.endpoint_uri}, "
-            f"Methods: {requests}"
+            "Making batch request WebSocket. URI: %s, Methods: %s",
+            self.endpoint_uri,
+            requests,
         )
         request_data = self.encode_batch_rpc_request(requests)
         future = asyncio.run_coroutine_threadsafe(