aboutsummaryrefslogtreecommitdiff
path: root/builtin/profiler/sampling.lua
blob: 4b53399a5da1f5de313b58ff9566a1c15520bacb (plain)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
--Minetest
--Copyright (C) 2016 T4im
--
--This program is free software; you can redistribute it and/or modify
--it under the terms of the GNU Lesser General Public License as published by
--the Free Software Foundation; either version 2.1 of the License, or
--(at your option) any later version.
--
--This program is distributed in the hope that it will be useful,
--but WITHOUT ANY WARRANTY; without even the implied warranty of
--MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
--GNU Lesser General Public License for more details.
--
--You should have received a copy of the GNU Lesser General Public License along
--with this program; if not, write to the Free Software Foundation, Inc.,
--51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
local setmetatable = setmetatable
local pairs, format = pairs, string.format
local min, max, huge = math.min, math.max, math.huge
local core = core

local profiler = ...
-- Split sampler and profile up, to possibly allow for rotation later.
local sampler = {}
local profile
local stats_total
local logged_time, logged_data

local _stat_mt = {
	get_time_avg = function(self)
		return self.time_all/self.samples
	end,
	get_part_avg = function(self)
		if not self.part_all then
			return 100 -- Extra handling for "total"
		end
		return self.part_all/self.samples
	end,
}
_stat_mt.__index = _stat_mt

function sampler.reset()
	-- Accumulated logged time since last sample.
	-- This helps determining, the relative time a mod used up.
	logged_time = 0
	-- The measurements taken through instrumentation since last sample.
	logged_data = {}

	profile = {
		-- Current mod statistics (max/min over the entire mod lifespan)
		-- Mod specific instrumentation statistics are nested within.
		stats = {},
		-- Current stats over all mods.
		stats_total = setmetatable({
			samples = 0,
			time_min = huge,
			time_max = 0,
			time_all = 0,
			part_min = 100,
			part_max = 100
		}, _stat_mt)
	}
	stats_total = profile.stats_total

	-- Provide access to the most recent profile.
	sampler.profile = profile
end

---
-- Log a measurement for the sampler to pick up later.
-- Keep `log` and its often called functions lean.
-- It will directly add to the instrumentation overhead.
--
function sampler.log(modname, instrument_name, time_diff)
	if time_diff <= 0 then
		if time_diff < 0 then
			-- This **might** have happened on a semi-regular basis with huge mods,
			-- resulting in negative statistics (perhaps midnight time jumps or ntp corrections?).
			core.log("warning", format(
					"Time travel of %s::%s by %dµs.",
					modname, instrument_name, time_diff
			))
		end
		-- Throwing these away is better, than having them mess with the overall result.
		return
	end

	local mod_data = logged_data[modname]
	if mod_data == nil then
		mod_data = {}
		logged_data[modname] = mod_data
	end

	mod_data[instrument_name] = (mod_data[instrument_name] or 0) + time_diff
	-- Update logged time since last sample.
	logged_time = logged_time + time_diff
end

---
-- Return a requested statistic.
-- Initialize if necessary.
--
local function get_statistic(stats_table, name)
	local statistic = stats_table[name]
	if statistic == nil then
		statistic = setmetatable({
			samples = 0,
			time_min = huge,
			time_max = 0,
			time_all = 0,
			part_min = 100,
			part_max = 0,
			part_all = 0,
		}, _stat_mt)
		stats_table[name] = statistic
	end
	return statistic
end

---
-- Update a statistic table
--
local function update_statistic(stats_table, time)
	stats_table.samples = stats_table.samples + 1

	-- Update absolute time (µs) spend by the subject
	stats_table.time_min = min(stats_table.time_min, time)
	stats_table.time_max = max(stats_table.time_max, time)
	stats_table.time_all = stats_table.time_all + time

	-- Update relative time (%) of this sample spend by the subject
	local current_part = (time/logged_time) * 100
	stats_table.part_min = min(stats_table.part_min, current_part)
	stats_table.part_max = max(stats_table.part_max, current_part)
	stats_table.part_all = stats_table.part_all + current_part
end

---
-- Sample all logged measurements each server step.
-- Like any globalstep function, this should not be too heavy,
-- but does not add to the instrumentation overhead.
--
local function sample(dtime)
	-- Rare, but happens and is currently of no informational value.
	if logged_time == 0 then
		return
	end

	for modname, instruments in pairs(logged_data) do
		local mod_stats = get_statistic(profile.stats, modname)
		if mod_stats.instruments == nil then
			-- Current statistics for each instrumentation component
			mod_stats.instruments = {}
		end

		local mod_time = 0
		for instrument_name, time in pairs(instruments) do
			if time > 0 then
				mod_time = mod_time + time
				local instrument_stats = get_statistic(mod_stats.instruments, instrument_name)

				-- Update time of this sample spend by the instrumented function.
				update_statistic(instrument_stats, time)
				-- Reset logged data for the next sample.
				instruments[instrument_name] = 0
			end
		end

		-- Update time of this sample spend by this mod.
		update_statistic(mod_stats, mod_time)
	end

	-- Update the total time spend over all mods.
	stats_total.time_min = min(stats_total.time_min, logged_time)
	stats_total.time_max = max(stats_total.time_max, logged_time)
	stats_total.time_all = stats_total.time_all + logged_time

	stats_total.samples = stats_total.samples + 1
	logged_time = 0
end

---
-- Setup empty profile and register the sampling function
--
function sampler.init()
	sampler.reset()

	if core.settings:get_bool("instrument.profiler") then
		core.register_globalstep(function()
			if logged_time == 0 then
				return
			end
			return profiler.empty_instrument()
		end)
		core.register_globalstep(profiler.instrument {
			func = sample,
			mod = "*profiler*",
			class = "Sampler (update stats)",
			label = false,
		})
	else
		core.register_globalstep(sample)
	end
end

return sampler