Depsgraph - Dependency Cycle - concurrency issue leading to memory after use errors. #103373

New Issue

Bastien Montagne · 2022-12-21T07:45:40+01:00

Bastien Montagne commented

2022-12-21 07:45:40 +01:00

Disclaimer: This is a very elusive 'bug'. I stumbled on it after making changes in a completely unrelated area (liboverrides diffing code in fcddb7cda7). Artificially raising the amount of threads seems to make it more easily reproducible though.

Reproducible fairly consistently on my machine with Sprites production file 110_0010_A.anim.blend version r2747. This file contains dependency loops, which as far as I understand makes depsgraph fail to fully handle dependencies between updates, leading to some data being freed while/before it is used from another ID.

Not sure how much we support these dependency loops cases, but think crashes at least should not be accepted here?

Here is a small patch I used to debug:

diff --git a/source/blender/blenkernel/intern/object_update.cc b/source/blender/blenkernel/intern/object_update.cc
index 625aa666023..7f1f4a1b4d2 100644
--- a/source/blender/blenkernel/intern/object_update.cc
+++ b/source/blender/blenkernel/intern/object_update.cc
@@ -376,6 +376,20 @@ void BKE_object_select_update(Depsgraph *depsgraph, Object *object)
   if (object->type == OB_MESH && !object->runtime.is_data_eval_owned) {
     Mesh *mesh_input = (Mesh *)object->runtime.data_orig;
     std::lock_guard lock{mesh_input->runtime->eval_mutex};
+
+    BLI_assert(mesh_input->runtime->mesh_eval != nullptr);
+    BLI_assert(mesh_input->runtime->mesh_eval == static_cast<Mesh *>(object->data));
+    if (mesh_input->runtime->mesh_eval != static_cast<Mesh *>(object->data)) {
+      printf(
+          "%s: mesh_input->runtime->mesh_eval (%p) of %s does not match object->data (%p) of "
+          "%s\n ",
+          __func__,
+          mesh_input->runtime->mesh_eval,
+          mesh_input->id.name,
+          object->data,
+          object->id.name);
+    }
+
     BKE_object_data_select_update(depsgraph, static_cast<ID *>(object->data));
   }
   else {

The interesting part of the error log with an ASAN build:

Dependency cycle detected:
  OBGEO-log_moss/MODIFIER(GeometryNodes) depends on
  GRfallen_log/GEOMETRY_EVAL_DONE() via 'Nodes Modifier'
  OBGEO-log_moss/GEOMETRY_EVAL() via 'Collection Geometry'
  OBGEO-log_moss/MODIFIER(GeometryNodes) via 'modifier stack order'
Dependency cycle detected:
  OBGEO-oak_slingshot-moss/GEOMETRY_EVAL() depends on
  OBGEO-oak_slingshot-moss/MODIFIER(GeometryNodes) via 'modifier stack order'
  GRPR-slingshot_tree/GEOMETRY_EVAL_DONE() via 'Nodes Modifier'
  OBGEO-oak_slingshot-moss/GEOMETRY_EVAL() via 'Collection Geometry'
Detected 2 dependency cycles

BLI_assert failed: source/blender/blenkernel/intern/object_update.cc:380, BKE_object_select_update(), at 'mesh_input->runtime->mesh_eval != nullptr'
BLI_assert failed: source/blender/blenkernel/intern/object_update.cc:381, BKE_object_select_update(), at 'mesh_input->runtime->mesh_eval == static_cast<Mesh *>(object->data)'
BKE_object_select_update: mesh_input->runtime->mesh_eval ((nil)) of MEPlane.029 does not match object->data (0x61c000286888) of OBGEO-oak_slingshot-moss

 =================================================================
==404553==ERROR: AddressSanitizer: heap-use-after-free on address 0x61c0002868b0 at pc 0x000013bb005c bp 0x7f394ec88070 sp 0x7f394ec88068
READ of size 2 at 0x61c0002868b0 thread T137
    - 0 0x13bb005b in BKE_object_data_select_update /home/bastien/blender/src/source/blender/blenkernel/intern/object_update.cc:357
    - 1 0x13bb0a4d in BKE_object_select_update /home/bastien/blender/src/source/blender/blenkernel/intern/object_update.cc:393
    - 2 0x168103db in operator() /home/bastien/blender/src/source/blender/depsgraph/intern/builder/deg_builder_nodes.cc:1532
    - 3 0x1684125a in __invoke_impl<void, blender::deg::DepsgraphNodeBuilder::build_object_data_geometry(Object*)::<lambda(Depsgraph*)>&, Depsgraph*> /usr/include/c++/12/bits/invoke.h:61
    - 4 0x1683a429 in __invoke_r<void, blender::deg::DepsgraphNodeBuilder::build_object_data_geometry(Object*)::<lambda(Depsgraph*)>&, Depsgraph*> /usr/include/c++/12/bits/invoke.h:111
    - 5 0x1683289f in _M_invoke /usr/include/c++/12/bits/std_function.h:290
    - 6 0x1696ceb0 in std::function<void (Depsgraph*)>::operator()(Depsgraph*) const /usr/include/c++/12/bits/std_function.h:591
    - 7 0x1696787c in evaluate_node /home/bastien/blender/src/source/blender/depsgraph/intern/eval/deg_eval.cc:101
    - 8 0x16967caf in deg_task_run_func /home/bastien/blender/src/source/blender/depsgraph/intern/eval/deg_eval.cc:119
    - 9 0x2f3f586c in Task::operator()() const /home/bastien/blender/src/source/blender/blenlib/intern/task_pool.cc:164
    - 10 0x2f3f9022 in tbb::internal::function_task<Task>::execute() /opt/lib/tbb/include/tbb/task.h:1059
    - 11 0x7f39bce4cff4 in tbb::internal::custom_scheduler<tbb::internal::IntelSchedulerTraits>::process_bypass_loop(tbb::internal::context_guard_helper<false>&, tbb::task*, long) (/opt/lib/tbb/lib/libtbb.so+0x2cff4)
    - 12 0x7f39bce4d382 in tbb::internal::custom_scheduler<tbb::internal::IntelSchedulerTraits>::local_wait_for_all(tbb::task&, tbb::task*) (/opt/lib/tbb/lib/libtbb.so+0x2d382)
    - 13 0x7f39bce32fb6 in tbb::internal::arena::process(tbb::internal::generic_scheduler&) (/opt/lib/tbb/lib/libtbb.so+0x12fb6)
    - 14 0x7f39bce4206f in tbb::internal::market::process(rml::job&) (/opt/lib/tbb/lib/libtbb.so+0x2206f)
    - 15 0x7f39bce4605b in tbb::internal::rml::private_worker::run() (/opt/lib/tbb/lib/libtbb.so+0x2605b)
    - 16 0x7f39bce46298 in tbb::internal::rml::private_worker::thread_routine(void*) (/opt/lib/tbb/lib/libtbb.so+0x26298)
    - 17 0x7f39ab0a7fd3 in start_thread nptl/pthread_create.c:442
    #18 0x7f39ab12866b in clone3 ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

0x61c0002868b0 is located 48 bytes inside of 1704-byte region [0x61c000286880,0x61c000286f28)
freed by thread T137 here:
    - 0 0x7f39bc6b76a8 in __interceptor_free ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:52
    - 1 0x2f43bbfa in MEM_lockfree_freeN /home/bastien/blender/src/intern/guardedalloc/intern/mallocn_lockfree_impl.c:117
    - 2 0x134f9b18 in BKE_id_free_ex /home/bastien/blender/src/source/blender/blenkernel/intern/lib_id_delete.c:168
    - 3 0x134f9b49 in BKE_id_free /home/bastien/blender/src/source/blender/blenkernel/intern/lib_id_delete.c:174
    - 4 0x1364372f in BKE_mesh_eval_geometry /home/bastien/blender/src/source/blender/blenkernel/intern/mesh.cc:1876
    - 5 0x1681190d in operator() /home/bastien/blender/src/source/blender/depsgraph/intern/builder/deg_builder_nodes.cc:1561
    - 6 0x16841442 in __invoke_impl<void, blender::deg::DepsgraphNodeBuilder::build_object_data_geometry_datablock(ID*)::<lambda(Depsgraph*)>&, Depsgraph*> /usr/include/c++/12/bits/invoke.h:61
    - 7 0x1683a7bb in __invoke_r<void, blender::deg::DepsgraphNodeBuilder::build_object_data_geometry_datablock(ID*)::<lambda(Depsgraph*)>&, Depsgraph*> /usr/include/c++/12/bits/invoke.h:111
    - 8 0x16832ad5 in _M_invoke /usr/include/c++/12/bits/std_function.h:290
    - 9 0x1696ceb0 in std::function<void (Depsgraph*)>::operator()(Depsgraph*) const /usr/include/c++/12/bits/std_function.h:591
    - 10 0x1696787c in evaluate_node /home/bastien/blender/src/source/blender/depsgraph/intern/eval/deg_eval.cc:101
    - 11 0x16967caf in deg_task_run_func /home/bastien/blender/src/source/blender/depsgraph/intern/eval/deg_eval.cc:119
    - 12 0x2f3f586c in Task::operator()() const /home/bastien/blender/src/source/blender/blenlib/intern/task_pool.cc:164
    - 13 0x2f3f9022 in tbb::internal::function_task<Task>::execute() /opt/lib/tbb/include/tbb/task.h:1059
    #14 0x7f39bce4cff4 in tbb::internal::custom_scheduler<tbb::internal::IntelSchedulerTraits>::process_bypass_loop(tbb::internal::context_guard_helper<false>&, tbb::task*, long) (/opt/lib/tbb/lib/libtbb.so+0x2cff4)

previously allocated by thread T0 here:
    - 0 0x7f39bc6b83b7 in __interceptor_calloc ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:77
    - 1 0x2f43c32f in MEM_lockfree_callocN /home/bastien/blender/src/intern/guardedalloc/intern/mallocn_lockfree_impl.c:223
    - 2 0x134ede74 in BKE_libblock_alloc_notest /home/bastien/blender/src/source/blender/blenkernel/intern/lib_id.c:1101
    - 3 0x134edfdc in BKE_libblock_alloc /home/bastien/blender/src/source/blender/blenkernel/intern/lib_id.c:1113
    - 4 0x134ef71d in BKE_libblock_copy_ex /home/bastien/blender/src/source/blender/blenkernel/intern/lib_id.c:1274
    - 5 0x134e9788 in BKE_id_copy_ex /home/bastien/blender/src/source/blender/blenkernel/intern/lib_id.c:637
    - 6 0x13632b83 in BKE_mesh_copy_for_eval /home/bastien/blender/src/source/blender/blenkernel/intern/mesh.cc:1109
    - 7 0x122b0c00 in operator() /home/bastien/blender/src/source/blender/blenkernel/intern/DerivedMesh.cc:1130
    - 8 0x122c264c in operator() /opt/lib/tbb/include/tbb/task_arena.h:96
    - 9 0x7f39bce332b4 in tbb::interface7::internal::isolate_within_arena(tbb::interface7::internal::delegate_base&, long) (/opt/lib/tbb/lib/libtbb.so+0x132b4)
    #10 0x7fff66c6047f  ([stack]+0x4b47f)

This trace makes it pretty clear that BKE_object_select_update from object evaluation code accesses data that has been freed by Mesh evaluation code (BKE_mesh_eval_geometry).

Note that skipping (returning) here does not help, since code will crash in another place then (like inside the BKE_library_foreach_ID_link call in deg_validate_copy_on_write_datablock).

PS: Also seems weird to me that freeing runtime mesh_eval in BKE_mesh_eval_geometry is not protected by a lock on mesh->runtime->eval_mutex?

Disclaimer: This is a very elusive 'bug'. I stumbled on it after making changes in a completely unrelated area (liboverrides diffing code in fcddb7cda7). Artificially raising the amount of threads seems to make it more easily reproducible though. Reproducible fairly consistently on my machine with Sprites production file `110_0010_A.anim.blend` version `r2747`. This file contains dependency loops, which as far as I understand makes depsgraph fail to fully handle dependencies between updates, leading to some data being freed while/before it is used from another ID. Not sure how much we support these dependency loops cases, but think crashes at least should not be accepted here? -------------------------------- Here is a small patch I used to debug: ``` diff --git a/source/blender/blenkernel/intern/object_update.cc b/source/blender/blenkernel/intern/object_update.cc index 625aa666023..7f1f4a1b4d2 100644 --- a/source/blender/blenkernel/intern/object_update.cc +++ b/source/blender/blenkernel/intern/object_update.cc @@ -376,6 +376,20 @@ void BKE_object_select_update(Depsgraph *depsgraph, Object *object) if (object->type == OB_MESH && !object->runtime.is_data_eval_owned) { Mesh *mesh_input = (Mesh *)object->runtime.data_orig; std::lock_guard lock{mesh_input->runtime->eval_mutex}; + + BLI_assert(mesh_input->runtime->mesh_eval != nullptr); + BLI_assert(mesh_input->runtime->mesh_eval == static_cast<Mesh *>(object->data)); + if (mesh_input->runtime->mesh_eval != static_cast<Mesh *>(object->data)) { + printf( + "%s: mesh_input->runtime->mesh_eval (%p) of %s does not match object->data (%p) of " + "%s\n ", + __func__, + mesh_input->runtime->mesh_eval, + mesh_input->id.name, + object->data, + object->id.name); + } + BKE_object_data_select_update(depsgraph, static_cast<ID *>(object->data)); } else { ``` The interesting part of the error log with an ASAN build: ```lines=10 Dependency cycle detected: OBGEO-log_moss/MODIFIER(GeometryNodes) depends on GRfallen_log/GEOMETRY_EVAL_DONE() via 'Nodes Modifier' OBGEO-log_moss/GEOMETRY_EVAL() via 'Collection Geometry' OBGEO-log_moss/MODIFIER(GeometryNodes) via 'modifier stack order' Dependency cycle detected: OBGEO-oak_slingshot-moss/GEOMETRY_EVAL() depends on OBGEO-oak_slingshot-moss/MODIFIER(GeometryNodes) via 'modifier stack order' GRPR-slingshot_tree/GEOMETRY_EVAL_DONE() via 'Nodes Modifier' OBGEO-oak_slingshot-moss/GEOMETRY_EVAL() via 'Collection Geometry' Detected 2 dependency cycles BLI_assert failed: source/blender/blenkernel/intern/object_update.cc:380, BKE_object_select_update(), at 'mesh_input->runtime->mesh_eval != nullptr' BLI_assert failed: source/blender/blenkernel/intern/object_update.cc:381, BKE_object_select_update(), at 'mesh_input->runtime->mesh_eval == static_cast<Mesh *>(object->data)' BKE_object_select_update: mesh_input->runtime->mesh_eval ((nil)) of MEPlane.029 does not match object->data (0x61c000286888) of OBGEO-oak_slingshot-moss ================================================================= ==404553==ERROR: AddressSanitizer: heap-use-after-free on address 0x61c0002868b0 at pc 0x000013bb005c bp 0x7f394ec88070 sp 0x7f394ec88068 READ of size 2 at 0x61c0002868b0 thread T137 - 0 0x13bb005b in BKE_object_data_select_update /home/bastien/blender/src/source/blender/blenkernel/intern/object_update.cc:357 - 1 0x13bb0a4d in BKE_object_select_update /home/bastien/blender/src/source/blender/blenkernel/intern/object_update.cc:393 - 2 0x168103db in operator() /home/bastien/blender/src/source/blender/depsgraph/intern/builder/deg_builder_nodes.cc:1532 - 3 0x1684125a in __invoke_impl<void, blender::deg::DepsgraphNodeBuilder::build_object_data_geometry(Object*)::<lambda(Depsgraph*)>&, Depsgraph*> /usr/include/c++/12/bits/invoke.h:61 - 4 0x1683a429 in __invoke_r<void, blender::deg::DepsgraphNodeBuilder::build_object_data_geometry(Object*)::<lambda(Depsgraph*)>&, Depsgraph*> /usr/include/c++/12/bits/invoke.h:111 - 5 0x1683289f in _M_invoke /usr/include/c++/12/bits/std_function.h:290 - 6 0x1696ceb0 in std::function<void (Depsgraph*)>::operator()(Depsgraph*) const /usr/include/c++/12/bits/std_function.h:591 - 7 0x1696787c in evaluate_node /home/bastien/blender/src/source/blender/depsgraph/intern/eval/deg_eval.cc:101 - 8 0x16967caf in deg_task_run_func /home/bastien/blender/src/source/blender/depsgraph/intern/eval/deg_eval.cc:119 - 9 0x2f3f586c in Task::operator()() const /home/bastien/blender/src/source/blender/blenlib/intern/task_pool.cc:164 - 10 0x2f3f9022 in tbb::internal::function_task<Task>::execute() /opt/lib/tbb/include/tbb/task.h:1059 - 11 0x7f39bce4cff4 in tbb::internal::custom_scheduler<tbb::internal::IntelSchedulerTraits>::process_bypass_loop(tbb::internal::context_guard_helper<false>&, tbb::task*, long) (/opt/lib/tbb/lib/libtbb.so+0x2cff4) - 12 0x7f39bce4d382 in tbb::internal::custom_scheduler<tbb::internal::IntelSchedulerTraits>::local_wait_for_all(tbb::task&, tbb::task*) (/opt/lib/tbb/lib/libtbb.so+0x2d382) - 13 0x7f39bce32fb6 in tbb::internal::arena::process(tbb::internal::generic_scheduler&) (/opt/lib/tbb/lib/libtbb.so+0x12fb6) - 14 0x7f39bce4206f in tbb::internal::market::process(rml::job&) (/opt/lib/tbb/lib/libtbb.so+0x2206f) - 15 0x7f39bce4605b in tbb::internal::rml::private_worker::run() (/opt/lib/tbb/lib/libtbb.so+0x2605b) - 16 0x7f39bce46298 in tbb::internal::rml::private_worker::thread_routine(void*) (/opt/lib/tbb/lib/libtbb.so+0x26298) - 17 0x7f39ab0a7fd3 in start_thread nptl/pthread_create.c:442 #18 0x7f39ab12866b in clone3 ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81 0x61c0002868b0 is located 48 bytes inside of 1704-byte region [0x61c000286880,0x61c000286f28) freed by thread T137 here: - 0 0x7f39bc6b76a8 in __interceptor_free ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:52 - 1 0x2f43bbfa in MEM_lockfree_freeN /home/bastien/blender/src/intern/guardedalloc/intern/mallocn_lockfree_impl.c:117 - 2 0x134f9b18 in BKE_id_free_ex /home/bastien/blender/src/source/blender/blenkernel/intern/lib_id_delete.c:168 - 3 0x134f9b49 in BKE_id_free /home/bastien/blender/src/source/blender/blenkernel/intern/lib_id_delete.c:174 - 4 0x1364372f in BKE_mesh_eval_geometry /home/bastien/blender/src/source/blender/blenkernel/intern/mesh.cc:1876 - 5 0x1681190d in operator() /home/bastien/blender/src/source/blender/depsgraph/intern/builder/deg_builder_nodes.cc:1561 - 6 0x16841442 in __invoke_impl<void, blender::deg::DepsgraphNodeBuilder::build_object_data_geometry_datablock(ID*)::<lambda(Depsgraph*)>&, Depsgraph*> /usr/include/c++/12/bits/invoke.h:61 - 7 0x1683a7bb in __invoke_r<void, blender::deg::DepsgraphNodeBuilder::build_object_data_geometry_datablock(ID*)::<lambda(Depsgraph*)>&, Depsgraph*> /usr/include/c++/12/bits/invoke.h:111 - 8 0x16832ad5 in _M_invoke /usr/include/c++/12/bits/std_function.h:290 - 9 0x1696ceb0 in std::function<void (Depsgraph*)>::operator()(Depsgraph*) const /usr/include/c++/12/bits/std_function.h:591 - 10 0x1696787c in evaluate_node /home/bastien/blender/src/source/blender/depsgraph/intern/eval/deg_eval.cc:101 - 11 0x16967caf in deg_task_run_func /home/bastien/blender/src/source/blender/depsgraph/intern/eval/deg_eval.cc:119 - 12 0x2f3f586c in Task::operator()() const /home/bastien/blender/src/source/blender/blenlib/intern/task_pool.cc:164 - 13 0x2f3f9022 in tbb::internal::function_task<Task>::execute() /opt/lib/tbb/include/tbb/task.h:1059 #14 0x7f39bce4cff4 in tbb::internal::custom_scheduler<tbb::internal::IntelSchedulerTraits>::process_bypass_loop(tbb::internal::context_guard_helper<false>&, tbb::task*, long) (/opt/lib/tbb/lib/libtbb.so+0x2cff4) previously allocated by thread T0 here: - 0 0x7f39bc6b83b7 in __interceptor_calloc ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:77 - 1 0x2f43c32f in MEM_lockfree_callocN /home/bastien/blender/src/intern/guardedalloc/intern/mallocn_lockfree_impl.c:223 - 2 0x134ede74 in BKE_libblock_alloc_notest /home/bastien/blender/src/source/blender/blenkernel/intern/lib_id.c:1101 - 3 0x134edfdc in BKE_libblock_alloc /home/bastien/blender/src/source/blender/blenkernel/intern/lib_id.c:1113 - 4 0x134ef71d in BKE_libblock_copy_ex /home/bastien/blender/src/source/blender/blenkernel/intern/lib_id.c:1274 - 5 0x134e9788 in BKE_id_copy_ex /home/bastien/blender/src/source/blender/blenkernel/intern/lib_id.c:637 - 6 0x13632b83 in BKE_mesh_copy_for_eval /home/bastien/blender/src/source/blender/blenkernel/intern/mesh.cc:1109 - 7 0x122b0c00 in operator() /home/bastien/blender/src/source/blender/blenkernel/intern/DerivedMesh.cc:1130 - 8 0x122c264c in operator() /opt/lib/tbb/include/tbb/task_arena.h:96 - 9 0x7f39bce332b4 in tbb::interface7::internal::isolate_within_arena(tbb::interface7::internal::delegate_base&, long) (/opt/lib/tbb/lib/libtbb.so+0x132b4) #10 0x7fff66c6047f ([stack]+0x4b47f) ``` This trace makes it pretty clear that `BKE_object_select_update` from object evaluation code accesses data that has been freed by Mesh evaluation code (`BKE_mesh_eval_geometry`). Note that skipping (returning) here does not help, since code will crash in another place then (like inside the `BKE_library_foreach_ID_link` call in `deg_validate_copy_on_write_datablock`). ---------------------------- PS: Also seems weird to me that freeing runtime `mesh_eval` in `BKE_mesh_eval_geometry` is not protected by a lock on `mesh->runtime->eval_mutex`?

Bastien Montagne commented

2022-12-21 07:45:40 +01:00

Changed status from 'Needs Triage' to: 'Confirmed'

Bastien Montagne commented

2022-12-21 07:45:40 +01:00

Added subscribers: @mont29, @Sergey, @JacquesLucke

Sergey Sharybin commented

2023-01-03 15:01:47 +01:00

BKE_mesh_eval_geometry is not supposed to be run on the same mesh mesh multiple times per single depsgraph update. But also, the geometry component of the object is not supposed to be executed before the mesh itself is evaluated.

Doing something like this P3417 should help with dealing with non-evaluated data when the dependnecy cycle is detected. Don't currently have Sprites SVN here, so can not dig deeper yet.

`BKE_mesh_eval_geometry` is not supposed to be run on the same mesh mesh multiple times per single depsgraph update. But also, the geometry component of the object is not supposed to be executed before the mesh itself is evaluated. Doing something like this [P3417](https://archive.blender.org/developer/P3417.txt) should help with dealing with non-evaluated data when the dependnecy cycle is detected. Don't currently have Sprites SVN here, so can not dig deeper yet.

Philipp Oeser removed the

Download

What's New

Blender Studio

Manual

Developers Blog

Documentation

Benchmark

Blender Conference

Development Fund

One-time Donations

Depsgraph - Dependency Cycle - concurrency issue leading to memory after use errors. #103373