From e5451053c69c535d6663a1f6e12d883d3b996b91 Mon Sep 17 00:00:00 2001 From: sys4-fr Date: Sat, 8 Sep 2018 15:19:48 +0200 Subject: [PATCH] =?UTF-8?q?Remplissage=20du=20d=C3=A9p=C3=B4t.?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- README.txt | 77 +++++++++++++++++++++++ after.lua | 40 ++++++++++++ init.lua | 181 +++++++++++++++++++++++++++++++++++++++++++++++++++++ queue.lua | 101 ++++++++++++++++++++++++++++++ 4 files changed, 399 insertions(+) create mode 100644 README.txt create mode 100644 after.lua create mode 100644 init.lua create mode 100644 queue.lua diff --git a/README.txt b/README.txt new file mode 100644 index 0000000..3f60bcf --- /dev/null +++ b/README.txt @@ -0,0 +1,77 @@ +[profnsched] : Profile and schedule mod (fr) +============================================ + +Buts : +====== + * Objectif principal : maintenir le temps d'exécution du pas (step) au plus près du tick rate (dedicated_server_step) + * analyser en temps réel les temps d'execution de certaines fonctions de module + (actuellement uniquement globalstep et minetest.after) + * Décaler, de façon adaptative, l'exécution des modules qui l'autorisent explicitement en cas de surcharge + * (WIP) Indiquer à chaque module le temps dont il dispose pour s'exécuter (utile pour les modules qui adaptent leurs calculs) + + +Concepts : +========== + * Les travaux en attentes sont placés dans des files d'executions priorisées + * La première file est toujours exécutée, même en cas de surcharge + * Les autres files sont traitées tant qu'il reste du temps (< tick rate) + * En cas d'arrêt prématuré (surcharge), chaque classe de priorité est transférée dans la précédente (ainsi en cas de surcharge on est certain que le travail sera executé) + * Il peut y avoir autant de files que souhaités (rester raisonnable cependant) + * Concrêtement : + - Dans l'idéal, toutes les files sont exécutées à chaque pas (step) ! + - En cas de surcharge, on a la garantie que les travaux de la file n seront exécutés au pas (step) n ou n+1 + - Mais on a aucune garantie de temps (à cause de la surcharge, les pas (step) dépassent le tick rate, parfois de plusieurs secondes...) + - Ne pas oublier que de toute façon en cas de surcharge, ni globalstep.after ni minetest.after ne peuvent garantir le temps écoulé + * En cas de surcharge une trace des travaux exécutés est transcrite dans le log du serveur (pour analyse des goulots d'étranglement) + + +Fonctions utiles : +================== + * Pour programmer : + * scheduler.add(class, job) -- ajoute le travail 'job' dans la file n° 'class' (job = {mod_name, func_id, func_code[, args]}) + * scheduler.asap(class, func_code) -- ajoute une fonction à exécuter dans la file n° 'class' + * Pour profiler (commande chat) : + /profnsched (génère un dump de stats au bout du nombre de secondes définies dans minetest.conf) + /profnsched n (génère un dump de stats au bout de n secondes) + /profnsched 0 (dump les stats en temps réel en cas de surcharge) + * Pour profiler (minetest.conf) + profnsched_activate = true/false + profnsched_dump_delay = n (dump des stats au bout de n secondes (si activé)) + + +Comparaisons : +============== + * minetest.globalstep + - Pour les traitements qui *nécessitent* une exécution à chaque pas (step) + - Peut être remplacé par minetest.after(0, *) ou scheduler.asap(0, *) mais cela ajoute du temps de traitement inutile. + * minetest.after + - Pour les traitements qui doivent s'exécuter après un certain temps écoulé + - Dans l'idéal c'est fiable, mais en cas de surcharge le temps peut être largement dépassé (inévitable) + * scheduler.add/asap + - Pour les traitements qui souhaitent être fréquemment exécutés + - mais qui n'ont pas besoin d'une fréquence fixe (tick) + - ni d'une durée précise entre chaque execution + - en bref qui acceptent de sacrifier de leur temps au profit de traitements plus importants qu'eux + + +Exemples possibles : +==================== + * Les calculs capitaux en file 1 + * Les traitements d'UI pourraient être en file 2 ou 3 + * Les traitements encore moins importants en file supérieure (génération des plantes, ...) + + +Hack actuel : +============= + * La boucle minetest.after qui vérifie les travaux expirés est classée en faible priorité (file 4) + (dans le meilleur des cas la vérification a lieu à chaque pas (step), sinon on reporte) + * Les travaux eux-mêmes issus de minetest.after sont en file 4 + (dans le meilleur des cas ils seront exécutés au prochain pas (step), sinon on reporte) + + +TODO : +====== + * fournir en paramètre au module appelé le temps d'execution souhaité/maximum + * mettre d'autres appels en surveillance (on_step, ...) + * nettoyer/optimiser le code ;) + diff --git a/after.lua b/after.lua new file mode 100644 index 0000000..70f5e5f --- /dev/null +++ b/after.lua @@ -0,0 +1,40 @@ +dofile(minetest.get_modpath("profnsched").."/queue.lua") + +local jobs = {} +local scheduler = scheduler + +function getnjobs() + return #jobs +end + +-- For minetest.after replacement +local function check_expired_jobs() + local time = core.get_us_time() + local tjobs = {} + for i,job in pairs(jobs) do + if time >= job.expire then + scheduler.add(1, job) + --jobs[i] = nil + else + tjobs[#tjobs+1] = job + end + end + jobs = tjobs + scheduler.asap(4, check_expired_jobs) +end +scheduler.asap(4, check_expired_jobs) + + +-- redefine core.after function +function minetest.after(after, func, ...) + assert(type(func) == "function", "Invalid core.after invocation") + local fname = debug.getinfo(2, "S").linedefined --imprecis + local job = { + func_code = func, + expire = core.get_us_time() + after*1000000, + arg = {...}, + mod_name = core.get_last_run_mod(), + func_id = "#"..fname + } + jobs[#jobs+1] = job +end diff --git a/init.lua b/init.lua new file mode 100644 index 0000000..5ea060b --- /dev/null +++ b/init.lua @@ -0,0 +1,181 @@ +dofile(minetest.get_modpath("profnsched").."/queue.lua") +dofile(minetest.get_modpath("profnsched").."/after.lua") + +local durations = {} +local active = minetest.setting_get("profnsched_activate") +local dump_delay = minetest.setting_get("profnsched_dump_delay") +if not active then active = false end +if not dump_delay then dump_delay = 60*5 end + + +local mathfloor = math.floor + +-- Usefull funcs + +local function dump_durations(current) --param: current durations or nil (to dump global durations) + if current then + local avg = 0 + local dt = 0 + for i,v in pairs(current) do + dt = mathfloor(v[3])/1000 + avg = mathfloor(durations[v[1]][v[2]].us/durations[v[1]][v[2]].n)/1000 + minetest.log("[Profnsched] "..dt.."ms (avg: "..avg.." ; "..durations[v[1]][v[2]].n.." calls) "..v[1].." "..v[2]) + end + else + for i,md in pairs(durations) do + for j,fn in pairs(md) do + avg = mathfloor(fn.us/fn.n)/1000 + minetest.log("[Profnsched] avg: "..avg.." ; "..fn.n.." calls ; "..i.." "..j) + end + end + end +end + +local function activate() + if active then + if dump_delay ~= 0 then + minetest.log("[Profnsched] Will dump global stats in "..dump_delay.."s") + minetest.after(dump_delay, dump_durations) + else + minetest.log("[Profnsched] Now will dump RT stats") + end + end +end +activate() + +minetest.register_chatcommand("profnsched", { + params = "", + description = "Activate mods profiling", + func = function(name, param) + active = true + if param == "" then + dump_delay = minetest.setting_get("profnsched_dump_delay") + if not dump_delay then dump_delay = 60*5 end + else + dump_delay = tonumber(param) + end + activate() + end +}) + + + + +local function update_durations(mod_name, func_id, dtime) + if not durations[mod_name] then + durations[mod_name] = {} + end + if not durations[mod_name][func_id] then + durations[mod_name][func_id] = { + us = 0, + n = 0, + cur = 0 + } + end + durations[mod_name][func_id].us = durations[mod_name][func_id].us + dtime + durations[mod_name][func_id].n = durations[mod_name][func_id].n + 1 + durations[mod_name][func_id].cur = dtime +end + +-------------------------------------------------------------- +-- Move olds globalsteps and redefine minetest internal caller + +local gs = {} -- global_steps (moved here) + +for i,f in ipairs(minetest.registered_globalsteps) do + gs[#gs+1] = { + mod_name = "unknown"..i, + func_id = "unknown(globalstep)", + func_code = f + } + minetest.registered_globalsteps[i] = nil +end + +local old_globalstep = minetest.register_globalstep + +function minetest.register_globalstep(func) + gs[#gs+1] = { + mod_name = core.get_last_run_mod(), + func_id = "unknown(globalstep)", + func_code = func + } +end + + + +-- Main code + +local last_elapsed_local_dtime = 0 +local last_internal_server_dtime = 0 +local tick_dtime = minetest.setting_get("dedicated_server_step")*1000000 + +old_globalstep(function(dtime) + local begin_time = core.get_us_time() + last_internal_server_dtime = dtime*1000000 - last_elapsed_local_dtime + local launch_dtime = begin_time - last_internal_server_dtime + + local current_durations = {} + current_durations[1] = {"Internal SERVER", "& unprofiled", last_internal_server_dtime} + + local tbegin = 0 + -- Globalsteps + for i,v in pairs(gs) do + tbegin = core.get_us_time() + v.func_code(dtime+(core.get_us_time()-tbegin)/1000000) + if active then + current_durations[#current_durations+1] = {v.mod_name, v.func_id, core.get_us_time()-tbegin} + end + end + + -- Others jobs + local njb = scheduler.waitingjobs() + local jbdone = 0 + for class,q in ipairs(scheduler.queue) do + --local grp = q.cur + for i,job in pairs(q.cur) do + tbegin = core.get_us_time() + core.set_last_run_mod(job.mod_name) + job.func_code(unpack(job.arg)) + jbdone = jbdone+1 + current_durations[#current_durations+1] = {job.mod_name, job.func_id, core.get_us_time()-tbegin} + q.cur[i] = nil + if class > 1 and ((core.get_us_time()-launch_dtime) > tick_dtime) then --class 1 fully processed even on overload + break + end + end + if ((core.get_us_time()-launch_dtime) > tick_dtime) then + break + end + end + --minetest.debug("[Profnsched] "..scheduler.waitingjobs()+getnjobs()) + scheduler.shift() + --minetest.debug("[Profnsched] "..scheduler.waitingjobs()+getnjobs()) + + local elapsed = (core.get_us_time()-launch_dtime) + + -- update all durations + for i,v in pairs(current_durations) do + update_durations(v[1], v[2], v[3]) + end + + if (elapsed > tick_dtime) then --overload ? + if last_internal_server_dtime < tick_dtime then -- caused by profiled mods ? + if active and dump_delay == 0 then + minetest.log("[Profnsched] Overload ! "..mathfloor(elapsed)/1000 .."ms") + dump_durations(current_durations) + --scheduler.fulldebug() + end + else + if active and dump_delay == 0 then + minetest.log("[Profnsched] Overload ! Caused by server or not profiled mods : "..mathfloor(last_internal_server_dtime)/1000 .."ms") + end + end + end + + for i,v in pairs(current_durations) do + current_durations[i] = nil + end + + last_elapsed_local_dtime = core.get_us_time() - begin_time +end) + diff --git a/queue.lua b/queue.lua new file mode 100644 index 0000000..f784667 --- /dev/null +++ b/queue.lua @@ -0,0 +1,101 @@ +scheduler = {} +-- scheduler.queue = {[1]={first=1, last=2, groups={[1]={}, [2]={}}}} +scheduler.queue = {[1]={cur={}, nxt={}, ncur=1, nnxt=1}} + +function scheduler.add(priority, job) + -- get asked class + local class = scheduler.queue[priority] + local p = priority + while not class do -- create all classes under 'priority' + --scheduler.queue[p] = {first=1, last=2, groups={[1]={}, [2]={}}} + scheduler.queue[p] = {cur={}, nxt={}, ncur=1, nnxt=1} + p = p-1 + class = scheduler.queue[p] + end + class = scheduler.queue[priority] + class.nxt[class.nnxt] = job + class.nnxt = class.nnxt+1 + -- get last group + --local grp = class.groups[class.last] + -- add job into last group + --grp[#grp+1] = job +end + +function scheduler.asap(priority, func) + scheduler.add(priority, { + mod_name = core.get_last_run_mod(), + func_id = "#"..debug.getinfo(2, "S").linedefined, --imprecis + func_code = func, + arg = {}, + }) +end + +function scheduler.mdebug(s) + minetest.debug("[Profnsched] "..s) +end + +function scheduler.shift() + local nb = scheduler.waitingjobs() + local qnext = nil + for class,q in ipairs(scheduler.queue) do + q.cur = q.nxt + q.nxt = {} + q.ncur = q.nnxt + q.nnxt = 1 + + --local tnext = class+1 + qnext = scheduler.queue[class+1] + if qnext then + local src = qnext.cur + for i,j in pairs(src) do + q.cur[q.ncur] = j + q.ncur = q.ncur+1 + src[i] = nil + end + qnext.cur = {} + qnext.ncur = 1 + end + end + --[[ + q.groups[q.first] = q.groups[q.last] + q.groups[q.last] = {} + local tnext = class+1 + tnext = scheduler.queue[tnext] + if tnext then + tsrc = tnext.groups[tnext.first] + tdst = q.groups[q.first] + for i,j in pairs(tsrc) do + tdst[#tdst+1] = j + tsrc[i] = nil + end + end + end]] + if nb ~= scheduler.waitingjobs() then --This should never happen, left because it was used during debug phase + mdebug("ERROR, This should never happen ! Lost jobs, some mod may not work from now, please restart the server.") + end + -- +end + +function scheduler.fulldebug() + minetest.log("[Profnsched]"..#scheduler.queue.." classes") + for class,q in pairs(scheduler.queue) do + minetest.log("[Profnsched] class "..class..":") + minetest.log("[Profnsched] current "..q.ncur) + minetest.log("[Profnsched] next "..q.nnxt) + end + minetest.log("[Profnsched] end") +end + + +function scheduler.waitingjobs() + local n = 0 + for class, q in pairs(scheduler.queue) do + for i,grp in pairs(q.cur) do + n = n+1 + end + for i,grp in pairs(q.nxt) do + n = n+1 + end + end + return n +end