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

20 files changed, 472 insertions, 75 deletions

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_stats) {
+        scene->update_stats->geometry.times.add_entry({"device_update (displacement)", time});
       }
+    });
+
+    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;
+          }
+        }
 
-      if (geom->need_build_bvh(bvh_layout)) {
-        num_bvh++;
+        if (geom->need_build_bvh(bvh_layout)) {
+          num_bvh++;
+        }
       }
-    }
 
-    if (progress.get_cancel())
-      return;
+      if (progress.get_cancel())
+        return;
+    }
   }
 
   /* Device re-update after displacement. */
   if (displacement_done) {
+    scoped_callback_timer timer([scene](double time) {
+      if (scene->update_stats) {
+        scene->update_stats->geometry.times.add_entry(
+            {"device_update (displacement: attributes)", time});
+      }
+    });
     device_free(device, dscene);
 
     device_update_attributes(device, dscene, scene, progress);
@@ -1355,22 +1408,29 @@ void GeometryManager::device_update(Device *device,
       return;
   }
 
-  TaskPool pool;
+  {
+    scoped_callback_timer timer([scene](double time) {
+      if (scene->update_stats) {
+        scene->update_stats->geometry.times.add_entry({"device_update (build object BVHs)", time});
+      }
+    });
+    TaskPool pool;
 
-  size_t i = 0;
-  foreach (Geometry *geom, scene->geometry) {
-    if (geom->need_update) {
-      pool.push(function_bind(
-          &Geometry::compute_bvh, geom, device, dscene, &scene->params, &progress, i, num_bvh));
-      if (geom->need_build_bvh(bvh_layout)) {
-        i++;
+    size_t i = 0;
+    foreach (Geometry *geom, scene->geometry) {
+      if (geom->need_update) {
+        pool.push(function_bind(
+            &Geometry::compute_bvh, geom, device, dscene, &scene->params, &progress, i, num_bvh));
+        if (geom->need_build_bvh(bvh_layout)) {
+          i++;
+        }
       }
     }
-  }
 
-  TaskPool::Summary summary;
-  pool.wait_work(&summary);
-  VLOG(2) << "Objects BVH build pool statistics:\n" << summary.full_report();
+    TaskPool::Summary summary;
+    pool.wait_work(&summary);
+    VLOG(2) << "Objects BVH build pool statistics:\n" << summary.full_report();
+  }
 
   foreach (Shader *shader, scene->shaders) {
     shader->need_update_geometry = false;
@@ -1380,21 +1440,43 @@ void GeometryManager::device_update(Device *device,
   bool motion_blur = need_motion == Scene::MOTION_BLUR;
 
   /* Update objects. */
-  vector<Object *> volume_objects;
-  foreach (Object *object, scene->objects) {
-    object->compute_bounds(motion_blur);
+  {
+    scoped_callback_timer timer([scene](double time) {
+      if (scene->update_stats) {
+        scene->update_stats->geometry.times.add_entry({"device_update (compute bounds)", time});
+      }
+    });
+    vector<Object *> volume_objects;
+    foreach (Object *object, scene->objects) {
+      object->compute_bounds(motion_blur);
+    }
   }
 
   if (progress.get_cancel())
     return;
 
-  device_update_bvh(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 (build scene BVH)", time});
+      }
+    });
+    device_update_bvh(device, dscene, scene, progress);
+    if (progress.get_cancel())
+      return;
+  }
 
-  device_update_mesh(device, dscene, scene, false, 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 (copy meshes to device)", time});
+      }
+    });
+    device_update_mesh(device, dscene, scene, false, progress);
+    if (progress.get_cancel())
+      return;
+  }
 
   need_update = false;
 
diff --git a/intern/cycles/render/image.cpp b/intern/cycles/render/image.cpp
index a5dfcf60d61..fd6186d8f1e 100644
--- a/intern/cycles/render/image.cpp
+++ b/intern/cycles/render/image.cpp
@@ -799,6 +799,12 @@ void ImageManager::device_update(Device *device, Scene *scene, Progress &progres
     return;
   }
 
+  scoped_callback_timer timer([scene](double time) {
+    if (scene->update_stats) {
+      scene->update_stats->image.times.add_entry({"device_update", time});
+    }
+  });
+
   TaskPool pool;
   for (size_t slot = 0; slot < images.size(); slot++) {
     Image *img = images[slot];
diff --git a/intern/cycles/render/integrator.cpp b/intern/cycles/render/integrator.cpp
index 6c295b20538..cc085af20a0 100644
--- a/intern/cycles/render/integrator.cpp
+++ b/intern/cycles/render/integrator.cpp
@@ -23,6 +23,7 @@
 #include "render/scene.h"
 #include "render/shader.h"
 #include "render/sobol.h"
+#include "render/stats.h"
 
 #include "kernel/kernel_types.h"
 
@@ -30,6 +31,7 @@
 #include "util/util_hash.h"
 #include "util/util_logging.h"
 #include "util/util_task.h"
+#include "util/util_time.h"
 
 CCL_NAMESPACE_BEGIN
 
@@ -106,6 +108,12 @@ void Integrator::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->integrator.times.add_entry({"device_update", time});
+    }
+  });
+
   device_free(device, dscene);
 
   KernelIntegrator *kintegrator = &dscene->data.integrator;
diff --git a/intern/cycles/render/light.cpp b/intern/cycles/render/light.cpp
index 5f586f98b13..100530ffba6 100644
--- a/intern/cycles/render/light.cpp
+++ b/intern/cycles/render/light.cpp
@@ -25,6 +25,7 @@
 #include "render/object.h"
 #include "render/scene.h"
 #include "render/shader.h"
+#include "render/stats.h"
 
 #include "util/util_foreach.h"
 #include "util/util_hash.h"
@@ -961,6 +962,12 @@ void LightManager::device_update(Device *device,
   if (!need_update)
     return;
 
+  scoped_callback_timer timer([scene](double time) {
+    if (scene->update_stats) {
+      scene->update_stats->light.times.add_entry({"device_update", time});
+    }
+  });
+
   VLOG(1) << "Total " << scene->lights.size() << " lights.";
 
   /* Detect which lights are enabled, also determins if we need to update the background. */
diff --git a/intern/cycles/render/object.cpp b/intern/cycles/render/object.cpp
index 9396ae49288..bce2e08b390 100644
--- a/intern/cycles/render/object.cpp
+++ b/intern/cycles/render/object.cpp
@@ -24,6 +24,7 @@
 #include "render/mesh.h"
 #include "render/particles.h"
 #include "render/scene.h"
+#include "render/stats.h"
 #include "render/volume.h"
 
 #include "util/util_foreach.h"
@@ -643,15 +644,32 @@ void ObjectManager::device_update(Device *device,
   if (scene->objects.size() == 0)
     return;
 
-  /* Assign object IDs. */
-  int index = 0;
-  foreach (Object *object, scene->objects) {
-    object->index = index++;
+  {
+    /* Assign object IDs. */
+    scoped_callback_timer timer([scene](double time) {
+      if (scene->update_stats) {
+        scene->update_stats->object.times.add_entry({"device_update (assign index)", time});
+      }
+    });
+
+    int index = 0;
+    foreach (Object *object, scene->objects) {
+      object->index = index++;
+    }
   }
 
-  /* set object transform matrices, before applying static transforms */
-  progress.set_status("Updating Objects", "Copying Transformations to device");
-  device_update_transforms(dscene, scene, progress);
+  {
+    /* set object transform matrices, before applying static transforms */
+    scoped_callback_timer timer([scene](double time) {
+      if (scene->update_stats) {
+        scene->update_stats->object.times.add_entry(
+            {"device_update (copy objects to device)", time});
+      }
+    });
+
+    progress.set_status("Updating Objects", "Copying Transformations to device");
+    device_update_transforms(dscene, scene, progress);
+  }
 
   if (progress.get_cancel())
     return;
@@ -659,6 +677,13 @@ void ObjectManager::device_update(Device *device,
   /* prepare for static BVH building */
   /* todo: do before to support getting object level coords? */
   if (scene->params.bvh_type == SceneParams::BVH_STATIC) {
+    scoped_callback_timer timer([scene](double time) {
+      if (scene->update_stats) {
+        scene->update_stats->object.times.add_entry(
+            {"device_update (apply static transforms)", time});
+      }
+    });
+
     progress.set_status("Updating Objects", "Applying Static Transformations");
     apply_static_transforms(dscene, scene, progress);
   }
@@ -670,6 +695,12 @@ void ObjectManager::device_update_flags(
   if (!need_update && !need_flags_update)
     return;
 
+  scoped_callback_timer timer([scene](double time) {
+    if (scene->update_stats) {
+      scene->update_stats->object.times.add_entry({"device_update_flags", time});
+    }
+  });
+
   need_update = false;
   need_flags_update = false;
 
diff --git a/intern/cycles/render/osl.cpp b/intern/cycles/render/osl.cpp
index 1c54dc2d531..90235edd761 100644
--- a/intern/cycles/render/osl.cpp
+++ b/intern/cycles/render/osl.cpp
@@ -24,6 +24,7 @@
 #include "render/osl.h"
 #include "render/scene.h"
 #include "render/shader.h"
+#include "render/stats.h"
 
 #ifdef WITH_OSL
 
@@ -98,6 +99,12 @@ void OSLShaderManager::device_update(Device *device,
   if (!need_update)
     return;
 
+  scoped_callback_timer timer([scene](double time) {
+    if (scene->update_stats) {
+      scene->update_stats->osl.times.add_entry({"device_update", time});
+    }
+  });
+
   VLOG(1) << "Total " << scene->shaders.size() << " shaders.";
 
   device_free(device, dscene, scene);
diff --git a/intern/cycles/render/particles.cpp b/intern/cycles/render/particles.cpp
index 494f5929df2..faad731d413 100644
--- a/intern/cycles/render/particles.cpp
+++ b/intern/cycles/render/particles.cpp
@@ -17,6 +17,7 @@
 #include "render/particles.h"
 #include "device/device.h"
 #include "render/scene.h"
+#include "render/stats.h"
 
 #include "util/util_foreach.h"
 #include "util/util_hash.h"
@@ -111,6 +112,12 @@ void ParticleSystemManager::device_update(Device *device,
   if (!need_update)
     return;
 
+  scoped_callback_timer timer([scene](double time) {
+    if (scene->update_stats) {
+      scene->update_stats->particles.times.add_entry({"device_update", time});
+    }
+  });
+
   VLOG(1) << "Total " << scene->particle_systems.size() << " particle systems.";
 
   device_free(device, dscene);
diff --git a/intern/cycles/render/scene.cpp b/intern/cycles/render/scene.cpp
index 8f863b5d15f..e98b2c76e88 100644
--- a/intern/cycles/render/scene.cpp
+++ b/intern/cycles/render/scene.cpp
@@ -95,7 +95,8 @@ Scene::Scene(const SceneParams &params_, Device *device)
       default_empty(NULL),
       device(device),
       dscene(device),
-      params(params_)
+      params(params_),
+      update_stats(NULL)
 {
   memset((void *)&dscene.data, 0, sizeof(dscene.data));
 
@@ -188,6 +189,7 @@ void Scene::free_memory(bool final)
     delete particle_system_manager;
     delete image_manager;
     delete bake_manager;
+    delete update_stats;
   }
 }
 
@@ -198,6 +200,20 @@ void Scene::device_update(Device *device_, Progress &progress)
 
   bool print_stats = need_data_update();
 
+  if (update_stats) {
+    update_stats->clear();
+  }
+
+  scoped_callback_timer timer([this, print_stats](double time) {
+    if (update_stats) {
+      update_stats->scene.times.add_entry({"device_update", time});
+
+      if (print_stats) {
+        printf("Update statistics:\n%s\n", update_stats->full_report().c_str());
+      }
+    }
+  });
+
   /* The order of updates is important, because there's dependencies between
    * the different managers, using data computed by previous managers.
    *
@@ -269,7 +285,7 @@ void Scene::device_update(Device *device_, Progress &progress)
     return;
 
   progress.set_status("Updating Lookup Tables");
-  lookup_tables->device_update(device, &dscene);
+  lookup_tables->device_update(device, &dscene, this);
 
   if (progress.get_cancel() || device->have_error())
     return;
@@ -293,7 +309,7 @@ void Scene::device_update(Device *device_, Progress &progress)
     return;
 
   progress.set_status("Updating Lookup Tables");
-  lookup_tables->device_update(device, &dscene);
+  lookup_tables->device_update(device, &dscene, this);
 
   if (progress.get_cancel() || device->have_error())
     return;
@@ -404,6 +420,13 @@ void Scene::collect_statistics(RenderStats *stats)
   image_manager->collect_statistics(stats);
 }
 
+void Scene::enable_update_stats()
+{
+  if (!update_stats) {
+    update_stats = new SceneUpdateStats();
+  }
+}
+
 DeviceRequestedFeatures Scene::get_requested_device_features()
 {
   DeviceRequestedFeatures requested_features;
diff --git a/intern/cycles/render/scene.h b/intern/cycles/render/scene.h
index 0e32a70952b..cc2ef8da589 100644
--- a/intern/cycles/render/scene.h
+++ b/intern/cycles/render/scene.h
@@ -59,6 +59,7 @@ class Progress;
 class BakeManager;
 class BakeData;
 class RenderStats;
+class SceneUpdateStats;
 class Volume;
 
 /* Scene Device Data */
@@ -260,6 +261,9 @@ class Scene : public NodeOwner {
   /* mutex must be locked manually by callers */
   thread_mutex mutex;
 
+  /* scene update statistics */
+  SceneUpdateStats *update_stats;
+
   Scene(const SceneParams &params, Device *device);
   ~Scene();
 
@@ -280,6 +284,8 @@ class Scene : public NodeOwner {
 
   void collect_statistics(RenderStats *stats);
 
+  void enable_update_stats();
+
   bool update(Progress &progress, bool &kernel_switch_needed);
 
   /* This function is used to create a node of a specified type instead of
diff --git a/intern/cycles/render/stats.cpp b/intern/cycles/render/stats.cpp
index 0937b95a891..e5600bad904 100644
--- a/intern/cycles/render/stats.cpp
+++ b/intern/cycles/render/stats.cpp
@@ -34,6 +34,12 @@ bool namedSizeEntryComparator(const NamedSizeEntry &a, const NamedSizeEntry &b)
   return a.size > b.size;
 }
 
+bool namedTimeEntryComparator(const NamedTimeEntry &a, const NamedTimeEntry &b)
+{
+  /* We sort in descending order. */
+  return a.time > b.time;
+}
+
 bool namedTimeSampleEntryComparator(const NamedNestedSampleStats &a,
                                     const NamedNestedSampleStats &b)
 {
@@ -55,6 +61,14 @@ NamedSizeEntry::NamedSizeEntry(const string &name, size_t size) : name(name), si
 {
 }
 
+NamedTimeEntry::NamedTimeEntry() : name(""), time(0)
+{
+}
+
+NamedTimeEntry::NamedTimeEntry(const string &name, double time) : name(name), time(time)
+{
+}
+
 /* Named size statistics. */
 
 NamedSizeStats::NamedSizeStats() : total_size(0)
@@ -87,6 +101,20 @@ string NamedSizeStats::full_report(int indent_level)
   return result;
 }
 
+string NamedTimeStats::full_report(int indent_level)
+{
+  const string indent(indent_level * kIndentNumSpaces, ' ');
+  const string double_indent = indent + indent;
+  string result = "";
+  result += string_printf("%sTotal time: %fs\n", indent.c_str(), total_time);
+  sort(entries.begin(), entries.end(), namedTimeEntryComparator);
+  foreach (const NamedTimeEntry &entry, entries) {
+    result += string_printf(
+        "%s%-40s %fs\n", double_indent.c_str(), entry.name.c_str(), entry.time);
+  }
+  return result;
+}
+
 /* Named time sample statistics. */
 
 NamedNestedSampleStats::NamedNestedSampleStats() : name(""), self_samples(0), sum_samples(0)
@@ -317,4 +345,55 @@ string RenderStats::full_report()
   return result;
 }
 
+NamedTimeStats::NamedTimeStats() : total_time(0.0)
+{
+}
+
+string UpdateTimeStats::full_report(int indent_level)
+{
+  return times.full_report(indent_level + 1);
+}
+
+SceneUpdateStats::SceneUpdateStats()
+{
+}
+
+string SceneUpdateStats::full_report()
+{
+  string result = "";
+  result += "Scene:\n" + scene.full_report(1);
+  result += "Geometry:\n" + geometry.full_report(1);
+  result += "Light:\n" + light.full_report(1);
+  result += "Object:\n" + object.full_report(1);
+  result += "Image:\n" + image.full_report(1);
+  result += "Background:\n" + background.full_report(1);
+  result += "Bake:\n" + bake.full_report(1);
+  result += "Camera:\n" + camera.full_report(1);
+  result += "Film:\n" + film.full_report(1);
+  result += "Integrator:\n" + integrator.full_report(1);
+  result += "OSL:\n" + osl.full_report(1);
+  result += "Particles:\n" + particles.full_report(1);
+  result += "SVM:\n" + svm.full_report(1);
+  result += "Tables:\n" + tables.full_report(1);
+  return result;
+}
+
+void SceneUpdateStats::clear()
+{
+  geometry.times.entries.clear();
+  image.times.entries.clear();
+  light.times.entries.clear();
+  object.times.entries.clear();
+  background.times.entries.clear();
+  bake.times.entries.clear();
+  camera.times.entries.clear();
+  film.times.entries.clear();
+  integrator.times.entries.clear();
+  osl.times.entries.clear();
+  particles.times.entries.clear();
+  scene.times.entries.clear();
+  svm.times.entries.clear();
+  tables.times.entries.clear();
+}
+
 CCL_NAMESPACE_END
diff --git a/intern/cycles/render/stats.h b/intern/cycles/render/stats.h
index e45403a3754..5dca6dd0b01 100644
--- a/intern/cycles/render/stats.h
+++ b/intern/cycles/render/stats.h
@@ -41,6 +41,15 @@ class NamedSizeEntry {
   size_t size;
 };
 
+class NamedTimeEntry {
+ public:
+  NamedTimeEntry();
+  NamedTimeEntry(const string &name, double time);
+
+  string name;
+  double time;
+};
+
 /* Container of named size entries. Used, for example, to store per-mesh memory
  * usage statistics. But also keeps track of overall memory usage of the
  * container.
@@ -64,6 +73,29 @@ class NamedSizeStats {
   vector<NamedSizeEntry> entries;
 };
 
+class NamedTimeStats {
+ public:
+  NamedTimeStats();
+
+  /* Add entry to the statistics. */
+  void add_entry(const NamedTimeEntry &entry)
+  {
+    total_time += entry.time;
+    entries.push_back(entry);
+  }
+
+  /* Generate full human-readable report. */
+  string full_report(int indent_level = 0);
+
+  /* Total time of all entries. */
+  double total_time;
+
+  /* NOTE: Is fine to read directly, but for adding use add_entry(), which
+   * makes sure all accumulating  values are properly updated.
+   */
+  vector<NamedTimeEntry> entries;
+};
+
 class NamedNestedSampleStats {
  public:
   NamedNestedSampleStats();
@@ -155,6 +187,38 @@ class RenderStats {
   NamedSampleCountStats objects;
 };
 
+class UpdateTimeStats {
+ public:
+  /* Generate full human-readable report. */
+  string full_report(int indent_level = 0);
+
+  NamedTimeStats times;
+};
+
+class SceneUpdateStats {
+ public:
+  SceneUpdateStats();
+
+  UpdateTimeStats geometry;
+  UpdateTimeStats image;
+  UpdateTimeStats light;
+  UpdateTimeStats object;
+  UpdateTimeStats background;
+  UpdateTimeStats bake;
+  UpdateTimeStats camera;
+  UpdateTimeStats film;
+  UpdateTimeStats integrator;
+  UpdateTimeStats osl;
+  UpdateTimeStats particles;
+  UpdateTimeStats scene;
+  UpdateTimeStats svm;
+  UpdateTimeStats tables;
+
+  string full_report();
+
+  void clear();
+};
+
 CCL_NAMESPACE_END
 
 #endif /* __RENDER_STATS_H__ */
diff --git a/intern/cycles/render/svm.cpp b/intern/cycles/render/svm.cpp
index 88714e20a90..d66744d06be 100644
--- a/intern/cycles/render/svm.cpp
+++ b/intern/cycles/render/svm.cpp
@@ -23,6 +23,7 @@
 #include "render/nodes.h"
 #include "render/scene.h"
 #include "render/shader.h"
+#include "render/stats.h"
 #include "render/svm.h"
 
 #include "util/util_foreach.h"
@@ -76,6 +77,12 @@ void SVMShaderManager::device_update(Device *device,
   if (!need_update)
     return;
 
+  scoped_callback_timer timer([scene](double time) {
+    if (scene->update_stats) {
+      scene->update_stats->svm.times.add_entry({"device_update", time});
+    }
+  });
+
   const int num_shaders = scene->shaders.size();
 
   VLOG(1) << "Total " << num_shaders << " shaders.";
diff --git a/intern/cycles/render/tables.cpp b/intern/cycles/render/tables.cpp
index 270e05abe29..b581537c852 100644
--- a/intern/cycles/render/tables.cpp
+++ b/intern/cycles/render/tables.cpp
@@ -17,8 +17,10 @@
 #include "render/tables.h"
 #include "device/device.h"
 #include "render/scene.h"
+#include "render/stats.h"
 
 #include "util/util_logging.h"
+#include "util/util_time.h"
 
 CCL_NAMESPACE_BEGIN
 
@@ -34,11 +36,17 @@ LookupTables::~LookupTables()
   assert(lookup_tables.size() == 0);
 }
 
-void LookupTables::device_update(Device *, DeviceScene *dscene)
+void LookupTables::device_update(Device *, DeviceScene *dscene, Scene *scene)
 {
   if (!need_update)
     return;
 
+  scoped_callback_timer timer([scene](double time) {
+    if (scene->update_stats) {
+      scene->update_stats->tables.times.add_entry({"device_update", time});
+    }
+  });
+
   VLOG(1) << "Total " << lookup_tables.size() << " lookup tables.";
 
   if (lookup_tables.size() > 0)
diff --git a/intern/cycles/render/tables.h b/intern/cycles/render/tables.h
index 3ed2959ae59..e912d9c01f4 100644
--- a/intern/cycles/render/tables.h
+++ b/intern/cycles/render/tables.h
@@ -42,7 +42,7 @@ class LookupTables {
   LookupTables();
   ~LookupTables();
 
-  void device_update(Device *device, DeviceScene *dscene);
+  void device_update(Device *device, DeviceScene *dscene, Scene *scene);
   void device_free(Device *device, DeviceScene *dscene);
 
   size_t add_table(DeviceScene *dscene, vector<float> &data);
diff --git a/intern/cycles/util/util_time.h b/intern/cycles/util/util_time.h
index bc9a7414312..a82d400a0d7 100644
--- a/intern/cycles/util/util_time.h
+++ b/intern/cycles/util/util_time.h
@@ -17,6 +17,7 @@
 #ifndef __UTIL_TIME_H__
 #define __UTIL_TIME_H__
 
+#include "util/util_function.h"
 #include "util/util_string.h"
 
 CCL_NAMESPACE_BEGIN
@@ -60,6 +61,26 @@ class scoped_timer {
   double time_start_;
 };
 
+class scoped_callback_timer {
+ public:
+  using callback_type = function<void(double)>;
+
+  explicit scoped_callback_timer(callback_type cb) : cb(cb)
+  {
+  }
+
+  ~scoped_callback_timer()
+  {
+    if (cb) {
+      cb(timer.get_time());
+    }
+  }
+
+ protected:
+  scoped_timer timer;
+  callback_type cb;
+};
+
 /* Make human readable string from time, compatible with Blender metadata. */
 
 string time_human_readable_from_seconds(const double seconds);