Fix large steps caused by uninterruptable spawn seed initialization within activation

Update version number to 0.0.8

api.lua

@@ -25,7 +25,7 @@ function adv_spawning.register(spawner_name,spawning_def)
 		end
 
 		adv_spawning.spawner_definitions[spawner_name] = spawning_def
-		print("ADV_SPAWNING: registering spawner \"" .. spawner_name .. "\"")
+		adv_spawning.dbg_log(0, "registering spawner \"" .. spawner_name .. "\"")
 		return true
 	else
 		return false

init.lua

@@ -8,10 +8,10 @@
 --
 -------------------------------------------------------------------------------
 
-local version = "0.0.7"
+local version = "0.0.8"
 
 if adv_spawning ~= nil then
-	core.log("error","MOD: adv_spawning requires adv_spawning variable to be available")
+	core.log("error", "MOD: adv_spawning requires adv_spawning variable to be available")
 end
 
 --------------------------------------------------------------------------------
@@ -31,4 +31,4 @@ dofile (adv_modpath .. "/spawn_seed.lua")
 
 adv_spawning.initialize()
 
-core.log("action","Advanced spawning mod version " .. version .. " loaded")
+core.log("action", "Advanced spawning mod version " .. version .. " loaded")

internal.lua

@@ -63,6 +63,8 @@ function adv_spawning.initialize()
 	adv_spawning.spawner_y_offset = 20
 	adv_spawning.max_spawning_frequency_hz = 5
 	adv_spawning.max_mapgen_tries_per_step = 3
+	adv_spawning.spawner_warned = {}
+	adv_spawning.loglevel = 0
 
 	adv_spawning.active_range = minetest.setting_get("active_block_range")
 
@@ -154,7 +156,9 @@ function adv_spawning.mapgen_hook(minp,maxp,blockseed)
 			if x > minp.x and
 				y > minp.y and
 				z > minp.z then
-				adv_spawning.quota_leave()
+				if not adv_spawning.quota_leave() then
+					adv_spawning.dbg_log(2, "mapgen_hook did use way too much time 1")
+				end
 				minetest.add_entity({x=x,y=y,z=z},"adv_spawning:spawn_seed")
 				adv_spawning.quota_enter(true)
 				adv_spawning.log("info", "adv_spawning: adding spawner entity at "
@@ -167,7 +171,9 @@ function adv_spawning.mapgen_hook(minp,maxp,blockseed)
 		end
 
 		adv_spawning.queue_mapgen_jobs(minp,maxp)
-		adv_spawning.quota_leave()
+		if not adv_spawning.quota_leave() then
+			adv_spawning.dbg_log(2, "mapgen_hook did use way too much time 2")
+		end
 	else
 		assert("Mapgen hook could not be executed" == nil)
 	end
@@ -221,7 +227,9 @@ function adv_spawning.global_onstep(dtime)
 
 	if adv_spawning.quota_enter() then
 		adv_spawning.handle_mapgen_spawning()
-		adv_spawning.quota_leave()
+		if not adv_spawning.quota_leave() then
+			adv_spawning.dbg_log(2, "globalstep took to long")
+		end
 	end
 end
 
@@ -233,25 +241,34 @@ end
 function adv_spawning.quota_enter(force)
 	--ONLY enable this one if you're quite sure there aren't bugs in
 	--assert(adv_spawning.quota_starttime == nil)
-
+	local retval = false
+	
 	if adv_spawning.quota_left <= 0 then
+	
 		if force == true then
-			print("Quota: task is too important to skip do it anyway," ..
+			if adv_spawning.quota_left < -10 then
-				" quota already passed by: " ..
+				adv_spawning.dbg_log(1, "Quota: task is too important to skip do it anyway," ..
-				string.format("%.2f ms",adv_spawning.quota_left))
+					" quota already passed by: " ..
-		else
+					string.format("%.2f ms",adv_spawning.quota_left))
-			if adv_spawning.quota_left * -2 > adv_spawning.quota_reload then
+			end
-				print("Quota: no time left: " ..
+			retval = true
+		else
+			if adv_spawning.quota_left * -2 > adv_spawning.quota_reload then
+				adv_spawning.dbg_log(1, "Quota: no time left: " ..
 					string.format("%.2f ms",adv_spawning.quota_left))
 			end
-			return false
 		end
+	else
+		retval = true
 	end
 --	print("+++++++++++++++++Quota enter+++++++++++++++++++++")
 --	print(debug.traceback())
 --	print("+++++++++++++++++++++++++++++++++++++++++++++++++")
-	adv_spawning.quota_starttime = adv_spawning.gettime()
+	if retval then
-	return true
+		adv_spawning.quota_starttime = adv_spawning.gettime()
+	end
+	
+	return retval
 end
 
 --------------------------------------------------------------------------------
@@ -301,8 +318,15 @@ function adv_spawning.quota_leave()
 	else
 		adv_spawning.quota_left = adv_spawning.quota_left - time_passed
 	end
+	
+	if (adv_spawning.quota_left < -adv_spawning.quota_reload) then
+		adv_spawning.dbg_log(1, "excessive overtime, quota remaining: " .. adv_spawning.quota_left)
+		return false
+	end
+	
 	adv_spawning.quota_starttime = nil
 	--print("-----------------Quota leave----------------------")
+	return true
 end
 
 --------------------------------------------------------------------------------
@@ -1296,7 +1320,6 @@ function adv_spawning.check_active_block(pos)
 		end
 	end
 
-
 	return false
 end
 
@@ -1338,11 +1361,16 @@ function adv_spawning.handle_mapgen_spawning()
 				tries < adv_spawning.max_mapgen_tries_per_step and
 				(not adv_spawning.time_over(10)) )do
 
+			local single_spawn_check = adv_spawning.gettime()
+
 			local retval,permanent_error = adv_spawning.handlespawner(toprocess.spawner,
 											{x=0,y=0,z=0},
 											toprocess.minp,
 											toprocess.maxp,
 											true)
+			
+			local delta = adv_spawning.gettime() - adv_spawning.quota_starttime
+
 			if retval then
 				toprocess.spawntotal = toprocess.spawntotal -1
 			end
@@ -1421,3 +1449,37 @@ function adv_spawning.dump_area(minp,maxp)
 	print("")
 	end
 end
+
+--------------------------------------------------------------------------------
+-- @function [parent=#adv_spawning] check_time
+-- @param starttime time since when to check
+-- @param checkid name of this check
+--
+-- @return current time for next check
+--------------------------------------------------------------------------------
+function adv_spawning.check_time(starttime, checkid)
+	local currenttime = adv_spawning.gettime()
+	local delta = currenttime - starttime
+	
+	if (delta > adv_spawning.quota_reload) then
+		if adv_spawning.spawner_warned[checkid] ~= true then
+			adv_spawning.dbg_log(1, "spawner " .. checkid ..
+				"\n\texceeded more then full reload time on init (" .. delta .. " ms)." ..
+				"\n\tFix it as it will cause major lag on mapgen!")
+			adv_spawning.spawner_warned[checkid] = true
+		end
+	end
+	
+	return currenttime
+end
+
+--------------------------------------------------------------------------------
+-- @function [parent=#adv_spawning] dbg_log
+-- @param loglevel level print it
+-- @param message message to print
+--------------------------------------------------------------------------------
+function adv_spawning.dbg_log(loglevel, message)
+	if (adv_spawning.loglevel >= loglevel ) then
+		core.log("action", "ADV_SPAWNING: " .. message)
+	end
+end

spawn_seed.lua

@@ -25,6 +25,11 @@ function adv_spawning.seed_step(self,dtime)
 	if (self.mydtime < 1/adv_spawning.max_spawning_frequency_hz) then
 		return
 	end
+	
+	--check if we did finish initialization of our spawner list by now
+	if not adv_spawning.seed_scan_for_applyable_spawners(self) then
+		return
+	end
 
 	if adv_spawning.quota_enter() then
 		self.pending_spawners = {}
@@ -39,12 +44,14 @@ function adv_spawning.seed_step(self,dtime)
 		end
 
 		local per_step_count = 0
+		local key = nil
 
 		while #self.pending_spawners > 0 and
-			per_step_count < adv_spawning.max_spawns_per_spawner do
+			per_step_count < adv_spawning.max_spawns_per_spawner and
+			adv_spawning.time_over(10) do
 
 			local rand_spawner = math.random(1,#self.pending_spawners)
-			local key = self.pending_spawners[rand_spawner]
+			key = self.pending_spawners[rand_spawner]
 
 			local tries = 1
 
@@ -63,7 +70,9 @@ function adv_spawning.seed_step(self,dtime)
 				end
 
 				--check quota again
-				adv_spawning.quota_leave()
+				if not adv_spawning.quota_leave() then
+					adv_spawning.dbg_log(2, "spawner " .. key .. " did use way too much time")
+				end
 				if not adv_spawning.quota_enter() then
 					return
 				end
@@ -76,9 +85,11 @@ function adv_spawning.seed_step(self,dtime)
 		end
 
 --		if (#self.pending_spawners > 0) then
---			print("Handled " .. per_step_count .. " spawners, spawners left: " .. #self.pending_spawners)
+--			adv_spawning.dbg_log(3, "Handled " .. per_step_count .. " spawners, spawners left: " .. #self.pending_spawners)
 --		end
-		adv_spawning.quota_leave()
+		if not adv_spawning.quota_leave() then
+			adv_spawning.dbg_log(2, "spawner " .. key .. " did use way too much time")
+		end
 	end
 end
 
@@ -103,13 +114,14 @@ function adv_spawning.seed_activate(self)
 		end
 
 		adv_spawning.seed_validate_spawndata(self)
-
+		
-		adv_spawning.seed_scan_for_applyable_spawners(self)
-
 		self.pending_spawners = {}
+		self.initialized_spawners = 0
 		self.activated = true
 
-		adv_spawning.quota_leave()
+		if not adv_spawning.quota_leave() then
+			adv_spawning.dbg_log(2, "on activate  " .. self.name .. " did use way too much time")
+		end
 	end
 end
 
@@ -208,9 +220,27 @@ end
 -- @return true/false
 --------------------------------------------------------------------------------
 function adv_spawning.seed_scan_for_applyable_spawners(self)
+
+	if self.initialized_spawners >= #adv_spawning.spawner_definitions then
+		return true
+	end
+
+	local runindex = 0
 	local pos = self.object:getpos()
 	for key,value in pairs(adv_spawning.spawner_definitions) do
+		if not adv_spawning.quota_enter() then
+			return false
+		end
+		local starttime = adv_spawning.gettime()
 		local continue = false
+		
+		if runindex >= self.initialized_spawners then
+			self.initialized_spawners = self.initialized_spawners + 1
+		else
+			continue = true
+		end
+		
+		runindex = runindex + 1
 
 		--check if cyclic spawning is enabled
 		if not continue and
@@ -234,6 +264,7 @@ function adv_spawning.seed_scan_for_applyable_spawners(self)
 				continue = true
 			end
 		end
+		starttime = adv_spawning.check_time(starttime, key  .. " at spawn range check")
 
 		--check for presence of environment
 		if not continue then
@@ -246,6 +277,7 @@ function adv_spawning.seed_scan_for_applyable_spawners(self)
 				continue = false
 			end
 		end
+		starttime = adv_spawning.check_time(starttime, key .. " at environment check")
 
 		if not continue then
 			self.spawning_data[key] = value.spawn_interval * math.random()
@@ -253,4 +285,6 @@ function adv_spawning.seed_scan_for_applyable_spawners(self)
 			self.spawning_data[key] = nil
 		end
 	end
+	
+	return self.initialized_spawners == #adv_spawning.spawner_definitions
 end

spawndef_checks.lua

@@ -19,13 +19,13 @@ function adv_spawning.verify_check_entities_around(entities_around)
 		for i=1,#entities_around,1 do
 
 			if type(entities_around[i].distance) ~= "number" then
-				print("ADV_SPAWNING: missing distance in entities_around definition")
+				adv_spawning.dbg_log(0, "missing distance in entities_around definition")
 				return false
 			end
 
 			if entities_around[i].type ~= "MIN" and
 				entities_around[i].type ~= "MAX" then
-				print("ADV_SPAWNING: invalid type \"" ..
+				adv_spawning.dbg_log(0, "invalid type \"" ..
 					dump(entities_around[i].type) ..
 					"\" in entities_around definition")
 				return false
@@ -46,13 +46,13 @@ function adv_spawning.verify_check_nodes_around(nodes_around)
 		for i=1,#nodes_around,1 do
 
 			if type(nodes_around[i].distance) ~= "number" then
-				print("ADV_SPAWNING: missing distance in entities_around definition")
+				adv_spawning.dbg_log(0, "missing distance in entities_around definition")
 				return false
 			end
 
 			if nodes_around[i].type ~= "MIN" and
 				nodes_around[i].type ~= "MAX" then
-				print("ADV_SPAWNING: invalid type \"" ..
+				adv_spawning.dbg_log(0, "invalid type \"" ..
 					dump(nodes_around[i].type) ..
 					"\" in entities_around definition")
 				return false
@@ -60,7 +60,7 @@ function adv_spawning.verify_check_nodes_around(nodes_around)
 
 			if nodes_around[i].name == nil or
 				type(nodes_around[i].name) ~= "table" then
-				print("ADV_SPAWNING: invalid type of name \"" ..
+				adv_spawning.dbg_log(0, "invalid type of name \"" ..
 					type(nodes_around[i].name) .. "\"" .. " Data: " ..
 					dump(nodes_around[i].name) ..
 					" in nodes_around definition")

testmod/init.lua

@@ -133,22 +133,22 @@ adv_spawning.register("some_bogus_entity_4",
 	})
 
 
-minetest.register_chatcommand("stats",
+minetest.register_chatcommand("adv_stats",
 	{
 		params		= "",
-		description = "show advanced spawning satistics" ,
+		description = "print advanced spawning satistics to logfile" ,
 		func		= function()
 			local stats = adv_spawning.get_statistics()
 
-			print("Adv. Spawning stats:")
+			adv_spawning.dbg_log(0, "Adv. Spawning stats:")
-			print("----------------------------------------")
+			adv_spawning.dbg_log(0, "----------------------------------------")
-			print("Spawners added: " .. stats.session.spawners_created)
+			adv_spawning.dbg_log(0, "Spawners added: " .. stats.session.spawners_created)
-			print("Spawnees added: " .. stats.session.entities_created)
+			adv_spawning.dbg_log(0, "Spawnees added: " .. stats.session.entities_created)
-			print("")
+			adv_spawning.dbg_log(0, "")
-			print("Longest step: " .. stats.step.max)
+			adv_spawning.dbg_log(0, "Longest step: " .. stats.step.max)
-			print("")
+			adv_spawning.dbg_log(0, "")
-			print("Current load: " .. stats.load.cur)
+			adv_spawning.dbg_log(0, "Current load: " .. stats.load.cur)
-			print("Average load: " .. stats.load.avg)
+			adv_spawning.dbg_log(0, "Average load: " .. stats.load.avg)
-			print("Maximum load: " .. stats.load.max)
+			adv_spawning.dbg_log(0, "Maximum load: " .. stats.load.max)
 		end
 	})