FBX IO: fix related to T44386: do not add again and again same material to a mesh on import.

Issue here is that FBX assigns materials by objects, while in Blender it is by default assigned
to meshes (obdata). This becomes critical with tons of objects using the same mesh (as generated
e.g. by exporting from Blender's dupliobjects).

We may add an option later to assign materials to objects too, but meh... We already have tons
of options in FBX. :|

Also, added some timing/steps reporting in console, helps seeing io process going on,
and spotting stupid issues like this one!

4 files changed, 143 insertions, 12 deletions

diff --git a/io_scene_fbx/__init__.py b/io_scene_fbx/__init__.py
index 96c5adf2..461189c1 100644
--- a/io_scene_fbx/__init__.py
+++ b/io_scene_fbx/__init__.py
@@ -21,7 +21,7 @@
 bl_info = {
     "name": "FBX format",
     "author": "Campbell Barton, Bastien Montagne, Jens Restemeier",
-    "version": (3, 2, 2),
+    "version": (3, 2, 3),
     "blender": (2, 74, 0),
     "location": "File > Import-Export",
     "description": "FBX IO meshes, UV's, vertex colors, materials, "
diff --git a/io_scene_fbx/export_fbx_bin.py b/io_scene_fbx/export_fbx_bin.py
index 00d1f3c3..95aebbd8 100644
--- a/io_scene_fbx/export_fbx_bin.py
+++ b/io_scene_fbx/export_fbx_bin.py
@@ -61,7 +61,7 @@ from .fbx_utils import (
     FBX_LIGHT_TYPES, FBX_LIGHT_DECAY_TYPES,
     RIGHT_HAND_AXES, FBX_FRAMERATES,
     # Miscellaneous utils.
-    units_convertor, units_convertor_iter, matrix4_to_array, similar_values, similar_values_iter,
+    PerfMon, units_convertor, units_convertor_iter, matrix4_to_array, similar_values, similar_values_iter,
     # Mesh transform helpers.
     vcos_transformed_gen, nors_transformed_gen,
     # UUID from key.
@@ -2064,9 +2064,13 @@ def fbx_data_from_scene(scene, settings):
     Do some pre-processing over scene's data...
     """
     objtypes = settings.object_types
+    perfmon = PerfMon()
+    perfmon.level_up()
 
     # ##### Gathering data...
 
+    perfmon.step("FBX export prepare: Wrapping Objects...")
+
     # This is rather simple for now, maybe we could end generating templates with most-used values
     # instead of default ones?
     objects = OrderedDict()  # Because we do not have any ordered set...
@@ -2081,6 +2085,8 @@ def fbx_data_from_scene(scene, settings):
             objects[dp_obj] = None
         ob_obj.dupli_list_clear()
 
+    perfmon.step("FBX export prepare: Wrapping Data (lamps, cameras, empties)...")
+
     data_lamps = OrderedDict((ob_obj.bdata.data, get_blenderID_key(ob_obj.bdata.data))
                              for ob_obj in objects if ob_obj.type == 'LAMP')
     # Unfortunately, FBX camera data contains object-level data (like position, orientation, etc.)...
@@ -2090,6 +2096,8 @@ def fbx_data_from_scene(scene, settings):
     data_empties = OrderedDict((ob_obj, get_blender_empty_key(ob_obj.bdata))
                                for ob_obj in objects if ob_obj.type == 'EMPTY')
 
+    perfmon.step("FBX export prepare: Wrapping Meshes...")
+
     data_meshes = OrderedDict()
     for ob_obj in objects:
         if ob_obj.type not in BLENDER_OBJECT_TYPES_MESHLIKE:
@@ -2120,6 +2128,8 @@ def fbx_data_from_scene(scene, settings):
         if use_org_data:
             data_meshes[ob_obj] = (get_blenderID_key(ob.data), ob.data, False)
 
+    perfmon.step("FBX export prepare: Wrapping ShapeKeys...")
+
     # ShapeKeys.
     data_deformers_shape = OrderedDict()
     geom_mat_co = settings.global_matrix if settings.bake_space_transform else None
@@ -2152,6 +2162,8 @@ def fbx_data_from_scene(scene, settings):
             data = (channel_key, geom_key, shape_verts_co, shape_verts_idx)
             data_deformers_shape.setdefault(me, (me_key, shapes_key, OrderedDict()))[2][shape] = data
 
+    perfmon.step("FBX export prepare: Wrapping Armatures...")
+
     # Armatures!
     data_deformers_skin = OrderedDict()
     data_bones = OrderedDict()
@@ -2167,12 +2179,16 @@ def fbx_data_from_scene(scene, settings):
     if settings.add_leaf_bones:
         data_leaf_bones = fbx_generate_leaf_bones(settings, data_bones)
 
+    perfmon.step("FBX export prepare: Wrapping World...")
+
     # Some world settings are embedded in FBX materials...
     if scene.world:
         data_world = OrderedDict(((scene.world, get_blenderID_key(scene.world)),))
     else:
         data_world = OrderedDict()
 
+    perfmon.step("FBX export prepare: Wrapping Materials...")
+
     # TODO: Check all the mat stuff works even when mats are linked to Objects
     #       (we can then have the same mesh used with different materials...).
     #       *Should* work, as FBX always links its materials to Models (i.e. objects).
@@ -2194,6 +2210,8 @@ def fbx_data_from_scene(scene, settings):
             else:
                 data_materials[mat] = (get_blenderID_key(mat), [ob_obj])
 
+    perfmon.step("FBX export prepare: Wrapping Textures...")
+
     # Note FBX textures also hold their mapping info.
     # TODO: Support layers?
     data_textures = OrderedDict()
@@ -2231,6 +2249,8 @@ def fbx_data_from_scene(scene, settings):
             else:
                 data_videos[img] = (get_blenderID_key(img), [tex])
 
+    perfmon.step("FBX export prepare: Wrapping Animations...")
+
     # Animation...
     animations = ()
     frame_start = scene.frame_start
@@ -2249,6 +2269,8 @@ def fbx_data_from_scene(scene, settings):
 
     # ##### Creation of templates...
 
+    perfmon.step("FBX export prepare: Generating templates...")
+
     templates = OrderedDict()
     templates[b"GlobalSettings"] = fbx_template_def_globalsettings(scene, settings, nbr_users=1)
 
@@ -2326,6 +2348,8 @@ def fbx_data_from_scene(scene, settings):
 
     # ##### Creation of connections...
 
+    perfmon.step("FBX export prepare: Generating Connections...")
+
     connections = []
 
     # Objects (with classical parenting).
@@ -2448,6 +2472,8 @@ def fbx_data_from_scene(scene, settings):
                         # Animcurve -> Animcurvenode.
                         connections.append((b"OP", get_fbx_uuid_from_key(acurve_key), acurvenode_id, fbx_item.encode()))
 
+    perfmon.level_down()
+
     # ##### And pack all this!
 
     return FBXExportData(
@@ -2636,22 +2662,34 @@ def fbx_objects_elements(root, scene_data):
     """
     Data (objects, geometry, material, textures, armatures, etc.).
     """
+    perfmon = PerfMon()
+    perfmon.level_up()
     objects = elem_empty(root, b"Objects")
 
+    perfmon.step("FBX export fetch empties (%d)..." % len(scene_data.data_empties))
+
     for empty in scene_data.data_empties:
         fbx_data_empty_elements(objects, empty, scene_data)
 
+    perfmon.step("FBX export fetch lamps (%d)..." % len(scene_data.data_lamps))
+
     for lamp in scene_data.data_lamps:
         fbx_data_lamp_elements(objects, lamp, scene_data)
 
+    perfmon.step("FBX export fetch cameras (%d)..." % len(scene_data.data_cameras))
+
     for cam in scene_data.data_cameras:
         fbx_data_camera_elements(objects, cam, scene_data)
 
+    perfmon.step("FBX export fetch meshes (%d)..." % len(scene_data.data_meshes))
+
     done_meshes = set()
     for me_obj in scene_data.data_meshes:
         fbx_data_mesh_elements(objects, me_obj, scene_data, done_meshes)
     del done_meshes
 
+    perfmon.step("FBX export fetch objects (%d)..." % len(scene_data.objects))
+
     for ob_obj in scene_data.objects:
         if ob_obj.is_dupli:
             continue
@@ -2663,6 +2701,8 @@ def fbx_objects_elements(root, scene_data):
             fbx_data_object_elements(objects, dp_obj, scene_data)
         ob_obj.dupli_list_clear()
 
+    perfmon.step("FBX export fetch remaining...")
+
     for ob_obj in scene_data.objects:
         if not (ob_obj.is_object and ob_obj.type == 'ARMATURE'):
             continue
@@ -2680,8 +2720,13 @@ def fbx_objects_elements(root, scene_data):
     for vid in scene_data.data_videos:
         fbx_data_video_elements(objects, vid, scene_data)
 
+    perfmon.step("FBX export fetch animations...")
+    start_time = time.process_time()
+
     fbx_data_animation_elements(objects, scene_data)
 
+    perfmon.level_down()
+
 
 def fbx_connections_elements(root, scene_data):
     """
diff --git a/io_scene_fbx/fbx_utils.py b/io_scene_fbx/fbx_utils.py
index 07e4d824..65ab2470 100644
--- a/io_scene_fbx/fbx_utils.py
+++ b/io_scene_fbx/fbx_utils.py
@@ -22,6 +22,7 @@
 
 
 import math
+import time
 
 from collections import namedtuple, OrderedDict
 from collections.abc import Iterable
@@ -147,6 +148,56 @@ FBX_FRAMERATES = (
 
 # ##### Misc utilities #####
 
+DO_PERFMON = True
+
+if DO_PERFMON:
+    class PerfMon():
+        def __init__(self):
+            self.level = -1
+            self.ref_time = []
+
+        def level_up(self, message=""):
+            self.level += 1
+            self.ref_time.append(None)
+            if message:
+                print("\t" * self.level, message, sep="")
+
+        def level_down(self, message=""):
+            if not self.ref_time:
+                if message:
+                    print(message)
+                return
+            ref_time = self.ref_time[self.level]
+            print("\t" * self.level,
+                  "\tDone (%f sec)\n" % ((time.process_time() - ref_time) if ref_time is not None else 0.0),
+                  sep="")
+            if message:
+                print("\t" * self.level, message, sep="")
+            del self.ref_time[self.level]
+            self.level -= 1
+
+        def step(self, message=""):
+            ref_time = self.ref_time[self.level]
+            curr_time = time.process_time()
+            if ref_time is not None:
+                print("\t" * self.level, "\tDone (%f sec)\n" % (curr_time - ref_time), sep="")
+            self.ref_time[self.level] = curr_time
+            print("\t" * self.level, message, sep="")
+else:
+    class PerfMon():
+        def __init__(self):
+            pass
+
+        def level_up(self, message=""):
+            pass
+
+        def level_down(self, message=""):
+            pass
+
+        def step(self, message=""):
+            pass
+
+
 # Note: this could be in a utility (math.units e.g.)...
 
 UNITS = {
diff --git a/io_scene_fbx/import_fbx.py b/io_scene_fbx/import_fbx.py
index 10a17dd3..33950f41 100644
--- a/io_scene_fbx/import_fbx.py
+++ b/io_scene_fbx/import_fbx.py
@@ -41,6 +41,7 @@ from . import parse_fbx, fbx_utils
 
 from .parse_fbx import data_types, FBXElem
 from .fbx_utils import (
+    PerfMon,
     units_convertor_iter,
     array_to_matrix4,
     similar_values,
@@ -2091,6 +2092,11 @@ def load(operator, context, filepath="",
     start_time_proc = time.process_time()
     start_time_sys = time.time()
 
+    perfmon = PerfMon()
+    perfmon.level_up()
+    perfmon.step("FBX Import: start importing %s" % filepath)
+    perfmon.level_up()
+
     # detect ascii files
     if is_ascii(filepath, 24):
         operator.report({'ERROR'}, "ASCII FBX files are not supported %r" % filepath)
@@ -2135,6 +2141,8 @@ def load(operator, context, filepath="",
 
     # #### Get some info from GlobalSettings.
 
+    perfmon.step("FBX import: Prepare...")
+
     fbx_settings = elem_find_first(elem_root, b'GlobalSettings')
     fbx_settings_props = elem_find_first(fbx_settings, b'Properties70')
     if fbx_settings is None or fbx_settings_props is None:
@@ -2194,6 +2202,8 @@ def load(operator, context, filepath="",
 
     # #### And now, the "real" data.
 
+    perfmon.step("FBX import: Templates...")
+
     fbx_defs = elem_find_first(elem_root, b'Definitions')  # can be None
     fbx_nodes = elem_find_first(elem_root, b'Objects')
     fbx_connections = elem_find_first(elem_root, b'Connections')
@@ -2234,6 +2244,8 @@ def load(operator, context, filepath="",
             return fbx_templates.get(key, fbx_elem_nil)
         return ret
 
+    perfmon.step("FBX import: Nodes...")
+
     # ----
     # Build FBX node-table
     def _():
@@ -2249,6 +2261,8 @@ def load(operator, context, filepath="",
     # http://download.autodesk.com/us/fbx/20112/FBX_SDK_HELP/index.html?url=
     #        WS73099cc142f487551fea285e1221e4f9ff8-7fda.htm,topicNumber=d0e6388
 
+    perfmon.step("FBX import: Connections...")
+
     fbx_connection_map = {}
     fbx_connection_map_reverse = {}
 
@@ -2261,6 +2275,8 @@ def load(operator, context, filepath="",
                 fbx_connection_map_reverse.setdefault(c_dst, []).append((c_src, fbx_link))
     _(); del _
 
+    perfmon.step("FBX import: Meshes...")
+
     # ----
     # Load mesh data
     def _():
@@ -2275,6 +2291,8 @@ def load(operator, context, filepath="",
                 fbx_item[1] = blen_read_geom(fbx_tmpl, fbx_obj, settings)
     _(); del _
 
+    perfmon.step("FBX import: Materials & Textures...")
+
     # ----
     # Load material data
     def _():
@@ -2310,6 +2328,8 @@ def load(operator, context, filepath="",
             fbx_item[1] = blen_read_texture_image(fbx_tmpl_tex, fbx_obj, basedir, settings)
     _(); del _
 
+    perfmon.step("FBX import: Cameras & Lamps...")
+
     # ----
     # Load camera data
     def _():
@@ -2353,6 +2373,8 @@ def load(operator, context, filepath="",
     def connection_filter_reverse(fbx_uuid, fbx_id):
         return connection_filter_ex(fbx_uuid, fbx_id, fbx_connection_map_reverse)
 
+    perfmon.step("FBX import: Objects & Armatures...")
+
     # -- temporary helper hierarchy to build armatures and objects from
     # lookup from uuid to helper node. Used to build parent-child relations and later to look up animated nodes.
     fbx_helper_nodes = {}
@@ -2517,6 +2539,8 @@ def load(operator, context, filepath="",
         # root_helper.print_info(0)
     _(); del _
 
+    perfmon.step("FBX import: ShapeKeys...")
+
     # We can handle shapes.
     blend_shape_channels = {}  # We do not need Shapes themselves, but keyblocks, for anim.
 
@@ -2567,6 +2591,8 @@ def load(operator, context, filepath="",
                 blend_shape_channels[bc_uuid] = keyblocks
     _(); del _
 
+    perfmon.step("FBX import: Animations...")
+
     # Animation!
     def _():
         fbx_tmpl_astack = fbx_template_get((b'AnimationStack', b'FbxAnimStack'))
@@ -2658,6 +2684,8 @@ def load(operator, context, filepath="",
 
     _(); del _
 
+    perfmon.step("FBX import: Assign materials...")
+
     def _():
         # link Material's to Geometry (via Model's)
         for fbx_uuid, fbx_item in fbx_table_nodes.items():
@@ -2671,17 +2699,19 @@ def load(operator, context, filepath="",
             if mesh is None:
                 continue
 
-            for (fbx_lnk,
-                 fbx_lnk_item,
-                 fbx_lnk_type) in connection_filter_forward(fbx_uuid, b'Model'):
+            # In Blender, we link materials to data, typically (meshes), while in FBX they are linked to objects...
+            # So we have to be careful not to re-add endlessly the same material to a mesh!
+            # This can easily happen with 'baked' dupliobjects, see T44386.
+            # TODO: add an option to link materials to objects in Blender instead?
+            done_mats = set()
 
+            for (fbx_lnk, fbx_lnk_item, fbx_lnk_type) in connection_filter_forward(fbx_uuid, b'Model'):
                 # link materials
                 fbx_lnk_uuid = elem_uuid(fbx_lnk)
-                for (fbx_lnk_material,
-                     material,
-                     fbx_lnk_material_type) in connection_filter_reverse(fbx_lnk_uuid, b'Material'):
-
-                    mesh.materials.append(material)
+                for (fbx_lnk_material, material, fbx_lnk_material_type) in connection_filter_reverse(fbx_lnk_uuid, b'Material'):
+                    if material not in done_mats:
+                        mesh.materials.append(material)
+                        done_mats.add(material)
 
             # We have to validate mesh polygons' mat_idx, see T41015!
             # Some FBX seem to have an extra 'default' material which is not defined in FBX file.
@@ -2689,6 +2719,8 @@ def load(operator, context, filepath="",
                 print("WARNING: mesh '%s' had invalid material indices, those were reset to first material" % mesh.name)
     _(); del _
 
+    perfmon.step("FBX import: Assign textures...")
+
     def _():
         material_images = {}
 
@@ -2898,6 +2930,8 @@ def load(operator, context, filepath="",
 
     _(); del _
 
+    perfmon.step("FBX import: Cycles z-offset workaround...")
+
     def _():
         # Annoying workaround for cycles having no z-offset
         if material_decals and use_alpha_decals:
@@ -2925,6 +2959,7 @@ def load(operator, context, filepath="",
                                 material.use_raytrace = False
     _(); del _
 
-    print('Import finished in %.4f sec (process time: %.4f sec).' %
-          (time.time() - start_time_sys, time.process_time() - start_time_proc))
+    perfmon.level_down()
+
+    perfmon.level_down("Import finished.")
     return {'FINISHED'}