util.timestamp() for performance debugging

[doktorstick]

Howdy.

I would like a debugging API to help identify performance bottlenecks. For instance:

Code: Select all

t1 = util.timestamp()
do_order_n_cubed_operations()
print ("function took", util.timestamp() - t1, "nanoseconds")

Optimally, it would measure only the time my code spent running, but if it cannot be that isolated, anything is better than nothing. Thanks for the consideration.

[keyboardhack]

This would be nice but someone will probably use it incorrectly by only processing entities for n miliseconds per tick which would break multiplayer. To prevent this maybe this function should only function when the game is started with

Code: Select all

--enable-performance-debugging

[Nexela]

having access to os.time and os.clock would be nice. But as keyboardhack said the potential for abuse is there.

[Choumiko]

if you use

Code: Select all

log("something")

in your script it writes to the factorio current log, with a timestamp (seconds.milliseconds since Factorio was started i think)

[prg]

If millisecond accuracy is enough you can just use log() to create timestamped log entries, then do the diff in your head. You probably want to stay way under 16ms in your on_tick handler, but this might still be useful for testing if you repeat the same operation a thousand times or so.

If you want to get access to os.clock() and co., good news! Turns out the os and io libraries are included in the Factorio executable, they're just getting disabled at startup, as was discovered in RE Series Part 1: A wild LUA appears !. We just need to disable the code that disables the libraries so we can use them on our own system for debugging. For this we can just NOP out a few bytes in LuaHelper::initLuaState(lua_State*). Look at the adresses that get passed to lua_setglobal() to find the strings "io" and "os", then replace the instructions for that call and the preceding lua_pushnil() with NOPs (0x90). In the 0.13.15 64bit Linux executable these would be 42 bytes starting at offset 0x14867d. Now you can do

Code: Select all

t0 = os.clock()
-- do stuff
print(os.clock()-t0)

Just don't forget to remove that code again in the mod you publish.

[aubergine18]

This would be nice but someone will probably use it incorrectly by only processing entities for n miliseconds per tick which would break multiplayer.

If that's the case then just disable or edit the offending mod? Having access to os.time etc would make it much easier for modders to find out which specific lines, loops, etc., are hogging the most CPU in their mods.

[Nexela]

If that's the case then just disable or edit the offending mod?

Well the typical mod user probably won't know which mod is causing the foobar leading to desync posts on the forum leading to devs spending time finding the offending mod, leading to the eventual discontinuince of said OS stuff again.

But as prg pointed out as mod developlers we do have a way to access OS for internal testing so all is good in the world!

[aubergine18]

Just noticed a console command that could be quite useful if your code is exposed via remote interface:

Code: Select all

/measured-command game.player.print 'how much time does this take to run?'

The `/measured-command` is like `/c` but tracks and displays the time taken to complete the operation.

[Boodals]

Although this is (or was, if a moderator moves it) in Won't implement, and is pretty old, I created a way to get performance metrics for lua scripts (I have source access), which will be in the next version of 0.17.
LuaGameScript.create_profiler, returns a LuaProfiler, which can be used anywhere a localised string is used. You can't read the raw time values from lua. This means that it is totally desync safe.