Expensive "crafting" calls

[BuckarooBanzay]

(just dumping this here so it does not get forgotten)

Recent heavy lag-spikes are accompanied by lots of crafting and network-receive spikes.
I suspect some auto-clicker or even low-level packet generation.

Prominent callbacks for minetest.register_on_craft

• xp_redo
• stamina

Testing:

/lua xp_redo.on_craft = function() end
/lua stamina.exhaust_player = function() end
/lua minetest.registered_on_crafts = {}

EDIT: turns out this is another issue with the (little-bit-) higher latency postgres backend

[OgelGames]

I think this could just be minegeld crafting, in combination with spamming middle-click (which crafts 10x at a time). I've been the source of several lag spikes in the past doing just that, and I'm sure I'm not the only one who crafts minegeld...

[BuckarooBanzay]

I think this could just be minegeld crafting, in combination with spamming middle-click (which crafts 10x at a time). I've been the source of several lag spikes in the past doing just that, and I'm sure I'm not the only one who crafts minegeld...

Yeah, chi confirmed it too 😞 it is pretty weird that simple middle-clicking can bump the lag into the minute-range, there may be some "on_craft" hooks somewhere, haven't checked yet...

[BuckarooBanzay]

Call stack for crafting (slightly different on recent engine commits, but still has the same issue):

• Client sends "Craft/Inventorymove" packet (10x with middle click)
• Network stack magic 🌈 🦄
• Call to Server::handleCommand_InventoryAction (https://github.com/minetest/minetest/blob/9bff154cba14686f5a3b56f4cba405824b88c402/src/network/serverpackethandler.cpp#L575)
  • Call to Server::checkPriv (https://github.com/minetest/minetest/blob/9bff154cba14686f5a3b56f4cba405824b88c402/src/server.cpp#L3133)
    • Call to Server::getPlayerEffectivePrivs (https://github.com/minetest/minetest/blob/9bff154cba14686f5a3b56f4cba405824b88c402/src/server.cpp#L3126)
      • Call to m_script->getAuth
      • Somewhere down here a query to the database gets executed (on every craft-packet) 🤦

There was a similar issue with the priv-check db-call before i installed the get_player_privs_cache mod, not sure how i approach this one..

TODO

• Check if minetest.builtin_auth_handler is globally accessible
• Override and cache minetest.builtin_auth_handler.get_auth
  • Cache the result initially
  • Invalidate on logout, setpassword or priv change
• Remove redundant get_player_privs_cache mod
• Add monitoring metrics for minetest.builtin_auth_handler

EDIT: disregard this, not accurate

[BuckarooBanzay]

this is still happening, reopening 😭

[BuckarooBanzay]

Only reproducible with lots of item-definitions

Main cpu-hog in function: ICraftAction::apply
https://github.com/minetest/minetest/blob/41a6136f774a30364b6d3fd2042c9dbeb34f2109/src/inventorymanager.cpp#L857-L896

Measured time around while loop:

# middle-click
ICraftAction::apply() while loop took 113 ms
# single click
ICraftAction::apply() while loop took 6 ms