Uploaded image for project: 'Minecraft: Java Edition'
  1. Minecraft: Java Edition
  2. MC-124072

performance problems with "execute" command

    Details

    • Type: Bug
    • Status: Resolved
    • Resolution: Fixed
    • Affects Version/s: Minecraft 18w01a, Minecraft 18w02a
    • Fix Version/s: Minecraft 18w03a
    • Labels:
      None
    • Confirmation Status:
      Confirmed

      Description

      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

          Activity

            People

            • Assignee:
              dinnerbone [Mojang] Dinnerbone (Nathan Adams)
              Reporter:
              brianmcn Brian McNamara
            • Votes:
              14 Vote for this issue
              Watchers:
              11 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:
                CHK: