[Bf-blender-cvs] [e3bc0210792] master: Add debug/timing prints in MakeLocal and remapping code.

[Bastien Montagne]

Commit: e3bc0210792b5504f899b31323326c3da9114864
Author: Bastien Montagne
Date:   Thu May 4 15:07:21 2017 +0200
Branches: master
https://developer.blender.org/rBe3bc0210792b5504f899b31323326c3da9114864

Add debug/timing prints in MakeLocal and remapping code.

===================================================================

M	source/blender/blenkernel/intern/library.c
M	source/blender/blenkernel/intern/library_remap.c

===================================================================

diff --git a/source/blender/blenkernel/intern/library.c b/source/blender/blenkernel/intern/library.c
index e380b5c17e0..15a90ab731e 100644
--- a/source/blender/blenkernel/intern/library.c
+++ b/source/blender/blenkernel/intern/library.c
@@ -133,6 +133,12 @@
 
 #include "atomic_ops.h"
 
+//#define DEBUG_TIME
+
+#ifdef DEBUG_TIME
+#  include "PIL_time_utildefines.h"
+#endif
+
 /* GS reads the memory pointed at in a specific ordering. 
  * only use this definition, makes little and big endian systems
  * work fine, in conjunction with MAKE_ID */
@@ -1777,9 +1783,18 @@ void BKE_library_make_local(
 	LinkNode *copied_ids = NULL;
 	MemArena *linklist_mem = BLI_memarena_new(512 * sizeof(*todo_ids), __func__);
 
+	GSet *done_ids = BLI_gset_ptr_new(__func__);
+
+#ifdef DEBUG_TIME
+	TIMEIT_START(make_local);
+#endif
+
 	BKE_main_relations_create(bmain);
 
-	GSet *done_ids = BLI_gset_ptr_new(__func__);
+#ifdef DEBUG_TIME
+	printf("Pre-compute current ID relations: Done.\n");
+	TIMEIT_VALUE_PRINT(make_local);
+#endif
 
 	/* Step 1: Detect datablocks to make local. */
 	for (a = set_listbasepointers(bmain, lbarray); a--; ) {
@@ -1830,6 +1845,11 @@ void BKE_library_make_local(
 		}
 	}
 
+#ifdef DEBUG_TIME
+	printf("Step 1: Detect datablocks to make local: Done.\n");
+	TIMEIT_VALUE_PRINT(make_local);
+#endif
+
 	/* Step 2: Check which datablocks we can directly make local (because they are only used by already, or future,
 	 * local data), others will need to be duplicated. */
 	GSet *loop_tags = BLI_gset_ptr_new(__func__);
@@ -1843,6 +1863,11 @@ void BKE_library_make_local(
 	/* Next step will most likely add new IDs, better to get rid of this mapping now. */
 	BKE_main_relations_free(bmain);
 
+#ifdef DEBUG_TIME
+	printf("Step 2: Check which datablocks we can directly make local: Done.\n");
+	TIMEIT_VALUE_PRINT(make_local);
+#endif
+
 	/* Step 3: Make IDs local, either directly (quick and simple), or using generic process,
 	 * which involves more complex checks and might instead create a local copy of original linked ID. */
 	for (LinkNode *it = todo_ids, *it_next; it; it = it_next) {
@@ -1883,11 +1908,16 @@ void BKE_library_make_local(
 		}
 	}
 
+#ifdef DEBUG_TIME
+	printf("Step 3: Make IDs local: Done.\n");
+	TIMEIT_VALUE_PRINT(make_local);
+#endif
+
 	/* At this point, we are done with directly made local IDs. Now we have to handle duplicated ones, since their
 	 * remaining linked original counterpart may not be needed anymore... */
 	todo_ids = NULL;
 
-	/* Step 4: We have to remap local usages of old (linked) ID to new (local) id in a separated loop,
+	/* Step 4: We have to remap local usages of old (linked) ID to new (local) ID in a separated loop,
 	 * as lbarray ordering is not enough to ensure us we did catch all dependencies
 	 * (e.g. if making local a parent object before its child...). See T48907. */
 	/* TODO This is now the biggest step by far (in term of processing time). We may be able to gain here by
@@ -1911,6 +1941,11 @@ void BKE_library_make_local(
 		}
 	}
 
+#ifdef DEBUG_TIME
+	printf("Step 4: Remap local usages of old (linked) ID to new (local) ID: Done.\n");
+	TIMEIT_VALUE_PRINT(make_local);
+#endif
+
 	/* Note: Keeping both version of the code (old one being safer, since it still has checks against unused IDs)
 	 * for now, we can remove old one once it has been tested for some time in master... */
 #if 1
@@ -1955,6 +1990,12 @@ void BKE_library_make_local(
 			}
 		}
 	}
+
+#ifdef DEBUG_TIME
+	printf("Step 5: Proxy 'remapping' hack: Done.\n");
+	TIMEIT_VALUE_PRINT(make_local);
+#endif
+
 #else
 	LinkNode *linked_loop_candidates = NULL;
 
@@ -2033,6 +2074,11 @@ void BKE_library_make_local(
 		}
 	}
 
+#ifdef DEBUG_TIME
+	printf("Step 5: Remove linked datablocks that have been copied and ended fully localized: Done.\n");
+	TIMEIT_VALUE_PRINT(make_local);
+#endif
+
 	/* Step 6: Try to find circle dependencies between indirectly-linked-only datablocks.
 	 * Those are fake 'usages' that prevent their deletion. See T49775 for nice ugly case. */
 	BKE_library_unused_linked_data_set_tag(bmain, false);
@@ -2069,10 +2115,21 @@ void BKE_library_make_local(
 			it->link = NULL;
 		}
 	}
+
+#ifdef DEBUG_TIME
+	printf("Step 6: Try to find circle dependencies between indirectly-linked-only datablocks: Done.\n");
+	TIMEIT_END(make_local);
+#endif
+
 #endif
 
 	BKE_main_id_clear_newpoins(bmain);
 	BLI_memarena_free(linklist_mem);
+
+#ifdef DEBUG_TIME
+	printf("Cleanup and finish: Done.\n");
+	TIMEIT_END(make_local);
+#endif
 }
 
 /**
diff --git a/source/blender/blenkernel/intern/library_remap.c b/source/blender/blenkernel/intern/library_remap.c
index d14e0cf0b65..24626c6ead7 100644
--- a/source/blender/blenkernel/intern/library_remap.c
+++ b/source/blender/blenkernel/intern/library_remap.c
@@ -526,8 +526,12 @@ void BKE_libblock_remap_locked(
 		id_us_clear_real(old_id);
 	}
 
-	BLI_assert(old_id->us - skipped_refcounted >= 0);
-	UNUSED_VARS_NDEBUG(skipped_refcounted);
+	if (old_id->us - skipped_refcounted < 0) {
+		printf("Error in remapping process from '%s' (%p) to '%s' (%p): "
+		       "wrong user count in old ID after process (summing up to %d)\n",
+		       old_id->name, old_id, new_id ? new_id->name : "<NULL>", new_id, old_id->us - skipped_refcounted);
+		BLI_assert(0);
+	}
 
 	if (skipped_direct == 0) {
 		/* old_id is assumed to not be used directly anymore... */