Details

Reviewers

Brecht Van Lommel (brecht)
Sergey Sharybin (sergey)
Stefan Werner (swerner)

Commits

rCcf6379815493: Add sample-based runtime profiler that measures time spent in various parts of…
rBS7fa6f72084b1: Cycles: Add sample-based runtime profiler that measures time spent in various…
rB7fa6f72084b1: Cycles: Add sample-based runtime profiler that measures time spent in various…

Summary

The actual info that ends up printed is still WIP, but in general I think having this information makes a lot of sense, especially since I don't measure any performance hit.

Right now, it shows a breakdown of the time spent in various parts of the kernel, total time spent on all objects and shaders, and relative cost of shaders and objects (how much time they took vs. how often they were hit).

Diff Detail

Repository

rB Blender

Branch

arcpatch-D3892

Build Status

Buildable 2433
Build 2433: arc lint + arc unit

Event Timeline

Lukas Stockner (lukasstockner97) created this revision.Nov 3 2018, 2:20 AM

Here's an example output of the BMW scene:

bmw_render.log11 KBDownload

Ray Molenkamp (LazyDodo) awarded a token.Nov 3 2018, 3:04 AM

Ray Molenkamp (LazyDodo) rescinded a token.

Ray Molenkamp (LazyDodo) awarded a token.

This looks great, that output is super useful.

Can we avoid creating a profiling thread for every render thread, and have just one? And also keep the same profiling thread for the entire render session? Right now it seems to creating and destroying threads continuously for viewport rendering.

The way I imagined this to work is that it would just be a single thread gathering the stats for all threads, without needing to merge stats.

intern/cycles/util/util_profiling.cpp
63	Do we really need to use a set for this? If the events are next to each other in the enum we can just check if it's within a range.
88	Code style: { on new line.
intern/cycles/util/util_profiling.h
142	Unused variable.

This revision now requires changes to proceed.Nov 3 2018, 1:32 PM

Addressed review.

Can we disable the stats threads when the stats are not needed? Particularly for viewport and icon preview renders.
For GPU rendering the stats are still printed with lots of NaNs. Instead it should print a line about stats not being supported for GPU render.
Under Object Statistics, I see the same name printed many times when there are instances (for example the fishy cat test scene). These should be merged.
What is "Relative Cost" exactly? Is it a percentage, and if so, can we display the "%" symbol next to the number?

Other than that this looks ready to me.

intern/cycles/util/util_profiling.cpp
121	Remove debug print.

This revision now requires changes to proceed.Nov 4 2018, 7:12 PM

Addressed feedback.

The relative cost measures (time spent in a shader)/(times a shader has been hit) relative to the overall time per hit of all shaders. Therefore, it's a measure of how complex the shader is. I guess it could be displayed as percent, but I'm not sure, I'll think about it.

Also, I added profiling output to the Denoiser. Technically this one could be profiled on CUDA/OpenCL as well since it records the events on the host side, but I don't think adding the additional code for handling the special case of only profiling one type is worth it.

Minor comments.

intern/cycles/blender/blender_session.cpp
519–520	For more code sharing with e.g. Cycles standalone, would be good if these 3 lines were moved into a `session->collect_statistics()` function.
intern/cycles/render/session.cpp
736	Put the `is_cpu && background` part of the test to disable profiling here, so it's not Blender specific and doesn't cause accidental performance impact for other Cycles integrations.
intern/cycles/render/stats.cpp
148–149	This has `O(n^2)` complexity, which is a problem when there are many objects. It should use a hash lookup.
264	Capitalize: "Non-local Means".

This revision now requires changes to proceed.Nov 7 2018, 10:46 AM

Lukas Stockner (lukasstockner97) marked 3 inline comments as done.Nov 8 2018, 4:28 AM

Lukas Stockner (lukasstockner97) added inline comments.

intern/cycles/render/session.cpp
736	CPU makes sense but I'm not sure about the `background` part - after all, `params.profiling` is false by default, so other Cycles integrations shouldn't be affected unless they explicitly support it in their code. Enabling it for GPU never makes sense, but someone might want to enable it for viewport rendering so I don't see why we should force it to be disabled here when it's already disabled for Blender and by default for others.
intern/cycles/render/stats.cpp
148–149	I tried that at first but didn't really find a way to implement it nicely. I had another go at it and the result is not too bad now, so I think it's worth it for the performance improvement.

Addressed feedback.

Hey, I was working on something like that too :D

Mine is based on PBRT's profiler, which instead of launching extra threads uses SIGPROF to do the sampling:
https://github.com/mmp/pbrt-v3/blob/master/src/core/stats.cpp#L220

By limiting its sampler to 64 states, PBRT can implement it as a simple atomic integer with little overhead.

Looks good to me now.

SIGPROF is lower overhead I guess, avoiding a thread context switch? I wouldn't mind switching to it when supported (so not on Windows). The current state could be compressed to 64 bits, by using some of the bits from the shader int. Scenes don't have that many shaders anyway.

These kinds of optimizations can be done after this is in master I think.

This revision is now accepted and ready to land.Nov 8 2018, 2:07 PM

Sergey Sharybin (sergey) added inline comments.Nov 8 2018, 2:35 PM

intern/cycles/blender/blender_sync.cpp
964	Why not to move this to a device info?
intern/cycles/kernel/kernel_types.h
1398	TODO(name): Sentence, which starts from a capital and ends with a fullstop,
intern/cycles/render/object.h
65	This is not an `id` i guess, but more like an index. If this is controlled by object, make it private. And in any case, consider adding a comment whether it's "any unique integer value" or is coming from a continuous indices of objects in the ObjectManager. P.S. From reading further, the real name is `index_in_device` (adjust to something shorter if possible), and comment should also state that device update is taking care of this field, and that nobody is supposed to initialize it in order to get Cycles integration to work.
intern/cycles/render/session.h
59	`do_profiling` or `is_profiling` ?
intern/cycles/render/stats.cpp
126–127	`const` ?
128	Comoooon.
intern/cycles/render/stats.h
79	`num_hits` ?
intern/cycles/util/util_profiling.h
100–102	Comment should state what those are indexed by, and what are the stored value are. How often is not descriptive, is it frequency in herz? Total number of events?
106–107	Indexed by ... ?
109	`do_stop_worker` ?

Sergey Sharybin (sergey) requested changes to this revision.Nov 8 2018, 2:35 PM

This revision now requires changes to proceed.Nov 8 2018, 2:35 PM

SIGPROF is interesting, but since it's a process-level signal, it might be a bad idea to set a handler in Cycles which is supposed to be used as a library after all...

I'm not sure what the advantage of having a single 64-bit state would be? I've added a comment in the code that goes into a bit of detail, but I'll add some more here:

The reads/writes that the code currently uses are guaranteed to be atomic on x86/x64 (and ARM afaik) even without explicit atomics/locking
Even on other exotic architectures where this might not be the case it would only show up as individual samples in the wrong event (since the profiler thread checks the values it just read, corrupt event/ids will be ignored), probably not even noticeable in practice
There is no guaranteed memory order, but that doesn't matter since there is no real interdependence between the states (if e.g. an additional field changes its meaning based on the current state, it would matter, but currently that's not the case)
Packing the current state into a compact format would add complexity to the state updates, and I'm trying to keep those as small as possible to minimize the performance impact (since they also run when the profiler isn't used)

intern/cycles/render/stats.h
79	Not really, it refers to the sum of the hits of this entry and all its sub-entries. The naming here is a bit confusing in general (for example, these actually are samples, not hits, I mixed up the labels), the new version should be clearer.

Addressed feedback.

I think this can be committed. There may be a few things where it can be extended (for example, it would be useful to group the scene_intersect calls by primary, diffuse, glossy, etc rays) and we could think of writing the output in a machine-readable format to allow for nice presentations (see https://rmanwiki.pixar.com/display/REN/Diagnostics for example), but the profiling data is already very useful as-is.

Still LGTM as well.

This revision was not accepted when it landed; it landed in state Needs Review.Nov 29 2018, 2:49 AM

Closed by commit rB7fa6f72084b1: Cycles: Add sample-based runtime profiler that measures time spent in various… (authored by Lukas Stockner (lukasstockner97)). · Explain Why

This revision was automatically updated to reflect the committed changes.

Brecht Van Lommel (brecht) mentioned this in D8596: Cycles: add debug logging for timing scene update.Sep 22 2020, 2:18 PM

Cycles: Add sample-based runtime profiler that measures time spent in various parts of the CPU kernel
ClosedPublic
Actions

Details

Diff Detail

Event Timeline

Revision Contents
Changeset List

Diff 12444

intern/cycles/blender/blender_session.cpp

intern/cycles/blender/blender_sync.cpp

intern/cycles/device/device_cpu.cpp

intern/cycles/device/device_denoising.h

intern/cycles/device/device_denoising.cpp

intern/cycles/kernel/CMakeLists.txt

intern/cycles/kernel/bvh/bvh.h

intern/cycles/kernel/kernel_globals.h

intern/cycles/kernel/kernel_passes.h

intern/cycles/kernel/kernel_path.h

intern/cycles/kernel/kernel_path_subsurface.h

intern/cycles/kernel/kernel_path_surface.h

intern/cycles/kernel/kernel_profiling.h

intern/cycles/kernel/kernel_shader.h

intern/cycles/kernel/kernel_types.h

intern/cycles/render/object.h

intern/cycles/render/object.cpp

intern/cycles/render/session.h

intern/cycles/render/session.cpp

intern/cycles/render/shader.cpp

intern/cycles/render/stats.h

intern/cycles/render/stats.cpp

intern/cycles/util/CMakeLists.txt

intern/cycles/util/util_profiling.h

intern/cycles/util/util_profiling.cpp

intern/cycles/util/util_stats.h

Cycles: Add sample-based runtime profiler that measures time spent in various parts of the CPU kernelClosedPublicActions

Details

Diff Detail

Event Timeline

Revision ContentsChangeset List

Diff 12444

intern/cycles/blender/blender_session.cpp

intern/cycles/blender/blender_sync.cpp

intern/cycles/device/device_cpu.cpp

intern/cycles/device/device_denoising.h

intern/cycles/device/device_denoising.cpp

intern/cycles/kernel/CMakeLists.txt

intern/cycles/kernel/bvh/bvh.h

intern/cycles/kernel/kernel_globals.h

intern/cycles/kernel/kernel_passes.h

intern/cycles/kernel/kernel_path.h

intern/cycles/kernel/kernel_path_subsurface.h

intern/cycles/kernel/kernel_path_surface.h

intern/cycles/kernel/kernel_profiling.h

intern/cycles/kernel/kernel_shader.h

intern/cycles/kernel/kernel_types.h

intern/cycles/render/object.h

intern/cycles/render/object.cpp

intern/cycles/render/session.h

intern/cycles/render/session.cpp

intern/cycles/render/shader.cpp

intern/cycles/render/stats.h

intern/cycles/render/stats.cpp

intern/cycles/util/CMakeLists.txt

intern/cycles/util/util_profiling.h

intern/cycles/util/util_profiling.cpp

intern/cycles/util/util_stats.h

Cycles: Add sample-based runtime profiler that measures time spent in various parts of the CPU kernel
ClosedPublic
Actions

Revision Contents
Changeset List