python ведение журнала выполняется очень медленно или неправильно настроено? - PullRequest
Новая
       3

python ведение журнала выполняется очень медленно или неправильно настроено?

0 голосов
/ 18 января 2020

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

Вот фрагмент кода для иллюстрации, который записывает строки CNT_MAX в файл с помощью явной записи или с помощью модуля регистрации (в зависимости от наличие аргумента запуска). 

import logging
import sys

LOG_FILE = "log.log" 
LOG_LINE = "="*200
CNT_MAX = 50000

def main():
    if len (sys.argv) >= 2:
        print("using logger")
        logging.basicConfig(filename=LOG_FILE, level=logging.INFO, filemode="w+")
        logger = logging.getLogger("L")

        for i in range(1,CNT_MAX):
            logger.info(LOG_LINE)

    else:
        print("explicit write")

        with open(LOG_FILE,"w+") as f:
            for i in range(1,CNT_MAX):
                f.write(LOG_LINE + "\n")


if __name__ == "__main__":
    main()

Вот две грубые оценки времени выполнения:

через регистратор 

%time python ./main.py 11
using logger
python ./main.py 11  1.13s user 0.08s system 99% cpu 1.223 total

явная запись 

%time python ./main.py
explicit write
python ./main.py  0.03s user 0.02s system 92% cpu 0.047 total

Я понимаю, что под капотом есть logi c и buffering et c, но производительность резко отличается, и никаких предупреждений об этом нет на первых страницах документа / примеров, поэтому, похоже, он не должен вести себя в таким образом.

На реальном скрипте я получил около десятков секунд с регистратором vs 1-2 с явной оболочкой записи файла.

Я проверил с помощью strace для, регистрация mb открывает / закрывает файл для каждый вызов журналирования (это было сумасшедшее предположение, я знаю, но я все равно должен был проверить), но сначала показалось, что основное отличие заключается в количестве методов записи системы (ниже приведены примеры трассировки для ru n с CNT_MAX = 5 в качестве иллюстрации)

трассировка с ведением журнала: 

%2>&1 strace python ./main.py 11|tail -15
fstat(1, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
getcwd("/home/omgzomg/check_logger", 1024) = 24
open("/home/omgzomg/check_logger/log.log", O_RDWR|O_CREAT|O_TRUNC, 0666) = 3
fstat(3, {st_mode=S_IFREG|0664, st_size=0, ...}) = 0
fstat(3, {st_mode=S_IFREG|0664, st_size=0, ...}) = 0
write(3, "INFO:L:========================="..., 209) = 209
write(3, "INFO:L:========================="..., 209) = 209
write(3, "INFO:L:========================="..., 209) = 209
write(3, "INFO:L:========================="..., 209) = 209
close(3)                                = 0
rt_sigaction(SIGINT, {SIG_DFL, [], SA_RESTORER, 0x7f14172d9390}, {0x534a20, [], SA_RESTORER, 0x7f14172d9390}, 8) = 0
write(1, "using logger\n", 13using logger
)          = 13
exit_group(0)                           = ?
+++ exited with 0 +++

трассировка с явной записью: 

%2>&1 strace python ./main.py|tail -15
read(5, "", 4096)                       = 0
close(5)                                = 0
close(4)                                = 0
close(3)                                = 0
fstat(1, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
open("log.log", O_RDWR|O_CREAT|O_TRUNC, 0666) = 3
fstat(3, {st_mode=S_IFREG|0664, st_size=0, ...}) = 0
fstat(3, {st_mode=S_IFREG|0664, st_size=0, ...}) = 0
write(3, "================================"..., 808) = 808
close(3)                                = 0
rt_sigaction(SIGINT, {SIG_DFL, [], SA_RESTORER, 0x7f83ed9f8390}, {0x534a20, [], SA_RESTORER, 0x7f83ed9f8390}, 8) = 0
write(1, "explicit write\n", 15explicit write
)        = 15
exit_group(0)                           = ?
+++ exited with 0 +++

Хорошо, я добавил грипп sh после каждая запись в файл, как: 

        with open(LOG_FILE,"w+") as f:
            for i in range(1,CNT_MAX):
                f.write(LOG_LINE + "\n")
                f.flush()

Теперь трассировка показывает явный системный вызов записи, становится немного медленнее, но все равно не ухудшается: 

%time python ./main.py
explicit write
python ./main.py  0.08s user 0.10s system 99% cpu 0.177 total

трассировка: 


fstat(1, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
open("log.log", O_RDWR|O_CREAT|O_TRUNC, 0666) = 3
fstat(3, {st_mode=S_IFREG|0664, st_size=0, ...}) = 0
fstat(3, {st_mode=S_IFREG|0664, st_size=0, ...}) = 0
write(3, "================================"..., 202) = 202
write(3, "================================"..., 202) = 202
write(3, "================================"..., 202) = 202
write(3, "================================"..., 202) = 202
close(3)                                = 0
rt_sigaction(SIGINT, {SIG_DFL, [], SA_RESTORER, 0x7f456e3e9390}, {0x534a20, [], SA_RESTORER, 0x7f456e3e9390}, 8) = 0
write(1, "explicit write\n", 15explicit write
)        = 15
exit_group(0)                           = ?
+++ exited with 0 +++

Какую конфигурацию я пропускаю? Какой-то поток или другое кэширование или другой параметр?

...