feat: build logger messages lazily

[BobTheBuidler]

What was wrong?

When using the logging module, we currently build the log message eagerly which leads to wasted cpu if the logger is not enabled.

According to DuckDuckGo's silly AI assistant:

"Using f-strings for logging in Python is generally discouraged because they evaluate the string immediately, which can lead to unnecessary computations even if the log level is not set to display that message. Instead, it's recommended to use the traditional formatting methods, like the % operator, which defer the string formatting until it's actually needed, improving performance and avoiding potential issues."

With this change, we will build the log messages lazily so the string is never built if the log will not actually be emitted, saving compute. This is just a microoptimization but will make a difference for power users such as myself who have use cases that require making a high volume of requests over a long period.

Related to Issue # N/A
Closes # N/A

How was it fixed?

replacing f-strings with strings which will be used with str.format

Todo:

• Clean up commit history
• Add entry to the release notes Not applicable for typical user so I skipped this addition

Cute Animal Picture

[kclowes]

Thank you! Before merging, I'd like to make sure that this actually makes a 'meaningful' difference in performance before we sacrifice code consistency. Do you happen to know what magnitude of faster this is? If not, would you mind running a couple benchmarks?

[BobTheBuidler]

This is on the backburner for now. I can tell you it saves about 33% of the time vs the existing code but I know you're going to want to see some data for this. I'm still going to put a benchmark together for that, when I get a chance. Stay tuned!

[BobTheBuidler]

@kclowes Another day, another 15 minute wait period while my stuff spins up... Perfect time to put this data together:

For this benchmark I used a logger.debug statement comparable to the one found in HTTPProvider.make_request, since every single request goes thru this function.

import logging
from time import time

logger = logging.getLogger('test')

endpoint_uri = 'https://somewebsite.com/somereallylongauthkey/'
method = "eth_call"
response = {"jsonrpc": "2.0", "id": 1, "result": "0x" + "0" * 64}

def test_old_3_inputs():
    logger.debug(
        f"Getting response HTTP. URI: {endpoint_uri}, Method: {method}, Response: {response}",
    )
        
def test_new_3_inputs():
    logger.debug(
        "Getting response HTTP. URI: %s, Method: %s Response: %s",
        endpoint_uri,
        method,
        response,
    )
    

start = time()
for _ in range(50_000):
    test_old_3_inputs()
print(f"old: {time() - start}")

start = time()
for _ in range(50_000):
    test_new_3_inputs()
print(f"new: {time() - start}")

old: 0.4092729091644287
new: 0.12366008758544922

So for every ~175k requests it will save about 1s, this is not an insignificant savings for a power user.

My 33% estimate above came from my own tests with only 1 input, not 3. So turns out this is more impactful than I originally intended!

[kclowes]

Awesome, thank you! I left one nit, but I think that's it. Do you want to add a newsfragment or should I?

[kclowes]

👍 nice!

[fselmo]

This lgtm too. Thanks for benchmarking!

[BobTheBuidler]

I committed your nit, and added the newsfragment. I think we're good to go!

[kclowes]

oop, that nit was a bad suggestion, sorry. I didn't see that endpoint was only defined in connect

[BobTheBuidler]

fixed, everything is green again

[fselmo]

rebased with main and squashed, merging 👍🏼