FerriteCore icon indicating copy to clipboard operation
FerriteCore copied to clipboard
verified publisher icon malte0811

Performance issues related to deduplicating models with large quantities

Open SolidBlock-cn opened this issue 2 years ago • 1 comments

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: https://github.com/SolidBlock-cn/extshape/issues/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 https://github.com/SolidBlock-cn/extshape/commit/ad456c0dcaa7ce759acd466481258bb9f8fb4f32

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.

SolidBlock-cn avatar Oct 22 '23 03:10 SolidBlock-cn

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

malte0811 avatar Oct 22 '23 07:10 malte0811