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 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(geom); - - /* Update normals. */ - mesh->add_face_normals(); - mesh->add_vertex_normals(); - - if (mesh->need_attribute(scene, ATTR_STD_POSITION_UNDISPLACED)) { - mesh->add_undisplaced(); + foreach (Geometry *geom, scene->geometry) { + foreach (Shader *shader, geom->used_shaders) { + if (shader->need_update_geometry) + geom->need_update = 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 (geom->need_update && (geom->type == Geometry::MESH || geom->type == Geometry::VOLUME)) { + Mesh *mesh = static_cast(geom); - /* Test if we need displacement. */ - if (mesh->has_true_displacement()) { - true_displacement_used = true; - } + /* Update normals. */ + mesh->add_face_normals(); + mesh->add_vertex_normals(); - if (progress.get_cancel()) - return; + if (mesh->need_attribute(scene, ATTR_STD_POSITION_UNDISPLACED)) { + mesh->add_undisplaced(); + } + + /* Test if we need tessellation. */ + if (mesh->subdivision_type != Mesh::SUBDIVISION_NONE && mesh->num_subd_verts == 0 && + mesh->subd_params) { + total_tess_needed++; + } + + /* 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; - - /* 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()); - - foreach (Geometry *geom, scene->geometry) { - if (geom->need_update) { - if (geom->type == Geometry::MESH) { - Mesh *mesh = static_cast(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 (attributes)", time}); } - - if (geom->need_build_bvh(bvh_layout)) { - num_bvh++; - } - } - + }); + device_update_attributes(device, dscene, scene, progress); if (progress.get_cancel()) return; } + /* Update displacement. */ + 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; + + { + 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(geom); + if (displace(device, dscene, scene, mesh, progress)) { + displacement_done = true; + } + } + + if (geom->need_build_bvh(bvh_layout)) { + num_bvh++; + } + } + + 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 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 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 ¶ms_, 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 ¶ms, 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 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 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 &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; + + 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);