Remplissage du dépôt.

This commit is contained in:
sys4-fr 2018-09-08 15:19:48 +02:00
commit e5451053c6
4 changed files with 399 additions and 0 deletions

77
README.txt Normal file
View File

@ -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 ;)

40
after.lua Normal file
View File

@ -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

181
init.lua Normal file
View File

@ -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 = "<text>",
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)

101
queue.lua Normal file
View File

@ -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