Slowdown during "(Re)Importing Assets"

[gudinoff]

Godot version:
3.2.4 RC4
3.2.4 RC5

OS/device including version:
Debian 10.8
Intel i5-2550K
AMD Radeon RX 480

Issue description:
Before opening the project on the editor, I deleted the ".import" folder to force assets to be re-imported.
When using Godot v3.2.4 RC4 it takes way longer than when using Godot v3.2.3.
To be honest, after 5 minutes I gave up and terminated the process.

For both Godot versions, I deleted the ".import" folder and launched the editor with "--verbose" flag on the command line, and took note of textures encode time (see results in table below).
The textures that took more time to encode were PNG files with resolution 2560x1440.

Edit: The slowdown seems to have been introduced in version 3.2.4 beta5. Check measurements below > #46956 (comment)

v3.2.3 output	v3.2.4 RC4 output	v3.2.4 RC5 output
ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 6374 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 46 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 54 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 209 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 233 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 112 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 365 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 251 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 197 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 242 ETC: Begin encoding, format: ETC2_RGB8 ETC: Time encoding: 12849 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 41 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 30 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 232 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 3125 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 1064 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 10929	ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 32105 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 799 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 756 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 5068 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 5999 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 341 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 8619 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 721 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 577 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 611 ETC: Begin encoding, format: ETC2_RGB8 ^C <--- me giving up	ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 31010 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 830 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 741 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 4986 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 5763 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 309 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 8349 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 605 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 584 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 606 ETC: Begin encoding, format: ETC2_RGB8 ^C <--- me giving up

Steps to reproduce:
Clean ".import" folder inside a project with texture assets.
Re-import assets.

Minimal reproduction project:
mrp.zip

[qarmin]

Looks that spends a lot of time when compressing image

#0  0x00000000027d25ea in squish::Vec4::Vec4(float __vector(4)) (this=0x7fffffffc260, v=...) at thirdparty/squish/simd_sse.h:51
#1  0x00000000027d2846 in squish::Vec4::SplatW (this=0x7fffffffc250) at thirdparty/squish/simd_sse.h:79
#2  0x00000000027d1c22 in squish::ClusterFit::Compress4 (this=0x7fffffffc5c0, block=0x13cff2f8) at thirdparty/squish/clusterfit.cpp:293
#3  0x00000000027d368b in squish::ColourFit::Compress (this=0x7fffffffc5c0, block=0x13cff2f8) at thirdparty/squish/colourfit.cpp:48
#4  0x000000000239ddac in squish::CompressMasked (
    rgba=0x7fffffffc880 "\274\273\271\377\276\275\273\377\275\274\272\377\306\302\301\377\274\273\271\377\271\270\266\377\270\267\265\377\274\270\267\377\271\270\266\377\273\272\270\377\271\270\266\377\267\264\262\377\267\263\262\377\300\274\273\377\300\274\273\377\264\260\257\377\004", mask=65535, 
    block=0x13cff2f8, flags=257, metric=0x0) at thirdparty/squish/squish.cpp:116
#5  0x000000000239e25f in squish::CompressImage (
    rgba=0x7fffcb13c020 "\t\006\001\377\v\a\005\377:72\377a^Y\377\212\207\202\377\231\227\222\377\252\252\245\377\254\253\246\377\235\234\227\377\241\240\233\377\235\234\227\377\241\240\233\377\233\232\225\377\233\232\225\377\226\223\217\377\224\217\215\377\227\225\221\377\243\242\236\377\236\235\230\377\237\236\231\377\232\231\224\377\233\232\225\377\223\222\215\377\202\202{\377\200\177x\377\206\206~\377\223\224\214\377\244\245\235\377\234\234\225\377\240\235\230\377\220\215\210\377\243\240\233\377\262\257\252\377\273\270\263\377\271\266\261\377\262\257\252\377\241\236\231\377\243\240\233\377\241\236\231\377\255\252\245\377\240\235\230\377\247\244\237\377\247\244\237\377\240\235\230\377\233\230\223\377\243\240\233\377\254\251\244\377\250\245\240\377\227\224\217\377\247\244\237\377"..., width=2560, height=1440, pitch=10240, blocks=0x13cd6be0, flags=257, metric=0x0) at thirdparty/squish/squish.cpp:227
#6  0x000000000239e2ea in squish::CompressImage (
    rgba=0x7fffcb13c020 "\t\006\001\377\v\a\005\377:72\377a^Y\377\212\207\202\377\231\227\222\377\252\252\245\377\254\253\246\377\235\234\227\377\241\240\233\377\235\234\227\377\241\240\233\377\233\232\225\377\233\232\225\377\226\223\217\377\224\217\215\377\227\225\221\377\243\242\236\377\236\235\230\377\237\236\231\377\232\231\224\377\233\232\225\377\223\222\215\377\202\202{\377\200\177x\377\206\206~\377\223\224\214\377\244\245\235\377\234\234\225\377\240\235\230\377\220\215\210\377\243\240\233\377\262\257\252\377\273\270\263\377\271\266\261\377\262\257\252\377\241\236\231\377\243\240\233\377\241\236\231\377\255\252\245\377\240\235\230\377\247\244\237\377\247\244\237\377\240\235\230\377\233\230\223\377\243\240\233\377\254\251\244\377\250\245\240\377\227\224\217\377\247\244\237\377"..., width=2560, height=1440, blocks=0x13cd6be0, flags=257, metric=0x0) at thirdparty/squish/squish.cpp:237
#7  0x0000000001cd72f2 in image_compress_squish (p_image=0xaaea1a0, p_lossy_quality=1, p_source=Image::COMPRESS_SOURCE_GENERIC)
    at modules/squish/image_compress_squish.cpp:193
#8  0x00000000044e3187 in Image::compress (this=0xaaea1a0, p_mode=Image::COMPRESS_S3TC, p_source=Image::COMPRESS_SOURCE_GENERIC, p_lossy_quality=1)
    at core/image.cpp:1974
#9  0x0000000002f450bf in ResourceImporterTexture::_save_stex (this=0xb954660, p_image=..., p_to_path=..., p_compress_mode=2, p_lossy_quality=1, 
    p_vram_compression=Image::COMPRESS_S3TC, p_mipmaps=true, p_texture_flags=5, p_streamable=false, p_detect_3d=false, p_detect_srgb=true, 
    p_force_rgbe=false, p_detect_normal=true, p_force_normal=false, p_force_po2_for_compressed=false) at editor/import/resource_importer_texture.cpp:342
#10 0x0000000002f4618b in ResourceImporterTexture::import (this=0xb954660, p_source_file=..., p_save_path=..., p_options=..., 
    r_platform_variants=0x7fffffffcce0, r_gen_files=0x7fffffffcce8, r_metadata=0x7fffffffcdb0) at editor/import/resource_importer_texture.cpp:500
#11 0x0000000002b19ec7 in EditorFileSystem::_reimport_file (this=0xc5dbae0, p_file=...) at editor/editor_file_system.cpp:1788
#12 0x0000000002b1ce09 in EditorFileSystem::reimport_files (this=0xc5dbae0, p_files=...) at editor/editor_file_system.cpp:1986
#13 0x0000000002b0ec58 in EditorFileSystem::_update_scan_actions (this=0xc5dbae0) at editor/editor_file_system.cpp:589
#14 0x0000000002b12eb8 in EditorFileSystem::_notification (this=0xc5dbae0, p_what=17) at editor/editor_file_system.cpp:1163
#15 0x0000000002b20612 in EditorFileSystem::_notificationv (this=0xc5dbae0, p_notification=17, p_reversed=false) at editor/editor_file_system.h:110
#16 0x0000000004529a1f in Object::notification (this=0xc5dbae0, p_notification=17, p_reversed=false) at core/object.cpp:929
#17 0x00000000035f0439 in SceneTree::_notify_group_pause (this=0x9a8ff70, p_group=..., p_notification=17) at scene/main/scene_tree.cpp:992
#18 0x00000000035edf3e in SceneTree::idle (this=0x9a8ff70, p_time=0.149999976) at scene/main/scene_tree.cpp:529
#19 0x000000000174d277 in Main::iteration () at main/main.cpp:2117
#20 0x000000000171291c in OS_X11::run (this=0x7fffffffd4f0) at platform/x11/os_x11.cpp:3641
#21 0x00000000016ff90b in main (argc=2, argv=0x7fffffffdde8) at platform/x11/godot_x11.cpp:56

[gudinoff]

Updated to include encode times of Godot version 3.2.4 RC5.

[Calinou]

Can you test this with older 3.2.4 betas and RCs? You can dowoad them here: https://downloads.tuxfamily.org/godotengine/3.2.4/

[gudinoff]

Sure.

It seems the problem was introduced in 3.2.4 beta5

v3.2.4 beta4 output

v3.2.4 beta5 output

ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 5767 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 41 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 42 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 187 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 207 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 117 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 314 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 228 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 183 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 219 ETC: Begin encoding, format: ETC2_RGB8 ETC: Time encoding: 11346 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 39 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 29 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 203 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 2953 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 915 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 9553

ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 33469 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 756 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 714 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 4605 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 5710 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 303 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 8138 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 647 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 578 ETC: Begin encoding, format: ETC2_RGBA8 ETC: Time encoding: 716 ETC: Begin encoding, format: ETC2_RGB8 ^C <--- me giving up

[qarmin]

Looks that this may be cause of this issues - #44683

[akien-mga]

Looks that this may be cause of this issues - #44683

Indeed, so this is not a bug but the expected behavior.

The MRP has a texture imported as lossy but with a lossy_quality of 1.0, which basically means spending a lot of time compressing to be as close as possible to the lossless version.

You should see a difference in quality between the imports from 3.2.3 and 3.2.4 RC - if not, then you likely don't need/want to use lossy_quality at 1.0 :)

[gudinoff]

I changed lossy_quality of all textures to 0.7 and the encoding times went back to similar values as before.
I was using 1.0 because I saw no drawbacks so, why not set quality to max? Now, I know better! =)

I would just leave here a direct link to #44682 which includes detailed and interesting information about the topic.

Also, I would suggest to include a note about this on the changelog.

Thanks =)
(I really like when these things get sorted out)

[akien-mga]

Also, I would suggest to include a note about this on the changelog.

Good point, I added a note to it in the preliminary changelog in https://godotengine.org/article/release-candidate-godot-3-2-4-rc-4