mojira.dev
MC-124072

performance problems with "execute" command

The 'execute' command runs much slower than one would expect, compared to other commands. This is problematic since "execute" is "the most important" command; the performance of "execute" currently dominates the overall wall-clock runtime of many user-created command systems.

SUMMARY

Here is the bug summary in a nutshell:

took 32 milliseconds to run 200000 iterations of
    seed
took 2692 milliseconds to run 200000 iterations of
    execute run seed

Wrapping a simple command in "execute run" can make the command run up to 80x slower.

EXPECTATIONS

I do expect there to be 'overhead' in using 'execute'. In its general form, there are implicit loops for subcommands such as `as` and `at` to create new 'sender contexts' and 'location contexts', and execute must run its body command for each context, installing (pushing) and uninstalling (popping) the context (stack) for each iteration of the body. Furthermore, `execute` must also accumulate the results of each body command so it can publish the correct outputs to its own `result` and `success`.

However the amount of time taken by `execute` in 18w01a (and in previous 1.13 snapshots; this is not a regression) seems too high, especially in cases where there is no `as`/`at` looping.

I suspect there is something inefficient being done at runtime, which is the bug I would like to see fixed.

(I can also imagine there might be further performance gains to be had by special-casing some code paths, like the 'loop over exactly one thing', but let's not go that far yet.)

MEASUREMENTS

I am attaching a world with a datapack that does microbenchmark measurements of various commands using the worldborder as a timer. To run the benchmarks yourself, go into the world, do a `/reload`, and follow the simple instructions in chat.

Here is the output on my machine:

18w01a
took 32 milliseconds to run 200000 iterations of
    seed
took 103 milliseconds to run 200000 iterations of
    function test:call_seed
took 485 milliseconds to run 200000 iterations of
    scoreboard players add @s A 1
took 962 milliseconds to run 200000 iterations of
    function test:call_add
took 19 milliseconds to run 200000 iterations of
    execute if entity @s
took 517 milliseconds to run 200000 iterations of
    execute at @s if entity @s
took 643 milliseconds to run 200000 iterations of
    execute at @s if entity @s
    seed
took 3685 milliseconds to run 200000 iterations of
    execute at @s if entity @s run seed
took 2450 milliseconds to run 200000 iterations of
    execute at @s if entity @s
    scoreboard players add @s A 1
took 8020 milliseconds to run 200000 iterations of
    execute at @s if entity @s run scoreboard players add @s A 1
took 2692 milliseconds to run 200000 iterations of
    execute run seed
took 6703 milliseconds to run 200000 iterations of
    execute run scoreboard players add @s A 1

The general measurement method is to start a worldborder and call a function 200 times, where the function body is the same command(s) repeated 1000 times.

Here is the same code running in 18w02a. I think any changes in the numbers are small enough to be just 'noise', but it will be useful to log and compare each snapshot to notice any regressions.

18w02a
took 47 milliseconds to run 200000 iterations of
    seed
took 97 milliseconds to run 200000 iterations of
    function test:call_seed
took 535 milliseconds to run 200000 iterations of
    scoreboard players add @s A 1
took 787 milliseconds to run 200000 iterations of
    function test:call_add
took 19 milliseconds to run 200000 iterations of
    execute if entity @s
took 597 milliseconds to run 200000 iterations of
    execute at @s if entity @s
took 663 milliseconds to run 200000 iterations of
    execute at @s if entity @s
    seed
took 3907 milliseconds to run 200000 iterations of
    execute at @s if entity @s run seed
took 2428 milliseconds to run 200000 iterations of
    execute at @s if entity @s
    scoreboard players add @s A 1
took 7941 milliseconds to run 200000 iterations of
    execute at @s if entity @s run scoreboard players add @s A 1
took 2801 milliseconds to run 200000 iterations of
    execute run seed
took 6589 milliseconds to run 200000 iterations of
    execute run scoreboard players add @s A 1

Here is some more data I have not reasoned about:

took 2757 milliseconds to run 200000 iterations of
    execute run seed
took 8872 milliseconds to run 200000 iterations of
    execute run execute run execute run seed
took 12058 milliseconds to run 200000 iterations of
    execute run execute run execute run execute run seed

Attachments

Comments 1

took 98 milliseconds to run 200000 iterations of
    seed
took 90 milliseconds to run 200000 iterations of
    function test:call_seed
took 353 milliseconds to run 200000 iterations of
    scoreboard players add @s A 1
took 330 milliseconds to run 200000 iterations of
    function test:call_add
took 13 milliseconds to run 200000 iterations of
    execute if entity @s
took 40 milliseconds to run 200000 iterations of
    execute at @s if entity @s
took 55 milliseconds to run 200000 iterations of
    execute at @s if entity @s
    seed
took 129 milliseconds to run 200000 iterations of
    execute at @s if entity @s run seed
took 431 milliseconds to run 200000 iterations of
    execute at @s if entity @s
    scoreboard players add @s A 1
took 438 milliseconds to run 200000 iterations of
    execute at @s if entity @s run scoreboard players add @s A 1
took 23 milliseconds to run 200000 iterations of
    execute run seed
took 270 milliseconds to run 200000 iterations of
    execute run scoreboard players add @s A 1

Brian McNamara

Nathan Adams

Confirmed

Minecraft 18w01a, Minecraft 18w02a

Minecraft 18w03a

Retrieved