Compare greedy vs lazy string interpolation in log messages

log-timing.py

# A simple timing test to compare lazy and greedy string interpolation
# in log messages

import timeit

# Debug messages will not be logged
SETUP = '''
import logging
logging.basicConfig(level=logging.WARNING)
log = logging.getLogger("mylogger")
fvalue = 3.14
ivalue = 1
svalue = 'Hello world'
'''

# Logging with f-strings (greedy string interpolation)
greedy_logging = '''
log.info(f'fstring float value {fvalue:2.3f} int value {ivalue:03} string value {svalue:>20}')
'''

# Lazy string interpolation
lazy_logging = '''
log.info('percent float value %2.3f int value %03d string value "%20s", fvalue, ivalue, svalue')
'''

if __name__ == '__main__':
    n = 1000000
    t_greedy = timeit.timeit(greedy_logging, setup=SETUP, number=n)
    t_lazy = timeit.timeit(lazy_logging, setup=SETUP, number=n)
    print(f'Greedy: {t_greedy}')
    print(f'Lazy  : {t_lazy}')

    print(f'greedy / lazy = {t_greedy*100/t_lazy:3.2f}%')
    print(f'lazy / greedy = {t_lazy*100/t_greedy:3.2f}%')

output.txt

Greedy: 0.918115834
Lazy  : 0.22738941700000004
greedy / lazy = 403.76%
lazy / greedy = 24.77%