Add trace functions in the render delegate hot spots

SConstruct

@@ -127,6 +127,7 @@ vars.AddVariables(
     BoolVariable('ENABLE_HYDRA_IN_USD_PROCEDURAL', 'Enable building hydra render delegate in the usd procedural', True),
     BoolVariable('ENABLE_SHARED_ARRAYS', 'Enable the use of shared arrays in hydra', False),
     BoolVariable('ENABLE_HYDRA2_RENDERSETTINGS', 'Enable the use of RenderSettings hydra prim', False),
+    BoolVariable('ENABLE_TRACING', 'Enable USD trace instrumentation (TRACE_FUNCTION/TRACE_SCOPE).', False),
     BoolVariable('BUILD_USDGENSCHEMA_ARNOLD', 'Whether or not to build the simplified usdgenschema', False),
     BoolVariable('IGNORE_ARCH_FLAGS', 'Ignore the arch flags when compiling usdgenschema', False),
     StringVariable('BOOST_LIB_NAME', 'Boost library name pattern', 'boost_%s'),
@@ -379,6 +380,9 @@ env['ENV']['PREFIX_PROCEDURAL'] = os.path.abspath(PREFIX_PROCEDURAL)
 if env['HYDRA_NORMALIZE_DEPTH']:
     env.Append(CPPDEFINES = Split('HYDRA_NORMALIZE_DEPTH'))
 
+if not env['ENABLE_TRACING']:
+    env.Append(CPPDEFINES = [{'TRACE_ENABLE': 0}])
+
 # Compiler settings
 if env['_COMPILER'] in ['gcc', 'clang']:
     env.Append(CCFLAGS = Split('-fno-operator-names -std=c++{}'.format(env['CXX_STANDARD'])))

cmake/utils/options.cmake

@@ -51,6 +51,7 @@ option(ENABLE_HYDRA_IN_USD_PROCEDURAL "Enable hydra in the procedural" ON)
 option(ENABLE_SHARED_ARRAYS "Enable using shared arrays" OFF)
 option(ENABLE_HYDRA2_RENDERSETTINGS "Enable using RenderSetting hydra prim" OFF)
 option(ENABLE_SCENE_INDEX_IN_BUNDLE "Add the scene index filters in the bundle" OFF)
+option(ENABLE_TRACING "Enable USD trace instrumentation (TRACE_FUNCTION/TRACE_SCOPE)." OFF)
 option(HYDRA_NORMALIZE_DEPTH "If true, return a normalized depth by using the P AOV. Otherwise, simply return the Z AOV for the depth" OFF)
 
 set(USD_OVERRIDE_PLUGINPATH_NAME "PXR_PLUGINPATH_NAME" CACHE STRING "Override the plugin path name for the USD libraries. Used when running the testsuite with a static procedural")

libs/common/CMakeLists.txt

@@ -7,7 +7,8 @@ set(COMMON_SRC
     "${CMAKE_CURRENT_SOURCE_DIR}/parameters_utils.cpp"
     "${CMAKE_CURRENT_SOURCE_DIR}/rendersettings_utils.cpp"
     "${CMAKE_CURRENT_SOURCE_DIR}/procedural_reader.cpp"
-    "${CMAKE_CURRENT_SOURCE_DIR}/shape_utils.cpp")
+    "${CMAKE_CURRENT_SOURCE_DIR}/shape_utils.cpp"
+    "${CMAKE_CURRENT_SOURCE_DIR}/trace_utils.cpp")
 
 set(COMMON_HDR
     "${CMAKE_CURRENT_SOURCE_DIR}/api_adapter.h"
@@ -19,7 +20,8 @@ set(COMMON_HDR
     "${CMAKE_CURRENT_SOURCE_DIR}/parameters_utils.h"
     "${CMAKE_CURRENT_SOURCE_DIR}/procedural_reader.h"
     "${CMAKE_CURRENT_SOURCE_DIR}/rendersettings_utils.h"
-    "${CMAKE_CURRENT_SOURCE_DIR}/shape_utils.h")
+    "${CMAKE_CURRENT_SOURCE_DIR}/shape_utils.h"
+    "${CMAKE_CURRENT_SOURCE_DIR}/trace_utils.h")
 
 add_library(common STATIC EXCLUDE_FROM_ALL ${COMMON_SRC})
 

libs/common/SConscript

@@ -26,6 +26,7 @@ source_files = [
     'materials_utils.cpp',
     'rendersettings_utils.cpp',
     'shape_utils.cpp',
+    'trace_utils.cpp',
     'procedural_reader.cpp',
 ]
 

libs/common/procedural_reader.cpp

@@ -4,6 +4,7 @@
 
 #include "procedural_reader.h"
 #include "diagnostic_utils.h"
+#include "trace_utils.h"
 #include <ai.h>
 #include <pxr/usd/usd/stage.h>
 #include <pxr/usd/usdUtils/stageCache.h>
@@ -20,6 +21,7 @@ void ProceduralReader::Read(const std::string &filename,
 {
     // Install diagnostic delegate to capture USD composition errors
     ArnoldUsdDiagnostic diagnostic;
+    ArnoldUsdTraceDiagnostic traceDiagnostic;
 
     // Nodes were already exported, should we skip here,
     // or should we just append the new nodes ?
@@ -87,6 +89,7 @@ bool ProceduralReader::Read(long int cacheId, const std::string &path)
 {
     // Install diagnostic delegate to capture USD composition errors
     ArnoldUsdDiagnostic diagnostic;
+    ArnoldUsdTraceDiagnostic traceDiagnostic;
 
     if (!GetNodes().empty()) {
         return true;

libs/common/trace_utils.cpp

@@ -0,0 +1,45 @@
+//
+// SPDX-License-Identifier: Apache-2.0
+//
+
+#include "trace_utils.h"
+
+#include <ai.h>
+
+#include <pxr/base/trace/collector.h>
+#include <pxr/base/trace/reporter.h>
+
+#include <cstdlib>
+#include <sstream>
+
+PXR_NAMESPACE_USING_DIRECTIVE
+
+ArnoldUsdTraceDiagnostic::ArnoldUsdTraceDiagnostic()
+{
+    const char *envVar = std::getenv("ARNOLD_USD_TRACE");
+    if (envVar == nullptr || envVar[0] == '\0')
+        return;
+
+    _enabled = true;
+    TraceCollector::GetInstance().SetEnabled(true);
+}
+
+ArnoldUsdTraceDiagnostic::~ArnoldUsdTraceDiagnostic()
+{
+    if (!_enabled)
+        return;
+
+    TraceCollector::GetInstance().SetEnabled(false);
+
+    TraceReporterPtr reporter = TraceReporter::GetGlobalReporter();
+
+    std::ostringstream ss;
+    reporter->ReportTimes(ss);
+    const std::string report = ss.str();
+    if (!report.empty()) {
+        AiMsgInfo("[usd] Trace report:\n%s", report.c_str());
+    }
+
+    reporter->ClearTree();
+    TraceCollector::GetInstance().Clear();
+}

libs/common/trace_utils.h

@@ -0,0 +1,37 @@
+//
+// SPDX-License-Identifier: Apache-2.0
+//
+
+#ifndef TRACE_UTILS_H
+#define TRACE_UTILS_H
+
+/// RAII object that enables USD trace collection on construction and, on
+/// destruction, flushes the collected data to Arnold's log via AiMsgInfo and
+/// then clears the reporter tree.
+///
+/// Activated only when the environment variable ARNOLD_USD_TRACE is set to a
+/// non-empty value, so there is no overhead in normal operation.
+///
+/// Example usage (mirrors ArnoldUsdDiagnostic in diagnostic_utils.h):
+/// \code
+/// void ProceduralReader::Read(...)
+/// {
+///     ArnoldUsdTraceDiagnostic traceDiagnostic;
+///     // ... do work ...
+/// }   // <-- destructor prints the trace report here
+/// \endcode
+///
+class ArnoldUsdTraceDiagnostic
+{
+public:
+    ArnoldUsdTraceDiagnostic();
+    ~ArnoldUsdTraceDiagnostic();
+
+    ArnoldUsdTraceDiagnostic(const ArnoldUsdTraceDiagnostic&) = delete;
+    ArnoldUsdTraceDiagnostic& operator=(const ArnoldUsdTraceDiagnostic&) = delete;
+
+private:
+    bool _enabled = false;
+};
+
+#endif // TRACE_UTILS_H

libs/render_delegate/CMakeLists.txt

@@ -77,6 +77,9 @@ endif()
 if (HYDRA_NORMALIZE_DEPTH)
     target_compile_definitions(render_delegate PUBLIC HYDRA_NORMALIZE_DEPTH=1)
 endif()
+if (NOT ENABLE_TRACING)
+    target_compile_definitions(render_delegate PUBLIC TRACE_ENABLE=0)
+endif()
 
 target_compile_definitions(render_delegate PRIVATE "HDARNOLD_EXPORTS=1")
 if (BUILD_SCENE_INDEX_PLUGIN OR ENABLE_SCENE_INDEX_IN_BUNDLE)

libs/render_delegate/basis_curves.cpp

@@ -16,6 +16,7 @@
 // See the License for the specific language governing permissions and
 // limitations under the License.
 #include "basis_curves.h"
+#include <pxr/base/trace/trace.h>
 
 #include <constant_strings.h>
 #include <shape_utils.h>
@@ -86,6 +87,8 @@ HdArnoldBasisCurves::HdArnoldBasisCurves(HdArnoldRenderDelegate* delegate, const
 void HdArnoldBasisCurves::Sync(
     HdSceneDelegate* sceneDelegate, HdRenderParam* renderParam, HdDirtyBits* dirtyBits, const TfToken& reprToken)
 {
+    AiProfileBlock("hydra_proc:sync:HdArnoldBasisCurves"); 
+    TRACE_FUNCTION();
     if (!GetRenderDelegate()->CanUpdateScene())
         return;
 

libs/render_delegate/instancer.cpp

@@ -17,6 +17,7 @@
 // limitations under the License.
 #include "instancer.h"
 #include "shape_utils.h"
+#include <pxr/base/trace/trace.h>
 #include <pxr/base/gf/quaternion.h>
 #include <pxr/base/gf/rotation.h>
 #include <pxr/imaging/hd/sceneDelegate.h>
@@ -81,6 +82,8 @@ HdArnoldInstancer::HdArnoldInstancer(
 
 void HdArnoldInstancer::Sync(HdSceneDelegate* sceneDelegate, HdRenderParam* renderParam, HdDirtyBits* dirtyBits)
 {
+    AiProfileBlock("hydra_proc:HdArnoldInstancer:Sync"); 
+    TRACE_FUNCTION();
     if (!_delegate->CanUpdateScene())
         return;
 

libs/render_delegate/light.cpp

@@ -32,6 +32,7 @@
 #include "light.h"
 #include "mesh.h"
 #include "instancer.h"
+#include <pxr/base/trace/trace.h>
 
 #include <pxr/usd/usdLux/tokens.h>
 #include <pxr/usd/usdLux/blackbody.h>
@@ -499,6 +500,8 @@ HdArnoldGenericLight::~HdArnoldGenericLight()
 
 void HdArnoldGenericLight::Sync(HdSceneDelegate* sceneDelegate, HdRenderParam* renderParam, HdDirtyBits* dirtyBits)
 {
+    AiProfileBlock("hydra_proc:HdArnoldGenericLight:Sync"); 
+    TRACE_FUNCTION();
 
     if (!_delegate->CanUpdateScene())
         return;

libs/render_delegate/mesh.cpp

@@ -31,6 +31,7 @@
 // limitations under the License.
 #include "mesh.h"
 #include "light.h"
+#include <pxr/base/trace/trace.h>
 
 #include <pxr/base/gf/vec2f.h>
 #include <pxr/imaging/pxOsd/tokens.h>
@@ -201,6 +202,8 @@ HdArnoldMesh::~HdArnoldMesh() {
 void HdArnoldMesh::Sync(
     HdSceneDelegate* sceneDelegate, HdRenderParam* renderParam, HdDirtyBits* dirtyBits, const TfToken& reprToken)
 {
+    AiProfileBlock("hydra_proc:HdArnoldMesh:Sync"); 
+    TRACE_FUNCTION();
     if (!GetRenderDelegate()->CanUpdateScene())
         return;
 

libs/render_delegate/node_graph.cpp

@@ -30,6 +30,7 @@
 // See the License for the specific language governing permissions and
 // limitations under the License.
 #include "node_graph.h"
+#include <pxr/base/trace/trace.h>
 
 #include <pxr/base/gf/rotation.h>
 #include <pxr/base/gf/vec2f.h>
@@ -148,6 +149,8 @@ HdArnoldNodeGraph::~HdArnoldNodeGraph()
 // Root function called to translate a shading NodeGraph primitive
 void HdArnoldNodeGraph::Sync(HdSceneDelegate* sceneDelegate, HdRenderParam* renderParam, HdDirtyBits* dirtyBits)
 {    
+    AiProfileBlock("hydra_proc:HdArnoldNodeGraph:Sync");
+    TRACE_FUNCTION();
     if (!_renderDelegate->CanUpdateScene())
         return;
 
@@ -350,6 +353,8 @@ std::vector<AtNode*> HdArnoldNodeGraph::GetOrCreateTerminals(
 
 AtNode* HdArnoldNodeGraph::ReadMaterialNetwork(const HdMaterialNetwork& network, const TfToken& terminalType, std::vector<SdfPath>& terminals)
 {
+    AiProfileBlock("hydra_proc:HdArnoldNodeGraph:ReadMaterialNetwork");
+    TRACE_FUNCTION();
     // Nothing to translate here
     if (network.nodes.empty())
         return nullptr;

libs/render_delegate/reader.cpp

@@ -6,6 +6,7 @@
 #include <constant_strings.h>
 #include <pxr/base/arch/env.h>
 #include <pxr/base/tf/pathUtils.h>
+#include <pxr/base/trace/trace.h>
 #include <iostream>
 #include <vector>
 #include <iostream>
@@ -268,6 +269,7 @@ void HydraArnoldReader::ReadStage(UsdStageRefPtr stage,
     if (arnoldRenderDelegate == 0)
         return;
     AiProfileBlock("hydra_proc:read_stage"); 
+    TRACE_FUNCTION();
     if (stage == nullptr) {
         AiMsgError("[usd] Unable to create USD stage from %s", _filename.c_str());
         return;
@@ -293,9 +295,13 @@ void HydraArnoldReader::ReadStage(UsdStageRefPtr stage,
                 _renderCameraPath = SdfPath(cameraPrim.GetPath());
         }
 
-        ChooseRenderSettings(stage, _renderSettings, _time);
+        {
+            TRACE_SCOPE("ChooseRenderSettings");
+            ChooseRenderSettings(stage, _renderSettings, _time);
+        }
 // TODO HERE WE COULD CHECK IF WE WANT TO USE HYDRA2
         if (!_renderSettings.empty()) {
+            TRACE_SCOPE("ReadRenderSettings");
             // Sets the default parameters on the Arnold option node (AA_samples, GI_diffuse_depth, ...)
             SetArnoldDefaultOptions(_universe);
 #ifdef ENABLE_HYDRA2_RENDERSETTINGS
@@ -346,35 +352,38 @@ void HydraArnoldReader::ReadStage(UsdStageRefPtr stage,
     SdfPath rootPath = (path.empty()) ? SdfPath::AbsoluteRootPath() : SdfPath(path.c_str());
     UsdPrim rootPrim = stage->GetPrimAtPath(rootPath);
 
-    // We want to render the purpose that this reader was assigned to.
-    // We also support the purposes "default" and "geometry" that are always rendered
-    // so we don't need to provide it here
-    TfTokenVector purpose;
-    purpose.push_back(_purpose);
-    arnoldRenderDelegate->SetRenderTags(purpose);
-
-    // This will return a "hidden" render tag if a primitive is of a disabled type
-    if (_imagingDelegate) {
-        _imagingDelegate->SetDisplayRender(_purpose == UsdGeomTokens->render);
-        _imagingDelegate->SetDisplayProxy(_purpose == UsdGeomTokens->proxy);
-        _imagingDelegate->SetDisplayGuides(_purpose == UsdGeomTokens->guide);
-    }
-
-    if (_useSceneIndex) {
-        if (!path.empty()) {
-            UsdStagePopulationMask mask({SdfPath(path)});
-            stage->SetPopulationMask(mask);
-        }
-        _stageSceneIndex->SetStage(stage);
-    } else {
-        SdfPathVector _excludedPrimPaths; // excluding nothing
-        _imagingDelegate->Populate(rootPrim, _excludedPrimPaths);
-    }
-    if (!path.empty() && !_useSceneIndex) {
-        UsdGeomXformCache xformCache(_imagingDelegate->GetTime());
-        const GfMatrix4d xf = xformCache.GetLocalToWorldTransform(rootPrim);
-        _imagingDelegate->SetRootTransform(xf);
-    }
+    {
+		TRACE_SCOPE("Populate/SetStage");
+		// We want to render the purpose that this reader was assigned to.
+		// We also support the purposes "default" and "geometry" that are always rendered
+		// so we don't need to provide it here
+		TfTokenVector purpose;
+		purpose.push_back(_purpose);
+		arnoldRenderDelegate->SetRenderTags(purpose);
+
+		// This will return a "hidden" render tag if a primitive is of a disabled type
+		if (_imagingDelegate) {
+			_imagingDelegate->SetDisplayRender(_purpose == UsdGeomTokens->render);
+			_imagingDelegate->SetDisplayProxy(_purpose == UsdGeomTokens->proxy);
+			_imagingDelegate->SetDisplayGuides(_purpose == UsdGeomTokens->guide);
+		}
+
+		if (_useSceneIndex) {
+			if (!path.empty()) {
+				UsdStagePopulationMask mask({SdfPath(path)});
+				stage->SetPopulationMask(mask);
+			}
+			_stageSceneIndex->SetStage(stage);
+		} else {
+			SdfPathVector _excludedPrimPaths; // excluding nothing
+			_imagingDelegate->Populate(rootPrim, _excludedPrimPaths);
+		}
+		if (!path.empty() && !_useSceneIndex) {
+			UsdGeomXformCache xformCache(_imagingDelegate->GetTime());
+			const GfMatrix4d xf = xformCache.GetLocalToWorldTransform(rootPrim);
+			_imagingDelegate->SetRootTransform(xf);
+		}
+    } // end TRACE_SCOPE("Populate/SetStage")
 
     // Not sure about the meaning of collection geometry -- should that be extended ?
     _collection = HdRprimCollection (HdTokens->geometry, HdReprSelector(HdReprTokens->hull));
@@ -395,14 +404,23 @@ void HydraArnoldReader::ReadStage(UsdStageRefPtr stage,
     // SdfPathVector root;
     // root.push_back(SdfPath("/"));
     // collection.SetRootPaths(root);
-    _renderIndex->SyncAll(&_tasks, &_taskContext);
-    arnoldRenderDelegate->ProcessConnections();
+    {
+        TRACE_SCOPE("SyncAll");
+        _renderIndex->SyncAll(&_tasks, &_taskContext);
+    }
+    {
+        TRACE_SCOPE("ProcessConnections");
+        arnoldRenderDelegate->ProcessConnections();
+    }
 
     // The scene might not be up to date, because of light links, etc, that were generated during the first sync.
     // HasPendingChanges updates the dirtybits for a resync, this is how it works in our hydra render pass.
-    while (arnoldRenderDelegate->HasPendingChanges(_renderIndex, _renderCameraPath, _shutter)) {
-        _renderIndex->SyncAll(&_tasks, &_taskContext);
-        arnoldRenderDelegate->ProcessConnections();
+    {
+        TRACE_SCOPE("PendingChanges");
+        while (arnoldRenderDelegate->HasPendingChanges(_renderIndex, _renderCameraPath, _shutter)) {
+            _renderIndex->SyncAll(&_tasks, &_taskContext);
+            arnoldRenderDelegate->ProcessConnections();
+        }
     }
 
 #ifndef ENABLE_SHARED_ARRAYS