[Bf-blender-cvs] [edd1164575f] master: Cycles: add time statistics to scene update

Kévin Dietrich noreply at git.blender.org
Fri Oct 2 00:15:51 CEST 2020


Commit: edd1164575feefda103c73119a98cbd994e53141
Author: Kévin Dietrich
Date:   Thu Oct 1 23:16:01 2020 +0200
Branches: master
https://developer.blender.org/rBedd1164575feefda103c73119a98cbd994e53141

Cycles: add time statistics to scene update

Gathers information for time spent in the various managers or object (Film, Camera, etc.) being updated in Scene::device_update.

The stats include the total time spent in the device_update methods as well as time spent in subroutines (e.g. bvh build, displacement, etc.).

This does not qualify as a full blown profiler, but is useful to identify potential bottleneck areas.

The stats can be enabled and printed by passing `--cycles-print-stats` on the command line to Cycles, or `-- --cycles-print-stats` to Blender.

Reviewed By: brecht

Maniphest Tasks: T79174

Differential Revision: https://developer.blender.org/D8596

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

M	intern/cycles/blender/blender_session.cpp
M	intern/cycles/render/background.cpp
M	intern/cycles/render/bake.cpp
M	intern/cycles/render/camera.cpp
M	intern/cycles/render/film.cpp
M	intern/cycles/render/geometry.cpp
M	intern/cycles/render/image.cpp
M	intern/cycles/render/integrator.cpp
M	intern/cycles/render/light.cpp
M	intern/cycles/render/object.cpp
M	intern/cycles/render/osl.cpp
M	intern/cycles/render/particles.cpp
M	intern/cycles/render/scene.cpp
M	intern/cycles/render/scene.h
M	intern/cycles/render/stats.cpp
M	intern/cycles/render/stats.h
M	intern/cycles/render/svm.cpp
M	intern/cycles/render/tables.cpp
M	intern/cycles/render/tables.h
M	intern/cycles/util/util_time.h

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

diff --git a/intern/cycles/blender/blender_session.cpp b/intern/cycles/blender/blender_session.cpp
index bf9fc784d79..8e962f17f56 100644
--- a/intern/cycles/blender/blender_session.cpp
+++ b/intern/cycles/blender/blender_session.cpp
@@ -562,6 +562,10 @@ void BlenderSession::render(BL::Depsgraph &b_depsgraph_)
     session->reset(buffer_params, effective_layer_samples);
 
     /* render */
+    if (!b_engine.is_preview() && background && print_render_stats) {
+      scene->enable_update_stats();
+    }
+
     session->start();
     session->wait();
 
diff --git a/intern/cycles/render/background.cpp b/intern/cycles/render/background.cpp
index 694bb640995..d2463454522 100644
--- a/intern/cycles/render/background.cpp
+++ b/intern/cycles/render/background.cpp
@@ -21,9 +21,11 @@
 #include "render/nodes.h"
 #include "render/scene.h"
 #include "render/shader.h"
+#include "render/stats.h"
 
 #include "util/util_foreach.h"
 #include "util/util_math.h"
+#include "util/util_time.h"
 #include "util/util_types.h"
 
 CCL_NAMESPACE_BEGIN
@@ -65,6 +67,12 @@ void Background::device_update(Device *device, DeviceScene *dscene, Scene *scene
   if (!need_update)
     return;
 
+  scoped_callback_timer timer([scene](double time) {
+    if (scene->update_stats) {
+      scene->update_stats->background.times.add_entry({"device_update", time});
+    }
+  });
+
   device_free(device, dscene);
 
   Shader *bg_shader = get_shader(scene);
diff --git a/intern/cycles/render/bake.cpp b/intern/cycles/render/bake.cpp
index c00451e931f..05f52159671 100644
--- a/intern/cycles/render/bake.cpp
+++ b/intern/cycles/render/bake.cpp
@@ -20,6 +20,7 @@
 #include "render/mesh.h"
 #include "render/object.h"
 #include "render/shader.h"
+#include "render/stats.h"
 
 #include "util/util_foreach.h"
 
@@ -125,6 +126,12 @@ void BakeManager::device_update(Device * /*device*/,
   if (!need_update)
     return;
 
+  scoped_callback_timer timer([scene](double time) {
+    if (scene->update_stats) {
+      scene->update_stats->bake.times.add_entry({"device_update", time});
+    }
+  });
+
   KernelIntegrator *kintegrator = &dscene->data.integrator;
   KernelBake *kbake = &dscene->data.bake;
 
diff --git a/intern/cycles/render/camera.cpp b/intern/cycles/render/camera.cpp
index 0fa1d512547..ee68c9ede22 100644
--- a/intern/cycles/render/camera.cpp
+++ b/intern/cycles/render/camera.cpp
@@ -18,6 +18,7 @@
 #include "render/mesh.h"
 #include "render/object.h"
 #include "render/scene.h"
+#include "render/stats.h"
 #include "render/tables.h"
 
 #include "device/device.h"
@@ -27,6 +28,7 @@
 #include "util/util_logging.h"
 #include "util/util_math_cdf.h"
 #include "util/util_task.h"
+#include "util/util_time.h"
 #include "util/util_vector.h"
 
 /* needed for calculating differentials */
@@ -231,6 +233,12 @@ void Camera::update(Scene *scene)
   if (!need_update)
     return;
 
+  scoped_callback_timer timer([scene](double time) {
+    if (scene->update_stats) {
+      scene->update_stats->camera.times.add_entry({"update", time});
+    }
+  });
+
   /* Full viewport to camera border in the viewport. */
   Transform fulltoborder = transform_from_viewplane(viewport_camera_border);
   Transform bordertofull = transform_inverse(fulltoborder);
@@ -466,6 +474,12 @@ void Camera::device_update(Device * /* device */, DeviceScene *dscene, Scene *sc
   if (!need_device_update)
     return;
 
+  scoped_callback_timer timer([scene](double time) {
+    if (scene->update_stats) {
+      scene->update_stats->camera.times.add_entry({"device_update", time});
+    }
+  });
+
   scene->lookup_tables->remove_table(&shutter_table_offset);
   if (kernel_camera.shuttertime != -1.0f) {
     vector<float> shutter_table;
diff --git a/intern/cycles/render/film.cpp b/intern/cycles/render/film.cpp
index 2da28222a7f..e4c1e452bd5 100644
--- a/intern/cycles/render/film.cpp
+++ b/intern/cycles/render/film.cpp
@@ -20,12 +20,14 @@
 #include "render/integrator.h"
 #include "render/mesh.h"
 #include "render/scene.h"
+#include "render/stats.h"
 #include "render/tables.h"
 
 #include "util/util_algorithm.h"
 #include "util/util_foreach.h"
 #include "util/util_math.h"
 #include "util/util_math_cdf.h"
+#include "util/util_time.h"
 
 CCL_NAMESPACE_BEGIN
 
@@ -408,6 +410,12 @@ void Film::device_update(Device *device, DeviceScene *dscene, Scene *scene)
   if (!need_update)
     return;
 
+  scoped_callback_timer timer([scene](double time) {
+    if (scene->update_stats) {
+      scene->update_stats->film.times.add_entry({"update", time});
+    }
+  });
+
   device_free(device, dscene, scene);
 
   KernelFilm *kfilm = &dscene->data.film;
diff --git a/intern/cycles/render/geometry.cpp b/intern/cycles/render/geometry.cpp
index 894adafa6e6..d96dc15f400 100644
--- a/intern/cycles/render/geometry.cpp
+++ b/intern/cycles/render/geometry.cpp
@@ -1106,6 +1106,12 @@ void GeometryManager::device_update_preprocess(Device *device, Scene *scene, Pro
     return;
   }
 
+  scoped_callback_timer timer([scene](double time) {
+    if (scene->update_stats) {
+      scene->update_stats->geometry.times.add_entry({"device_update_preprocess", time});
+    }
+  });
+
   progress.set_status("Updating Meshes Flags");
 
   /* Update flags. */
@@ -1231,41 +1237,56 @@ void GeometryManager::device_update(Device *device,
   bool true_displacement_used = false;
   size_t total_tess_needed = 0;
 
-  foreach (Geometry *geom, scene->geometry) {
-    foreach (Shader *shader, geom->used_shaders) {
-      if (shader->need_update_geometry)
-        geom->need_update = true;
-    }
+  {
+    scoped_callback_timer timer([scene](double time) {
+      if (scene->update_stats) {
+        scene->update_stats->geometry.times.add_entry({"device_update (normals)", time});
+      }
+    });
 
-    if (geom->need_update && (geom->type == Geometry::MESH || geom->type == Geometry::VOLUME)) {
-      Mesh *mesh = static_cast<Mesh *>(geom);
+    foreach (Geometry *geom, scene->geometry) {
+      foreach (Shader *shader, geom->used_shaders) {
+        if (shader->need_update_geometry)
+          geom->need_update = true;
+      }
 
-      /* Update normals. */
-      mesh->add_face_normals();
-      mesh->add_vertex_normals();
+      if (geom->need_update && (geom->type == Geometry::MESH || geom->type == Geometry::VOLUME)) {
+        Mesh *mesh = static_cast<Mesh *>(geom);
 
-      if (mesh->need_attribute(scene, ATTR_STD_POSITION_UNDISPLACED)) {
-        mesh->add_undisplaced();
-      }
+        /* Update normals. */
+        mesh->add_face_normals();
+        mesh->add_vertex_normals();
 
-      /* Test if we need tessellation. */
-      if (mesh->subdivision_type != Mesh::SUBDIVISION_NONE && mesh->num_subd_verts == 0 &&
-          mesh->subd_params) {
-        total_tess_needed++;
-      }
+        if (mesh->need_attribute(scene, ATTR_STD_POSITION_UNDISPLACED)) {
+          mesh->add_undisplaced();
+        }
 
-      /* Test if we need displacement. */
-      if (mesh->has_true_displacement()) {
-        true_displacement_used = true;
-      }
+        /* Test if we need tessellation. */
+        if (mesh->subdivision_type != Mesh::SUBDIVISION_NONE && mesh->num_subd_verts == 0 &&
+            mesh->subd_params) {
+          total_tess_needed++;
+        }
 
-      if (progress.get_cancel())
-        return;
+        /* Test if we need displacement. */
+        if (mesh->has_true_displacement()) {
+          true_displacement_used = true;
+        }
+
+        if (progress.get_cancel())
+          return;
+      }
     }
   }
 
   /* Tessellate meshes that are using subdivision */
   if (total_tess_needed) {
+    scoped_callback_timer timer([scene](double time) {
+      if (scene->update_stats) {
+        scene->update_stats->geometry.times.add_entry(
+            {"device_update (adaptive subdivision)", time});
+      }
+    });
+
     Camera *dicing_camera = scene->dicing_camera;
     dicing_camera->update(scene);
 
@@ -1302,7 +1323,12 @@ void GeometryManager::device_update(Device *device,
   /* Update images needed for true displacement. */
   bool old_need_object_flags_update = false;
   if (true_displacement_used) {
-    VLOG(1) << "Updating images used for true displacement.";
+    scoped_callback_timer timer([scene](double time) {
+      if (scene->update_stats) {
+        scene->update_stats->geometry.times.add_entry(
+            {"device_update (displacement: load images)", time});
+      }
+    });
     device_update_displacement_images(device, scene, progress);
     old_need_object_flags_update = scene->object_manager->need_flags_update;
     scene->object_manager->device_update_flags(device, dscene, scene, progress, false);
@@ -1313,41 +1339,68 @@ void GeometryManager::device_update(Device *device,
 
   mesh_calc_offset(scene);
   if (true_displacement_used) {
+    scoped_callback_timer timer([scene](double time) {
+      if (scene->update_stats) {
+        scene->update_stats->geometry.times.add_entry(
+            {"device_update (displacement: copy meshes to device)", time});
+      }
+    });
     device_update_mesh(device, dscene, scene, true, progress);
   }
   if (progress.get_cancel())
     return;
 
-  device_update_attributes(device, dscene, scene, progress);
-  if (progress.get_cancel())
-    return;
+  {
+    scoped_callback_timer timer([scene](double time) {
+      if (scene->update_stats) {
+        scene->update_stats->geometry.times.add_entry({"device_update (attributes)", time});
+      }
+    });
+    device_update_attributes(device, dscene, scene, progress);
+    if (progress.get_cancel())
+      return;
+  }
 
   /* Update displacement. */
-  bool displacement_done = false;
-  size_t num_bvh = 0;
   BVHLayout bvh_layout = BVHParams::best_bvh_layout(scene->params.bvh_layout,
                                                     device->get_bvh_layout_mask());
+  bool displacement_done = false;
+  size_t num_bvh = 0;
 
-  foreach (Geometry *geom, scene->geometry) {
-    if (geom->need_update) {
-      if (geom->type == Geometry::MESH) {
-        Mesh *mesh = static_cast<Mesh *>(geom);
-        if (displace(device, dscene, scene, mesh, progress)) {
-          displacement_done = true;
-        }
+  {
+    scoped_callback_timer timer([scene](double time) {
+      if (scene->update_

@@ Diff output truncated at 10240 characters. @@



More information about the Bf-blender-cvs mailing list