Debug fstring bottleneck in sending

[scrameta]

In the file cluster.py there is a line that logs the args as debug using a fstring. This is a significant bottleneck when sending large messages even when logging is disabled since the fstring is always evaluated. Please could it be changed as follows:

diff cluster.py cluster.py -u

--- cluster.py 2022-04-12 09:47:46.545790433 +0000

+++ cluster.py 2022-04-12 09:51:55.789286947 +0000

@@ -900,7 +900,7 @@

         node = self.nodes_manager.get_node_from_slot(

             slot, self.read_from_replicas and command in READ_COMMANDS

         )

•        log.debug(f"Target for {args}: slot {slot}")
  

•        log.debug("Target for {%s}: slot {%s}",args,slot)
  
         return [node]
  

  def _should_reinitialized(self):

[chayim]

@dvora-h mind taking a look? This looks like a bug we picked up in the cluster PR and should not be present.

[alongouldman]

@chayim @dvora-h can i take this issue and fix it all over the code? I'm happy to 😊

Here is explanation about why %-string is better:

https://blog.pilosus.org/posts/2020/01/24/python-f-strings-in-logging/

[chayim]

There's been a lot of discussion on f-strings being better than %s formatters recently (and hence the switch to that in redis-py).

If we can demonstrate this is true, then we should also remove the string checker for CI (cc @dvora-h )

[utkarshgupta137]

f-strings are only a bottleneck for logging because %s substitutions are deferred & possibly skipped, like in the case of debug logs in cluster code, which were recently removed in #2238.

[alongouldman]

@chayim I'm happy to demonstrate, do you mean in general demonstration, or in redis's use case?

If you mean in redis, do you have a set of performance tests which I can use?

[chayim]

@alongouldman We don't have perf tests here in the repo that are viable - though we keep starting and stopping that.

I mean the redis use case. But frankly, if it's generically pythonic (as in how list comprehensions beat out pure for loops), that's fine.

[alongouldman]

Hi @chayim

This is the test I run:

import logging
import timeit

def short_f_string():
	name = "world"
	logging.debug(f"hello {name}")


def long_f_string():
	name = """
	looooooooooooooooooooooooooooooonnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnngggggggggggggggggg  massage wow this is so longg
	looooooooooooooooooooooooooooooonnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnngggggggggggggggggg  massage wow this is so longg
	looooooooooooooooooooooooooooooonnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnngggggggggggggggggg  massage wow this is so longg
	looooooooooooooooooooooooooooooonnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnngggggggggggggggggg  massage wow this is so longg
	looooooooooooooooooooooooooooooonnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnngggggggggggggggggg  massage wow this is so longg
	looooooooooooooooooooooooooooooonnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnngggggggggggggggggg  massage wow this is so longg
	looooooooooooooooooooooooooooooonnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnngggggggggggggggggg  massage wow this is so longg
	looooooooooooooooooooooooooooooonnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnngggggggggggggggggg  massage wow this is so longg
	looooooooooooooooooooooooooooooonnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnngggggggggggggggggg  massage wow this is so longg
	looooooooooooooooooooooooooooooonnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnngggggggggggggggggg  massage wow this is so longg
	looooooooooooooooooooooooooooooonnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnngggggggggggggggggg  massage wow this is so longg
	looooooooooooooooooooooooooooooonnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnngggggggggggggggggg  massage wow this is so longg
	looooooooooooooooooooooooooooooonnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnngggggggggggggggggg  massage wow this is so longg
	looooooooooooooooooooooooooooooonnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnngggggggggggggggggg  massage wow this is so longg
	looooooooooooooooooooooooooooooonnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnngggggggggggggggggg  massage wow this is so longg
	looooooooooooooooooooooooooooooonnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnngggggggggggggggggg  massage wow this is so longg
	"""
	logging.debug(f"hello {name}")


def multiple_f_string():
	name = "world"
	other = "how are you today"
	num = 4
	logging.debug(f"hello {name}, {other}? {num} | hello {name}, {other}? {num} | hello {name}, {other}? {num} | hello {name}, {other}? {num}")



def short_string_format():
	name = "world"
	logging.debug("hello %s", name)


def long_string_format():
	name = """
	looooooooooooooooooooooooooooooonnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnngggggggggggggggggg  massage wow this is so longg
	looooooooooooooooooooooooooooooonnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnngggggggggggggggggg  massage wow this is so longg
	looooooooooooooooooooooooooooooonnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnngggggggggggggggggg  massage wow this is so longg
	looooooooooooooooooooooooooooooonnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnngggggggggggggggggg  massage wow this is so longg
	looooooooooooooooooooooooooooooonnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnngggggggggggggggggg  massage wow this is so longg
	looooooooooooooooooooooooooooooonnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnngggggggggggggggggg  massage wow this is so longg
	looooooooooooooooooooooooooooooonnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnngggggggggggggggggg  massage wow this is so longg
	looooooooooooooooooooooooooooooonnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnngggggggggggggggggg  massage wow this is so longg
	looooooooooooooooooooooooooooooonnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnngggggggggggggggggg  massage wow this is so longg
	looooooooooooooooooooooooooooooonnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnngggggggggggggggggg  massage wow this is so longg
	looooooooooooooooooooooooooooooonnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnngggggggggggggggggg  massage wow this is so longg
	looooooooooooooooooooooooooooooonnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnngggggggggggggggggg  massage wow this is so longg
	looooooooooooooooooooooooooooooonnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnngggggggggggggggggg  massage wow this is so longg
	looooooooooooooooooooooooooooooonnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnngggggggggggggggggg  massage wow this is so longg
	looooooooooooooooooooooooooooooonnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnngggggggggggggggggg  massage wow this is so longg
	looooooooooooooooooooooooooooooonnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnngggggggggggggggggg  massage wow this is so longg
	"""
	logging.debug("hello %s", name)


def multiple_string_format():
	name = "world"
	other = "how are you today"
	num = 4
	logging.debug(
		"hello %s, %s? %d | hello %s, %s? %d | hello %s, %s? %d | hello %s, %s? %d",
		name, other, num,
		name, other, num,
		name, other, num,
		name, other, num,
	)


if __name__ == "__main__":
	amount = 10000000
	print("string_format")
	print("short_string_format: ", timeit.timeit(short_string_format, number=amount))
	print("long_string_format: ", timeit.timeit(long_string_format, number=amount))
	print("multiple_string_format: ", timeit.timeit(multiple_string_format, number=amount))

	print("f-string")
	print("short_f_string: ", timeit.timeit(short_f_string, number=amount))
	print("long_f_string: ", timeit.timeit(long_f_string, number=amount))
	print("multiple_f_string: ", timeit.timeit(multiple_f_string, number=amount))

These are the results:

➜  /Users/alon/Library/Application Support/JetBrains/PyCharm2021.3/scratches python scratch_22.py
f-string
short_f_string:  7.538512164999999
long_f_string:  8.713512263999998
multiple_f_string:  13.378046865999998
string_format
short_string_format:  7.461573618999996
long_string_format:  7.435051018999999
multiple_string_format:  8.826595583

➜  /Users/alon/Library/Application Support/JetBrains/PyCharm2021.3/scratches python scratch_22.py
string_format
short_string_format:  7.590091192999999
long_string_format:  7.533264764000001
multiple_string_format:  8.920953102
f-string
short_f_string:  7.827805414
long_f_string:  9.243438682
multiple_f_string:  13.923798607999998

➜  /Users/alon/Library/Application Support/JetBrains/PyCharm2021.3/scratches python scratch_22.py
string_format
short_string_format:  8.702303225
long_string_format:  8.292103442999998
multiple_string_format:  9.268010628000003
f-string
short_f_string:  8.124534014999998
long_f_string:  9.488321374000002
multiple_f_string:  14.037382780999998

➜  /Users/alon/Library/Application Support/JetBrains/PyCharm2021.3/scratches python scratch_22.py
f-string
short_f_string:  8.382262702
long_f_string:  9.412909211000002
multiple_f_string:  13.798953093000002
string_format
short_string_format:  7.728673025999999
long_string_format:  7.664428079000004
multiple_string_format:  8.991047841000004

(I tried to change the order of the function calls, just to make sure that its nothing to do with the order for some reason)

Looks like in a single short string format, there is no much difference... but either long text, or multiple arguments, %-format is faster.

What do you think? Should I change that around redis-py's codebase?

[github-actions]

This issue is marked stale. It will be closed in 30 days if it is not updated.