Benchmarking lua functions

[randomdude]

Seeing as there is no way to access either os or socket modules, how can I track how long does a function takes to run over a fixed number of ticks?

Currently im just logging random messages at the start and end of the function, but for very fast/small functions the timestamps are not accurate enough.

I have seen other messages in the forum, like viewtopic.php?f=25&t=52407&p=306807&hil ... rk#p306676 by @Optera with timings over N ticks, but I can't find the code to do that.

Is there any wiki or post that shows how to do it?

Thanks

[Bilka]

If you use /measured-command <command> instead of /c <command> in the console, the game will benchmark the function for you. Of course this means that you have to be able to run the function from the console, so you might have to add a remote interface: https://lua-api.factorio.com/latest/LuaRemote.html

If you just want to benchmark the overall game, you can use the --benchmark FILE commandline argument when starting the game, I assume that that is what Optera used.

[randomdude]

Thanks for the response

I have tried the benchmark route, but the game just loads and shutdowns without doing anything

Could it be because it's the steam binary? I don't see anything in the log file

Code: Select all

   0.000 Program arguments: "Factorio.exe" "--benchmark" "wads3.zip" "--benchmark-ticks" "10000"
   ...
   20.704 Factorio initialised
  20.705 Loading map wads3.zip: 8215632 bytes.
  20.755 Loading Level.dat: 16237919 bytes.
  20.759 Info Scenario.cpp:136: Map version 0.16.51-0
  21.103 Loading script.dat: 705762 bytes.
  21.105 Checksum for script Factorio/temp/currently-playing/control.lua: 950616531
  21.112 Checksum for script __FARL__/control.lua: 118530187
  21.114 Checksum for script __AfraidOfTheDark__/control.lua: 2322376383
  21.123 Checksum for script __autofill__/control.lua: 2417227806
  21.127 Checksum for script __BlackMarket__/control.lua: 4050367475
  21.129 Checksum for script __bobinserters__/control.lua: 47546247
  21.132 Checksum for script __even-distribution__/control.lua: 916752674
  21.134 Checksum for script __EvoGUI__/control.lua: 1091021108
  21.139 Checksum for script __Factorissimo2__/control.lua: 3203797068
  21.149 Checksum for script __FNEI__/control.lua: 4230980642
  21.172 Checksum for script __helmod__/control.lua: 1399040573
  21.173 Checksum for script __KS_Power__/control.lua: 2839612813
  21.175 Checksum for script __LogisticTrainNetwork__/control.lua: 1045368828
  21.176 Checksum for script __long-reach__/control.lua: 2450699146
  21.185 Checksum for script __Nanobots__/control.lua: 3216505520
  21.186 Checksum for script __nixie-tubes__/control.lua: 2853236676
  21.188 Checksum for script __upgrade-planner__/control.lua: 1007996437
  21.189 Checksum for script __Waterfill_v15__/control.lua: 0
  21.190 Checksum for script __Zoom__/control.lua: 1056507806
  21.191 Checksum for script __bobclasses__/control.lua: 3423507869
  21.192 Checksum for script __bobores__/control.lua: 3649119228
  21.193 Checksum for script __bobplates__/control.lua: 2137047030
  21.206 Checksum for script __rso-mod__/control.lua: 3942136372
  21.208 Checksum for script __boblogistics__/control.lua: 4188534431
  21.211 Checksum for script __WhistleStopFactories__/control.lua: 1316849903
  21.212 Checksum for script __angelsrefining__/control.lua: 884011260
  21.213 Checksum for script __LoaderRedux__/control.lua: 111384177
  21.215 Checksum for script __SpaceMod__/control.lua: 2906056273
  21.243 Script @__LogisticTrainNetwork__/control.lua:230: [LTN] on_load: complete
  25.756 DSound: Stopping voice
  25.756 DSound: Joining thread
  25.758 DSound: Exit _dsound_update; tid=2468
  25.758 DSound: Waiting for voice to stop ... signaled
  25.758 DSound: Joined thread
  25.758 DSound: Destroying thread
  25.758 DSound: Thread destroyed
  25.758 DSound: Releasing buffer
  25.758 DSound: Voice stopped
  25.758 DSound: Deallocating voice
  25.758 DSound: Deallocated voice
  25.780 Steam API shutdown.
  25.782 Goodbye

[Bilka]

25.780 Steam API shutdown.

Steam can be weird about commandline arguments, try using the standalone version from factorio.com.

Also, you might have to pipe the output into a file using ">> my file.txt"

[randomdude]

Thanks again Bilka. I've made some progress with the standalone version, but now for some reason it gets stuck at 90% loading (Loading sound), while still counting the updates.

Code: Select all

Running update 9700
Running update 9800
Running update 9900
Performed 10000 updates in 665.928 ms
  avg: 0.067 ms, min: 0.048 ms, max: 0.555 ms
  checksum: 2275046773
  12.281 DSound: Stopping voice
  12.281 DSound: Joining thread
  12.282 DSound: Exit _dsound_update; tid=14708
  12.282 DSound: Waiting for voice to stop ... signaled
  12.282 DSound: Joined thread
  12.283 DSound: Destroying thread
  12.283 DSound: Thread destroyed
  12.283 DSound: Releasing buffer
  12.284 DSound: Voice stopped
  12.284 DSound: Deallocating voice
  12.284 DSound: Deallocated voice
  12.346 Goodbye

I have restarted and removed all mods to see if that would help, but still does that, and there is nothing different in the logs.

Is that expected? Also, should I make another post on Technical help, or is it fine to keep it here?

[Bilka]

Thanks again Bilka. I've made some progress with the standalone version, but now for some reason it gets stuck at 90% loading (Loading sound), while still counting the updates.

Is that expected?

That is expected yes, the save file is loaded, but not rendered, so the game has nothing to show you, meaning it shows you the latest state that it rendered - the loading screen.

[eradicator]

Currently im just logging random messages at the start and end of the function, but for very fast/small functions the timestamps are not accurate enough.

General rule: If calling it once is too fast, call it a million times, or however often it takes for the accuracy to be relevant. I find that for most things in factorio 10k to 100k repetitions get me into the one-second range where i can get good numbers.

[randomdude]

Currently im just logging random messages at the start and end of the function, but for very fast/small functions the timestamps are not accurate enough.

General rule: If calling it once is too fast, call it a million times, or however often it takes for the accuracy to be relevant. I find that for most things in factorio 10k to 100k repetitions get me into the one-second range where i can get good numbers.

Yes, the problem I had with that would be creating (imo) very synthetic situations, as, taking LTN for example as its from the same author that InventorySensor, where I found the comment about benchmarking that started me in this journey, but I haven't used it, so I don't know how to pose an example with it.

If I call the on_tick function 10k times to get more accurate measurements, from what I understand, it's just gonna block for, lets say each on_tick runs for 1 microsecond, a total of 10ms, where the environment won't change, trains won't be dispatched as there won't be inventory changes, etc. so it will be testing the same conditions over and over, which won't be as useful and realistic

I was thinking on exposing the looped version of the function and using the measurement command Bilka gave me, but then, it would be the same situation, as the command would block too, right?

On the other hand, using the benchmark option, wouldn't it require a very specific scenario to get useful and valid measurements? If I understood what Bilka said yesterday, the game runs, just without rendering, so any entity will be updating too, so:

- You would have to disable biters to avoid any kind of randomness and their updates
- You would need a lot of copies of the entities you want to test, in order to skew the timings in a meaningful way to take measurements
- You would be only able to time things that happen automatically (on_tick mostly), as there is no way to interact with the game

This is hard

[eradicator]

Depends on what you're trying to measure ofc. If you're writing a mod and want to know which implementation of a function is faster you can measure it with loops, e.g. when you're unsure how expensive a call to the c state is. If you want to measure if i.e. your iron smelter with bots and beacons is more UPS friendly than the smelter with belts... then ofc looping doesn't help. I think the --benchmark command was meant for the latter, though i haven't used it.

And you forgot to say what exactly you're trying to measure ;).

[Optera]

On the other hand, using the benchmark option, wouldn't it require a very specific scenario to get useful and valid measurements? If I understood what Bilka said yesterday, the game runs, just without rendering, so any entity will be updating too, so:

- You would have to disable biters to avoid any kind of randomness and their updates
- You would need a lot of copies of the entities you want to test, in order to skew the timings in a meaningful way to take measurements
- You would be only able to time things that happen automatically (on_tick mostly), as there is no way to interact with the game

This is hard

I never bothered doing that for my benchmarks.
My results are created from a single save, benchmarked 5-10 times for 10k-100k ticks then averaged.

The idea is that any variables will average out when doing enough benchmark runs for each code iteration.

[randomdude]

And you forgot to say what exactly you're trying to measure .

I'm at that point with most games with mods where I start trying to tweak them to my own experience and interests and basically fiddle with them to also try and give back to the community either by fixing bugs, adding features or whatever

I was playing with Black Market, and after a while, I started to miss a couple signals to allow me to automate it a bit more, in truly factorio spirit.

Let's say every day i buy some copper and iron ore, and thru transformation, make some labs to sell them. Now, I don't wanna transform all into labs, just enough to recoup my expenses, and keep the remaining plates for use on the factory.

For this, I would need 2 signals: One on buying chests that shows the total order cost, and one on selling chests that shows the value of all the items in that chest at the moment

So I set my way to check how to implement them, when I stumbled upon the discussion i mentioned above where Optera was asking about the perf of calculating total signals for both wires (before the merged_signals existed) and write perf.

That got me thinking, the buying side is no problem as orders are mostly static, so it's easy to cache, the selling part can potentially change every tick as more items are inserted in the chest.

So I wanted to measure 2 different options:

- Recalculating on each tick, that presumably would be bad, but I can't discard it without knowing
- Trying to find a balance between update rate and the risk of overselling by trying multiple update rates

And of course, I don't want to change anything that turns it for the worse, so I wanted a baseline too

As you can see, I dont really need to measure anything, but it's just something i enjoy doing and I'm too deep into this rabbit hole to pull out now

[eradicator]

I see. (Also it's nice if people actually explain what they're trying to do instead of becoming grumpy and insulting me for not being able to read their minds *sigh*.)

I don't know black market (except for the mod portal description) and have little experience with circuits, but i do remember a "trick" when reading them. The CircuitConditionSpecification has a .fullfilled bit, which you can check without reading the whole circuit. So every tick you just ask the circuit "are we still ok?", and if yes don't do anything else (because it's still the same as the last time you checked). If not you do your processing and update the condition to the current state. Though this only really works for singular signals. If you need multiple signals then you can't have a singular condition for them (i.e. you can test "A > 10" but not "A > 10 and B > 10"). You could also do something like dynamic per-entity update rates, i.e. check entities that seem to update often more frequently.

For benchmarking this @Opteras approach of benchmarking the whole map is probably best. Start with an empty map, then construct something that as much as possible only does the thing you want to benchmark. Then make a blueprint of that and copy it 1000 times. Then measure the map :).