builtin/game/mod_profiling.lua

   1 -- Minetest: builtin/game/mod_profiling.lua
   2
   3 local mod_statistics = {}
   4 mod_statistics.step_total = 0
   5 mod_statistics.data = {}
   6 mod_statistics.stats = {}
   7 mod_statistics.stats["total"] = {
   8         min_us = math.huge,
   9         max_us = 0,
  10         avg_us = 0,
  11         min_per = 100,
  12         max_per = 100,
  13         avg_per = 100
  14 }
  15
  16 local replacement_table = {
  17         "register_globalstep",
  18         "register_on_placenode",
  19         "register_on_dignode",
  20         "register_on_punchnode",
  21         "register_on_generated",
  22         "register_on_newplayer",
  23         "register_on_dieplayer",
  24         "register_on_respawnplayer",
  25         "register_on_prejoinplayer",
  26         "register_on_joinplayer",
  27         "register_on_leaveplayer",
  28         "register_on_cheat",
  29         "register_on_chat_message",
  30         "register_on_player_receive_fields",
  31         "register_on_mapgen_init",
  32         "register_on_craft",
  33         "register_craft_predict",
  34         "register_on_item_eat"
  35 }
  36
  37 --------------------------------------------------------------------------------
  38 function mod_statistics.log_time(type, modname, time_in_us)
  39
  40         if modname == nil then
  41                 modname = "builtin"
  42         end
  43
  44         if mod_statistics.data[modname] == nil then
  45                 mod_statistics.data[modname] = {}
  46         end
  47
  48         if mod_statistics.data[modname][type] == nil then
  49                 mod_statistics.data[modname][type] = 0
  50         end
  51
  52         mod_statistics.data[modname][type] =
  53                 mod_statistics.data[modname][type] + time_in_us
  54         mod_statistics.step_total = mod_statistics.step_total + time_in_us
  55 end
  56
  57 --------------------------------------------------------------------------------
  58 function mod_statistics.update_statistics(dtime)
  59         for modname,types in pairs(mod_statistics.data) do
  60
  61                 if mod_statistics.stats[modname] == nil then
  62                         mod_statistics.stats[modname] = {
  63                                 min_us = math.huge,
  64                                 max_us = 0,
  65                                 avg_us = 0,
  66                                 min_per = 100,
  67                                 max_per = 0,
  68                                 avg_per = 0
  69                         }
  70                 end
  71
  72                 local modtime = 0
  73                 for type,time in pairs(types) do
  74                         modtime = modtime + time
  75                         if mod_statistics.stats[modname].types == nil then
  76                                 mod_statistics.stats[modname].types = {}
  77                         end
  78                         if mod_statistics.stats[modname].types[type] == nil then
  79                                 mod_statistics.stats[modname].types[type] = {
  80                                         min_us = math.huge,
  81                                         max_us = 0,
  82                                         avg_us = 0,
  83                                         min_per = 100,
  84                                         max_per = 0,
  85                                         avg_per = 0
  86                                 }
  87                         end
  88
  89                         local toupdate = mod_statistics.stats[modname].types[type]
  90
  91                         --update us values
  92                         toupdate.min_us = math.min(time, toupdate.min_us)
  93                         toupdate.max_us = math.max(time, toupdate.max_us)
  94                         --TODO find better algorithm
  95                         toupdate.avg_us = toupdate.avg_us * 0.99 + modtime * 0.01
  96
  97                         --update percentage values
  98                         local cur_per = (time/mod_statistics.step_total) * 100
  99                         toupdate.min_per = math.min(toupdate.min_per, cur_per)
 100
 101                         toupdate.max_per = math.max(toupdate.max_per, cur_per)
 102
 103                         --TODO find better algorithm
 104                         toupdate.avg_per = toupdate.avg_per * 0.99 + cur_per * 0.01
 105
 106                         mod_statistics.data[modname][type] = 0
 107                 end
 108
 109                 --per mod statistics
 110                 --update us values
 111                 mod_statistics.stats[modname].min_us =
 112                         math.min(modtime, mod_statistics.stats[modname].min_us)
 113                 mod_statistics.stats[modname].max_us =
 114                         math.max(modtime, mod_statistics.stats[modname].max_us)
 115                 --TODO find better algorithm
 116                 mod_statistics.stats[modname].avg_us =
 117                         mod_statistics.stats[modname].avg_us * 0.99 + modtime * 0.01
 118
 119                 --update percentage values
 120                 local cur_per = (modtime/mod_statistics.step_total) * 100
 121                 mod_statistics.stats[modname].min_per =
 122                         math.min(mod_statistics.stats[modname].min_per, cur_per)
 123
 124                 mod_statistics.stats[modname].max_per =
 125                         math.max(mod_statistics.stats[modname].max_per, cur_per)
 126
 127                 --TODO find better algorithm
 128                 mod_statistics.stats[modname].avg_per =
 129                         mod_statistics.stats[modname].avg_per * 0.99 + cur_per * 0.01
 130         end
 131
 132         --update "total"
 133         mod_statistics.stats["total"].min_us =
 134                 math.min(mod_statistics.step_total, mod_statistics.stats["total"].min_us)
 135         mod_statistics.stats["total"].max_us =
 136                 math.max(mod_statistics.step_total, mod_statistics.stats["total"].max_us)
 137         --TODO find better algorithm
 138         mod_statistics.stats["total"].avg_us =
 139                 mod_statistics.stats["total"].avg_us * 0.99 +
 140                 mod_statistics.step_total * 0.01
 141
 142         mod_statistics.step_total = 0
 143 end
 144
 145 --------------------------------------------------------------------------------
 146 local function build_callback(log_id, fct)
 147         return function( toregister )
 148                 local modname = core.get_current_modname()
 149
 150                 fct(function(...)
 151                         local starttime = core.get_us_time()
 152                         -- note maximum 10 return values are supported unless someone finds
 153                         -- a way to store a variable lenght return value list
 154                         local r0, r1, r2, r3, r4, r5, r6, r7, r8, r9 = toregister(...)
 155                         local delta = core.get_us_time() - starttime
 156                         mod_statistics.log_time(log_id, modname, delta)
 157                         return r0, r1, r2, r3, r4, r5, r6, r7, r8, r9
 158                         end
 159                 )
 160         end
 161 end
 162
 163 --------------------------------------------------------------------------------
 164 function profiling_print_log(cmd, filter)
 165
 166         print("Filter:" .. dump(filter))
 167
 168         core.log("action", "Values below show times/percentages per server step.")
 169         core.log("action", "Following suffixes are used for entities:")
 170         core.log("action", "\t#oa := on_activate, #os := on_step, #op := on_punch, #or := on_rightclick, #gs := get_staticdata")
 171         core.log("action",
 172                 string.format("%16s | %25s | %10s | %10s | %10s | %9s | %9s | %9s",
 173                 "modname", "type" , "min µs", "max µs", "avg µs", "min %", "max %", "avg %")
 174         )
 175         core.log("action",
 176                 "-----------------+---------------------------+-----------+" ..
 177                 "-----------+-----------+-----------+-----------+-----------")
 178         for modname,statistics in pairs(mod_statistics.stats) do
 179                 if modname ~= "total" then
 180
 181                         if (filter == "") or (modname == filter) then
 182                                 if modname:len() > 16 then
 183                                         modname = "..." .. modname:sub(-13)
 184                                 end
 185
 186                                 core.log("action",
 187                                         string.format("%16s | %25s | %9d | %9d | %9d | %9d | %9d | %9d",
 188                                         modname,
 189                                         " ",
 190                                         statistics.min_us,
 191                                         statistics.max_us,
 192                                         statistics.avg_us,
 193                                         statistics.min_per,
 194                                         statistics.max_per,
 195                                         statistics.avg_per)
 196                                 )
 197                                 if core.setting_getbool("detailed_profiling") then
 198                                         if statistics.types ~= nil then
 199                                                 for type,typestats in pairs(statistics.types) do
 200
 201                                                         if type:len() > 25 then
 202                                                                 type = "..." .. type:sub(-22)
 203                                                         end
 204
 205                                                         core.log("action",
 206                                                                 string.format(
 207                                                                 "%16s | %25s | %9d | %9d | %9d | %9d | %9d | %9d",
 208                                                                 " ",
 209                                                                 type,
 210                                                                 typestats.min_us,
 211                                                                 typestats.max_us,
 212                                                                 typestats.avg_us,
 213                                                                 typestats.min_per,
 214                                                                 typestats.max_per,
 215                                                                 typestats.avg_per)
 216                                                         )
 217                                                 end
 218                                         end
 219                                 end
 220                         end
 221                 end
 222         end
 223                 core.log("action",
 224                         "-----------------+---------------------------+-----------+" ..
 225                         "-----------+-----------+-----------+-----------+-----------")
 226
 227         if filter == "" then
 228                 core.log("action",
 229                         string.format("%16s | %25s | %9d | %9d | %9d | %9d | %9d | %9d",
 230                         "total",
 231                         " ",
 232                         mod_statistics.stats["total"].min_us,
 233                         mod_statistics.stats["total"].max_us,
 234                         mod_statistics.stats["total"].avg_us,
 235                         mod_statistics.stats["total"].min_per,
 236                         mod_statistics.stats["total"].max_per,
 237                         mod_statistics.stats["total"].avg_per)
 238                 )
 239         end
 240         core.log("action", " ")
 241
 242         return true
 243 end
 244
 245 --------------------------------------------------------------------------------
 246 local function initialize_profiling()
 247         core.log("action", "Initialize tracing")
 248
 249         mod_statistics.entity_callbacks = {}
 250
 251         -- first register our own globalstep handler
 252         core.register_globalstep(mod_statistics.update_statistics)
 253
 254         local rp_register_entity = core.register_entity
 255         core.register_entity = function(name, prototype)
 256                 local modname = core.get_current_modname()
 257                 local new_on_activate = nil
 258                 local new_on_step = nil
 259                 local new_on_punch = nil
 260                 local new_rightclick = nil
 261                 local new_get_staticdata = nil
 262
 263                 if prototype.on_activate ~= nil then
 264                         local cbid = name .. "#oa"
 265                         mod_statistics.entity_callbacks[cbid] = prototype.on_activate
 266                         new_on_activate = function(self, staticdata, dtime_s)
 267                                 local starttime = core.get_us_time()
 268                                 mod_statistics.entity_callbacks[cbid](self, staticdata, dtime_s)
 269                                 local delta = core.get_us_time() -starttime
 270                                 mod_statistics.log_time(cbid, modname, delta)
 271                         end
 272                 end
 273
 274                 if prototype.on_step ~= nil then
 275                         local cbid = name .. "#os"
 276                         mod_statistics.entity_callbacks[cbid] = prototype.on_step
 277                         new_on_step = function(self, dtime)
 278                                 local starttime = core.get_us_time()
 279                                 mod_statistics.entity_callbacks[cbid](self, dtime)
 280                                 local delta = core.get_us_time() -starttime
 281                                 mod_statistics.log_time(cbid, modname, delta)
 282                         end
 283                 end
 284
 285                 if prototype.on_punch ~= nil then
 286                         local cbid = name .. "#op"
 287                         mod_statistics.entity_callbacks[cbid] = prototype.on_punch
 288                         new_on_punch = function(self, hitter)
 289                                 local starttime = core.get_us_time()
 290                                 mod_statistics.entity_callbacks[cbid](self, hitter)
 291                                 local delta = core.get_us_time() -starttime
 292                                 mod_statistics.log_time(cbid, modname, delta)
 293                         end
 294                 end
 295
 296                 if prototype.rightclick ~= nil then
 297                         local cbid = name .. "#rc"
 298                         mod_statistics.entity_callbacks[cbid] = prototype.rightclick
 299                         new_rightclick = function(self, clicker)
 300                                 local starttime = core.get_us_time()
 301                                 mod_statistics.entity_callbacks[cbid](self, clicker)
 302                                 local delta = core.get_us_time() -starttime
 303                                 mod_statistics.log_time(cbid, modname, delta)
 304                         end
 305                 end
 306
 307                 if prototype.get_staticdata ~= nil then
 308                         local cbid = name .. "#gs"
 309                         mod_statistics.entity_callbacks[cbid] = prototype.get_staticdata
 310                         new_get_staticdata = function(self)
 311                                 local starttime = core.get_us_time()
 312                                 local retval = mod_statistics.entity_callbacks[cbid](self)
 313                                 local delta = core.get_us_time() -starttime
 314                                 mod_statistics.log_time(cbid, modname, delta)
 315                                 return retval
 316                         end
 317                 end
 318
 319                 prototype.on_activate = new_on_activate
 320                 prototype.on_step = new_on_step
 321                 prototype.on_punch = new_on_punch
 322                 prototype.rightclick = new_rightclick
 323                 prototype.get_staticdata = new_get_staticdata
 324
 325                 rp_register_entity(name,prototype)
 326         end
 327
 328         for i,v in ipairs(replacement_table) do
 329                 local to_replace = core[v]
 330                 core[v] = build_callback(v, to_replace)
 331         end
 332
 333         local rp_register_abm = core.register_abm
 334         core.register_abm = function(spec)
 335
 336                 local modname = core.get_current_modname()
 337
 338                 local replacement_spec = {
 339                         nodenames = spec.nodenames,
 340                         neighbors = spec.neighbors,
 341                         interval  = spec.interval,
 342                         chance    = spec.chance,
 343                         action = function(pos, node, active_object_count, active_object_count_wider)
 344                                 local starttime = core.get_us_time()
 345                                 spec.action(pos, node, active_object_count, active_object_count_wider)
 346                                 local delta = core.get_us_time() - starttime
 347                                 mod_statistics.log_time("abm", modname, delta)
 348                         end
 349                 }
 350                 rp_register_abm(replacement_spec)
 351         end
 352
 353         core.log("action", "Mod profiling initialized")
 354 end
 355
 356 initialize_profiling()