Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Performance issues related to deduplicating models with large quantities #135

Open
SolidBlock-cn opened this issue Oct 22, 2023 · 1 comment
Open

Performance issues related to deduplicating models with large quantities #135

SolidBlock-cn opened this issue Oct 22, 2023 · 1 comment

Comments

@SolidBlock-cn
Copy link

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.
@SolidBlock-cn SolidBlock-cn changed the title Performance issues related to deduplication models with large quantities Performance issues related to deduplicating models with large quantities Oct 22, 2023
@malte0811
Copy link
Owner

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@malte0811 @SolidBlock-cn