util.timestamp() for performance debugging

Post Reply
doktorstick
Fast Inserter
Fast Inserter
Posts: 151
Joined: Fri Aug 12, 2016 10:22 pm
Contact:

util.timestamp() for performance debugging

Post by 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
Filter Inserter
Filter Inserter
Posts: 478
Joined: Sat Aug 23, 2014 11:43 pm
Contact:

Re: util.timestamp() for performance debugging

Post by 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
Waste of bytes : P

Nexela
Smart Inserter
Smart Inserter
Posts: 1828
Joined: Wed May 25, 2016 11:09 am
Contact:

Re: util.timestamp() for performance debugging

Post by Nexela »

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

Choumiko
Smart Inserter
Smart Inserter
Posts: 1352
Joined: Fri Mar 21, 2014 10:51 pm
Contact:

Re: util.timestamp() for performance debugging

Post by 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)

User avatar
prg
Filter Inserter
Filter Inserter
Posts: 947
Joined: Mon Jan 19, 2015 12:39 am
Contact:

Re: util.timestamp() for performance debugging

Post by 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.
Automatic Belt (and pipe) Planner—Automate yet another aspect of constructing your factory!

User avatar
aubergine18
Smart Inserter
Smart Inserter
Posts: 1264
Joined: Fri Jul 22, 2016 8:51 pm
Contact:

Re: util.timestamp() for performance debugging

Post by aubergine18 »

keyboardhack wrote: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.
Better forum search for modders: Enclose your search term in quotes, eg. "font_color" or "custom-input" - it prevents the forum search from splitting on hypens and underscores, resulting in much more accurate results.

Nexela
Smart Inserter
Smart Inserter
Posts: 1828
Joined: Wed May 25, 2016 11:09 am
Contact:

Re: util.timestamp() for performance debugging

Post by 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!

User avatar
aubergine18
Smart Inserter
Smart Inserter
Posts: 1264
Joined: Fri Jul 22, 2016 8:51 pm
Contact:

Re: util.timestamp() for performance debugging

Post by 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.
Better forum search for modders: Enclose your search term in quotes, eg. "font_color" or "custom-input" - it prevents the forum search from splitting on hypens and underscores, resulting in much more accurate results.

Boodals
Fast Inserter
Fast Inserter
Posts: 129
Joined: Sun Feb 11, 2018 7:10 pm
Contact:

Re: util.timestamp() for performance debugging

Post by 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.

Post Reply

Return to “Implemented mod requests”