Performance issues related to deduplicating models with large quantities

Question

Performance issues related to deduplicating models with large quantities

SolidBlock-cn opened this issue a year ago · 1 comments

SolidBlock-cn commented a year ago

A couple of days ago, my mod (Extended Block Shapes) received the following issue, stating what when both FerriteCore and ExtendedBlockShapes are installed, the loading takes quite a long time:
SolidBlock-cn/extshape#40
I've investigated into it, and found the performance issue lies on Deduplicator.deduplicate, which is mixed-in within BasicBakedModel.Builder.addQuad by SimpleModelBuilderMixin.deduplicate.

If I use another mixin to directly "cancel" the deduplicate method at the head (which means skipping the entire deduplicate method), then the game can load swiftly.
I've also found that the deduplication does not take long time for initial several models, but takes longer time along with the expansion of Deduplicator.BAKED_QUAD_CACHE.

I monitored the time used to baking every 1000 models, and also monitored the time used to call deduplicate. Especially, as I suspect the time is spent mainly calling containsKey, I monitored the time calling containsKey 10000 times. This is my test result:

[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanotime calling `containsKey` 10000 times: 687500
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanoTime calling deduplicate() = 2900; deduped = false
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanotime calling `containsKey` 10000 times: 354300
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanoTime calling deduplicate() = 600; deduped = false
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanotime calling `containsKey` 10000 times: 512300
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanoTime calling deduplicate() = 1600; deduped = false
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanotime calling `containsKey` 10000 times: 457700
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanoTime calling deduplicate() = 2800; deduped = true
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanotime calling `containsKey` 10000 times: 638700
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanoTime calling deduplicate() = 900; deduped = false
[11:14:05] [Worker-Main-6/INFO] (ModelLoaderMixin) bakedModels.size() = 1000, nanoTime baking the 1000 models: 233823700
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanotime calling `containsKey` 10000 times: 551000
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanoTime calling deduplicate() = 1200; deduped = false
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanotime calling `containsKey` 10000 times: 327300
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanoTime calling deduplicate() = 600; deduped = false
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanotime calling `containsKey` 10000 times: 324100
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanoTime calling deduplicate() = 700; deduped = false
[11:14:05] [Worker-Main-6/INFO] (ModelLoaderMixin) bakedModels.size() = 2000, nanoTime baking the 1000 models: 70261200
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanotime calling `containsKey` 10000 times: 281300
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanoTime calling deduplicate() = 600; deduped = false
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanotime calling `containsKey` 10000 times: 244000
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanoTime calling deduplicate() = 500; deduped = false
[11:14:05] [Worker-Main-6/INFO] (ModelLoaderMixin) bakedModels.size() = 3000, nanoTime baking the 1000 models: 37804100
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanotime calling `containsKey` 10000 times: 625500
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanoTime calling deduplicate() = 900; deduped = false
[11:14:05] [Worker-Main-6/INFO] (ModelLoaderMixin) bakedModels.size() = 4000, nanoTime baking the 1000 models: 31680900
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanotime calling `containsKey` 10000 times: 1161900
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanoTime calling deduplicate() = 1300; deduped = false
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanotime calling `containsKey` 10000 times: 605100
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanoTime calling deduplicate() = 900; deduped = false
[11:14:05] [Worker-Main-6/INFO] (ModelLoaderMixin) bakedModels.size() = 5000, nanoTime baking the 1000 models: 53660200
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanotime calling `containsKey` 10000 times: 414800
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanoTime calling deduplicate() = 1500; deduped = true
[11:14:05] [Worker-Main-6/INFO] (ModelLoaderMixin) bakedModels.size() = 6000, nanoTime baking the 1000 models: 35186500
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanotime calling `containsKey` 10000 times: 288600
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanoTime calling deduplicate() = 1100; deduped = false
[11:14:05] [Worker-Main-6/INFO] (ModelLoaderMixin) bakedModels.size() = 7000, nanoTime baking the 1000 models: 37228800
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanotime calling `containsKey` 10000 times: 985600
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanoTime calling deduplicate() = 1000; deduped = false
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanotime calling `containsKey` 10000 times: 534800
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanoTime calling deduplicate() = 1200; deduped = true
[11:14:05] [Worker-Main-6/INFO] (ModelLoaderMixin) bakedModels.size() = 8000, nanoTime baking the 1000 models: 26900400
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanotime calling `containsKey` 10000 times: 3471200
[11:14:05] [Worker-Main-6/WARN] (DeduplicatorMixin) nanoTime calling deduplicate() = 5300; deduped = false
[11:14:05] [Worker-Main-6/INFO] (ModelLoaderMixin) bakedModels.size() = 9000, nanoTime baking the 1000 models: 26424400
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanotime calling `containsKey` 10000 times: 280900
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanoTime calling deduplicate() = 600; deduped = false
[11:14:05] [Worker-Main-6/INFO] (ModelLoaderMixin) bakedModels.size() = 10000, nanoTime baking the 1000 models: 24267400
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanotime calling `containsKey` 10000 times: 2076000
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanoTime calling deduplicate() = 2400; deduped = false
[11:14:05] [Worker-Main-6/INFO] (ModelLoaderMixin) bakedModels.size() = 11000, nanoTime baking the 1000 models: 29114100
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanotime calling `containsKey` 10000 times: 553600
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanoTime calling deduplicate() = 900; deduped = false
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanotime calling `containsKey` 10000 times: 476200
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanoTime calling deduplicate() = 1200; deduped = true
[11:14:05] [Worker-Main-6/INFO] (ModelLoaderMixin) bakedModels.size() = 12000, nanoTime baking the 1000 models: 49536200
[11:14:05] [Worker-Main-6/INFO] (DeduplicatorMixin) nanotime calling `containsKey` 10000 times: 6927300
[11:14:05] [Worker-Main-6/WARN] (DeduplicatorMixin) nanoTime calling deduplicate() = 7800; deduped = false
[11:14:06] [Worker-Main-6/INFO] (ModelLoaderMixin) bakedModels.size() = 13000, nanoTime baking the 1000 models: 300282000
[11:14:07] [Worker-Main-6/INFO] (DeduplicatorMixin) nanotime calling `containsKey` 10000 times: 527885000
[11:14:07] [Worker-Main-6/WARN] (DeduplicatorMixin) nanoTime calling deduplicate() = 123300; deduped = false
[11:14:09] [Worker-Main-6/INFO] (ModelLoaderMixin) bakedModels.size() = 14000, nanoTime baking the 1000 models: 3691802000
[11:14:17] [Worker-Main-6/INFO] (DeduplicatorMixin) nanotime calling `containsKey` 10000 times: 6613199600
[11:14:17] [Worker-Main-6/WARN] (DeduplicatorMixin) nanoTime calling deduplicate() = 1488800; deduped = false
[11:14:20] [Worker-Main-6/INFO] (ModelLoaderMixin) bakedModels.size() = 15000, nanoTime baking the 1000 models: 11014133900
[11:14:29] [Worker-Main-6/INFO] (DeduplicatorMixin) nanotime calling `containsKey` 10000 times: 7495897400
[11:14:29] [Worker-Main-6/WARN] (DeduplicatorMixin) nanoTime calling deduplicate() = 2464000; deduped = false
[11:14:33] [Worker-Main-6/INFO] (ModelLoaderMixin) bakedModels.size() = 16000, nanoTime baking the 1000 models: 12818771200

For my test code, see SolidBlock-cn/extshape@ad456c0

In conclusion, I suspect that BAKED_QUAD_CACHE.containsKey during the deduplicate may take too long time, which happens significantly when number of models is very high.

malte0811 · Answer 1 · 2023-10-22T07:13:21.000Z

This is actually already fixed in 2aa56a0, but apparently I never released a build with that fix. I'll try to do that today.

Share to