ProxyRenderDelegate::update() being called twice for each frame during playback

[csyshing]

Hi,

I was looking into a Maya playback performance issue, found that one of the expensive calls is engine.Execute() which is triggered due to render tags are marked as dirty in _UpdateRenderTags() , if attaching gdb to ProxyRenderDelegate::update(), I noticed that this method is being called twice for each frame, one from TanimIdleCmd::refreshViews (viewMode=kPlaybackViewActive) (see stack trace frame 20), the other from TanimIdleCmd::refreshViews (viewMode=viewMode@entry=kPlaybackViewAll) (see stack trace frame 20):

The first run:

#0  pxrInternal_v0_20__pxrReserved__::ProxyRenderDelegate::update (this=0x1562d090, container=..., frameContext=...) at maya-usd/lib/mayaUsd/render/vp2RenderDelegate/proxyRenderDelegate.cpp:869
#1  0x00007fffaa32bfcf in MHWRender::THsubSceneEvaluator::update (nodes=..., this=0x156e2c70) at /local/S/Maya_2022PFix_DI/src/Maya/src/OpenMayaRender/Render/THsubSceneEvaluator.cpp:116
#2  MHWRender::THsubSceneEvaluator::update (this=0x156e2c70, nodes=...) at /local/S/Maya_2022PFix_DI/src/Maya/src/OpenMayaRender/Render/THsubSceneEvaluator.cpp:110
#3  0x00007ffff79c1719 in OGSSubSceneItem::update (this=<optimized out>) at /local/S/Maya_2022PFix_DI/src/Maya/src/OGSMayaBridge/ObjectManagement/OGSSubSceneItem.cpp:305
#4  0x00007ffff7baecb9 in OGSMayaSubSceneManager::updateSubScene (this=this@entry=0x9fabc48, subSceneItem=...) at /local/S/Maya_2022PFix_DI/src/Maya/src/OGSMayaBridge/Translators/SubScene/OGSMayaSubSceneManager.cpp:100
#5  0x00007ffff7baeba9 in OGSMayaSubSceneManager::UpdateAllSubScenes (this=0x9fabc48) at /local/S/Maya_2022PFix_DI/src/Maya/src/OGSMayaBridge/Translators/SubScene/OGSMayaSubSceneManager.cpp:81
#6  0x00007ffff7a0910f in OGSUpdateVisibilityTask::performExecute (this=this@entry=0x7fffffff4ed0) at /local/S/Maya_2022PFix_DI/src/Maya/src/OGSMayaBridge/TaskManagement/OGSUpdateVisibilityTask.cpp:269
#7  0x00007ffff7a08947 in OGSUpdateVisibilityTask::getResult (this=0x7fffffff4ed0) at /local/S/Maya_2022PFix_DI/src/Maya/src/OGSMayaBridge/TaskManagement/OGSUpdateVisibilityTask.h:50
#8  OGSUpdateTask::performExecute (this=this@entry=0x7fffffff4fe0) at /local/S/Maya_2022PFix_DI/src/Maya/src/OGSMayaBridge/TaskManagement/OGSUpdateTask.cpp:100
#9  0x00007ffff79882ba in OGSUpdateTask::getResult (this=0x7fffffff4fe0) at /local/S/Maya_2022PFix_DI/src/Maya/src/OGSMayaBridge/TaskManagement/OGSUpdateTask.h:37
#10 OGSApplicationBridge::UpdateScene (this=0x9fab8d0, additionalWork=additionalWork@entry=0x7fffffff50b0) at /local/S/Maya_2022PFix_DI/src/Maya/src/OGSMayaBridge/ObjectManagement/OGSApplicationBridge.cpp:528
#11 0x00007ffff79e559e in OGSMayaRenderer::updateScene (this=0x9a2ae40, additionalWork=additionalWork@entry=0x7fffffff50b0, sceneUpdated=sceneUpdated@entry=0x0) at /local/S/Maya_2022PFix_DI/src/Maya/src/OGSMayaBridge/Renderers/OGSMayaRenderer.cpp:975
#12 0x00007ffff79df2cd in OGSMayaBaseRenderer::performSceneRender (this=this@entry=0x9982390, sceneOp=sceneOp@entry=0x0, sceneUpdated=sceneUpdated@entry=0x0) at /local/S/Maya_2022PFix_DI/src/Maya/src/OGSMayaBridge/Renderers/OGSMayaBaseRenderer.cpp:502
#13 0x00007ffff79ff5e9 in OGSViewportRenderer::performSceneRender (sceneUpdated=0x0, sceneOp=0x0, this=0x9982390) at /local/S/Maya_2022PFix_DI/src/Maya/src/OGSMayaBridge/Renderers/OGSViewportRenderer.cpp:936
#14 OGSViewportRenderer::performSceneRender (sceneUpdated=0x0, sceneOp=0x0, this=0x9982390) at /local/S/Maya_2022PFix_DI/src/Maya/src/OGSMayaBridge/Renderers/OGSViewportRenderer.cpp:924
#15 OGSViewportRenderer::performRender (this=0x9982390, info=...) at /local/S/Maya_2022PFix_DI/src/Maya/src/OGSMayaBridge/Renderers/OGSViewportRenderer.cpp:1368
#16 0x00007ffff7a05b99 in non-virtual thunk to OGSViewportRenderer::render(ThardwareRenderInfo const&) () at /local/S/Maya_2022PFix_DI/src/Maya/src/Components/OGS/SDK/Include/internal/OGS/Objects/ObjectModel.h:822
#17 0x00007ffff0aeb523 in TidleRefreshCmd::refreshOGSRender (view=0x111257f0, presentBuffer=<optimized out>, shadedActiveOnly=<optimized out>, disp=<optimized out>, reduceLOD=<optimized out>, usingOffscreen=<optimized out>, forOverlay=false)
    at /local/S/Maya_2022PFix_DI/src/Maya/src/DataModelUI/Draw/refresh/TidleRefreshCmd.cpp:1189
#18 0x00007ffff0aeaf6e in TidleRefreshCmd::refresh (myView=myView@entry=0x111257f0, disp=<optimized out>, disp@entry=kGouraudShaded, refreshBackGround=<optimized out>, presentBuffer=presentBuffer@entry=true, shadedActiveOnly=<optimized out>, reduceLOD=<optimized out>, 
    usingOffscreen=false, forOverlay=false) at /local/S/Maya_2022PFix_DI/src/Maya/src/DataModelUI/Draw/refresh/TidleRefreshCmd.cpp:940
#19 0x00007ffff0ae7ed4 in TtoolRefresh::refresh (this=this@entry=0x7fffffff57a0, view=0x111257f0, usingOffscreen=usingOffscreen@entry=false, forcing=<optimized out>, forcing@entry=false) at /local/S/Maya_2022PFix_DI/src/Maya/src/DataModelUI/Draw/refresh/TtoolRefresh.cpp:377
#20 0x00007ffff316fb42 in TanimIdleCmd::refreshViews (viewMode=kPlaybackViewActive) at /local/S/Maya_2022PFix_DI/src/Maya/src/Shared/AnimBase/TanimIdleCmd/TanimIdleCmd.cpp:469
#21 0x00007ffff31a358f in TcurrentTimeCmd::viewTime (whichTime=..., dirty=true, respectViewMode=<optimized out>) at /local/S/Maya_2022PFix_DI/src/Maya/src/Shared/Commands/TcurrentTimeAction/TcurrentTimeCmd.cpp:327
#22 TcurrentTimeCmd::viewTime (whichTime=..., dirty=<optimized out>, respectViewMode=<optimized out>) at /local/S/Maya_2022PFix_DI/src/Maya/src/Shared/Commands/TcurrentTimeAction/TcurrentTimeCmd.cpp:290
#23 0x00007fffa9df6980 in TtimeControl::notifyNewValue (this=<optimized out>, finalize=<optimized out>) at /local/S/Maya_2022PFix_DI/src/Maya/src/AnimUISlice/UI/TtimeControl/TtimeControl.cpp:4126
#24 0x00007fffa9df4751 in TtimeControl::handleDrag (this=0xf90fa00, frameTime=<optimized out>) at /local/S/Maya_2022PFix_DI/src/Maya/src/AnimUISlice/UI/TtimeControl/TtimeControl.cpp:3280
#25 0x00007fffa9df4e45 in TtimeControl::mouseMoveEvent (this=0xf90fa00, event=0x7fffffff5e60) at /local/S/Maya_2022PFix_DI/src/Maya/src/AnimUISlice/UI/TtimeControl/TtimeControl.cpp:3467
#26 0x00007fffa9e00246 in TtimePort::mousePressEvent (this=this@entry=0xf90fa00, event=event@entry=0x7fffffff5e60) at /local/S/Maya_2022PFix_DI/src/Maya/src/AnimUISlice/UI/TtimePort/TtimePort.cpp:991
#27 0x00007fffa9df3d9b in TtimeControl::mousePressEvent (this=0xf90fa00, event=0x7fffffff5e60) at /local/S/Maya_2022PFix_DI/src/Maya/src/AnimUISlice/UI/TtimeControl/TtimeControl.cpp:3025

The second run:

#0  pxrInternal_v0_20__pxrReserved__::ProxyRenderDelegate::update (this=0x1562d090, container=..., frameContext=...) at maya-usd/lib/mayaUsd/render/vp2RenderDelegate/proxyRenderDelegate.cpp:869
#1  0x00007fffaa32bfcf in MHWRender::THsubSceneEvaluator::update (nodes=..., this=0x156e2c70) at /local/S/Maya_2022PFix_DI/src/Maya/src/OpenMayaRender/Render/THsubSceneEvaluator.cpp:116
#2  MHWRender::THsubSceneEvaluator::update (this=0x156e2c70, nodes=...) at /local/S/Maya_2022PFix_DI/src/Maya/src/OpenMayaRender/Render/THsubSceneEvaluator.cpp:110
#3  0x00007ffff79c1719 in OGSSubSceneItem::update (this=<optimized out>) at /local/S/Maya_2022PFix_DI/src/Maya/src/OGSMayaBridge/ObjectManagement/OGSSubSceneItem.cpp:305
#4  0x00007ffff7baecb9 in OGSMayaSubSceneManager::updateSubScene (this=this@entry=0x9fabc48, subSceneItem=...) at /local/S/Maya_2022PFix_DI/src/Maya/src/OGSMayaBridge/Translators/SubScene/OGSMayaSubSceneManager.cpp:100
#5  0x00007ffff7baeba9 in OGSMayaSubSceneManager::UpdateAllSubScenes (this=0x9fabc48) at /local/S/Maya_2022PFix_DI/src/Maya/src/OGSMayaBridge/Translators/SubScene/OGSMayaSubSceneManager.cpp:81
#6  0x00007ffff7a0910f in OGSUpdateVisibilityTask::performExecute (this=this@entry=0x7fffffff4fe0) at /local/S/Maya_2022PFix_DI/src/Maya/src/OGSMayaBridge/TaskManagement/OGSUpdateVisibilityTask.cpp:269
#7  0x00007ffff7a08947 in OGSUpdateVisibilityTask::getResult (this=0x7fffffff4fe0) at /local/S/Maya_2022PFix_DI/src/Maya/src/OGSMayaBridge/TaskManagement/OGSUpdateVisibilityTask.h:50
#8  OGSUpdateTask::performExecute (this=this@entry=0x7fffffff50f0) at /local/S/Maya_2022PFix_DI/src/Maya/src/OGSMayaBridge/TaskManagement/OGSUpdateTask.cpp:100
#9  0x00007ffff79882ba in OGSUpdateTask::getResult (this=0x7fffffff50f0) at /local/S/Maya_2022PFix_DI/src/Maya/src/OGSMayaBridge/TaskManagement/OGSUpdateTask.h:37
#10 OGSApplicationBridge::UpdateScene (this=0x9fab8d0, additionalWork=additionalWork@entry=0x7fffffff51c0) at /local/S/Maya_2022PFix_DI/src/Maya/src/OGSMayaBridge/ObjectManagement/OGSApplicationBridge.cpp:528
#11 0x00007ffff79e559e in OGSMayaRenderer::updateScene (this=0x9a2ae40, additionalWork=additionalWork@entry=0x7fffffff51c0, sceneUpdated=sceneUpdated@entry=0x0) at /local/S/Maya_2022PFix_DI/src/Maya/src/OGSMayaBridge/Renderers/OGSMayaRenderer.cpp:975
#12 0x00007ffff79df2cd in OGSMayaBaseRenderer::performSceneRender (this=this@entry=0x9982390, sceneOp=sceneOp@entry=0x0, sceneUpdated=sceneUpdated@entry=0x0) at /local/S/Maya_2022PFix_DI/src/Maya/src/OGSMayaBridge/Renderers/OGSMayaBaseRenderer.cpp:502
#13 0x00007ffff79ff5e9 in OGSViewportRenderer::performSceneRender (sceneUpdated=0x0, sceneOp=0x0, this=0x9982390) at /local/S/Maya_2022PFix_DI/src/Maya/src/OGSMayaBridge/Renderers/OGSViewportRenderer.cpp:936
#14 OGSViewportRenderer::performSceneRender (sceneUpdated=0x0, sceneOp=0x0, this=0x9982390) at /local/S/Maya_2022PFix_DI/src/Maya/src/OGSMayaBridge/Renderers/OGSViewportRenderer.cpp:924
#15 OGSViewportRenderer::performRender (this=0x9982390, info=...) at /local/S/Maya_2022PFix_DI/src/Maya/src/OGSMayaBridge/Renderers/OGSViewportRenderer.cpp:1368
#16 0x00007ffff7a05b99 in non-virtual thunk to OGSViewportRenderer::render(ThardwareRenderInfo const&) () at /local/S/Maya_2022PFix_DI/src/Maya/src/Components/OGS/SDK/Include/internal/OGS/Objects/ObjectModel.h:822
#17 0x00007ffff0aeb523 in TidleRefreshCmd::refreshOGSRender (view=0x111257f0, presentBuffer=<optimized out>, shadedActiveOnly=<optimized out>, disp=<optimized out>, reduceLOD=<optimized out>, usingOffscreen=<optimized out>, forOverlay=false)
    at /local/S/Maya_2022PFix_DI/src/Maya/src/DataModelUI/Draw/refresh/TidleRefreshCmd.cpp:1189
#18 0x00007ffff0aeaf6e in TidleRefreshCmd::refresh (myView=myView@entry=0x111257f0, disp=<optimized out>, disp@entry=kGouraudShaded, refreshBackGround=<optimized out>, presentBuffer=presentBuffer@entry=true, shadedActiveOnly=<optimized out>, reduceLOD=<optimized out>, 
    usingOffscreen=false, forOverlay=false) at /local/S/Maya_2022PFix_DI/src/Maya/src/DataModelUI/Draw/refresh/TidleRefreshCmd.cpp:940
#19 0x00007ffff0ae7ed4 in TtoolRefresh::refresh (this=this@entry=0x7fffffff58b0, view=0x111257f0, usingOffscreen=usingOffscreen@entry=false, forcing=<optimized out>, forcing@entry=false) at /local/S/Maya_2022PFix_DI/src/Maya/src/DataModelUI/Draw/refresh/TtoolRefresh.cpp:377
#20 0x00007ffff316fb42 in TanimIdleCmd::refreshViews (viewMode=viewMode@entry=kPlaybackViewAll) at /local/S/Maya_2022PFix_DI/src/Maya/src/Shared/AnimBase/TanimIdleCmd/TanimIdleCmd.cpp:469
#21 0x00007ffff31a3421 in TcurrentTimeCmd::finalize (this=this@entry=0x1577d900) at /local/S/Maya_2022PFix_DI/src/Maya/src/Shared/Commands/TcurrentTimeAction/TcurrentTimeCmd.cpp:213
#22 0x00007fffa9df69b9 in TtimeControl::notifyNewValue (this=0xf90fa00, finalize=<optimized out>) at /local/S/Maya_2022PFix_DI/src/Maya/src/AnimUISlice/UI/TtimeControl/TtimeControl.cpp:4115
#23 0x00007fffa9e0091d in TtimePort::mouseReleaseEvent (this=this@entry=0xf90fa00, event=event@entry=0x7fffffff5e60) at /local/S/Maya_2022PFix_DI/src/Maya/src/AnimUISlice/UI/TtimePort/TtimePort.cpp:1162
#24 0x00007fffa9df3597 in TtimeControl::mouseReleaseEvent (this=0xf90fa00, event=0x7fffffff5e60) at /local/S/Maya_2022PFix_DI/src/Maya/src/AnimUISlice/UI/TtimeControl/TtimeControl.cpp:2856
#25 0x00007fffee711376 in QWidget::event (this=this@entry=0xf90fa00, event=event@entry=0x7fffffff5e60) at kernel/qwidget.cpp:9019
#26 0x00007fffa9deb319 in TtimeControl::event (this=0xf90fa00, event=0x7fffffff5e60) at /local/S/Maya_2022PFix_DI/src/Maya/src/AnimUISlice/UI/TtimeControl/TtimeControl.cpp:485
#27 0x00007fffee6d16ff in QApplicationPrivate::notify_helper (this=this@entry=0x3747fd0, receiver=receiver@entry=0xf90fa00, e=e@entry=0x7fffffff5e60) at kernel/qapplication.cpp:3632

This side effect of having ProxyRenderDelegate::update() being called twice caused _UpdateRenderTags() being called twice as well, and then engine.Execute() would be also run twice.

My questions:

• ProxyRenderDelegate is inherited from MPxSubSceneOverride, is it by design that update() method should be called twice for each frame?
• Any improvement could be done to avoid running engine.Execute() two times?

Thanks,
Zhicheng

[williamkrick]

Hi @csyshing,

The second callstack you posted is coming through TtimeControl::mouseReleaseEvent(). I think that the workflow you captured was clicking on Maya's timeline, is that correct? Maya does an extra refresh when the mouse is released after the timeline is scrubbed or clicked on, which is what I think you are seeing here. I think if you are displaying a single viewport and playback the scene, or scrub the timeline while holding the mouse down you should see one call to update() per time displayed.

Maya is expecting to be able to call MPxSubSceneOverride::update() multiple times a frame without paying a significant performance cost. This is necessary when Maya is displaying multiple viewports at the same time. The MPxSubSceneOverride should be tracking what has changed and only doing a minimal update.

I think our intent is that _UpdateRenderTags() only marks things dirty if render tags change in some way, and that the call to _engine.Execute() will be fast when nothing is dirty. Based on your question I'm guessing _UpdateRenderTags() is marking rprims dirty every time it is called, and that causes _engine.Execute() to have something to do and not be fast.

What exactly is happening inside the calls to _UpdateRenderTags()? Can you create a sharable file which can reproduce this issue?

William

[csyshing]

@williamkrick Yes, I clicked on Maya's timeline, I was trying to reduce the trace log message but wasn't aware there's a difference between clicking and continuously playing.

The scene for testing is a very large and complicate scene, I think I will dig into _engine.Execute() to see if there is anything we can do.

Thanks for the explanation of MPxSubSceneOverride::update()!