Возможно ли, что временные метки в файле журнала Python не являются хронологическими в многопоточной системе? - PullRequest
Новая
       14

Возможно ли, что временные метки в файле журнала Python не являются хронологическими в многопоточной системе?

0 голосов
/ 15 января 2019

Я написал свой код в API Python, управляемом событиями. on_tick() вызывается API асинхронно, и внутри этой функции лежит мой код. Между двумя последовательными вызовами на on_tick() моя обработка обычно заканчивается, но иногда занимает больше времени. Я вошел в on_tick() в трех местах и ​​ожидаю, что эти строки будут записаны в хронологическом порядке. Но иногда я вижу, что в следующей строке время журнала меньше, чем в предыдущей строке! Как на земле это возможно? 

def on_tick(ticks):

    logging.info('entered inside on_tick()')

    tens_of_lines;

    logging.info('calling strategy controller from on_tick()') 

    strategy_controller()

    logging.info('returning from on_tick()') 

    return

при извлечении нескольких строк из файла журнала, я вижу: 

2019-01-14 09:25:17,434 entered inside on_tick()
2019-01-14 09:25:17,452 calling strategy controller from on_tick()
2019-01-14 09:25:18,241 returning from on_tick()
2019-01-14 09:25:18,252 entered inside on_tick()
2019-01-14 09:25:18,294 calling strategy controller from on_tick()
2019-01-14 09:25:18,956 returning from on_tick()
2019-01-14 09:25:18,957 entered inside on_tick()
2019-01-14 09:25:19,994 calling strategy controller from on_tick()
=> 2019-01-14 09:25:19,685 returning from on_tick()
2019-01-14 09:25:19,696 entered inside on_tick()
2019-01-14 09:25:19,722 calling strategy controller from on_tick()
2019-01-14 09:25:20,270 returning from on_tick()
2019-01-14 09:25:20,280 entered inside on_tick()
2019-01-14 09:25:20,315 calling strategy controller from on_tick()
2019-01-14 09:25:20,563 returning from on_tick()

Я специально выделил проблемную строку с =>. Он печатается позже, но имеет более раннюю временную отметку. Это тоже на сотни миллисекунд! Я даже не могу думать о сценариях, где это возможно. Кроме того, если следующий вызов on_tick() произойдет до того, как завершится предыдущий вызов, завершится ли предыдущий вызов первым, сохранив поток следующего вызова приостановленным? Можете ли вы помочь?

РЕДАКТИРОВАТЬ: я попытался изменить команду logging.info() на logfile.write(), где logfile - это дескриптор файла журнала, полученного с помощью команды open. Время, которое я записал в файлы, получается datetime.now(). БИНГО! Это решило проблему. Теперь все записанные строки имеют хронологическое время. Чтобы понять, почему это происходит, я сохранил в целых строках и 1018 *, и logfile.write и записал их в два разных файла. Я понял, что logging.info иногда печатает неправильно! И эти неправильные времена отстают от меня ровно на 1 секунду! Например, в приведенном выше журнале единственное неправильное время - это строка выше =>, т. Е. Фактически 19,994 должно было быть 18,994.

Не уверен, почему это происходит. Я использую приведенную ниже конфигурацию для регистрации. 

logger = logging.getLogger('some_random_string')

#The below is done to make sure the vendor's API doesn't mess with my logs
for handler in logging.root.handlers[:]:
    logging.root.removeHandler(handler)

logging.basicConfig(format='%(asctime)s %(message)s', filename='log_file_name.log',level=logging.INFO)

#Change the logging time to India time
def customTime(*args):
    utc_dt = pytz.utc.localize(datetime.utcnow())
    my_tz = pytz.timezone("Asia/Calcutta")
    converted = utc_dt.astimezone(my_tz)
    return converted.timetuple()

logging.Formatter.converter = customTime

1 Ответ

0 голосов
/ 15 января 2019

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

...