Depsgraph: Move evaluation debug prints to depsgraph

This way we can easily control format and keep it consistent.

And also possibly do other trickery, like coloring addresses!
This commit is contained in:
Sergey Sharybin 2018-03-16 11:14:38 +01:00
parent 5de9c8f6f0
commit 3baf31e73a
11 changed files with 125 additions and 68 deletions

@ -76,6 +76,8 @@
#include "atomic_ops.h"
#include "DEG_depsgraph.h"
/* ***************************************** */
/* AnimData API */
@ -2918,15 +2920,13 @@ void BKE_animsys_evaluate_all_animation(Main *main, Scene *scene, float ctime)
/* ************** */
/* Evaluation API */
#define DEBUG_PRINT if (G.debug & G_DEBUG_DEPSGRAPH_EVAL) printf
void BKE_animsys_eval_animdata(EvaluationContext *eval_ctx, ID *id)
{
AnimData *adt = BKE_animdata_from_id(id);
Scene *scene = NULL; /* XXX: this is only needed for flushing RNA updates,
* which should get handled as part of the dependency graph instead...
*/
DEBUG_PRINT("%s on %s, time=%f\n\n", __func__, id->name, (double)eval_ctx->ctime);
DEG_debug_print_eval_time(__func__, id->name, id, eval_ctx->ctime);
BKE_animsys_evaluate_animdata(scene, id, adt, eval_ctx->ctime, ADT_RECALC_ANIM);
}
@ -2939,11 +2939,8 @@ void BKE_animsys_eval_driver(EvaluationContext *eval_ctx,
PointerRNA id_ptr;
bool ok = false;
DEBUG_PRINT("%s on %s (%s[%d])\n",
__func__,
id->name,
fcu->rna_path,
fcu->array_index);
DEG_debug_print_eval_subdata_index(
__func__, id->name, id, "fcu", fcu->rna_path, fcu, fcu->array_index);
RNA_id_pointer_create(id, &id_ptr);
@ -2976,5 +2973,3 @@ void BKE_animsys_eval_driver(EvaluationContext *eval_ctx,
}
}
}
#undef DEBUG_PRINT

@ -53,12 +53,6 @@
#include "DEG_depsgraph.h"
#ifdef WITH_LEGACY_DEPSGRAPH
# define DEBUG_PRINT if (!DEG_depsgraph_use_legacy() && G.debug & G_DEBUG_DEPSGRAPH_EVAL) printf
#else
# define DEBUG_PRINT if (G.debug & G_DEBUG_DEPSGRAPH_EVAL) printf
#endif
/* ********************** SPLINE IK SOLVER ******************* */
/* Temporary evaluation tree data used for Spline IK */
@ -565,7 +559,7 @@ void BKE_pose_eval_init(EvaluationContext *UNUSED(eval_ctx),
{
bPoseChannel *pchan;
DEBUG_PRINT("%s on %s\n", __func__, ob->id.name);
DEG_debug_print_eval(__func__, ob->id.name, ob);
BLI_assert(ob->type == OB_ARMATURE);
@ -587,7 +581,7 @@ void BKE_pose_eval_init_ik(EvaluationContext *UNUSED(eval_ctx),
Object *ob,
bPose *UNUSED(pose))
{
DEBUG_PRINT("%s on %s\n", __func__, ob->id.name);
DEG_debug_print_eval(__func__, ob->id.name, ob);
BLI_assert(ob->type == OB_ARMATURE);
const float ctime = BKE_scene_frame_get(scene); /* not accurate... */
bArmature *arm = (bArmature *)ob->data;
@ -608,7 +602,8 @@ void BKE_pose_eval_bone(EvaluationContext *UNUSED(eval_ctx),
Object *ob,
bPoseChannel *pchan)
{
DEBUG_PRINT("%s on %s pchan %s\n", __func__, ob->id.name, pchan->name);
DEG_debug_print_eval_subdata(
__func__, ob->id.name, ob, "pchan", pchan->name, pchan);
BLI_assert(ob->type == OB_ARMATURE);
bArmature *arm = (bArmature *)ob->data;
if (arm->edbo || (arm->flag & ARM_RESTPOS)) {
@ -643,7 +638,8 @@ void BKE_pose_constraints_evaluate(EvaluationContext *UNUSED(eval_ctx),
Object *ob,
bPoseChannel *pchan)
{
DEBUG_PRINT("%s on %s pchan %s\n", __func__, ob->id.name, pchan->name);
DEG_debug_print_eval_subdata(
__func__, ob->id.name, ob, "pchan", pchan->name, pchan);
bArmature *arm = (bArmature *)ob->data;
if (arm->flag & ARM_RESTPOS) {
return;
@ -663,7 +659,7 @@ void BKE_pose_bone_done(EvaluationContext *UNUSED(eval_ctx),
bPoseChannel *pchan)
{
float imat[4][4];
DEBUG_PRINT("%s on pchan %s\n", __func__, pchan->name);
DEG_debug_print_eval(__func__, pchan->name, pchan);
if (pchan->bone) {
invert_m4_m4(imat, pchan->bone->arm_mat);
mul_m4_m4m4(pchan->chan_mat, pchan->pose_mat, imat);
@ -675,7 +671,8 @@ void BKE_pose_iktree_evaluate(EvaluationContext *UNUSED(eval_ctx),
Object *ob,
bPoseChannel *rootchan)
{
DEBUG_PRINT("%s on %s pchan %s\n", __func__, ob->id.name, rootchan->name);
DEG_debug_print_eval_subdata(
__func__, ob->id.name, ob, "rootchan", rootchan->name, rootchan);
BLI_assert(ob->type == OB_ARMATURE);
const float ctime = BKE_scene_frame_get(scene); /* not accurate... */
bArmature *arm = (bArmature *)ob->data;
@ -689,8 +686,10 @@ void BKE_pose_splineik_evaluate(EvaluationContext *UNUSED(eval_ctx),
Scene *scene,
Object *ob,
bPoseChannel *rootchan)
{
DEBUG_PRINT("%s on %s pchan %s\n", __func__, ob->id.name, rootchan->name);
DEG_debug_print_eval_subdata(
__func__, ob->id.name, ob, "rootchan", rootchan->name, rootchan);
BLI_assert(ob->type == OB_ARMATURE);
const float ctime = BKE_scene_frame_get(scene); /* not accurate... */
bArmature *arm = (bArmature *)ob->data;
@ -706,7 +705,7 @@ void BKE_pose_eval_flush(EvaluationContext *UNUSED(eval_ctx),
bPose *UNUSED(pose))
{
float ctime = BKE_scene_frame_get(scene); /* not accurate... */
DEBUG_PRINT("%s on %s\n", __func__, ob->id.name);
DEG_debug_print_eval(__func__, ob->id.name, ob);
BLI_assert(ob->type == OB_ARMATURE);
/* 6. release the IK tree */
@ -718,7 +717,7 @@ void BKE_pose_eval_flush(EvaluationContext *UNUSED(eval_ctx),
void BKE_pose_eval_proxy_copy(EvaluationContext *UNUSED(eval_ctx), Object *ob)
{
BLI_assert(ID_IS_LINKED(ob) && ob->proxy_from != NULL);
DEBUG_PRINT("%s on %s\n", __func__, ob->id.name);
DEG_debug_print_eval(__func__, ob->id.name, ob);
if (BKE_pose_copy_result(ob->pose, ob->proxy_from->pose) == false) {
printf("Proxy copy error, lib Object: %s proxy Object: %s\n",
ob->id.name + 2, ob->proxy_from->id.name + 2);

@ -65,6 +65,8 @@
#include "BKE_object.h"
#include "BKE_material.h"
#include "DEG_depsgraph.h"
/* globals */
/* local */
@ -5253,9 +5255,7 @@ void BKE_curve_rect_from_textbox(const struct Curve *cu, const struct TextBox *t
void BKE_curve_eval_geometry(EvaluationContext *UNUSED(eval_ctx),
Curve *curve)
{
if (G.debug & G_DEBUG_DEPSGRAPH_EVAL) {
printf("%s on %s\n", __func__, curve->id.name);
}
DEG_debug_print_eval(__func__, curve->id.name, curve);
if (curve->bb == NULL || (curve->bb->flag & BOUNDBOX_DIRTY)) {
BKE_curve_texspace_calc(curve);
}

@ -46,6 +46,7 @@
#include "BKE_global.h"
#include "BKE_mask.h"
#include "DEG_depsgraph.h"
unsigned int BKE_mask_spline_resolution(MaskSpline *spline, int width, int height)
{
@ -897,11 +898,9 @@ void BKE_mask_layer_evaluate_deform(MaskLayer *masklay, const float ctime)
}
}
#define DEBUG_PRINT if (G.debug & G_DEBUG_DEPSGRAPH_EVAL) printf
void BKE_mask_eval_animation(struct EvaluationContext *eval_ctx, Mask *mask)
{
DEBUG_PRINT("%s on %s (%p)\n", __func__, mask->id.name, mask);
DEG_debug_print_eval(__func__, mask->id.name, mask);
for (MaskLayer *mask_layer = mask->masklayers.first;
mask_layer != NULL;
mask_layer = mask_layer->next)
@ -912,7 +911,7 @@ void BKE_mask_eval_animation(struct EvaluationContext *eval_ctx, Mask *mask)
void BKE_mask_eval_update(struct EvaluationContext *eval_ctx, Mask *mask)
{
DEBUG_PRINT("%s on %s (%p)\n", __func__, mask->id.name, mask);
DEG_debug_print_eval(__func__, mask->id.name, mask);
for (MaskLayer *mask_layer = mask->masklayers.first;
mask_layer != NULL;
mask_layer = mask_layer->next)

@ -2636,9 +2636,7 @@ Mesh *BKE_mesh_new_from_object(
void BKE_mesh_eval_geometry(EvaluationContext *UNUSED(eval_ctx),
Mesh *mesh)
{
if (G.debug & G_DEBUG_DEPSGRAPH_EVAL) {
printf("%s on %s\n", __func__, mesh->id.name);
}
DEG_debug_print_eval(__func__, mesh->id.name, mesh);
if (mesh->bb == NULL || (mesh->bb->flag & BOUNDBOX_DIRTY)) {
BKE_mesh_texspace_calc(mesh);
}

@ -73,12 +73,12 @@
#include "IMB_imbuf.h"
#include "IMB_moviecache.h"
#include "DEG_depsgraph.h"
#ifdef WITH_OPENEXR
# include "intern/openexr/openexr_multi.h"
#endif
#define DEBUG_PRINT if (G.debug & G_DEBUG_DEPSGRAPH_EVAL) printf
/*********************** movieclip buffer loaders *************************/
static int sequence_guess_offset(const char *full_name, int head_len, unsigned short numlen)
@ -1611,6 +1611,6 @@ bool BKE_movieclip_put_frame_if_possible(MovieClip *clip,
void BKE_movieclip_eval_update(struct EvaluationContext *UNUSED(eval_ctx), MovieClip *clip)
{
DEBUG_PRINT("%s on %s (%p)\n", __func__, clip->id.name, clip);
DEG_debug_print_eval(__func__, clip->id.name, clip);
BKE_tracking_dopesheet_tag_update(&clip->tracking);
}

@ -61,18 +61,12 @@
#include "DEG_depsgraph.h"
#ifdef WITH_LEGACY_DEPSGRAPH
# define DEBUG_PRINT if (!DEG_depsgraph_use_legacy() && G.debug & G_DEBUG_DEPSGRAPH_EVAL) printf
#else
# define DEBUG_PRINT if (G.debug & G_DEBUG_DEPSGRAPH_EVAL) printf
#endif
static ThreadMutex material_lock = BLI_MUTEX_INITIALIZER;
void BKE_object_eval_local_transform(EvaluationContext *UNUSED(eval_ctx),
Object *ob)
{
DEBUG_PRINT("%s on %s\n", __func__, ob->id.name);
DEG_debug_print_eval(__func__, ob->id.name, ob);
/* calculate local matrix */
BKE_object_to_mat4(ob, ob->obmat);
@ -90,7 +84,7 @@ void BKE_object_eval_parent(EvaluationContext *UNUSED(eval_ctx),
float tmat[4][4];
float locmat[4][4];
DEBUG_PRINT("%s on %s\n", __func__, ob->id.name);
DEG_debug_print_eval(__func__, ob->id.name, ob);
/* get local matrix (but don't calculate it, as that was done already!) */
// XXX: redundant?
@ -119,7 +113,7 @@ void BKE_object_eval_constraints(EvaluationContext *UNUSED(eval_ctx),
bConstraintOb *cob;
float ctime = BKE_scene_frame_get(scene);
DEBUG_PRINT("%s on %s\n", __func__, ob->id.name);
DEG_debug_print_eval(__func__, ob->id.name, ob);
/* evaluate constraints stack */
/* TODO: split this into:
@ -137,7 +131,7 @@ void BKE_object_eval_constraints(EvaluationContext *UNUSED(eval_ctx),
void BKE_object_eval_done(EvaluationContext *UNUSED(eval_ctx), Object *ob)
{
DEBUG_PRINT("%s on %s\n", __func__, ob->id.name);
DEG_debug_print_eval(__func__, ob->id.name, ob);
/* Set negative scale flag in object. */
if (is_negative_m4(ob->obmat)) ob->transflag |= OB_NEG_SCALE;
@ -332,7 +326,7 @@ void BKE_object_eval_uber_data(EvaluationContext *eval_ctx,
Scene *scene,
Object *ob)
{
DEBUG_PRINT("%s on %s\n", __func__, ob->id.name);
DEG_debug_print_eval(__func__, ob->id.name, ob);
BLI_assert(ob->type != OB_ARMATURE);
BKE_object_handle_data_update(eval_ctx, scene, ob);
@ -343,7 +337,7 @@ void BKE_object_eval_cloth(EvaluationContext *UNUSED(eval_ctx),
Scene *scene,
Object *object)
{
DEBUG_PRINT("%s on %s\n", __func__, object->id.name);
DEG_debug_print_eval(__func__, object->id.name, object);
BKE_ptcache_object_reset(scene, object, PTCACHE_RESET_DEPSGRAPH);
}

@ -93,6 +93,7 @@
#include "PIL_time.h"
#include "RE_shader_ext.h"
#include "DEG_depsgraph.h"
/* fluid sim particle import */
#ifdef WITH_MOD_FLUID
@ -4405,8 +4406,6 @@ void BKE_particle_system_eval_init(EvaluationContext *UNUSED(eval_ctx),
Scene *scene,
Object *ob)
{
if (G.debug & G_DEBUG_DEPSGRAPH_EVAL) {
printf("%s on %s\n", __func__, ob->id.name);
}
DEG_debug_print_eval(__func__, ob->id.name, ob);
BKE_ptcache_object_reset(scene, ob, PTCACHE_RESET_DEPSGRAPH);
}

@ -66,6 +66,8 @@
#include "BKE_rigidbody.h"
#include "BKE_scene.h"
#include "DEG_depsgraph.h"
/* ************************************** */
/* Memory Management */
@ -1689,11 +1691,7 @@ void BKE_rigidbody_rebuild_sim(EvaluationContext *UNUSED(eval_ctx),
Scene *scene)
{
float ctime = BKE_scene_frame_get(scene);
if (G.debug & G_DEBUG_DEPSGRAPH_EVAL) {
printf("%s at %f\n", __func__, ctime);
}
DEG_debug_print_eval_time(__func__, scene->id.name, scene, ctime);
/* rebuild sim data (i.e. after resetting to start of timeline) */
if (BKE_scene_check_rigidbody_active(scene)) {
BKE_rigidbody_rebuild_world(scene, ctime);
@ -1704,11 +1702,7 @@ void BKE_rigidbody_eval_simulation(EvaluationContext *UNUSED(eval_ctx),
Scene *scene)
{
float ctime = BKE_scene_frame_get(scene);
if (G.debug & G_DEBUG_DEPSGRAPH_EVAL) {
printf("%s at %f\n", __func__, ctime);
}
DEG_debug_print_eval_time(__func__, scene->id.name, scene, ctime);
/* evaluate rigidbody sim */
if (BKE_scene_check_rigidbody_active(scene)) {
BKE_rigidbody_do_simulation(scene, ctime);
@ -1721,11 +1715,7 @@ void BKE_rigidbody_object_sync_transforms(EvaluationContext *UNUSED(eval_ctx),
{
RigidBodyWorld *rbw = scene->rigidbody_world;
float ctime = BKE_scene_frame_get(scene);
if (G.debug & G_DEBUG_DEPSGRAPH_EVAL) {
printf("%s on %s\n", __func__, ob->id.name);
}
DEG_debug_print_eval_time(__func__, ob->id.name, ob, ctime);
/* read values pushed into RBO from sim/cache... */
BKE_rigidbody_sync_transforms(rbw, ob, ctime);
}

@ -208,6 +208,32 @@ void DEG_editors_set_update_cb(DEG_EditorUpdateIDCb id_func,
void DEG_editors_update_pre(struct Main *bmain, struct Scene *scene, bool time);
/* Evaluation Debug ------------------------------ */
void DEG_debug_print_eval(const char* function_name,
const char* object_name,
const void* object_address);
void DEG_debug_print_eval_subdata(const char *function_name,
const char *object_name,
const void *object_address,
const char *subdata_comment,
const char *subdata_name,
const void *subdata_address);
void DEG_debug_print_eval_subdata_index(const char *function_name,
const char *object_name,
const void *object_address,
const char *subdata_comment,
const char *subdata_name,
const void *subdata_address,
const int subdata_index);
void DEG_debug_print_eval_time(const char* function_name,
const char* object_name,
const void* object_address,
float time);
#ifdef __cplusplus
} /* extern "C" */
#endif

@ -494,3 +494,60 @@ void DEG_editors_update_pre(Main *bmain, Scene *scene, bool time)
DEG::deg_editor_update_scene_pre_cb(bmain, scene, time);
}
}
void DEG_debug_print_eval(const char *function_name,
const char *object_name,
const void *object_address)
{
if ((G.debug & G_DEBUG_DEPSGRAPH_EVAL) == 0) {
return;
}
printf("%s on %s (%p)\n", function_name, object_name, object_address);
}
void DEG_debug_print_eval_subdata(const char *function_name,
const char *object_name,
const void *object_address,
const char *subdata_comment,
const char *subdata_name,
const void *subdata_address)
{
if ((G.debug & G_DEBUG_DEPSGRAPH_EVAL) == 0) {
return;
}
printf("%s on %s (%p) %s %s (%p)\n",
function_name,
object_name, object_address,
subdata_comment,
subdata_name, subdata_address);
}
void DEG_debug_print_eval_subdata_index(const char *function_name,
const char *object_name,
const void *object_address,
const char *subdata_comment,
const char *subdata_name,
const void *subdata_address,
const int subdata_index)
{
if ((G.debug & G_DEBUG_DEPSGRAPH_EVAL) == 0) {
return;
}
printf("%s on %s (%p) %s %s[%d] (%p)\n",
function_name,
object_name, object_address,
subdata_comment,
subdata_name, subdata_index, subdata_address);
}
void DEG_debug_print_eval_time(const char *function_name,
const char *object_name,
const void *object_address,
float time)
{
if ((G.debug & G_DEBUG_DEPSGRAPH_EVAL) == 0) {
return;
}
printf("%s on %s (%p) at time %f\n",
function_name, object_name, object_address, time);
}