Commit: efb967e504e9fcc4572c452bed9fbd155cbebfed
Author: Mateusz Grzeliński
Date: Sat Aug 1 17:47:45 2020 +0200
Branches: soc-2020-info-editor
https://developer.blender.org/rBefb967e504e9fcc4572c452bed9fbd155cbebfed
Experimental: add log based timing functions
Automatically enabled in debug builds
===================================================================
M source/blender/blenkernel/intern/lib_id.c
M source/blender/blenlib/PIL_time_utildefines.h
M source/blender/modifiers/CMakeLists.txt
M source/blender/modifiers/intern/MOD_decimate.c
===================================================================
diff --git a/source/blender/blenkernel/intern/lib_id.c
b/source/blender/blenkernel/intern/lib_id.c
index a64e550579d..c5c3d9866fe 100644
--- a/source/blender/blenkernel/intern/lib_id.c
+++ b/source/blender/blenkernel/intern/lib_id.c
@@ -77,11 +77,7 @@
#include "atomic_ops.h"
-//#define DEBUG_TIME
-
-#ifdef DEBUG_TIME
-# include "PIL_time_utildefines.h"
-#endif
+#include "PIL_time_utildefines.h"
static CLG_LogRef LOG = {.identifier = "bke.lib_id"};
@@ -1836,16 +1832,12 @@ void BKE_library_make_local(Main *bmain,
GSet *done_ids = BLI_gset_ptr_new(__func__);
-#ifdef DEBUG_TIME
- TIMEIT_START(make_local);
-#endif
+ CLOG_DEBUG_TIMEIT_START(&LOG, 0, make_local);
BKE_main_relations_create(bmain, 0);
-#ifdef DEBUG_TIME
- printf("Pre-compute current ID relations: Done.\n");
- TIMEIT_VALUE_PRINT(make_local);
-#endif
+ CLOG_DEBUG(&LOG, 0, "Pre-compute current ID relations: Done.");
+ CLOG_DEBUG_TIMEIT_VALUE_PRINT(&LOG, 0, make_local);
/* Step 1: Detect data-blocks to make local. */
for (int a = set_listbasepointers(bmain, lbarray); a--;) {
@@ -1900,10 +1892,8 @@ void BKE_library_make_local(Main *bmain,
}
}
-#ifdef DEBUG_TIME
- printf("Step 1: Detect data-blocks to make local: Done.\n");
- TIMEIT_VALUE_PRINT(make_local);
-#endif
+ CLOG_DEBUG(&LOG, 0, "Step 1: Detect data-blocks to make local: Done.");
+ CLOG_DEBUG_TIMEIT_VALUE_PRINT(&LOG, 0, make_local);
/* Step 2: Check which data-blocks we can directly make local
* (because they are only used by already, or future, local data),
@@ -1919,10 +1909,8 @@ void BKE_library_make_local(Main *bmain,
/* 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 data-blocks we can directly make local:
Done.\n");
- TIMEIT_VALUE_PRINT(make_local);
-#endif
+ CLOG_DEBUG(&LOG, 0, "Step 2: Check which data-blocks we can directly make
local: Done.");
+ CLOG_DEBUG_TIMEIT_VALUE_PRINT(&LOG, 0, make_local);
/* Step 3: Make IDs local, either directly (quick and simple), or using
generic process,
* which involves more complex checks and might instead
@@ -1973,10 +1961,8 @@ void BKE_library_make_local(Main *bmain,
}
}
-#ifdef DEBUG_TIME
- printf("Step 3: Make IDs local: Done.\n");
- TIMEIT_VALUE_PRINT(make_local);
-#endif
+ CLOG_DEBUG(&LOG, 0, "Step 3: Make IDs local: Done.");
+ CLOG_DEBUG_TIMEIT_VALUE_PRINT(&LOG, 0, make_local);
/* At this point, we are done with directly made local IDs.
* Now we have to handle duplicated ones, since their
@@ -2010,10 +1996,8 @@ void BKE_library_make_local(Main *bmain,
}
}
-#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
+ CLOG_DEBUG(&LOG, 0, "Step 4: Remap local usages of old (linked) ID to new
(local) ID: Done.");
+ CLOG_DEBUG_TIMEIT_VALUE_PRINT(&LOG, 0, make_local);
/* Step 5: proxy 'remapping' hack. */
for (LinkNode *it = copied_ids; it; it = it->next) {
@@ -2066,10 +2050,8 @@ void BKE_library_make_local(Main *bmain,
}
}
-#ifdef DEBUG_TIME
- printf("Step 5: Proxy 'remapping' hack: Done.\n");
- TIMEIT_VALUE_PRINT(make_local);
-#endif
+ CLOG_DEBUG(&LOG, 0, "Step 5: Proxy 'remapping' hack: Done.");
+ CLOG_DEBUG_TIMEIT_VALUE_PRINT(&LOG, 0, make_local);
/* This is probably more of a hack than something we should do here, but...
* Issue is, the whole copying + remapping done in complex cases above may
leave pose-channels
@@ -2085,18 +2067,14 @@ void BKE_library_make_local(Main *bmain,
}
}
-#ifdef DEBUG_TIME
- printf("Hack: Forcefully rebuild armature object poses: Done.\n");
- TIMEIT_VALUE_PRINT(make_local);
-#endif
+ CLOG_DEBUG(&LOG, 0, "Hack: Forcefully rebuild armature object poses: Done.");
+ CLOG_DEBUG_TIMEIT_VALUE_PRINT(&LOG, 0, make_local);
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
+ CLOG_DEBUG(&LOG, 0, "Cleanup and finish: Done.");
+ CLOG_DEBUG_TIMEIT_END(&LOG, 0, make_local);
}
/**
diff --git a/source/blender/blenlib/PIL_time_utildefines.h
b/source/blender/blenlib/PIL_time_utildefines.h
index ffe753badf8..7e8b5bfd61b 100644
--- a/source/blender/blenlib/PIL_time_utildefines.h
+++ b/source/blender/blenlib/PIL_time_utildefines.h
@@ -128,4 +128,148 @@
} \
(void)0
+/* CLOG function family, available only in debug builds (?) */
+#ifdef DEBUG
+
+# define CLOG_DEBUG_TIMEIT_START(log_ref, level, var) \
+ { \
+ double _clog_debug_timeit_##var = PIL_check_seconds_timer(); \
+ CLOG_DEBUG(log_ref, level, "time start (" #var ")"); \
+ { \
+ (void)0
+
+/**
+ * \return the time since TIMEIT_START was called.
+ */
+# define CLOG_DEBUG_TIMEIT_VALUE(var) \
+ (float)(PIL_check_seconds_timer() - _clog_debug_timeit_##var)
+
+# define CLOG_DEBUG_TIMEIT_VALUE_PRINT(log_ref, level, var) \
+ { \
+ CLOG_DEBUG(log_ref, level, "time update (" #var "): %.6f",
CLOG_DEBUG_TIMEIT_VALUE(var)); \
+ } \
+ (void)0
+
+# define CLOG_DEBUG_TIMEIT_END(log_ref, level, var) \
+ } \
+ CLOG_DEBUG(log_ref, level, "time end (" #var "): %.6f",
CLOG_DEBUG_TIMEIT_VALUE(var)); \
+ } \
+ (void)0
+
+/**
+ * _AVERAGED variants do same thing as their basic counterpart,
+ * but additionally add elapsed time to an averaged static value,
+ * useful to get sensible timing of code running fast and often.
+ */
+# define CLOG_DEBUG_TIMEIT_START_AVERAGED(log_ref, level, var) \
+ { \
+ static float _clog_debug_sum_##var = 0.0f; \
+ static float _clog_debug_num_##var = 0.0f; \
+ double _clog_debug_timeit_##var = PIL_check_seconds_timer(); \
+ CLOG_DEBUG(log_ref, level, "time start (" #var ")"); \
+ { \
+ (void)0
+
+# define CLOG_DEBUG_TIMEIT_AVERAGED_VALUE(var) \
+ (_clog_debug_num##var ? (_clog_debug_sum_##var / _clog_debug_num_##var) :
0.0f)
+
+# define CLOG_DEBUG_TIMEIT_END_AVERAGED(log_ref, level, var) \
+ } \
+ const float _clog_debug_delta_##var = CLOG_DEBUG_TIMEIT_VALUE(var); \
+ _clog_debug_sum_##var += _clog_debug_delta_##var; \
+ _clog_debug_num_##var++; \
+ CLOG_DEBUG(log_ref, level, "time end (" #var "): %.6f",
_clog_debug_delta_##var); \
+ CLOG_DEBUG(log_ref, \
+ level, \
+ "time averaged (" #var "): %.6f (total: %.6f, in %d runs)", \
+ (_clog_debug_sum_##var / _clog_debug_num_##var), \
+ _clog_debug_sum_##var, \
+ (int)_clog_debug_num_##var); \
+ } \
+ (void)0
+
+/**
+ * Given some function/expression:
+ * TIMEIT_BENCH(some_function(), some_unique_description);
+ */
+# define CLOG_DEBUG_TIMEIT_BENCH(log_ref, level, expr, id) \
+ { \
+ CLOG_DEBUG_TIMEIT_START(log_ref, level, id); \
+ (expr); \
+ CLOG_DEBUG_TIMEIT_END(log_ref, level, id); \
+ } \
+ (void)0
+
+# define CLOG_DEBUG_TIMEIT_BLOCK_INIT(log_ref, id) double
_clog_debug_timeit_var_##id = 0
+
+# define CLOG_DEBUG_TIMEIT_BLOCK_START(id) \
+ { \
+ double _clog_debug_timeit_block_start_##id = PIL_check_seconds_timer(); \
+ { \
+ (void)0
+
+# define CLOG_DEBUG_TIMEIT_BLOCK_END(id) \
+ } \
+ _clog_debug_timeit_var_##id += (PIL_check_seconds_timer() - \
+ _clog_debug_timeit_block_start_##id); \
+ } \
+ (void)0
+
+# define CLOG_TIMEIT_BLOCK_STATS(log_ref, level, id) \
+ { \
+ CLOG_DEBUG(log_ref, level, "%s time (in seconds): %f", #id,
_clog_debug_timeit_var_##id); \
+ } \
+ (void)0
+#else
+
+# define CLOG_DEBUG_TIMEIT_START(log_ref, level, var) \
+ { \
+ { \
+ (void)0
+
+# define CLOG_DEBUG_TIMEIT_VALUE(var) \
+ do { \
+ } while (false)
+
+# define CLOG_DEBUG_TIMEIT_VALUE_PRINT(log_ref, level, var) {}(void)0
+
+# define CLOG_DEBUG_TIMEIT_END(log_ref, level, var) \
+ } \
+ } \
+ (void)0
+
+# define CLOG_DEBUG_TIMEIT_START_AVERAGED(log_ref, level, var) \
+ { \
+ { \
+ (void)0
+
+# define CLOG_DEBUG_TIMEIT_AVERAGED_VALUE(var) \
+ do { \
+ } while (false)
+
+# define CLOG_DEBUG_TIMEIT_END_AVERAGED(log_ref, level, var) \
+ } \
+ } \
+ (void)0
+
+# define CLOG_DEBUG_TIMEIT_BENCH(log_ref, level, expr, id) {}(void)0
+
+# define CLOG_DEBUG_TIMEIT_BLOCK_INIT(log_ref, id) \
+ do { \
+ } while (false)
+
+# define CLOG_DEBUG_TIMEIT_BLOCK_START(id) \
+ { \
+ { \
+ (void)0
+
+# define CLOG_DEBUG_TIMEIT_BLOCK_END(id) \
+ } \
+ } \
+ (void)0
+
+# define CLOG_TIMEIT_BLOCK_STATS(log_ref, level, id) {}(void)0
+
+#endif // DEBUG
+
#endif /* __PIL_TIME_UTILDEFINES_H__ */
diff --git a/source/blender/modifiers/CMakeLists.txt
b/source/blender/modifiers/CMakeLists.txt
index cf87e3598b6..8d5657536af 100644
--- a/source/blender/modifiers/CMakeLists.txt
+++ b/source/blender/modifiers/CMakeLists.txt
@@ -35,6 +35,7 @@ set(INC
../windowmanager
../../../intern/eigen
../../../intern/guardedalloc
+ ../../../intern/clog
# dna_type_offsets.h in BLO_read_write.h
${CMAKE_BINARY_DIR}/source/blender/makesdna/intern
diff --git a/source/blender/modifiers/intern/MOD_decimate.c
b/source/blender/modifiers/intern/MOD_decimate.c
index 75fd558ae39..a173b766fbf 100644
--- a/source/blender/modifiers/intern/MOD_decimate.c
+++ b/source/blender/modifiers/intern/MOD_decimate.c
@@ -32,6 +32,7 @@
#include "DNA_object_types.h"
#include "DNA_screen_types.h"
+#include "CLG_log.h"
#include "MEM_guardedalloc.h"
#include "BKE_context.h"
@@ -49,16 +50,14 @@
#include "bmesh.h"
#include "bmesh_tools.h"
-// #define USE_TIMEIT
-
-#ifdef USE_TIMEIT
-# include "PIL_time.h"
-# include "PIL_time_utildefines.h"
-#endif
+#include "PIL_time.h"
+#include "PIL_time_utildefines.h"
#include "MOD_ui_common.h"
#include "MOD_util.h"
+static CLG_LogRef LOG = {"mod.decimate"};
+
static void initData(ModifierData *md)
{
DecimateModifierData *dmd = (DecimateModifierData *)md;
@@ -108,9 +107,7 @@ static Mesh *modifyMesh(ModifierData *md, const
ModifierEvalContext *ctx, Mesh *
bool calc_face_normal;
float *vweig
@@ Diff output truncated at 10240 characters. @@
_______________________________________________
Bf-blender-cvs mailing list
[email protected]
https://lists.blender.org/mailman/listinfo/bf-blender-cvs
