From d2b71969e346c25649c7ed888487e9f276633058 Mon Sep 17 00:00:00 2001 From: Coethium Date: Sun, 21 Aug 2016 18:10:21 +0200 Subject: [PATCH] [Profnsched] New module (fr) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * 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 ... see README for more ! --- mods/profnsched/README.txt | 68 +++++++++++++++++ mods/profnsched/init.lua | 150 +++++++++++++++++++++++++++++++++++++ mods/profnsched/queue.lua | 83 ++++++++++++++++++++ 3 files changed, 301 insertions(+) create mode 100644 mods/profnsched/README.txt create mode 100644 mods/profnsched/init.lua create mode 100644 mods/profnsched/queue.lua diff --git a/mods/profnsched/README.txt b/mods/profnsched/README.txt new file mode 100644 index 00000000..ee81f58a --- /dev/null +++ b/mods/profnsched/README.txt @@ -0,0 +1,68 @@ +[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 : +================== + * 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' + +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/mods/profnsched/init.lua b/mods/profnsched/init.lua new file mode 100644 index 00000000..7e69ebb5 --- /dev/null +++ b/mods/profnsched/init.lua @@ -0,0 +1,150 @@ +dofile(minetest.get_modpath("profnsched").."/queue.lua") + +local jobs = {} +local durations = {} + +-------------------------------------------------------------- +-- 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 + +-- Usefull func + +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 + + +-- For minetest.after replacement +local function check_expired_jobs() + local time = core.get_us_time() + for i,job in pairs(jobs) do + if time >= job.expire then + scheduler.add(1, job) + jobs[i] = nil + end + end + scheduler.asap(4, check_expired_jobs) +end +scheduler.asap(4, check_expired_jobs) + +-- 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) + current_durations[#current_durations+1] = {v.mod_name, v.func_id, core.get_us_time()-tbegin} + end + + -- Others jobs + local njb = scheduler.waitingjobs() + local jbdone = 0 + for class,q in ipairs(scheduler.queue) do + local grp = q.groups[q.first] + for i,job in pairs(grp) 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} + grp[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 + scheduler.shift() + + 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 ? + local mathfloor = math.floor + if last_internal_server_dtime < tick_dtime then -- caused by profiled mods ? + minetest.log("[Profnsched] Overload ! "..mathfloor(elapsed)/1000 .."ms") + local avg = 0 + local dt = 0 + for i,v in pairs(current_durations) 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 + minetest.log("[Profnsched] Overload ! Caused by server or not profiled mods : "..mathfloor(last_internal_server_dtime)/1000 .."ms") + 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) + + +-- 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/mods/profnsched/queue.lua b/mods/profnsched/queue.lua new file mode 100644 index 00000000..15ab69ca --- /dev/null +++ b/mods/profnsched/queue.lua @@ -0,0 +1,83 @@ +scheduler = {} +scheduler.queue = {[1]={first=1, last=2, groups={[1]={}, [2]={}}}} + +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]={}}} + p = p-1 + class = scheduler.queue[p] + end + class = scheduler.queue[priority] + -- 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 = "todo", + func_code = func, + arg = {}, + }) +end + +function scheduler.mdebug(s) + minetest.debug("[Profnsched] "..s) +end + +function scheduler.shift() + local nb = scheduler.waitingjobs() + local tsrc = nil + local tdst = nil + for class,q in ipairs(scheduler.queue) do + 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]"..table.getn(scheduler.queue).." classes") + for class,q in pairs(scheduler.queue) do + minetest.log("[Profnsched] class "..class..":") + minetest.log("[Profnsched] "..q.first.." "..q.last.." ("..q.last-q.first+1 .." groups)") + for i,grp in pairs(q.groups) do + local n = 0 + for j,jb in pairs(grp) do + n = n+1 + end + minetest.log("[Profnsched] group "..i..", "..n.." jobs") + end + 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.groups) do + for j,jb in pairs(grp) do + n = n+1 + end + end + end + return n +end