View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0000873LDMudOtherpublic2020-01-10 19:412020-04-29 00:26
Reporterrealms-mud Assigned ToGnomi  
PrioritynormalSeverityminorReproducibilityalways
Status resolvedResolutionfixed 
Summary0000873: LDMud 3.6.* performance significantly worse than 3.5.0
DescriptionI noticed that the changes from 3.5.0 to 3.6.0 (and 3.6.1) come with a pretty significant performance hit.

Here's some output from one of my more CPU-intensive tests first running with the 3.5.0 driver and then with the 3.6.0 driver. I did test with 3.6.1, but since the speed was roughly the same as 3.6.0, I did not bother throwing that data on here as well:

First, 3.5.0:

2020.01.10 12:55:28 LDMud 3.5.0 (3.5.0) (release)
Compiling file: /lib/tests/modules/crafting/craftWeaponTest.c
Testing lib/tests/modules/crafting/craftWeaponTest
[ PASSED ] CraftSelectedOptionBecomesEnabledWhenAllCriteriaMet (5181ms)
[ PASSED ] ChoosingCraftSelectedFailsWhenDisabled (135ms)
[ PASSED ] CraftingASwordGeneratesTheCorrectItemAndReducesMaterials (197ms)
[ PASSED ] CraftingIsNotAffectedByNotApplicableLimitedByCraftingTypeResearch (186ms)
[ PASSED ] CraftingItemIsNotAffectedByCraftingBonusesWhenOfDifferentType (190ms)
[ PASSED ] CraftingItemIsAffectedByCraftingBonusesWhenOfType (188ms)
[ PASSED ] CraftingSetsEnchantments (369ms)
Test executed: lib/tests/modules/crafting/craftWeaponTest -> [ PASSED ]
 -> built in 6484 ms.


Next, 3.6.0 -

2020.01.10 12:55:48 LDMud 3.6.0 (3.6.0) (release)
Compiling file: /lib/tests/modules/crafting/craftWeaponTest.c
Testing lib/tests/modules/crafting/craftWeaponTest
[ PASSED ] CraftSelectedOptionBecomesEnabledWhenAllCriteriaMet (11437ms)
[ PASSED ] ChoosingCraftSelectedFailsWhenDisabled (370ms)
[ PASSED ] CraftingASwordGeneratesTheCorrectItemAndReducesMaterials (458ms)
[ PASSED ] CraftingIsNotAffectedByNotApplicableLimitedByCraftingTypeResearch (469ms)
[ PASSED ] CraftingItemIsNotAffectedByCraftingBonusesWhenOfDifferentType (489ms)
[ PASSED ] CraftingItemIsAffectedByCraftingBonusesWhenOfType (481ms)
[ PASSED ] CraftingSetsEnchantments (783ms)
Test executed: lib/tests/modules/crafting/craftWeaponTest -> [ PASSED ]
 -> built in 14553 ms.

For my entire test suite, the overall execution time went from roughly 6:45 minutes to around 11:00 minutes over a half dozen runs and every test in my test suite is 30% to 100+% slower. I am also able to see this performance issue in-game, but it's much harder to accurately measure. Anecdotally, I can definitely see things that take a hundred ms in 3.5 take "a lot longer" in 3.6, but my test framework is a much more reliable measure.
Steps To ReproduceFind any object of observable complexity with which you can evaluate a method and execute it in both 3.5 and 3.6.
TagsNo tags attached.
External Data (URL)

Activities

Gnomi

2020-01-10 20:01

manager   ~0002498

You need to give us some more code to test it on. I checked some of our tests in the test suite and they ran in the same time in both versions.
And in our production MUD we don't have any that long running code.

realms-mud

2020-01-10 22:37

reporter   ~0002499

I'm trying to find something that doesn't cascade into a really painful example but I'm not having too much luck. That said, it looks like a decent test would be to grab the following files from my repo:

The test is:
https://github.com/realms-mud/core-lib/blob/master/lib/tests/items/itemTest.c

For this, you can comment out every method after CanSetBonusesOnItems() as this test takes on average 220ms on 3.5 and 470ms on 3.6 - most appears to be time spent in load_object on all of the dependencies, for what that's worth.

This has quite a few dependencies, but it should work if you just copy over the /lib directory and all of its contents to <root>/lib on your instance (ie: you will need your own master, simul_efun, etc), but any should be fine:

https://github.com/realms-mud/core-lib/tree/master/lib

Do not try to copy the rest of the mudlib over because that would bring some database dependencies (and needed DB structure) over and I don't think we want to go there.

To execute the test, you should be able to just do: load_object("/lib/tests/items/itemTest.c")->executeTests();

If this becomes painful for you, I can get you a running environment to work with.

Gnomi

2020-01-11 11:53

manager   ~0002500

I added a simul-efun for format() and regreplace(), but now I get a runtime error:

2020.01.11 11:50:59 Item: The 'bonus <thing>' element must be a string as defined in the keys of the bonusList mapping in /lib/dictionaries/bonusesDictionary.c and it must be set to an appropriate value.
2020.01.11 11:50:59 program: lib/items/item.c, object: lib/items/item#0 line 93
      38 ' epilog' in ' master.c' (' master') line 27
     137 ' run_test' in ' master.c' (' master') line 15
   36498 ' executeTests' in 'lib/tests/framework/testFixture.c' ('lib/tests/items/itemTest') line 47
   74158 'CanSetBonusesOnItems' in 'lib/tests/items/itemTest.c' ('lib/tests/items/itemTest') line 27
   74194 ' set' in ' lib/items/item.c' (' lib/items/item#0') line 514
   74285 ' isValidBonus' in ' lib/items/item.c' (' lib/items/item#0') line 93
2020.01.11 11:50:59 Error in master_ob->epilog()

realms-mud

2020-01-13 17:19

reporter   ~0002507

Sorry about that. I'd forgotten about my format efun, but regreplace should just be the standard efun. For format(string, int), it just deals with line-wrap, so returning the passed-in string would be fine.

If I had to guess (which, admittedly, this would be a blind guess), the file_size(...) check on line 65 of lib/items/item.c would almost certainly be the culprit since that is typically a privileged check in valid_read. I know I do have some file_size(...) checks in a few other places throughout the codebase.

Are you using a master/simul_efun that I have access to? If so, I can get this running locally and given you something that'll work "out of the box" rather than playing tag on this.

Gnomi

2020-01-13 17:23

manager   ~0002508

This is my master (the inc and sys directory are from ldmud's test directory):

#include "/inc/base.inc"
#include "/inc/sefun.inc"

void run_test()
{
    object ob;
    int *start, *end;

    msg("\nRealms-MUD test\n"
          "---------------\n");

    ob = load_object("lib/tests/items/itemTest");

    start = utime();
    ob->executeTests();
    end = utime();
    msg("Duration: %d\n", (end[0] - start[0]) * 1000000 + end[1] - start[1]);
    shutdown(0);

    return 0;
}

string *epilog(int eflag)
{
    set_driver_hook(H_INCLUDE_DIRS, ({ "/sys/"}));

    run_test();
    return 0;
}


And this the simul-efun:
string format(string str, int width)
{
    return str;
}

varargs string regreplace(string txt, string pattern, string|closure replacepattern, int flags)
{
    return efun::regreplace(txt, pattern, replacepattern, flags);
}

realms-mud

2020-01-13 20:06

reporter   ~0002509

Since I wasn't able to use your master.c (has a couple include files I don't have), I grabbed (a really awful) one that works. You should be able to just untar this tarball somewhere as a root mudlib directory and point the driver at it.

Thanks for your efforts!
test.tar.gz (888,164 bytes)

Gnomi

2020-01-13 20:25

manager   ~0002510

As I wrote the inc and sys directories are in the directory /test in the LDMud sources.

realms-mud

2020-01-13 20:32

reporter   ~0002511

I guess reading is hard for me. ;)

realms-mud

2020-01-13 21:12

reporter   ~0002512

It looks like all you need to do to "fix" the issue you're seeing is to change the CanSetBonusesOnItems test to remove the setup/check for "bonus fire attack". Reset isn't getting called on the objects loaded for that.... keeping that in the test is not really important in this context and only changes the execution time by about 5ms on average.

IE: Change lib/tests/items/itemTest.c to just be:
<code>
inherit "/lib/tests/framework/testFixture.c";

object Item;

void Setup()
{
    Item = clone_object("/lib/items/item");
}

void CleanUp()
{
    destruct(Item);
}

void CanSetBonusesOnItems()
{
    // Only test a few of these - the full set is tested in dictionaries/bonusesDictionaryTest
    ExpectFalse(Item->query("enchanted"), "item is enchanted");
    ExpectTrue(Item->set("bonus armor class", 5), "bonus armor class can be set");
    ExpectTrue(Item->set("bonus gem crafting", 7), "bonus armor class can be set");

    ExpectEq(5, Item->query("bonus armor class"), "bonus armor class query returns correctly");
    ExpectEq(7, Item->query("bonus gem crafting"), "bonus gem crafting query returns correctly");
    ExpectTrue(Item->query("enchanted"), "item is enchanted");
}
</code>

realms-mud

2020-01-13 21:13

reporter   ~0002513

... and the Mantis Wiki let me down... apologies for the fubar formatting.

Gnomi

2020-01-14 11:20

manager   ~0002518

I can reproduce it and will look into it.

Gnomi

2020-01-14 21:49

manager   ~0002519

Could you try the optimization branch in my repository: https://github.com/amotzkau/ldmud/tree/optimization

I found that the most of the extra time was spent on passing the source files through iconv().
As ASCII or UTF-8 files will be the most common case I implemented a shortcut for that, that just checks the input. These checks also have extra costs in comparison to 3.5.2, but they are necessary.

I would be interested how this optimization does with your test suite. The test case I have runs between 31 and 35ms, so the difference to 3.5.2 is within the margin of error...

realms-mud

2020-01-15 00:43

reporter   ~0002520

I did a few test runs and the results look really good:

3.5:
Test executed: lib/tests/modules/crafting/craftWeaponTest -> [ PASSED ]
 -> built in 6387 ms.

3.6:
Test executed: lib/tests/modules/crafting/craftWeaponTest -> [ PASSED ]
 -> built in 14722 ms.

Your optimization:
Test executed: lib/tests/modules/crafting/craftWeaponTest -> [ PASSED ]
 -> built in 6892 ms

A much faster test (the full itemTest.c I pointed you to earlier):
3.5: 149ms
3.6: 241ms
Your optimizations: 168ms

There's definitely a little overhead, but it's not linear like it was and overall I'd say it's pretty negligible.

zesstra

2020-01-18 17:30

administrator   ~0002521

I think, it is also worth pointing out that your test suite is performing that bad on 3.6.x concerning the performance because it is so heavily compiling lots of programs. Once an object is loaded, there should be not much slowdown.

Gnomi

2020-04-29 00:26

manager   ~0002530

Optimization was released in LDMud 3.6.2

Issue History

Date Modified Username Field Change
2020-01-10 19:41 realms-mud New Issue
2020-01-10 20:01 Gnomi Note Added: 0002498
2020-01-10 20:01 Gnomi Assigned To => Gnomi
2020-01-10 20:01 Gnomi Status new => feedback
2020-01-10 22:37 realms-mud Note Added: 0002499
2020-01-10 22:37 realms-mud Status feedback => assigned
2020-01-11 11:53 Gnomi Note Added: 0002500
2020-01-13 17:19 realms-mud Note Added: 0002507
2020-01-13 17:23 Gnomi Note Added: 0002508
2020-01-13 20:06 realms-mud File Added: test.tar.gz
2020-01-13 20:06 realms-mud Note Added: 0002509
2020-01-13 20:25 Gnomi Note Added: 0002510
2020-01-13 20:32 realms-mud Note Added: 0002511
2020-01-13 21:12 realms-mud Note Added: 0002512
2020-01-13 21:13 realms-mud Note Added: 0002513
2020-01-14 11:20 Gnomi Note Added: 0002518
2020-01-14 21:49 Gnomi Note Added: 0002519
2020-01-15 00:43 realms-mud Note Added: 0002520
2020-01-18 17:30 zesstra Note Added: 0002521
2020-04-29 00:26 Gnomi Status assigned => resolved
2020-04-29 00:26 Gnomi Resolution open => fixed
2020-04-29 00:26 Gnomi Note Added: 0002530