1

Тема: Исследование последних 5 сек. жизни LUA-скрипта в QUIK

Обновлено: 24.12.2012
(по сравнению с предыдущим вариантом данного материала помимо проверки на новой версии QUIK еще проведено исследование событий, происходящих при закрытии терминала)

Замечание: исследования проводились на терминале QUIK версии 6.8.4.14, возможно в других версиях будут какие-то отличия.


В описании обработчика OnStop в документации QLUA есть примечание:
"После окончания выполнения функции таймаут завершения работы скрипта 5 секунд. По истечении этого интервала функция main() завершается принудительно."

Стало интересно точно разобраться со следующими моментами:

  • сколько времени после нажатия кнопки "Завершить" еще может жить скрипт на самом деле?

  • от какого момента времени отсчитываются указанные 5 секунд?

  • вызываются ли в течение этих 5 секунд какие-либо другие обработчики?

  • вызываются ли после остановки скрипта какие-либо обработчики кроме OnStop()?

  • что происходит с работающими скриптами в момент закрытия терминала?

Для этого сделал такой простенький скрипт:

f = nil

function writeToLog(proc_name)
    f:write(os.date() .. " ".. proc_name .. "\n")
    f:flush()
end

function OnInit(path)
    f = io.open(path .. ".out", "w+t")
    writeToLog("OnInit")
end

function OnStop(signal)
    writeToLog("OnStop start")
    local i
    for i = 1, 6 do
        writeToLog("OnStop process")
        sleep(500)
    end
    writeToLog("OnStop end")
end

function OnClose()
    writeToLog("OnClose start")
    local i
    for i = 1, 6 do
        writeToLog("OnClose process")
        sleep(500)
    end
    writeToLog("OnClose end")
end

function main()
    writeToLog("main start")
    while true do
        writeToLog("main process")
        sleep(500)
    end
    writeToLog("main stop")
end

function OnAllTrade(trade)
    writeToLog("OnAllTrade")
end

Что здесь есть:

  • writeToLog - записывает переданную строку в в лог-файл

  • обработчик OnInit - создает лог-файл с именем <имя-файла-lua>.out, после чего в него записываются вызовы всех имеющихся функций

  • обработчик OnStop - содержит цикл задержки на 3 секунды (путем вызова 6 раз sleep на пол-секунды), чтобы можно было понять от какого момента отсчитываются 5 секунд; во время задержки раз в пол секунды производится запись в лог о работе OnStop

  • обработчик OnClose - содержит цикл задержки на 3 секунды (путем вызова 6 раз sleep на пол-секунды), чтобы можно было понять что еще обрабатывается в терминале; во время задержки раз в пол секунды производится запись в лог о работе OnClose

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

  • обработчик OnAllTrade - добавлен для того, чтобы можно было понять вызываются ли обработчики во время 5-ти секундного ожидания завершения работы скрипта или нет; выбран именно этот обработчик из тех соображений, что данное событие происходит очень часто; разумеется, в терминале открыта таблица всех сделок


Запустил скрипт. Через некоторое время нажал на кнопку "Остановить".
Через 8 сек. скрипт остановился (видно по диалогу скриптов Lua), запись в лог прекратилась. Что же там в логе?

Начало лога выглядит так:

09/18/13 02:40:25 OnInit
09/18/13 02:40:25 OnAllTrade
09/18/13 02:40:25 OnAllTrade
09/18/13 02:40:25 OnAllTrade
09/18/13 02:40:25 main start
09/18/13 02:40:25 main process
09/18/13 02:40:25 OnAllTrade
09/18/13 02:40:25 OnAllTrade
09/18/13 02:40:25 OnAllTrade

Что здесь интересно: несмотря на то, что вывод в лог текста "main start" стоит первой строкой внутри функции main(), однако до собственно старта этой функции (т.е. соотв. записи в лог) вполне могут быть вызваны другие обработчики (что мы видим на примере 3-х строк OnAllTrade), если соответствующие события происходят достаточно часто. Отсюда вывод: все инициирующие действия в скрипте обязательно необходимо выполнить внутри обработчика OnInit, т.к. только он гарантированно будет выполнен до запуска отдельного потока с main().

В середине лог-файла идут вперемешку записи "main process" и "OnAllTrade", это понятно, эту часть я опускаю. Интересное происходит в конце:

09/18/13 02:40:31 main process
09/18/13 02:40:31 OnAllTrade
09/18/13 02:40:31 OnAllTrade
09/18/13 02:40:31 OnAllTrade
09/18/13 02:40:31 OnAllTrade
09/18/13 02:40:32 main process
09/18/13 02:40:32 OnStop start
09/18/13 02:40:32 OnStop process
09/18/13 02:40:32 main process
09/18/13 02:40:33 OnStop process
09/18/13 02:40:33 main process
09/18/13 02:40:33 OnStop process
09/18/13 02:40:33 main process
09/18/13 02:40:34 OnStop process
09/18/13 02:40:34 main process
09/18/13 02:40:34 OnStop process
09/18/13 02:40:34 main process
09/18/13 02:40:35 OnStop process
09/18/13 02:40:35 main process
09/18/13 02:40:35 OnStop end
09/18/13 02:40:35 main process
09/18/13 02:40:36 main process
09/18/13 02:40:36 main process
09/18/13 02:40:37 main process
09/18/13 02:40:37 main process
09/18/13 02:40:38 main process
09/18/13 02:40:38 main process
09/18/13 02:40:39 main process
09/18/13 02:40:39 main process
09/18/13 02:40:40 main process

Здесь приведены буквально все последние строки из лога. Что тут видно:

  • В 02:40:32 нажата кнопка "Завершить" (запись в логе "OnStop start"), после чего видим поочередно идущие записи "OnStop process" и "main process" раз в пол-секунды.

  • Через 3 секунды в 02:40:35 завершается работа OnStop (запись в логе "OnStop end"), после чего в течение 5 секунд, т.е. до 02:40:40 в логе есть записи о работе функции main() - "main process". Таким образом с момента нажатия "Завершить" прошло 8 сек, и только после этого скрипт был остановлен.

  • Отмечу также, что после начала работы OnStop больше в логе нет ни одной записи про вызов OnAllTrade, хотя до этого такие события происходили крайне часто.


Из всего этого можно сделать следующие выводы:

  1. 5 секунд на завершение функции main() дается с момента после завершения обработчика OnStop(), а не с момента нажатия на кнопку "Завершить" (что соответствует документации). Т.е. сам обработчик OnStop() может работать сколько угодно времени.

  2. После вызова OnStop() и до самого окончания работы скрипта никакой другой обработчик (кроме работы функции main) не вызывается; во время работы OnStop() отсутствие вызовов понятно: эта функция работает в том же потоке, что и другие функции обратного вызова, а потому пока OnStop() не завершится, другие вызваны быть не могут; а дальше, думаю, ожидание завершения main (т.е. отдельного потока) организовано в основном потоке терминала, причем "жестким тупым циклом", а не на объектах синхронизации с тайм-аутом, использование которых наверное дало бы возможность отработать еще и другим обработчикам; нельзя сказать, что это недочет, просто такая реализация. Хотя, конечно, хорошо бы документировать тот факт, что другие обработчики после OnStop() уже не работают.


После этого я снова запустил скрипт и закрыл терминал QUIK.

Что произошло: окно терминала тут же исчезло, однако запись в лог продолжалась! Т.е. скрипт продолжал работать. Впрочем, примерно тоже самое время, вот финальный фрагмент лога для этого случая:

09/18/13 02:44:02 OnAllTrade
09/18/13 02:44:02 OnAllTrade
09/18/13 02:44:02 OnAllTrade
09/18/13 02:44:02 main process
09/18/13 02:44:03 OnClose start
09/18/13 02:44:03 OnClose process
09/18/13 02:44:03 main process
09/18/13 02:44:03 OnClose process
09/18/13 02:44:03 main process
09/18/13 02:44:04 OnClose process
09/18/13 02:44:04 main process
09/18/13 02:44:04 OnClose process
09/18/13 02:44:04 main process
09/18/13 02:44:05 OnClose process
09/18/13 02:44:05 main process
09/18/13 02:44:05 OnClose process
09/18/13 02:44:05 main process
09/18/13 02:44:06 OnClose end
09/18/13 02:44:06 OnStop start
09/18/13 02:44:06 OnStop process
09/18/13 02:44:06 main process
09/18/13 02:44:06 OnStop process
09/18/13 02:44:06 main process
09/18/13 02:44:07 OnStop process
09/18/13 02:44:07 main process
09/18/13 02:44:07 OnStop process
09/18/13 02:44:07 main process
09/18/13 02:44:08 OnStop process
09/18/13 02:44:08 main process
09/18/13 02:44:08 OnStop process
09/18/13 02:44:08 main process
09/18/13 02:44:09 OnStop end
09/18/13 02:44:09 main process
09/18/13 02:44:09 main process
09/18/13 02:44:10 main process
09/18/13 02:44:10 main process
09/18/13 02:44:11 main process
09/18/13 02:44:11 main process
09/18/13 02:44:12 main process
09/18/13 02:44:12 main process
09/18/13 02:44:13 main process
09/18/13 02:44:13 main process
  • Вначале 3 секунды работает OnClose()

  • Затем 3 секунды работает OnStop()

  • После чего еще 4 секунды (вероятно, это погрешность изменений) работает main(), после чего скрипт останавливается и процесс терминала QUIK info.exe прекращает работу (исчезает из диспетчера задач)

  • Отмечу также, что после закрытия терминала вызываются только OnClose() и OnStop(). Ни одной записи про вызов OnAllTrade() больше нет.


Из этого можно сделать дополнительные выводы:

  1. И при закрытии терминала, и при остановке его кнопкой "Остановить" диалога Lua-скриптов всегда будет самым последним вызван OnStop(), причем в случае закрытия терминала он будет вызван после OnClose().


По результатам была обновлена картинка в части места отсчета 5-ти секундного интервала.

Архив со скриптом и полным логом здесь.

2

Re: Исследование последних 5 сек. жизни LUA-скрипта в QUIK

Это пост оставил просто для истории, как было в самой первой версии, когда появилась возможность писать скрипты на Lua в QUIK.

Замечание: исследования проводились на терминале QUIK версии 6.4.0.169, возможно в других версиях будут какие-то отличия.

Открыл таблицу "Всех сделок", запустил скрипт. Через некоторое время нажал на кнопку "Остановить".
Через 8 сек. терминал QUIK упал с какой-то внутренней ошибкой, а я пошел смотреть лог.

Начало лога выглядит так:

01/06/13 00:04:55 OnInit
01/06/13 00:04:55 OnAllTrade
01/06/13 00:04:55 OnAllTrade
01/06/13 00:04:55 OnAllTrade
01/06/13 00:04:55 main start
01/06/13 00:04:55 main process
01/06/13 00:04:55 OnAllTrade
01/06/13 00:04:55 OnAllTrade

Что здесь интересно: несмотря на то, что запись "main start" в лог-файл стоит первой строкой в main, однако до собственно старта этой функции вполне могут быть вызваны другие обработчики (что мы видим на примере 3-х строк OnAllTrade), если соответствующие события происходят достаточно часто. Т.е. все инициирующие действия в скрипте обязательно необходимо выполнить в обработчике OnInit.

В середине лог-файла идут вперемешку записи "main process" и "OnAllTrade", это понятно, эту часть я опускаю. Интересное происходит в конце:

01/06/13 00:05:05 OnAllTrade
01/06/13 00:05:05 main process
01/06/13 00:05:05 main process
01/06/13 00:05:06 main process
01/06/13 00:05:06 OnStop start
01/06/13 00:05:06 OnStop process
01/06/13 00:05:06 main process
01/06/13 00:05:06 OnStop process
01/06/13 00:05:07 main process
01/06/13 00:05:07 OnStop process
01/06/13 00:05:07 main process
01/06/13 00:05:07 OnStop process
01/06/13 00:05:08 main process
01/06/13 00:05:08 OnStop process
01/06/13 00:05:08 main process
01/06/13 00:05:08 OnStop process
01/06/13 00:05:09 main process
01/06/13 00:05:09 OnStop end
01/06/13 00:05:09 main process
01/06/13 00:05:10 main process
01/06/13 00:05:10 main process
01/06/13 00:05:11 main process
01/06/13 00:05:11 main process
01/06/13 00:05:12 main process
01/06/13 00:05:12 main process
01/06/13 00:05:13 main process
01/06/13 00:05:13 main process
01/06/13 00:05:14 main process 

Здесь приведены буквально все последние строки из лога. Что тут видно:

  • В 00:05:06 нажата кнопка "Завершить" (запись в логе "OnStop start"), после чего видим поочередно идущие записи "OnStop process" и "main process" раз в пол-секунды.

  • Через 3 секунды в 00:05:09 завершается работа OnStop (запись в логе "OnStop end"), после чего в течение 5 секунд, т.е. до 00:05:14 в логе есть записи и работе функции main "main process". Таким образом с момента нажатия "Завершить" прошло 8 сек, и только после этого скрипт был остановлен.

  • Отмечу также, что после начала работы OnStop в логе нет ни одной записи про вызов OnAllTrade, хотя до этого такие события происходили крайне часто.


Из всего этого можно сделать такие выводы:

  1. 5 секунд на завершение функции main дается после завершения обработчика OnStop, а не после нажатия на кнопку "Завершить" (что соответствует документации).

  2. После вызова OnStop и до самого окончаня работы скрипта никакой другой обработчик (кроме работы функции main) не вызывается; во время работы OnStop отсутствие вызовов понятно: эта функция работает в том же потоке, что и другие обработчики, а потому пока она не завершится, другие вызваны быть не могут; а дальше, думаю, ожидание завершения main (т.е. отдельного потока) организовано в основном же потоке терминала, причем "жестким тупым циклом", а не на объектах синхронизации с тайм-аутом, использование которых наверное дало бы возможность отработать еще и другим обработчикам; нельзя сказать, что это недочет, просто такая реализация.

  3. То, что терминал "упал" после принудительного завершения main связано, думаю, с тем, что, как известно, в исследуемой версии 6.4.0.169 присутствует ошибка вызова обработчиков после завершения скрипта; я думаю, что вызов OnTrade после завершения скрипта (и, наверное, завершении работы виртуальной LUA-машины) приводит к каким-то разрушительным последствиям, из-за чего терминал падает; справедливость такой версии можно будет проверить позже, когда указанная ошибка будет исправлена.

3

Re: Исследование последних 5 сек. жизни LUA-скрипта в QUIK

< reserved >