Logging prevents GLTF from lazy loading modules (27x load time for the add-on)

[ideasman42]

Blender has a convention of lazy loading modules for faster startup times,

GLTF mostly follows this however importing GLTF logging pulls in many other modules, since GLTF is enabled by default, it should not be imposing a startup cost, even if its a small one since it impacts startup for automation, render farms, tests, etc.

This can be avoided by having the logging levels in the file, or even making this a developer only feature since very few users would be interested in this - you could use bpy.app.debug_value or some other method to set the levels.

---

This is a list of modules loaded with times, using:

PYTHONPROFILEIMPORTTIME=1 ./blender.bin --factory-startup

import time: self [us] | cumulative | imported package
--- snip ---
import time:       664 |       1140 |   io_scene_3ds
import time:      1344 |       1344 |   io_scene_fbx
import time:       395 |        395 |   io_anim_bvh
import time:       348 |        348 |   io_mesh_ply
import time:       388 |        388 |   io_scene_obj
import time:       349 |        349 |   io_scene_x3d
import time:       386 |        386 |   io_mesh_stl
import time:       435 |        435 |   io_mesh_uv_layout
import time:       257 |        257 |   io_curve_svg
import time:       205 |        205 |           io_scene_gltf2.io.imp
import time:       231 |        435 |         io_scene_gltf2.io
import time:       176 |        610 |       io_scene_gltf2.io.com
import time:       152 |        152 |       time
import time:      1172 |       1172 |                 enum
import time:        98 |         98 |                   _sre
import time:       536 |        536 |                     sre_constants
import time:       727 |       1263 |                   sre_parse
import time:       534 |       1893 |                 sre_compile
import time:       306 |        306 |                 copyreg
import time:       854 |       4224 |               re
import time:       323 |        323 |               token
import time:      1471 |       6017 |             tokenize
import time:       321 |       6338 |           linecache
import time:       590 |       6928 |         traceback
import time:       346 |        346 |           _weakrefset
import time:       668 |       1014 |         weakref
import time:       209 |        209 |         collections.abc
import time:        52 |         52 |           _string
import time:      1241 |       1293 |         string
import time:       895 |        895 |         threading
import time:        50 |         50 |         atexit
import time:      1505 |      11891 |       logging
import time:       271 |      12923 |     io_scene_gltf2.io.com.gltf2_io_debug
import time:       515 |      13437 |   io_scene_gltf2

With the import removed: from .io.com.gltf2_io_debug import Log.

import time: self [us] | cumulative | imported package
--- snip ---
import time:       664 |       1145 |   io_scene_3ds
import time:      1372 |       1372 |   io_scene_fbx
import time:       390 |        390 |   io_anim_bvh
import time:       351 |        351 |   io_mesh_ply
import time:       389 |        389 |   io_scene_obj
import time:       353 |        353 |   io_scene_x3d
import time:       390 |        390 |   io_mesh_stl
import time:       432 |        432 |   io_mesh_uv_layout
import time:       258 |        258 |   io_curve_svg
import time:       486 |        486 |   io_scene_gltf2

Patch to test:

diff --git a/io_scene_gltf2/__init__.py b/io_scene_gltf2/__init__.py
index 20afb1d9..d9d2e6e1 100755
--- a/io_scene_gltf2/__init__.py
+++ b/io_scene_gltf2/__init__.py
@@ -22,7 +22,7 @@ import bpy
 from bpy_extras.io_utils import ImportHelper, ExportHelper
 from bpy.types import Operator, AddonPreferences

-from .io.com.gltf2_io_debug import Log
+# from .io.com.gltf2_io_debug import Log

 from bpy.props import (CollectionProperty,
                        StringProperty,
@@ -442,11 +442,11 @@ class ImportGLTF2(Operator, ImportHelper):

     filter_glob: StringProperty(default="*.glb;*.gltf", options={'HIDDEN'})

-    loglevel: EnumProperty(
-        items=Log.get_levels(),
-        name="Log Level",
-        description="Set level of log to display",
-        default=Log.default())
+    # loglevel: EnumProperty(
+    #     items=Log.get_levels(),
+    #     name="Log Level",
+    #     description="Set level of log to display",
+    #     default=Log.default())

     import_pack_images: BoolProperty(
         name='Pack images',
@@ -525,4 +525,3 @@ def unregister():
     # remove from the export / import menu
     bpy.types.TOPBAR_MT_file_export.remove(menu_func_export)
     bpy.types.TOPBAR_MT_file_import.remove(menu_func_import)
-

[julienduroure]

@ideasman42 : Thanks Campbell. Is there any convention and/or list of already used values for bpy.app.debug_value? Or we can choose any wanted values?

I will manage it ASAP

[ideasman42]

Hey Julien, there is a log-level, see help for --log-level, we could expose this via bpy.app.log_level, see https://developer.blender.org/diffusion/B/browse/master/intern/clog/CLG_log.h$55 for log level usage.

What do you think?

[julienduroure]

Hey Campbell, Yes, if this data can be exposed via bpy.app.log_level, it can be helpfull to use it instead of logging level from logging package.

But if is's not done yet in bpy, it's maybe because other addon developers don't find it usefull, so we can adapt this addon to fit other addon best practices.

Let's me know what is your preferences.

[julienduroure]

I just committed a first fix for loading modules. Using bpy.app.debug_value for now. We may find a better solution if log_level become expose to bpy

Note that we still have to refactor logging to use same way for import and export ( #89 )

[julienduroure]

Because the initial problem is now solved (lazy loading time), I propose to close this issue, and continue discussion on #89 when bpy.app.log_level will be available