Depsgraph: Implement backtrace functionality

The goal is to make it easier to track down sources of errors during
the dependency graph builder.

With this change whenever a relation can not be added a trace to the
entity which requested the relation will be printed. For example:

```
Failed to add relation "Copy Location"
Could not find op_from: OperationKey(type: BONE, component name: 'MissingBone', operation code: BONE_DONE)

Trace:

Depth    Type                     Name
-----    ----                     ----
1        Object                   Armature.001
2        Pose Channel             Bone
3        Constraint               Copy Location
```

On an implementation detail traced places where `checkIsBuiltAndTag`
is called, with some additional places to help tracking pose channels,
constraints, and modifiers.

Further improvements in granularity are possible, but that could happen
as a followup development once the core part is proven to work.

An example of such improvement would be to have entries in the trace
which will indicate NLA and drivers building. Currently it might be
a bit confusing to see IDs in the trace referenced from driver.

Even with such limitation the current state of the patch brings a
very valuable information (some information is much better than no
information at all).

Differential Revision: https://developer.blender.org/D15017
This commit is contained in:
Sergey Sharybin 2022-05-24 11:45:56 +02:00
parent 089175bb1f
commit 2da7977e3e
8 changed files with 344 additions and 22 deletions

View File

@ -40,6 +40,7 @@ set(SRC
intern/builder/deg_builder_relations_view_layer.cc
intern/builder/deg_builder_remove_noop.cc
intern/builder/deg_builder_rna.cc
intern/builder/deg_builder_stack.cc
intern/builder/deg_builder_transitive.cc
intern/builder/pipeline.cc
intern/builder/pipeline_all_objects.cc
@ -103,6 +104,7 @@ set(SRC
intern/builder/deg_builder_relations_impl.h
intern/builder/deg_builder_remove_noop.h
intern/builder/deg_builder_rna.h
intern/builder/deg_builder_stack.h
intern/builder/deg_builder_transitive.h
intern/builder/pipeline.h
intern/builder/pipeline_all_objects.h

View File

@ -586,11 +586,12 @@ void DepsgraphRelationBuilder::build_id(ID *id)
void DepsgraphRelationBuilder::build_generic_id(ID *id)
{
if (built_map_.checkIsBuiltAndTag(id)) {
return;
}
const BuilderStack::ScopedEntry stack_entry = stack_.trace(*id);
build_idproperties(id->properties);
build_animdata(id);
build_parameters(id);
@ -621,6 +622,9 @@ void DepsgraphRelationBuilder::build_collection(LayerCollection *from_layer_coll
* recurses into all the nested objects and collections. */
return;
}
const BuilderStack::ScopedEntry stack_entry = stack_.trace(collection->id);
const bool group_done = built_map_.checkIsBuiltAndTag(collection);
OperationKey object_transform_final_key(object != nullptr ? &object->id : nullptr,
NodeType::TRANSFORM,
@ -684,6 +688,9 @@ void DepsgraphRelationBuilder::build_object(Object *object)
if (built_map_.checkIsBuiltAndTag(object)) {
return;
}
const BuilderStack::ScopedEntry stack_entry = stack_.trace(object->id);
/* Object Transforms */
OperationCode base_op = (object->parent) ? OperationCode::TRANSFORM_PARENT :
OperationCode::TRANSFORM_LOCAL;
@ -1133,6 +1140,9 @@ void DepsgraphRelationBuilder::build_constraints(ID *id,
if (cti == nullptr) {
continue;
}
const BuilderStack::ScopedEntry stack_entry = stack_.trace(*con);
/* Special case for camera tracking -- it doesn't use targets to
* define relations. */
/* TODO: we can now represent dependencies in a much richer manner,
@ -1500,6 +1510,9 @@ void DepsgraphRelationBuilder::build_action(bAction *action)
if (built_map_.checkIsBuiltAndTag(action)) {
return;
}
const BuilderStack::ScopedEntry stack_entry = stack_.trace(action->id);
build_idproperties(action->id.properties);
if (!BLI_listbase_is_empty(&action->curves)) {
TimeSourceKey time_src_key;
@ -1787,6 +1800,9 @@ void DepsgraphRelationBuilder::build_world(World *world)
if (built_map_.checkIsBuiltAndTag(world)) {
return;
}
const BuilderStack::ScopedEntry stack_entry = stack_.trace(world->id);
build_idproperties(world->id.properties);
/* animation */
build_animdata(&world->id);
@ -2012,6 +2028,9 @@ void DepsgraphRelationBuilder::build_particle_settings(ParticleSettings *part)
if (built_map_.checkIsBuiltAndTag(part)) {
return;
}
const BuilderStack::ScopedEntry stack_entry = stack_.trace(part->id);
/* Animation data relations. */
build_animdata(&part->id);
build_parameters(&part->id);
@ -2070,6 +2089,9 @@ void DepsgraphRelationBuilder::build_shapekeys(Key *key)
if (built_map_.checkIsBuiltAndTag(key)) {
return;
}
const BuilderStack::ScopedEntry stack_entry = stack_.trace(key->id);
build_idproperties(key->id.properties);
/* Attach animdata to geometry. */
build_animdata(&key->id);
@ -2131,6 +2153,8 @@ void DepsgraphRelationBuilder::build_object_data_geometry(Object *object)
LISTBASE_FOREACH (ModifierData *, md, &object->modifiers) {
const ModifierTypeInfo *mti = BKE_modifier_get_info((ModifierType)md->type);
if (mti->updateDepsgraph) {
const BuilderStack::ScopedEntry stack_entry = stack_.trace(*md);
DepsNodeHandle handle = create_node_handle(obdata_ubereval_key);
ctx.node = reinterpret_cast<::DepsNodeHandle *>(&handle);
mti->updateDepsgraph(md, &ctx);
@ -2251,6 +2275,9 @@ void DepsgraphRelationBuilder::build_object_data_geometry_datablock(ID *obdata)
if (built_map_.checkIsBuiltAndTag(obdata)) {
return;
}
const BuilderStack::ScopedEntry stack_entry = stack_.trace(*obdata);
build_idproperties(obdata->properties);
/* Animation. */
build_animdata(obdata);
@ -2369,6 +2396,9 @@ void DepsgraphRelationBuilder::build_armature(bArmature *armature)
if (built_map_.checkIsBuiltAndTag(armature)) {
return;
}
const BuilderStack::ScopedEntry stack_entry = stack_.trace(armature->id);
build_idproperties(armature->id.properties);
build_animdata(&armature->id);
build_parameters(&armature->id);
@ -2388,6 +2418,9 @@ void DepsgraphRelationBuilder::build_camera(Camera *camera)
if (built_map_.checkIsBuiltAndTag(camera)) {
return;
}
const BuilderStack::ScopedEntry stack_entry = stack_.trace(camera->id);
build_idproperties(camera->id.properties);
build_animdata(&camera->id);
build_parameters(&camera->id);
@ -2405,6 +2438,9 @@ void DepsgraphRelationBuilder::build_light(Light *lamp)
if (built_map_.checkIsBuiltAndTag(lamp)) {
return;
}
const BuilderStack::ScopedEntry stack_entry = stack_.trace(lamp->id);
build_idproperties(lamp->id.properties);
build_animdata(&lamp->id);
build_parameters(&lamp->id);
@ -2469,6 +2505,9 @@ void DepsgraphRelationBuilder::build_nodetree(bNodeTree *ntree)
if (built_map_.checkIsBuiltAndTag(ntree)) {
return;
}
const BuilderStack::ScopedEntry stack_entry = stack_.trace(ntree->id);
build_idproperties(ntree->id.properties);
build_animdata(&ntree->id);
build_parameters(&ntree->id);
@ -2574,6 +2613,9 @@ void DepsgraphRelationBuilder::build_material(Material *material)
if (built_map_.checkIsBuiltAndTag(material)) {
return;
}
const BuilderStack::ScopedEntry stack_entry = stack_.trace(material->id);
build_idproperties(material->id.properties);
/* animation */
build_animdata(&material->id);
@ -2610,6 +2652,9 @@ void DepsgraphRelationBuilder::build_texture(Tex *texture)
if (built_map_.checkIsBuiltAndTag(texture)) {
return;
}
const BuilderStack::ScopedEntry stack_entry = stack_.trace(texture->id);
/* texture itself */
ComponentKey texture_key(&texture->id, NodeType::GENERIC_DATABLOCK);
build_idproperties(texture->id.properties);
@ -2651,6 +2696,9 @@ void DepsgraphRelationBuilder::build_image(Image *image)
if (built_map_.checkIsBuiltAndTag(image)) {
return;
}
const BuilderStack::ScopedEntry stack_entry = stack_.trace(image->id);
build_idproperties(image->id.properties);
build_parameters(&image->id);
}
@ -2660,6 +2708,9 @@ void DepsgraphRelationBuilder::build_cachefile(CacheFile *cache_file)
if (built_map_.checkIsBuiltAndTag(cache_file)) {
return;
}
const BuilderStack::ScopedEntry stack_entry = stack_.trace(cache_file->id);
build_idproperties(cache_file->id.properties);
/* Animation. */
build_animdata(&cache_file->id);
@ -2689,6 +2740,9 @@ void DepsgraphRelationBuilder::build_mask(Mask *mask)
if (built_map_.checkIsBuiltAndTag(mask)) {
return;
}
const BuilderStack::ScopedEntry stack_entry = stack_.trace(mask->id);
ID *mask_id = &mask->id;
build_idproperties(mask_id->properties);
/* F-Curve animation. */
@ -2727,6 +2781,8 @@ void DepsgraphRelationBuilder::build_freestyle_linestyle(FreestyleLineStyle *lin
return;
}
const BuilderStack::ScopedEntry stack_entry = stack_.trace(linestyle->id);
ID *linestyle_id = &linestyle->id;
build_parameters(linestyle_id);
build_idproperties(linestyle_id->properties);
@ -2739,6 +2795,9 @@ void DepsgraphRelationBuilder::build_movieclip(MovieClip *clip)
if (built_map_.checkIsBuiltAndTag(clip)) {
return;
}
const BuilderStack::ScopedEntry stack_entry = stack_.trace(clip->id);
/* Animation. */
build_idproperties(clip->id.properties);
build_animdata(&clip->id);
@ -2750,6 +2809,9 @@ void DepsgraphRelationBuilder::build_lightprobe(LightProbe *probe)
if (built_map_.checkIsBuiltAndTag(probe)) {
return;
}
const BuilderStack::ScopedEntry stack_entry = stack_.trace(probe->id);
build_idproperties(probe->id.properties);
build_animdata(&probe->id);
build_parameters(&probe->id);
@ -2760,6 +2822,9 @@ void DepsgraphRelationBuilder::build_speaker(Speaker *speaker)
if (built_map_.checkIsBuiltAndTag(speaker)) {
return;
}
const BuilderStack::ScopedEntry stack_entry = stack_.trace(speaker->id);
build_idproperties(speaker->id.properties);
build_animdata(&speaker->id);
build_parameters(&speaker->id);
@ -2776,6 +2841,9 @@ void DepsgraphRelationBuilder::build_sound(bSound *sound)
if (built_map_.checkIsBuiltAndTag(sound)) {
return;
}
const BuilderStack::ScopedEntry stack_entry = stack_.trace(sound->id);
build_idproperties(sound->id.properties);
build_animdata(&sound->id);
build_parameters(&sound->id);
@ -2786,6 +2854,9 @@ void DepsgraphRelationBuilder::build_simulation(Simulation *simulation)
if (built_map_.checkIsBuiltAndTag(simulation)) {
return;
}
const BuilderStack::ScopedEntry stack_entry = stack_.trace(simulation->id);
build_idproperties(simulation->id.properties);
build_animdata(&simulation->id);
build_parameters(&simulation->id);
@ -2850,6 +2921,9 @@ void DepsgraphRelationBuilder::build_scene_sequencer(Scene *scene)
if (built_map_.checkIsBuiltAndTag(scene, BuilderMap::TAG_SCENE_SEQUENCER)) {
return;
}
/* TODO(sergey): Trace as a scene sequencer. */
build_scene_audio(scene);
ComponentKey scene_audio_key(&scene->id, NodeType::AUDIO);
/* Make sure dependencies from sequences data goes to the sequencer evaluation. */
@ -2893,6 +2967,9 @@ void DepsgraphRelationBuilder::build_vfont(VFont *vfont)
if (built_map_.checkIsBuiltAndTag(vfont)) {
return;
}
const BuilderStack::ScopedEntry stack_entry = stack_.trace(vfont->id);
build_parameters(&vfont->id);
build_idproperties(vfont->id.properties);
}

View File

@ -23,6 +23,7 @@
#include "intern/builder/deg_builder.h"
#include "intern/builder/deg_builder_map.h"
#include "intern/builder/deg_builder_rna.h"
#include "intern/builder/deg_builder_stack.h"
#include "intern/depsgraph.h"
#include "intern/node/deg_node.h"
#include "intern/node/deg_node_component.h"
@ -363,6 +364,7 @@ class DepsgraphRelationBuilder : public DepsgraphBuilder {
BuilderMap built_map_;
RNANodeQuery rna_node_query_;
BuilderStack stack_;
};
struct DepsNodeHandle {

View File

@ -9,6 +9,8 @@
#include "intern/node/deg_node_id.h"
#include <iostream>
#include "DNA_ID.h"
#include "DNA_object_types.h"
#include "DNA_rigidbody_types.h"
@ -33,35 +35,28 @@ Relation *DepsgraphRelationBuilder::add_relation(const KeyFrom &key_from,
Node *node_to = get_node(key_to);
OperationNode *op_from = node_from ? node_from->get_exit_operation() : nullptr;
OperationNode *op_to = node_to ? node_to->get_entry_operation() : nullptr;
if (op_from && op_to) {
return add_operation_relation(op_from, op_to, description, flags);
}
/* TODO(sergey): Report error in the interface. */
std::cerr << "--------------------------------------------------------------------\n";
std::cerr << "Failed to add relation \"" << description << "\"\n";
if (!op_from) {
/* XXX TODO: handle as error or report if needed. */
fprintf(stderr,
"add_relation(%s) - Could not find op_from (%s)\n",
description,
key_from.identifier().c_str());
}
else {
fprintf(stderr,
"add_relation(%s) - Failed, but op_from (%s) was ok\n",
description,
key_from.identifier().c_str());
std::cerr << "Could not find op_from: " << key_from.identifier() << "\n";
}
if (!op_to) {
/* XXX TODO: handle as error or report if needed. */
fprintf(stderr,
"add_relation(%s) - Could not find op_to (%s)\n",
description,
key_to.identifier().c_str());
std::cerr << "Could not find op_to: " << key_to.identifier() << "\n";
}
else {
fprintf(stderr,
"add_relation(%s) - Failed, but op_to (%s) was ok\n",
description,
key_to.identifier().c_str());
if (!stack_.is_empty()) {
std::cerr << "\nTrace:\n\n";
stack_.print_backtrace(std::cerr);
std::cerr << "\n";
}
return nullptr;

View File

@ -322,7 +322,11 @@ void DepsgraphRelationBuilder::build_rig(Object *object)
RootPChanMap root_map;
bool pose_depends_on_local_transform = false;
LISTBASE_FOREACH (bPoseChannel *, pchan, &object->pose->chanbase) {
const BuilderStack::ScopedEntry stack_entry = stack_.trace(*pchan);
LISTBASE_FOREACH (bConstraint *, con, &pchan->constraints) {
const BuilderStack::ScopedEntry stack_entry = stack_.trace(*con);
switch (con->type) {
case CONSTRAINT_TYPE_KINEMATIC:
build_ik_pose(object, pchan, con, &root_map);
@ -356,6 +360,8 @@ void DepsgraphRelationBuilder::build_rig(Object *object)
}
/* Links between operations for each bone. */
LISTBASE_FOREACH (bPoseChannel *, pchan, &object->pose->chanbase) {
const BuilderStack::ScopedEntry stack_entry = stack_.trace(*pchan);
build_idproperties(pchan->prop);
OperationKey bone_local_key(
&object->id, NodeType::BONE, pchan->name, OperationCode::BONE_LOCAL);

View File

@ -36,6 +36,9 @@ void DepsgraphRelationBuilder::build_scene_parameters(Scene *scene)
if (built_map_.checkIsBuiltAndTag(scene, BuilderMap::TAG_PARAMETERS)) {
return;
}
/* TODO(sergey): Trace as a scene parameters. */
build_idproperties(scene->id.properties);
build_parameters(&scene->id);
OperationKey parameters_eval_key(
@ -56,6 +59,9 @@ void DepsgraphRelationBuilder::build_scene_compositor(Scene *scene)
if (scene->nodetree == nullptr) {
return;
}
/* TODO(sergey): Trace as a scene compositor. */
build_nodetree(scene->nodetree);
}

View File

@ -0,0 +1,94 @@
/* SPDX-License-Identifier: GPL-2.0-or-later
* Copyright 2022 Blender Foundation. All rights reserved. */
/** \file
* \ingroup depsgraph
*/
#include "intern/builder/deg_builder_stack.h"
#include <iomanip>
#include <ios>
#include <iostream>
#include "BKE_idtype.h"
#include "DNA_ID.h"
#include "DNA_action_types.h"
#include "DNA_constraint_types.h"
#include "DNA_modifier_types.h"
namespace blender::deg {
/* Spacing between adjacent columns, in number of spaces. */
constexpr int kColumnSpacing = 4;
/* Width of table columns including column padding.
* The type column width is a guesstimate based on "Particle Settings" with some extra padding. */
constexpr int kPrintDepthWidth = 5 + kColumnSpacing;
constexpr int kPrintTypeWidth = 21 + kColumnSpacing;
namespace {
/* NOTE: Depth column printing is already taken care of. */
void print(std::ostream &stream, const ID *id)
{
const IDTypeInfo *id_type_info = BKE_idtype_get_info_from_id(id);
stream << std::setw(kPrintTypeWidth) << id_type_info->name << (id->name + 2) << "\n";
}
void print(std::ostream &stream, const bConstraint *constraint)
{
stream << std::setw(kPrintTypeWidth) << ("Constraint") << constraint->name << "\n";
}
void print(std::ostream &stream, const ModifierData *modifier_data)
{
stream << std::setw(kPrintTypeWidth) << ("Modifier") << modifier_data->name << "\n";
}
void print(std::ostream &stream, const bPoseChannel *pchan)
{
stream << std::setw(kPrintTypeWidth) << ("Pose Channel") << pchan->name << "\n";
}
} // namespace
void BuilderStack::print_backtrace(std::ostream &stream)
{
const std::ios_base::fmtflags old_flags(stream.flags());
stream << std::left;
stream << std::setw(kPrintDepthWidth) << "Depth" << std::setw(kPrintTypeWidth) << "Type"
<< "Name"
<< "\n";
stream << std::setw(kPrintDepthWidth) << "-----" << std::setw(kPrintTypeWidth) << "----"
<< "----"
<< "\n";
int depth = 1;
for (const Entry &entry : stack_) {
stream << std::setw(kPrintDepthWidth) << depth;
++depth;
if (entry.id_ != nullptr) {
print(stream, entry.id_);
}
else if (entry.constraint_ != nullptr) {
print(stream, entry.constraint_);
}
else if (entry.modifier_data_ != nullptr) {
print(stream, entry.modifier_data_);
}
else if (entry.pchan_ != nullptr) {
print(stream, entry.pchan_);
}
}
stream.flags(old_flags);
}
} // namespace blender::deg

View File

@ -0,0 +1,140 @@
/* SPDX-License-Identifier: GPL-2.0-or-later
* Copyright 2022 Blender Foundation. All rights reserved. */
/** \file
* \ingroup depsgraph
*/
#pragma once
#include "BLI_utildefines.h"
#include "BLI_vector.hh"
struct ID;
struct bConstraint;
struct bPoseChannel;
struct ModifierData;
namespace blender::deg {
/* This class keeps track of the builder calls nesting, allowing to unroll them back and provide a
* clue about how the builder made it to its current state.
*
* The tracing is based on the builder giving a trace clues to the stack. Typical usage is:
*
* void DepsgraphRelationBuilder::my_id_builder(ID *id)
* {
* if (built_map_.checkIsBuiltAndTag(id)) {
* return;
* }
*
* const BuilderStack::ScopedEntry stack_entry = stack_.trace(*id);
*
* ...
* }
*/
class BuilderStack {
public:
/* Entry of the backtrace.
* A cheap-to-construct wrapper which allows to gather a proper string representation whenever
* the stack is printed. */
class Entry {
public:
explicit Entry(const ID &id) : id_(&id)
{
}
explicit Entry(const bConstraint &constraint) : constraint_(&constraint)
{
}
explicit Entry(const bPoseChannel &pchan) : pchan_(&pchan)
{
}
explicit Entry(const ModifierData &modifier_data) : modifier_data_(&modifier_data)
{
}
private:
friend class BuilderStack;
const ID *id_ = nullptr;
const bConstraint *constraint_ = nullptr;
const ModifierData *modifier_data_ = nullptr;
const bPoseChannel *pchan_ = nullptr;
};
using Stack = Vector<Entry>;
/* A helper class to provide a RAII style of tracing. It is constructed by the
* `BuilderStack::trace` (which pushes entry to the stack), and upon destruction of this object
* the corresponding entry is popped from the stack.
*
* The goal of this `ScopedEntry` is to free developers from worryign about removing entries from
* the stack whenever leaving a builder step scope. */
class ScopedEntry {
public:
/* Delete copy constructor and operator: scoped entries are only supposed to be constructed
* once and never copied. */
ScopedEntry(const ScopedEntry &other) = delete;
ScopedEntry &operator=(const ScopedEntry &other) = delete;
/* Move semantic. */
ScopedEntry(ScopedEntry &&other) noexcept : stack_(other.stack_)
{
other.stack_ = nullptr;
}
ScopedEntry &operator=(ScopedEntry &&other)
{
if (this == &other) {
return *this;
}
stack_ = other.stack_;
other.stack_ = nullptr;
return *this;
}
~ScopedEntry()
{
/* Stack will become nullptr when the entry was moved somewhere else. */
if (stack_ != nullptr) {
BLI_assert(!stack_->is_empty());
stack_->pop_last();
}
}
private:
friend BuilderStack;
explicit ScopedEntry(Stack &stack) : stack_(&stack)
{
}
Stack *stack_;
};
BuilderStack() = default;
~BuilderStack() = default;
bool is_empty() const
{
return stack_.is_empty();
}
void print_backtrace(std::ostream &stream);
template<class... Args> ScopedEntry trace(const Args &...args)
{
stack_.append_as(args...);
return ScopedEntry(stack_);
}
private:
Stack stack_;
};
} // namespace blender::deg