builtin/profiler/sampling.lua

   1 --Minetest
   2 --Copyright (C) 2016 T4im
   3 --
   4 --This program is free software; you can redistribute it and/or modify
   5 --it under the terms of the GNU Lesser General Public License as published by
   6 --the Free Software Foundation; either version 2.1 of the License, or
   7 --(at your option) any later version.
   8 --
   9 --This program is distributed in the hope that it will be useful,
  10 --but WITHOUT ANY WARRANTY; without even the implied warranty of
  11 --MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  12 --GNU Lesser General Public License for more details.
  13 --
  14 --You should have received a copy of the GNU Lesser General Public License along
  15 --with this program; if not, write to the Free Software Foundation, Inc.,
  16 --51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
  17 local setmetatable = setmetatable
  18 local pairs, format = pairs, string.format
  19 local min, max, huge = math.min, math.max, math.huge
  20 local core = core
  21
  22 local profiler = ...
  23 -- Split sampler and profile up, to possibly allow for rotation later.
  24 local sampler = {}
  25 local profile
  26 local stats_total
  27 local logged_time, logged_data
  28
  29 local _stat_mt = {
  30         get_time_avg = function(self)
  31                 return self.time_all/self.samples
  32         end,
  33         get_part_avg = function(self)
  34                 if not self.part_all then
  35                         return 100 -- Extra handling for "total"
  36                 end
  37                 return self.part_all/self.samples
  38         end,
  39 }
  40 _stat_mt.__index = _stat_mt
  41
  42 function sampler.reset()
  43         -- Accumulated logged time since last sample.
  44         -- This helps determining, the relative time a mod used up.
  45         logged_time = 0
  46         -- The measurements taken through instrumentation since last sample.
  47         logged_data = {}
  48
  49         profile = {
  50                 -- Current mod statistics (max/min over the entire mod lifespan)
  51                 -- Mod specific instrumentation statistics are nested within.
  52                 stats = {},
  53                 -- Current stats over all mods.
  54                 stats_total = setmetatable({
  55                         samples = 0,
  56                         time_min = huge,
  57                         time_max = 0,
  58                         time_all = 0,
  59                         part_min = 100,
  60                         part_max = 100
  61                 }, _stat_mt)
  62         }
  63         stats_total = profile.stats_total
  64
  65         -- Provide access to the most recent profile.
  66         sampler.profile = profile
  67 end
  68
  69 ---
  70 -- Log a measurement for the sampler to pick up later.
  71 -- Keep `log` and its often called functions lean.
  72 -- It will directly add to the instrumentation overhead.
  73 --
  74 function sampler.log(modname, instrument_name, time_diff)
  75         if time_diff <= 0 then
  76                 if time_diff < 0 then
  77                         -- This **might** have happened on a semi-regular basis with huge mods,
  78                         -- resulting in negative statistics (perhaps midnight time jumps or ntp corrections?).
  79                         core.log("warning", format(
  80                                         "Time travel of %s::%s by %dµs.",
  81                                         modname, instrument_name, time_diff
  82                         ))
  83                 end
  84                 -- Throwing these away is better, than having them mess with the overall result.
  85                 return
  86         end
  87
  88         local mod_data = logged_data[modname]
  89         if mod_data == nil then
  90                 mod_data = {}
  91                 logged_data[modname] = mod_data
  92         end
  93
  94         mod_data[instrument_name] = (mod_data[instrument_name] or 0) + time_diff
  95         -- Update logged time since last sample.
  96         logged_time = logged_time + time_diff
  97 end
  98
  99 ---
 100 -- Return a requested statistic.
 101 -- Initialize if necessary.
 102 --
 103 local function get_statistic(stats_table, name)
 104         local statistic = stats_table[name]
 105         if statistic == nil then
 106                 statistic = setmetatable({
 107                         samples = 0,
 108                         time_min = huge,
 109                         time_max = 0,
 110                         time_all = 0,
 111                         part_min = 100,
 112                         part_max = 0,
 113                         part_all = 0,
 114                 }, _stat_mt)
 115                 stats_table[name] = statistic
 116         end
 117         return statistic
 118 end
 119
 120 ---
 121 -- Update a statistic table
 122 --
 123 local function update_statistic(stats_table, time)
 124         stats_table.samples = stats_table.samples + 1
 125
 126         -- Update absolute time (µs) spend by the subject
 127         stats_table.time_min = min(stats_table.time_min, time)
 128         stats_table.time_max = max(stats_table.time_max, time)
 129         stats_table.time_all = stats_table.time_all + time
 130
 131         -- Update relative time (%) of this sample spend by the subject
 132         local current_part = (time/logged_time) * 100
 133         stats_table.part_min = min(stats_table.part_min, current_part)
 134         stats_table.part_max = max(stats_table.part_max, current_part)
 135         stats_table.part_all = stats_table.part_all + current_part
 136 end
 137
 138 ---
 139 -- Sample all logged measurements each server step.
 140 -- Like any globalstep function, this should not be too heavy,
 141 -- but does not add to the instrumentation overhead.
 142 --
 143 local function sample(dtime)
 144         -- Rare, but happens and is currently of no informational value.
 145         if logged_time == 0 then
 146                 return
 147         end
 148
 149         for modname, instruments in pairs(logged_data) do
 150                 local mod_stats = get_statistic(profile.stats, modname)
 151                 if mod_stats.instruments == nil then
 152                         -- Current statistics for each instrumentation component
 153                         mod_stats.instruments = {}
 154                 end
 155
 156                 local mod_time = 0
 157                 for instrument_name, time in pairs(instruments) do
 158                         if time > 0 then
 159                                 mod_time = mod_time + time
 160                                 local instrument_stats = get_statistic(mod_stats.instruments, instrument_name)
 161
 162                                 -- Update time of this sample spend by the instrumented function.
 163                                 update_statistic(instrument_stats, time)
 164                                 -- Reset logged data for the next sample.
 165                                 instruments[instrument_name] = 0
 166                         end
 167                 end
 168
 169                 -- Update time of this sample spend by this mod.
 170                 update_statistic(mod_stats, mod_time)
 171         end
 172
 173         -- Update the total time spend over all mods.
 174         stats_total.time_min = min(stats_total.time_min, logged_time)
 175         stats_total.time_max = max(stats_total.time_max, logged_time)
 176         stats_total.time_all = stats_total.time_all + logged_time
 177
 178         stats_total.samples = stats_total.samples + 1
 179         logged_time = 0
 180 end
 181
 182 ---
 183 -- Setup empty profile and register the sampling function
 184 --
 185 function sampler.init()
 186         sampler.reset()
 187
 188         if core.setting_getbool("instrument.profiler") then
 189                 core.register_globalstep(function()
 190                         if logged_time == 0 then
 191                                 return
 192                         end
 193                         return profiler.empty_instrument()
 194                 end)
 195                 core.register_globalstep(profiler.instrument {
 196                         func = sample,
 197                         mod = "*profiler*",
 198                         class = "Sampler (update stats)",
 199                         label = false,
 200                 })
 201         else
 202                 core.register_globalstep(sample)
 203         end
 204 end
 205
 206 return sampler