Milliseconds time profiler for mods

[cpeosphoros]

Hello.

Factorio, with reason, doesn't provide access to the "os" object, less so to third party lua libraries. That makes it impossible to write a time profiler inside a mod.

I come up with a way to circunvect that. It's quite simple.

First, you have to add some instant logging capacity to your mod. I'm using stdlib.log (https://github.com/Afforess/Factorio-St ... er-example) for that. Be sure that you make debug=true when creating your log, like this:

Code: Select all

LOGGER = Logger.new("Your Mod Name", "fancylog", true, {log_ticks=true} )

Then, you create this lua file in the same directory LOGGER will be writing to. In my example, it would be "~/.factorio/script-output/logs/Your Mod Name":

Code: Select all

require "socket"

local function getMS()
	return socket.gettime() * 1000
end

local input
while not input do
	input = io.open("fancylog.log")
end

io.output("profile.log")
local t1 = getMS()
while true do
	while not input:read(0) do end
	local t2 = getMS()
	local dt = t2 - t1
	local line = input:read("*line")
	io.write(string.format("%12d: %s\n", dt, line))
	io.flush()
	t1 = t2
end

Then you make sure to delete any existing copy of fancylog.log in that directory, and run the profiler from your terminal prompt, like this:

Code: Select all

~/.factorio/script-output/logs/Your Mod Name $ lua profiler.lua

It will "hang", waiting fancylog.log to be created.

Next, you open factorio, load your modded game and let it run for as long as you want, do the actions you want to profile, etc. and exit the game (you don't have to save, if you don't want to).

Go back to the terminal where you are running the profiler and kill it with ctrl-C.

profile.log will look something like this:

Code: Select all

           1: 89:01:52.39: Configuration changed.
         214: 89:01:52.39: Loading Registry
           0: 89:01:52.39: Creating Registry
           1: 89:01:52.39: Registered job table: 0x00007fd42c003cb0 with name Concreteer and priority 10
        2756: 89:01:54.00: Check Tick
           0: 89:01:54.00: Checking Udo Schmidt for Concreteer
        7903: 89:01:54.00: Worked 16 times
        4222: 89:01:56.00: Check Tick
           0: 89:01:56.00: Checking Udo Schmidt for Concreteer
        7658: 89:01:56.00: Worked 26 times
        4064: 89:01:58.00: Check Tick
           0: 89:01:58.00: Checking Udo Schmidt for Concreteer
        8244: 89:01:58.00: Worked 32 times

The first column is the time, in integer milliseconds, since the last logged message. The second column is the tick number, as provided by stdlib.log and the third is your actual log messages.

This script uses the luasocket third party library, so we can get the time in milliseconds, as the default lua os.time() only gives precision in seconds.

The easiest way to get lua socket in a linux machine is run these commands in your pront:

Code: Select all

sudo apt-get install luarocks
sudo luarocks install luasocket

That is it. Hope that will be useful to someone.

[cpeosphoros]

New version:

Code: Select all

require "socket"

local fileName = "loop.log"
local input

-----------------------
-- Utility functions --
-----------------------
local function write(dt, line)
	local lineOut = string.format("%09.3f: %s", dt, line)
	io.write(lineOut .. "\n")
	print(lineOut)
	io.flush()
end

local function getMS()
	return socket.gettime() * 1000
end

local function waitData()
	--print("Waiting data. " .. os.time())
	while not input:read(0) do end
end

local function readLine()
	--input:read("*line")
	local line = ""
	repeat
		waitData()
		local char = input:read(1)
		if char == "\n" then
			return line
		end
		line = line .. char
	until false
end

--------------------
-- Special timers --
--------------------

local timer = {}

local profile = {}

local warns = {job=100, worker=100, Cycle=200}
local warnCount = {}

profile["set"] = function(index,t)
	timer[index] = t
	write(0, "Profiling " .. index)
end

profile["get"] = function(index, t2)
	local t = timer[index]
	if t then
		dt = t2 - t
		write(dt, "Profiled " .. index)
		local warn
		local warnIndex
		for i, v in pairs(warns) do
			if string.find(index, i) then
				warnIndex = i
				warn = v
				break
			end
		end 
		if warn and dt > warn then
			warnCount[index] = warnCount[index] or 0
			warnCount[index] = warnCount[index] + 1
			write(warnCount[index], "WARN! " .. index)
		end
	else
		write(t2, "Not found timer ".. index)
	end
end

---------------
-- Main loop --
---------------

os.remove(fileName)
-- wait for the log to be created
while not input do
	input = io.open(fileName)
end
io.output("profile.log")

local t1 = getMS()
while true do
	-- wait for data
	waitData()
	local t2 = getMS()
	local dt = t2 - t1
	local line = readLine()
	-- write timed data
	write(dt, line)

	--check for special timer
	if string.find(line, "profile") then
		--parse the line. Malformed lines will raise errors in the next step
	    local words = {}
	    for w in string.gfind(line, "%S+") do
	      words[#words +1] =  w
	    end
	    --expected syntax is that the line ends in either:
	    -- "profile set label"
	    -- "profile get label"
	    -- so we index the profile array of funtions with the second last word
	    -- and pass the last one as the index for that function, along with the time.
	    -- "label" must contain only non-space chars
	    local f = profile[words[#words -1]]
	    if f then
	    	f(words[#words], t2)
	    end
	end

	--begin again
	t1 = t2
end

It still records time line by line, but also allows for timing nested or intercalled larger cycles.

To use the larger cycles, you may do something like this:

Code: Select all

LOGGER.log("profile set cycle1")
--do some work
LOGGER.log("profile set cycle2")
--do some work
LOGGER.log("profile get cycle1")
--do some work
LOGGER.log("profile set cycle3")
--do some work
LOGGER.log("profile get cycle2")
--do some work
LOGGER.log("profile get cycle3")

And the results would be:

Code: Select all

00000.038: 85:38:16.00: profile set cycle1
00000.000: Profiling cycle1
00000.043: 85:38:16.00: Some work logged here
00000.029: 85:38:16.00: profile set cycle2
00000.000: Profiling cycle2
00000.042: 85:38:16.00: Some work logged here
00000.054: 85:38:16.00: profile get cycle1
00000.200: Profiled cycle1
00000.043: 85:38:16.00: Some work logged here
00000.029: 85:38:16.00: profile set cycle3
00000.000: Profiling cycle3
00000.483: 85:38:16.00: Some work logged here
00000.094: 85:38:16.00: profile get cycle2
00001.327: Profiled cycle2
00000.483: 85:38:16.00: Some work logged here
00000.094: 85:38:16.00: profile get cycle3
00001.861: Profiled cycle3

It will also work with messages like LOGGER.log("Starting hard work. profile set cycleX"), as long as "profile set/get label" are the final words of a line.

Also, it will currently break if you use the reserved word "profile" anywhere else in your logs.

[Betep3akata]

Thanks fo this magic tool

P.S.: tested on http://files.luaforge.net/releases/luaf ... s/5.1.4-35 (for windows) where luasocket already included.