Ведение журнала должно быть ленивым (потому что программисты)

Ведение журнала - одна из самых важных вещей в программировании. Я люблю называть это «искусством». Это потому, что если вы хорошо ведете журнал, вы можете сэкономить много времени (свое или своих товарищей по команде), если:

что-то идет не так в производстве
вы работаете над новым фрагментом кода
вы реорганизуете старую программу, которая в чем-то сложна

Тем не менее, есть несколько передовых методов ведения журнала. Мы хотели бы показать некоторые проблемы, связанные с производительностью, которые вы можете легко реализовать в своем повседневном коде.

Мы собираемся использовать для этого Python.

Ведение журнала Python

Вот привет, мир для входа в Python

>>>import logging
>>>logging.warning("Hello logging")
WARNING:root:Hello logging

Здесь мы используем warning в качестве уровня журнала, потому что это уровень по умолчанию, установленный в python, когда вы используете модуль ведения журнала (который использует экземпляр класса регистратора с именем root). Фактически, если вы попытаетесь запустить

>>>import logging
>>>logging.info(“Hello logging”)

Ничего не отображается, потому что уровень info ниже уровня warning и никаких сообщений не отображается.

Это определение функции warning в модуле logging

def warning(msg, *args, **kwargs):

Такая же структура применяется к определениям других уровней журнала. По сути, мы должны передать сообщение в качестве первого аргумента, но мы можем передать больше аргументов после этого.

Это ключ к шаблону ленивого ведения журнала. Позже мы увидим, почему это так важно.

Обсуждение дешево

Покажем код.

>>>import logging
>>>class RaiseWhenPrinted:
...    def __str__(self):
...        raise Exception(“I was printed”)
>>>raise_when_printed = RaiseWhenPrinted()

Итак, класс RaiseWhenPrinted вызывает исключение всякий раз, когда вы пытаетесь вызвать его метод __str__. Это происходит, например, когда вы хотите зарегистрировать экземпляр этого объекта raise_when_printed. Давай сделаем это

>>>logging.info(“Logging {}”.format(raise_when_printed))
Traceback (most recent call last):
File “<input>”, line 1, in <module>
File “<input>”, line 3, in __str__
Exception: I was printed

Таким образом, даже если уровень ведения журнала ниже info, возникает исключение. Это означает, что метод __str__ экземпляра RaiseWhenPrinted был вызван, даже если для уровня журнала не задано значение info.

Здесь на помощь приходит ленивое ведение журнала. Давайте изменим наш код.

>>>logging.info(“Logging %s”, raise_when_printed)

В этом случае исключение не возникает. Это означает, что метод __str__ не был вызван. Поэтому мы сделали наш журнал ленивым, потому что он не оценивался, если он нам действительно не нужен.

Фактически, если мы запустим

>>>logging.warning(“Logging %s”, raise_when_printed)

мы получаем полную трассировку стека исключения, что означает, что метод __str__ был вызван должным образом.

Это почему?

Объяснение довольно простое (и, на мой взгляд, очень элегантное).

Напомним определение функции уровня журнала info (которая совпадает с определением warning).

def info(msg, *args, **kwargs):

Итак, если мы напишем нашу команду журнала в коде, используя метод format для объединения строк (то же самое применимо для f-строк)

logging.info(“Logging {}”.format(raise_when_printed))

мы в основном говорим интерпретатору, что аргумент msg - это строка "Logging {}.format(raise_when_printed)", которая вычисляется немедленно во время выполнения.

Вместо этого напишите команду ленивым способом

logging.info(“Logging %s”, raise_when_printed)

сообщает интерпретатору, что аргумент msg - это "Logging %s”, которая является обычной строкой, а другой аргумент - это экземпляр raise_when_printed. Здесь метод __str__ еще не был вызван.

Когда программа достигает этой строки, вызывается функция info, которая внутренне проверяет, соответствует ли установленный уровень журнала. В противном случае ничего не происходит. В противном случае образуется строка.

Это в основном определение лени в программировании.

Время это!

Поговорим о спектаклях. Здесь мы используем библиотеку timeit. Эта библиотека может помочь нам подсчитать, сколько времени требуется для выполнения команды.

>>>import timeit
>>>lazy = “logging.info(‘lazy %s’, ‘logging’)”
>>>not_lazy = “logging.info(‘not lazy {}’.format(‘logging’))”
>>>setup = “import logging”

Итак, в основном мы создаем две наши команды ведения журнала lazy и not_lazy, потому что timeit хочет строку в качестве первого аргумента (он вызывает exec для этой строки). Переменная setup важна, потому что она указывает timeit, какие команды следует запускать для настройки среды. Если мы запустим две команды, мы получим

>>>timeit.timeit(not_lazy, setup=setup)
0.9043805910005176
>>>timeit.timeit(lazy, setup=setup)
0.7162870119991567

Так что разница не так велика, но мы должны заметить, что строка для регистрации очень проста. С учетом этого разница довольно большая.

Подводя итоги

Ленивое ведение журнала - не обычная практика в python, даже если это пример из официальной документации.

Я не могу сказать, что в Flowe мы регистрируем все таким образом, но мы знаем об этом и постепенно реорганизуем наш код, преобразовывая наши журналы в ленивые журналы.

Но если вы начинаете новый проект, вам обязательно стоит подумать об использовании этого подхода.

Ведение журнала должно быть ленивым (потому что программисты)