Error when setting a Timer text formatted as a json

[kleysonr]

I would like to log the elapsed time with the function's parameters as a json.

If I run the code below:

import time
from codetiming import Timer
import sys

def get_text(requestId, funcContext, parameters_to_exclude):
	_data = {
		'requestId': requestId,
		'exec_time_ms': '{:.0f}',
		'exec': {k:v for k,v in funcContext.f_locals.items() if k not in parameters_to_exclude}
	}
	return '{}'.format(_data)

def principal(name, age, city):
    
    print(get_text('111', sys._getframe(), []))

    with Timer():

        time.sleep(2)

principal(name='lara', age=30, city='boston')

I will get the following output:

{'requestId': '111', 'exec_time_ms': '{:.0f}', 'exec': {'name': 'lara', 'age': 30, 'city': 'boston'}}
Elapsed time: 2.0022 seconds

But I would like to get the following one:

{'requestId': '111', 'exec_time_ms': 2002, 'exec': {'name': 'lara', 'age': 30, 'city': 'boston'}}

Then I changed from Timer() to:

with Timer(text=get_text('111', sys._getframe(), ['request', 'info'])):

But after the change, I'm getting the following error:

Traceback (most recent call last):
  File "/usr/lib/python3.7/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/usr/lib/python3.7/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/home/kleyson/.vscode/extensions/ms-python.python-2021.9.1191016588/pythonFiles/lib/python/debugpy/__main__.py", line 45, in <module>
    cli.main()
  File "/home/kleyson/.vscode/extensions/ms-python.python-2021.9.1191016588/pythonFiles/lib/python/debugpy/../debugpy/server/cli.py", line 444, in main
    run()
  File "/home/kleyson/.vscode/extensions/ms-python.python-2021.9.1191016588/pythonFiles/lib/python/debugpy/../debugpy/server/cli.py", line 285, in run_file
    runpy.run_path(target_as_str, run_name=compat.force_str("__main__"))
  File "/usr/lib/python3.7/runpy.py", line 263, in run_path
    pkg_name=pkg_name, script_name=fname)
  File "/usr/lib/python3.7/runpy.py", line 96, in _run_module_code
    mod_name, mod_spec, pkg_name, script_name)
  File "/usr/lib/python3.7/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/data/detran/dev/face-recognition/software/app/test.py", line 24, in <module>
    principal(name='lara', age=30, city='boston')
  File "/data/detran/dev/face-recognition/software/app/test.py", line 21, in principal
    time.sleep(2)
  File "/home/kleyson/.virtualenvs/face-recognition/lib/python3.7/site-packages/codetiming/_timer.py", line 74, in __exit__
    self.stop()
  File "/home/kleyson/.virtualenvs/face-recognition/lib/python3.7/site-packages/codetiming/_timer.py", line 60, in stop
    text = self.text.format(self.last, **attributes)
KeyError: "'requestId'"

How to do that ? Is that possible ?

[gahjelle]

@kleysonr Thank you for a great description of your use case.

The reason that your change doesn't work is that under the hood Timer() uses .format() to insert the elapsed time into the string. However, the curly braces in the string representation of the _data dictionary are also attempted to be replaced.

There are a few different ways you can work around this (these mainly rely on enhancements to this package that are not covered in the accompanying article on https://realpython.com/python-timer/):

1. Use a callable to create the text dynamically (#30)

This is probably the closest to your code. The argument to text is allowed to be a function that takes one parameter (the elapsed time in seconds) and returns the text that should be printed. Since you rely on several other parameters as well, you can capture those in a closure and dynamically create the text function as an inner function (see https://realpython.com/inner-functions-what-are-they-good-for/#retaining-state-with-inner-functions-closures for details about closures):

import time
from codetiming import Timer
import sys


def create_text(requestId, funcContext, parameters_to_exclude):
    def get_text(exec_time_s):
        _data = {
            "requestId": requestId,
            "exec_time_ms": f"{1000 * exec_time_s:.0f}",
            "exec": {
                k: v
                for k, v in funcContext.f_locals.items()
                if k not in parameters_to_exclude
            },
        }
        return str(_data)  # "{}".format(_data)

    return get_text


def principal(name, age, city):
    with Timer(text=create_text("111", sys._getframe(), [])):
        time.sleep(2)


principal(name="lara", age=30, city="boston")

Note that create_text() returns a generated get_text() with the proper values for requestId, funcContext, and parameters_to_exclude set.

As a small detail, I replaced "{}".format(_data) with str(_data) since they do exactly the same thing and IMHO the latter is more explicit.

2. Have the logger take care of the extra information

This would be possible even with the original version of Timer, although we'll take advantage of the new attributes (#25) that can be used in text. This might be a more logical setup where the logger handles all the information that should be logged and the Timer only really concerns itself with measuring time. Still, it's fairly similar to version 1 above.

The difference from the previous version is that you use closures to create the logger function instead of a text callable:

import time
from codetiming import Timer
import sys


def create_logger(requestId, funcContext, parameters_to_exclude):
    def logger(exec_time_ms):
        _data = {
            "requestId": requestId,
            "exec_time_ms": exec_time_ms,
            "exec": {
                k: v
                for k, v in funcContext.f_locals.items()
                if k not in parameters_to_exclude
            },
        }
        print(_data)

    return logger


def principal(name, age, city):
    with Timer(
        text="{milliseconds:.0f}", logger=create_logger("111", sys._getframe(), [])
    ):
        time.sleep(2)


principal(name="lara", age=30, city="boston")

One added trick here is to use text="{milliseconds:0f}" which passes the elapsed time in milliseconds to the logger, so the conversion does not need to be done in the logger (again, so that logger is only concerned with logging and Timer takes care of things related to timing).

3. Manually print based on a Timer object (#13)

The elapsed time is available as a .last attribute after measuring the time. You can use this to manually print the information you're interested in. To do so, you need to add a reference to the timer, for instance using as t in the context manager. You should also use logger=None to turn off the normal printing of the elapsed time:

import time
from codetiming import Timer
import sys


def get_text(requestId, funcContext, parameters_to_exclude, exec_time_s):
    _data = {
        "requestId": requestId,
        "exec_time_ms": f"{1000 * exec_time_s:.0f}",
        "exec": {
            k: v
            for k, v in funcContext.f_locals.items()
            if k not in parameters_to_exclude
        },
    }
    return str(_data)


def principal(name, age, city):
    with Timer(logger=None) as t:
        time.sleep(2)
    print(get_text("111", sys._getframe(), ["t"], t.last))


principal(name="lara", age=30, city="boston")

You probably also want to add t as a parameter to exclude since it's only used for timing purposes. Personally, I think this is less elegant than the previous solution, but it gives you the flexibility to use the elapsed time however you want, and it avoids the inner functions if you're not comfortable with those.

Again, thank you for reporting this. I hope one of the suggestions works well for you.

Take care,
Geir Arne

[kleysonr]

Awesome.
Thanks.