From 49ff0c6b1b8c0d8507902b09e3cbefde50aa49a3 Mon Sep 17 00:00:00 2001 From: Pierre Baillargeon Date: Fri, 23 Dec 2022 12:07:55 -0500 Subject: [PATCH 1/3] MAYA-104552 improve message diagnostics Improve the message batching to be usable for errors too. Also, remove hard-coded crash when we can. We should never explicitly choose crash Maya under the user's feet just because of some-sub-system is unhappy. Errors are fine for those cases. Use the diagnostic batch context in places that caused problems due to the flood of error messages when loading large scene with missing textures or layers. Unfortunately, there are some messages that comes from OGS and which require a Maya fix to avoid flooding the script editor, those cannot be fixed in the plugin. (Well, it would need investigation why the VP2 delegate does what it does and causs those OGS errors.) --- lib/mayaUsd/nodes/proxyShapeBase.cpp | 3 + .../vp2RenderDelegate/proxyRenderDelegate.cpp | 3 + lib/mayaUsd/utils/diagnosticDelegate.cpp | 86 ++++++++++++------- lib/mayaUsd/utils/diagnosticDelegate.h | 4 +- 4 files changed, 62 insertions(+), 34 deletions(-) diff --git a/lib/mayaUsd/nodes/proxyShapeBase.cpp b/lib/mayaUsd/nodes/proxyShapeBase.cpp index f986b5d395..c89c0c6010 100644 --- a/lib/mayaUsd/nodes/proxyShapeBase.cpp +++ b/lib/mayaUsd/nodes/proxyShapeBase.cpp @@ -23,6 +23,7 @@ #include #include #include +#include #include #include #include @@ -509,6 +510,8 @@ void MayaUsdProxyShapeBase::postConstructor() /* virtual */ MStatus MayaUsdProxyShapeBase::compute(const MPlug& plug, MDataBlock& dataBlock) { + UsdMayaDiagnosticBatchContext batchDiagnosticMessages; + if (plug == outTimeAttr || plug.isDynamic()) ProxyAccessor::compute(_usdAccessor, plug, dataBlock); diff --git a/lib/mayaUsd/render/vp2RenderDelegate/proxyRenderDelegate.cpp b/lib/mayaUsd/render/vp2RenderDelegate/proxyRenderDelegate.cpp index bb153a2999..4d803d3d26 100644 --- a/lib/mayaUsd/render/vp2RenderDelegate/proxyRenderDelegate.cpp +++ b/lib/mayaUsd/render/vp2RenderDelegate/proxyRenderDelegate.cpp @@ -23,6 +23,7 @@ #include #include #include +#include #include #include @@ -1190,6 +1191,8 @@ void ProxyRenderDelegate::update(MSubSceneContainer& container, const MFrameCont MProfiler::kColorD_L1, "ProxyRenderDelegate::update"); + UsdMayaDiagnosticBatchContext batchDiagnosticMessages; + // Without a proxy shape we can't do anything if (_proxyShapeData->ProxyShape() == nullptr) return; diff --git a/lib/mayaUsd/utils/diagnosticDelegate.cpp b/lib/mayaUsd/utils/diagnosticDelegate.cpp index d017377376..d0f0048569 100644 --- a/lib/mayaUsd/utils/diagnosticDelegate.cpp +++ b/lib/mayaUsd/utils/diagnosticDelegate.cpp @@ -54,11 +54,20 @@ namespace { class _StatusOnlyDelegate : public UsdUtilsCoalescingDiagnosticDelegate { void IssueWarning(const TfWarning&) override { } + void IssueError(const TfError&) override { } void IssueFatalError(const TfCallContext&, const std::string&) override { } }; class _WarningOnlyDelegate : public UsdUtilsCoalescingDiagnosticDelegate { + void IssueStatus(const TfStatus&) override { } + void IssueError(const TfError&) override { } + void IssueFatalError(const TfCallContext&, const std::string&) override { } +}; + +class _ErrorOnlyDelegate : public UsdUtilsCoalescingDiagnosticDelegate +{ + void IssueWarning(const TfWarning&) override { } void IssueStatus(const TfStatus&) override { } void IssueFatalError(const TfCallContext&, const std::string&) override { } }; @@ -112,8 +121,9 @@ UsdMayaDiagnosticDelegate::~UsdMayaDiagnosticDelegate() void UsdMayaDiagnosticDelegate::IssueError(const TfError& err) { - // Errors are never batched. They should be rare, and in those cases, we - // want to see them separately. + if (_batchCount.load() > 0) { + return; // Batched. + } const auto diagnosticMessage = _FormatDiagnostic(err); @@ -171,7 +181,11 @@ void UsdMayaDiagnosticDelegate::IssueFatalError( void UsdMayaDiagnosticDelegate::InstallDelegate() { if (!ArchIsMainThread()) { - TF_FATAL_CODING_ERROR("Cannot install delegate from secondary thread"); + // Don't crash, but inform user about failure to install + // the USD diagnostic message handler. + TF_RUNTIME_ERROR( + "Cannot install the USD diagnostic message printer from a secondary thread"); + return; } if (_installationCount++ > 0) { @@ -185,7 +199,11 @@ void UsdMayaDiagnosticDelegate::InstallDelegate() void UsdMayaDiagnosticDelegate::RemoveDelegate() { if (!ArchIsMainThread()) { - TF_FATAL_CODING_ERROR("Cannot remove delegate from secondary thread"); + // Don't crash, but inform user about failure to remove + // the USD diagnostic message handler. + TF_RUNTIME_ERROR( + "Cannot remove the USD diagnostic message printer from a secondary thread"); + return; } if (_installationCount == 0 || _installationCount-- > 1) { @@ -208,28 +226,44 @@ int UsdMayaDiagnosticDelegate::GetBatchCount() void UsdMayaDiagnosticDelegate::_StartBatch() { - TF_AXIOM(ArchIsMainThread()); + if (!ArchIsMainThread()) + return; if (_batchCount.fetch_add(1) == 0) { // This is the first _StartBatch; add the batching delegates. _batchedStatuses.reset(new _StatusOnlyDelegate()); _batchedWarnings.reset(new _WarningOnlyDelegate()); + _batchedErrors.reset(new _ErrorOnlyDelegate()); } } void UsdMayaDiagnosticDelegate::_EndBatch() { - TF_AXIOM(ArchIsMainThread()); + if (!ArchIsMainThread()) + return; const int prevValue = _batchCount.fetch_sub(1); if (prevValue <= 0) { - TF_FATAL_ERROR("_EndBatch invoked before _StartBatch"); + TF_RUNTIME_ERROR("_EndBatch invoked before _StartBatch"); } else if (prevValue == 1) { // This is the last _EndBatch; print the diagnostic messages. // and remove the batching delegates. _FlushBatch(); _batchedStatuses.reset(); _batchedWarnings.reset(); + _batchedErrors.reset(); + } +} + +static void flushDiagnostics( + const std::unique_ptr& delegate, + const std::function& printer) +{ + const UsdUtilsCoalescingDiagnosticDelegateVector messages = delegate + ? delegate->TakeCoalescedDiagnostics() + : UsdUtilsCoalescingDiagnosticDelegateVector(); + for (const UsdUtilsCoalescingDiagnosticDelegateItem& item : messages) { + printer(_FormatCoalescedDiagnostic(item)); } } @@ -237,43 +271,31 @@ void UsdMayaDiagnosticDelegate::_FlushBatch() { TF_AXIOM(ArchIsMainThread()); - const UsdUtilsCoalescingDiagnosticDelegateVector statuses = _batchedStatuses - ? _batchedStatuses->TakeCoalescedDiagnostics() - : UsdUtilsCoalescingDiagnosticDelegateVector(); - const UsdUtilsCoalescingDiagnosticDelegateVector warnings = _batchedWarnings - ? _batchedWarnings->TakeCoalescedDiagnostics() - : UsdUtilsCoalescingDiagnosticDelegateVector(); - // Note that we must be in the main thread here, so it's safe to call // displayInfo/displayWarning. - for (const UsdUtilsCoalescingDiagnosticDelegateItem& item : statuses) { - MGlobal::displayInfo(_FormatCoalescedDiagnostic(item)); - } - for (const UsdUtilsCoalescingDiagnosticDelegateItem& item : warnings) { - MGlobal::displayWarning(_FormatCoalescedDiagnostic(item)); - } + flushDiagnostics(_batchedStatuses, MGlobal::displayInfo); + flushDiagnostics(_batchedWarnings, MGlobal::displayWarning); + flushDiagnostics(_batchedErrors, MGlobal::displayError); } UsdMayaDiagnosticBatchContext::UsdMayaDiagnosticBatchContext() : _delegate(_IsDiagnosticBatchingEnabled() ? _sharedDelegate : nullptr) { - TF_DEBUG(PXRUSDMAYA_DIAGNOSTICS).Msg(">> Entering batch context\n"); - if (!ArchIsMainThread()) { - TF_FATAL_CODING_ERROR("Cannot construct context on secondary thread"); - } - if (std::shared_ptr ptr = _delegate.lock()) { - ptr->_StartBatch(); + if (ArchIsMainThread()) { + TF_DEBUG(PXRUSDMAYA_DIAGNOSTICS).Msg(">> Entering batch context\n"); + if (std::shared_ptr ptr = _delegate.lock()) { + ptr->_StartBatch(); + } } } UsdMayaDiagnosticBatchContext::~UsdMayaDiagnosticBatchContext() { - TF_DEBUG(PXRUSDMAYA_DIAGNOSTICS).Msg("!! Exiting batch context\n"); - if (!ArchIsMainThread()) { - TF_FATAL_CODING_ERROR("Cannot destruct context on secondary thread"); - } - if (std::shared_ptr ptr = _delegate.lock()) { - ptr->_EndBatch(); + if (ArchIsMainThread()) { + TF_DEBUG(PXRUSDMAYA_DIAGNOSTICS).Msg("!! Exiting batch context\n"); + if (std::shared_ptr ptr = _delegate.lock()) { + ptr->_EndBatch(); + } } } diff --git a/lib/mayaUsd/utils/diagnosticDelegate.h b/lib/mayaUsd/utils/diagnosticDelegate.h index df52c1e2f6..b091fb399f 100644 --- a/lib/mayaUsd/utils/diagnosticDelegate.h +++ b/lib/mayaUsd/utils/diagnosticDelegate.h @@ -81,6 +81,7 @@ class UsdMayaDiagnosticDelegate : TfDiagnosticMgr::Delegate std::atomic_int _batchCount; std::unique_ptr _batchedStatuses; std::unique_ptr _batchedWarnings; + std::unique_ptr _batchedErrors; UsdMayaDiagnosticDelegate(); @@ -96,8 +97,7 @@ class UsdMayaDiagnosticDelegate : TfDiagnosticMgr::Delegate /// /// Batch contexts must only exist on the main thread (though they will apply /// to any diagnostics issued on secondary threads while they're alive). If -/// they're constructed on secondary threads, they will issue a fatal coding -/// error. +/// they're constructed on secondary threads, they will do nothing. /// /// Batch contexts can be constructed and destructed out of "scope" order, e.g., /// this is allowed: From ccbd437fff02540313eda0805c4aa146327fb392 Mon Sep 17 00:00:00 2001 From: Pierre Baillargeon Date: Fri, 23 Dec 2022 18:42:09 -0500 Subject: [PATCH 2/3] MAYA-104552 make all USD diagnostic be coalesced. - Always accumulate and coalesce messages. - Use a thread to peridodically write messages. - Only write messages if there are some pending and at least a second has passed. - For low-volume messages, this will print all messages. - For high-violumes messages, this avoids a flood of messages. The design goes like this: - All messages are accumulated by the above delegates. - A thread, periodicFlusher, wakes up every second to conditionally flush pending messages. - The condition for flushing are that a forced flush is requested or some messages have been received and one second has elapsed. - Requesting a flushing of accumulated messages is done by queuing a task to be run on idle in the main thread. If a task is already queued, nothing is done. - The main-thread task takes (extract and removes) all accumulted messages and prints them in the script console via MGlobal. - This can only be done in the main thread because that is what MGlobal supports. - Only start to batch message if more than a threshold are received within one second. - Flush directly if flushing is triggered in the main thread. Use the batching context to force a flush of diagnostic messages in unit tests that assert about messages. --- lib/mayaUsd/nodes/proxyShapeBase.cpp | 2 - lib/mayaUsd/python/wrapDiagnosticDelegate.cpp | 27 +- .../render/pxrUsdMayaGL/batchRenderer.cpp | 10 - .../render/pxrUsdMayaGL/batchRenderer.h | 12 - .../render/pxrUsdMayaGL/shapeAdapter.cpp | 4 - .../vp2RenderDelegate/proxyRenderDelegate.cpp | 2 - lib/mayaUsd/utils/diagnosticDelegate.cpp | 505 ++++++++++++------ lib/mayaUsd/utils/diagnosticDelegate.h | 64 +-- .../mayaUsd/utils/testDiagnosticDelegate.py | 47 +- test/lib/ufe/testAttribute.py | 21 +- test/lib/ufe/testAttributes.py | 14 +- test/lib/ufe/testConnections.py | 5 +- .../testUsdExportStripNamespaces.py | 28 +- 13 files changed, 458 insertions(+), 283 deletions(-) diff --git a/lib/mayaUsd/nodes/proxyShapeBase.cpp b/lib/mayaUsd/nodes/proxyShapeBase.cpp index c89c0c6010..5c0aea28a5 100644 --- a/lib/mayaUsd/nodes/proxyShapeBase.cpp +++ b/lib/mayaUsd/nodes/proxyShapeBase.cpp @@ -510,8 +510,6 @@ void MayaUsdProxyShapeBase::postConstructor() /* virtual */ MStatus MayaUsdProxyShapeBase::compute(const MPlug& plug, MDataBlock& dataBlock) { - UsdMayaDiagnosticBatchContext batchDiagnosticMessages; - if (plug == outTimeAttr || plug.isDynamic()) ProxyAccessor::compute(_usdAccessor, plug, dataBlock); diff --git a/lib/mayaUsd/python/wrapDiagnosticDelegate.cpp b/lib/mayaUsd/python/wrapDiagnosticDelegate.cpp index a95b661dd2..bb23f2ba32 100644 --- a/lib/mayaUsd/python/wrapDiagnosticDelegate.cpp +++ b/lib/mayaUsd/python/wrapDiagnosticDelegate.cpp @@ -28,16 +28,26 @@ PXR_NAMESPACE_USING_DIRECTIVE; namespace { -// This exposes UsdMayaDiagnosticBatchContext as a Python "context manager" -// object that can be used with the "with"-statement. +// This exposes a DiagnosticBatchContext as a Python "context manager" +// object that can be used with the "with"-statement to flush diagostic +// messages class _PyDiagnosticBatchContext { public: - void __enter__() { _context.reset(new UsdMayaDiagnosticBatchContext()); } - void __exit__(object, object, object) { _context.reset(); } + _PyDiagnosticBatchContext() { } + _PyDiagnosticBatchContext(int c) + : count(c) + { + } + void __enter__() { UsdMayaDiagnosticDelegate::SetMaximumUnbatchedDiagnostics(count); } + void __exit__(object, object, object) + { + UsdMayaDiagnosticDelegate::Flush(); + UsdMayaDiagnosticDelegate::SetMaximumUnbatchedDiagnostics(100); + } private: - std::unique_ptr _context; + int count = 0; }; } // anonymous namespace @@ -46,11 +56,14 @@ void wrapDiagnosticDelegate() { typedef UsdMayaDiagnosticDelegate This; class_("DiagnosticDelegate", no_init) - .def("GetBatchCount", &This::GetBatchCount) - .staticmethod("GetBatchCount"); + .def("Flush", &This::Flush) + .staticmethod("Flush") + .def("SetMaximumUnbatchedDiagnostics", &This::SetMaximumUnbatchedDiagnostics) + .staticmethod("SetMaximumUnbatchedDiagnostics"); typedef _PyDiagnosticBatchContext Context; class_("DiagnosticBatchContext") + .def(init()) .def("__enter__", &Context::__enter__, return_self<>()) .def("__exit__", &Context::__exit__); } diff --git a/lib/mayaUsd/render/pxrUsdMayaGL/batchRenderer.cpp b/lib/mayaUsd/render/pxrUsdMayaGL/batchRenderer.cpp index 22863948d6..113d6ef600 100644 --- a/lib/mayaUsd/render/pxrUsdMayaGL/batchRenderer.cpp +++ b/lib/mayaUsd/render/pxrUsdMayaGL/batchRenderer.cpp @@ -1374,21 +1374,11 @@ bool UsdMayaGLBatchRenderer::_UpdateIsSelectionPending(const bool isPending) return true; } -void UsdMayaGLBatchRenderer::StartBatchingFrameDiagnostics() -{ - if (!_sharedDiagBatchCtx) { - _sharedDiagBatchCtx.reset(new UsdMayaDiagnosticBatchContext()); - } -} - void UsdMayaGLBatchRenderer::_MayaRenderDidEnd(const MHWRender::MDrawContext* /* context */) { // Completing a viewport render invalidates any previous selection // computation we may have done, so mark a new one as pending. _UpdateIsSelectionPending(true); - - // End any diagnostics batching. - _sharedDiagBatchCtx.reset(); } PXR_NAMESPACE_CLOSE_SCOPE diff --git a/lib/mayaUsd/render/pxrUsdMayaGL/batchRenderer.h b/lib/mayaUsd/render/pxrUsdMayaGL/batchRenderer.h index f5aebc5a5b..fdade16625 100644 --- a/lib/mayaUsd/render/pxrUsdMayaGL/batchRenderer.h +++ b/lib/mayaUsd/render/pxrUsdMayaGL/batchRenderer.h @@ -271,12 +271,6 @@ class UsdMayaGLBatchRenderer MAYAUSD_CORE_PUBLIC inline bool GetObjectSoftSelectEnabled() { return _objectSoftSelectEnabled; } - /// Starts batching all diagnostics until the end of the current frame draw. - /// The batch renderer will automatically release the diagnostics when Maya - /// is done rendering the frame. - MAYAUSD_CORE_PUBLIC - void StartBatchingFrameDiagnostics(); - private: friend class TfSingleton; @@ -479,12 +473,6 @@ class UsdMayaGLBatchRenderer HdxSelectionTrackerSharedPtr _selectionTracker; UsdMayaGLSoftSelectHelper _softSelectHelper; - - /// Shared diagnostic batch context. Used for cases where we want to batch - /// diagnostics across multiple function calls, e.g., batching all of the - /// Sync() diagnostics across all prepareForDraw() callbacks in a single - /// frame. - std::unique_ptr _sharedDiagBatchCtx; }; MAYAUSD_TEMPLATE_CLASS(TfSingleton); diff --git a/lib/mayaUsd/render/pxrUsdMayaGL/shapeAdapter.cpp b/lib/mayaUsd/render/pxrUsdMayaGL/shapeAdapter.cpp index 3aed576a09..fb862db132 100644 --- a/lib/mayaUsd/render/pxrUsdMayaGL/shapeAdapter.cpp +++ b/lib/mayaUsd/render/pxrUsdMayaGL/shapeAdapter.cpp @@ -98,8 +98,6 @@ bool PxrMayaHdShapeAdapter::Sync( { // Legacy viewport implementation. - UsdMayaGLBatchRenderer::GetInstance().StartBatchingFrameDiagnostics(); - const unsigned int displayStyle = px_LegacyViewportUtils::GetMFrameContextDisplayStyle(legacyDisplayStyle); const MHWRender::DisplayStatus displayStatus = _ToMHWRenderDisplayStatus(legacyDisplayStatus); @@ -135,8 +133,6 @@ bool PxrMayaHdShapeAdapter::Sync( { // Viewport 2.0 implementation. - UsdMayaGLBatchRenderer::GetInstance().StartBatchingFrameDiagnostics(); - TF_DEBUG(PXRUSDMAYAGL_SHAPE_ADAPTER_LIFECYCLE) .Msg("Synchronizing PxrMayaHdShapeAdapter for Viewport 2.0: %p\n", this); diff --git a/lib/mayaUsd/render/vp2RenderDelegate/proxyRenderDelegate.cpp b/lib/mayaUsd/render/vp2RenderDelegate/proxyRenderDelegate.cpp index 4d803d3d26..eeef13557b 100644 --- a/lib/mayaUsd/render/vp2RenderDelegate/proxyRenderDelegate.cpp +++ b/lib/mayaUsd/render/vp2RenderDelegate/proxyRenderDelegate.cpp @@ -1191,8 +1191,6 @@ void ProxyRenderDelegate::update(MSubSceneContainer& container, const MFrameCont MProfiler::kColorD_L1, "ProxyRenderDelegate::update"); - UsdMayaDiagnosticBatchContext batchDiagnosticMessages; - // Without a proxy shape we can't do anything if (_proxyShapeData->ProxyShape() == nullptr) return; diff --git a/lib/mayaUsd/utils/diagnosticDelegate.cpp b/lib/mayaUsd/utils/diagnosticDelegate.cpp index d0f0048569..d33d81767f 100644 --- a/lib/mayaUsd/utils/diagnosticDelegate.cpp +++ b/lib/mayaUsd/utils/diagnosticDelegate.cpp @@ -22,17 +22,55 @@ #include #include +#include #include +#include +#include +#include +#include +#include + PXR_NAMESPACE_OPEN_SCOPE +// The design goes like this: +// +// - All messages are accumulated by the diagnostic delegates. (See below.) +// - Another delegate (see below) tells the diagnostic message flusher when +// any message arrives. +// - The diagnostic message flusher has two purposes: +// - the first purpose is to detect bursts of messages and to withhold +// further messages from being written out when a burst is detected, +// - the second purpose is to write out (flush) the messages periodically. +// - The condition for flushing are either: +// - that a forced flush is requested, +// - or that fewer than a maximum consecutive messages have been received, +// - or that one second has elapsed since the last time messages were flushed. +// - Flushing can either be immediate or delayed. +// - Immediate flushing is done when a forced flush is requested or when +// *outside* of bursts of messages. +// - Delayed flushing is done when a burst of messages is detected, +// to avoid writing too many messages in the log. +// - Requesting a flushing of accumulated messages is done either directly +// or indirectly. +// - Direct flushing is done when the flushing request is triggered in the +// main thread. +// - Indirect flushing is done by queuing a task to be run on-idle in the +// main thread. If a task is already queued, nothing is done, to avoid +// queuing multiple redundant tasks to do the same thing. +// - The actual flushing takes (extract and removes) all accumulated messages +// and prints them in the script console via MGlobal. +// - This can only be done in the main thread due to the limitations of MGlobal. +// - Printing of messages is done either fully or coalesced. +// - All messages are printed fully when not in a burst. +// - All messages are printed coalesced when in a burst. Coalesced messages +// only print a sample of the message followed by "and X similar". + TF_DEFINE_ENV_SETTING( PIXMAYA_DIAGNOSTICS_BATCH, true, - "Whether to batch diagnostics coming from the same call site. " - "If batching is off, all secondary threads' diagnostics will be " - "printed to stderr."); + "Whether to batch diagnostics coming from the same call site."); TF_DEFINE_ENV_SETTING( MAYAUSD_SHOW_FULL_DIAGNOSTICS, @@ -40,144 +78,308 @@ TF_DEFINE_ENV_SETTING( "This env flag controls the granularity of TF error/warning/status messages " "being displayed in Maya."); -// Globally-shared delegate. Uses shared_ptr so we can have weak ptrs. -static std::shared_ptr _sharedDelegate; +TF_DEFINE_ENV_SETTING( + MAYAUSD_MAXIMUM_UNBATCHED_DIAGNOSTICS, + 10, + "This env flag controls the maximum number of diagnostic messages that can " + "be emitted in one second before automatic batching of messages is used."); + +namespace { + +class DiagnosticFlusher; + +std::unique_ptr _batchedStatuses; +std::unique_ptr _batchedWarnings; +std::unique_ptr _batchedErrors; +std::unique_ptr _waker; +std::unique_ptr _flusher; // The delegate can be installed by multiple plugins (e.g. pxrUsd and // mayaUsdPlugin), so keep track of installations to ensure that we only add // the delegate for the first installation call, and that we only remove it for // the last removal call. -static int _installationCount = 0; +std::atomic _installationCount; -namespace { +std::atomic _batchedContextCount; -class _StatusOnlyDelegate : public UsdUtilsCoalescingDiagnosticDelegate +bool IsDiagnosticBatchingEnabled() { return TfGetEnvSetting(PIXMAYA_DIAGNOSTICS_BATCH); } + +/// @brief USD diagnostic delegate that accumulates all status messages. +class StatusOnlyDelegate : public UsdUtilsCoalescingDiagnosticDelegate { void IssueWarning(const TfWarning&) override { } void IssueError(const TfError&) override { } void IssueFatalError(const TfCallContext&, const std::string&) override { } }; -class _WarningOnlyDelegate : public UsdUtilsCoalescingDiagnosticDelegate +/// @brief USD diagnostic delegate that accumulates all warning messages. +class WarningOnlyDelegate : public UsdUtilsCoalescingDiagnosticDelegate { void IssueStatus(const TfStatus&) override { } void IssueError(const TfError&) override { } void IssueFatalError(const TfCallContext&, const std::string&) override { } }; -class _ErrorOnlyDelegate : public UsdUtilsCoalescingDiagnosticDelegate +/// @brief USD diagnostic delegate that accumulates all error messages. +class ErrorOnlyDelegate : public UsdUtilsCoalescingDiagnosticDelegate { void IssueWarning(const TfWarning&) override { } void IssueStatus(const TfStatus&) override { } - void IssueFatalError(const TfCallContext&, const std::string&) override { } + void IssueError(const TfError& err) override + { + // Note: UsdUtilsCoalescingDiagnosticDelegate does not coalesces errors! + // So, the only way to make it keep errors is to convert the error + // into a warning. + // + // Note: USD warnings and errors have the exact same layout, only a different concrete type. + // More-over, USD made all its diagnostic classes have private constructors! So + // the only way to convert an error into a warning is through a rei-interpret cast. + const TfWarning& warning = reinterpret_cast(err); + UsdUtilsCoalescingDiagnosticDelegate ::IssueWarning(warning); + } + void IssueFatalError(const TfCallContext& context, const std::string& msg) override + { + UsdMayaDiagnosticDelegate::Flush(); + + TfLogCrash( + "FATAL ERROR", + msg, + /*additionalInfo*/ std::string(), + context, + /*logToDb*/ true); + _UnhandledAbort(); + } }; -} // anonymous namespace - -static MString _FormatDiagnostic(const TfDiagnosticBase& d) +/// @brief Periodically flushes the accumulated messages. +class DiagnosticFlusher { - if (!TfGetEnvSetting(MAYAUSD_SHOW_FULL_DIAGNOSTICS)) { - return d.GetCommentary().c_str(); - } else { - const std::string msg = TfStringPrintf( - "%s -- %s in %s at line %zu of %s", - d.GetCommentary().c_str(), - TfDiagnosticMgr::GetCodeName(d.GetDiagnosticCode()).c_str(), - d.GetContext().GetFunction(), - d.GetContext().GetLine(), - ghc::filesystem::path(d.GetContext().GetFile()).relative_path().string().c_str()); - return msg.c_str(); +public: + DiagnosticFlusher() { } + + ~DiagnosticFlusher() { } + + /// @brief Force all mesage to be immediately flushed. + void forceFlush() + { + _burstDiagnosticCount = 0; + resetLastFlushTime(); + triggerFlushInMainThread(); } -} -static MString _FormatCoalescedDiagnostic(const UsdUtilsCoalescingDiagnosticDelegateItem& item) -{ - const size_t numItems = item.unsharedItems.size(); - const std::string suffix - = numItems == 1 ? std::string() : TfStringPrintf(" -- and %zu similar", numItems - 1); - const std::string message - = TfStringPrintf("%s%s", item.unsharedItems[0].commentary.c_str(), suffix.c_str()); + /// @brief Sets the maximum number of consecutive messages before they + /// are considered a burst. + void setMaximumUnbatchedDiagnostics(int count) { _maximumUnbatchedDiagnostics = count; } - return message.c_str(); -} + /// @brief Gets the maximum number of consecutive messages before they + /// are considered a burst. + int getMaximumUnbatchedDiagnostics() const { return _maximumUnbatchedDiagnostics; } -static bool _IsDiagnosticBatchingEnabled() { return TfGetEnvSetting(PIXMAYA_DIAGNOSTICS_BATCH); } + /// @brief Gets the default maximum number of consecutive messages + /// before they are considered a burst. + static int getDefaultMaximumUnbatchedDiagnostics() + { + return TfGetEnvSetting(MAYAUSD_MAXIMUM_UNBATCHED_DIAGNOSTICS); + } -UsdMayaDiagnosticDelegate::UsdMayaDiagnosticDelegate() - : _batchCount(0) -{ - TfDiagnosticMgr::GetInstance().AddDelegate(this); -} + /// @brief Called when a diagnostic message is created to be printed. + void receivedDiagnostic() + { + // On the first diagnostic message, check how long since we flushed the diagnostics. + // If it is less than a minimum, we assume we are in a burst of messages and delay + // writing messages. + // + // If it is the first message in a long time, we flush it immediately. + const int burstCount = _burstDiagnosticCount.fetch_add(1); + if (_pendingDiagnosticCount.fetch_add(1) >= _maximumUnbatchedDiagnostics) + return triggerFlushInMainThreadLaterIfNeeded(); + + const double elapsed = getElapsedSecondsSinceLastFlush(); + if (elapsed < _flushingPeriod) { + if (burstCount >= _maximumUnbatchedDiagnostics) { + return triggerFlushInMainThreadLaterIfNeeded(); + } + } else { + // Note: clear the burst count since the time elapsed since the last + // diagnostic is greater than the flushing period. We reset to + // one instead of zero since this message is part of the new + // potential burst of diagnostic messages. + _burstDiagnosticCount = 1; + } -UsdMayaDiagnosticDelegate::~UsdMayaDiagnosticDelegate() -{ - // If a batch context was open when the delegate is removed, we need to - // flush all the batched diagnostics in order to avoid losing any. - // The batch context should know how to clean itself up when the delegate - // is gone. - _FlushBatch(); - TfDiagnosticMgr::GetInstance().RemoveDelegate(this); -} + triggerFlushInMainThreadIfNeeded(); + } -void UsdMayaDiagnosticDelegate::IssueError(const TfError& err) -{ - if (_batchCount.load() > 0) { - return; // Batched. +private: + using Clock = std::chrono::steady_clock; + using TimePoint = Clock::time_point; + using Sec = std::chrono::seconds; + + static MString formatCoalescedDiagnostic(const UsdUtilsCoalescingDiagnosticDelegateItem& item) + { + const size_t numItems = item.unsharedItems.size(); + const std::string suffix + = numItems == 1 ? std::string() : TfStringPrintf(" -- and %zu similar", numItems - 1); + const std::string message + = TfStringPrintf("%s%s", item.unsharedItems[0].commentary.c_str(), suffix.c_str()); + + return message.c_str(); } - const auto diagnosticMessage = _FormatDiagnostic(err); + static MString formatDiagnostic(const std::unique_ptr& item) + { + if (!item) + return MString(); + if (!TfGetEnvSetting(MAYAUSD_SHOW_FULL_DIAGNOSTICS)) { + return item->GetCommentary().c_str(); + } else { + const std::string msg = TfStringPrintf( + "%s -- %s in %s at line %zu of %s", + item->GetCommentary().c_str(), + TfDiagnosticMgr::GetCodeName(item->GetDiagnosticCode()).c_str(), + item->GetContext().GetFunction(), + item->GetContext().GetLine(), + ghc::filesystem::path(item->GetContext().GetFile()) + .relative_path() + .string() + .c_str()); + return msg.c_str(); + } + } - if (ArchIsMainThread()) { - MGlobal::displayError(diagnosticMessage); - } else { - std::cerr << diagnosticMessage << std::endl; + static void flushDiagnostics( + const std::unique_ptr& delegate, + const bool printBatched, + const std::function& printer) + { + if (!delegate) + return; + + if (printBatched) { + const UsdUtilsCoalescingDiagnosticDelegateVector messages + = delegate->TakeCoalescedDiagnostics(); + for (const UsdUtilsCoalescingDiagnosticDelegateItem& item : messages) { + printer(formatCoalescedDiagnostic(item)); + } + } else { + std::vector> messages + = delegate->TakeUncoalescedDiagnostics(); + for (const std::unique_ptr& item : messages) { + printer(formatDiagnostic(item)); + } + } } -} -void UsdMayaDiagnosticDelegate::IssueStatus(const TfStatus& status) -{ - if (_batchCount.load() > 0) { - return; // Batched. + void flushPerformedInMainThread() + { + TF_AXIOM(ArchIsMainThread()); + + _triggeredFlush = false; + const bool printBatched + = _pendingDiagnosticCount.fetch_and(0) > _maximumUnbatchedDiagnostics; + + updateLastFlushTime(); + + // Note that we must be in the main thread here, so it's safe to call + // displayInfo/displayWarning. + flushDiagnostics(_batchedStatuses, printBatched, MGlobal::displayInfo); + flushDiagnostics(_batchedWarnings, printBatched, MGlobal::displayWarning); + flushDiagnostics(_batchedErrors, printBatched, MGlobal::displayError); } - const auto diagnosticMessage = _FormatDiagnostic(status); + static void flushPerformedInMainThreadCallback(void* data) + { + DiagnosticFlusher* self = static_cast(data); + self->flushPerformedInMainThread(); + } - if (ArchIsMainThread()) { - MGlobal::displayInfo(diagnosticMessage); - } else { - std::cerr << diagnosticMessage << std::endl; + void triggerFlushInMainThreadLaterIfNeeded() + { + if (_triggeredFlush) + return; + _triggeredFlush = true; + + // Note: the periodic thread access member variables, so it must be initialized + // after all members are initialized. That is why we create it in the + // constructor body and not the initialization list. + std::thread([this]() { + using namespace std::chrono_literals; + std::this_thread::sleep_for(1s); + triggerFlushInMainThread(); + }).detach(); } -} -void UsdMayaDiagnosticDelegate::IssueWarning(const TfWarning& warning) -{ - if (_batchCount.load() > 0) { - return; // Batched. + void triggerFlushInMainThreadIfNeeded() + { + if (_triggeredFlush) + return; + _triggeredFlush = true; + triggerFlushInMainThread(); + } + + void triggerFlushInMainThread() + { + if (ArchIsMainThread()) { + flushPerformedInMainThread(); + } else { + MGlobal::executeTaskOnIdle(flushPerformedInMainThreadCallback, this); + } } - const auto diagnosticMessage = _FormatDiagnostic(warning); + static TimePoint getElapsedTimePoint() { return Clock::now(); } - if (ArchIsMainThread()) { - MGlobal::displayWarning(diagnosticMessage); - } else { - std::cerr << diagnosticMessage << std::endl; + void updateLastFlushTime() + { + const TimePoint now = getElapsedTimePoint(); + std::unique_lock lock(_pendingDiagnosticsMutex); + _lastFlushTime = now; + } + + void resetLastFlushTime() + { + std::unique_lock lock(_pendingDiagnosticsMutex); + _lastFlushTime = TimePoint(); + } + + double getElapsedSecondsSinceLastFlush() + { + const auto now = getElapsedTimePoint(); + std::unique_lock lock(_pendingDiagnosticsMutex); + return std::chrono::duration(now - _lastFlushTime).count(); } -} -void UsdMayaDiagnosticDelegate::IssueFatalError( - const TfCallContext& context, - const std::string& msg) + std::mutex _pendingDiagnosticsMutex; + TimePoint _lastFlushTime = TimePoint(); + std::atomic _triggeredFlush; + std::atomic _pendingDiagnosticCount; + std::atomic _burstDiagnosticCount; + + int _maximumUnbatchedDiagnostics = getDefaultMaximumUnbatchedDiagnostics(); + + static constexpr double _flushingPeriod = 1.; +}; + +/// @brief USD diagnostic delegate that wakes up the flushing thread. +class WakeUpDelegate : public TfDiagnosticMgr::Delegate { - TfLogCrash( - "FATAL ERROR", - msg, - /*additionalInfo*/ std::string(), - context, - /*logToDb*/ true); - _UnhandledAbort(); -} +public: + WakeUpDelegate() { TfDiagnosticMgr::GetInstance().AddDelegate(this); } + ~WakeUpDelegate() + { + try { + TfDiagnosticMgr::GetInstance().RemoveDelegate(this); + } catch (const std::exception&) { + } + } + + void IssueError(const TfError&) override { _flusher->receivedDiagnostic(); } + void IssueWarning(const TfWarning&) override { _flusher->receivedDiagnostic(); } + void IssueStatus(const TfStatus&) override { _flusher->receivedDiagnostic(); } + void IssueFatalError(const TfCallContext&, const std::string&) override { } +}; + +} // anonymous namespace -/* static */ void UsdMayaDiagnosticDelegate::InstallDelegate() { if (!ArchIsMainThread()) { @@ -192,10 +394,19 @@ void UsdMayaDiagnosticDelegate::InstallDelegate() return; } - _sharedDelegate.reset(new UsdMayaDiagnosticDelegate()); + _batchedStatuses = std::make_unique(); + _batchedWarnings = std::make_unique(); + _batchedErrors = std::make_unique(); + + // Note: flusher accesses the batched status, so the flusher must be created + // after the batcher. + _flusher = std::make_unique(); + + // Note: waker accesses the flusher, so the waker must be created + // after the flusher. + _waker = std::make_unique(); } -/* static */ void UsdMayaDiagnosticDelegate::RemoveDelegate() { if (!ArchIsMainThread()) { @@ -210,93 +421,65 @@ void UsdMayaDiagnosticDelegate::RemoveDelegate() return; } - _sharedDelegate.reset(); -} + Flush(); -/* static */ -int UsdMayaDiagnosticDelegate::GetBatchCount() -{ - if (std::shared_ptr ptr = _sharedDelegate) { - return ptr->_batchCount.load(); - } + // Note: waker accesses the flusher, so the waker must be destroyed + // before the flusher. + _waker.reset(); + + // Note: flusher accesses the batched status, so the flusher must be destroyed + // before the batcher. + _flusher.reset(); - TF_RUNTIME_ERROR("Delegate is not installed"); - return 0; + _batchedStatuses.reset(); + _batchedWarnings.reset(); + _batchedErrors.reset(); } -void UsdMayaDiagnosticDelegate::_StartBatch() +void UsdMayaDiagnosticDelegate::Flush() { - if (!ArchIsMainThread()) - return; - - if (_batchCount.fetch_add(1) == 0) { - // This is the first _StartBatch; add the batching delegates. - _batchedStatuses.reset(new _StatusOnlyDelegate()); - _batchedWarnings.reset(new _WarningOnlyDelegate()); - _batchedErrors.reset(new _ErrorOnlyDelegate()); - } + if (_flusher) + _flusher->forceFlush(); } -void UsdMayaDiagnosticDelegate::_EndBatch() +void UsdMayaDiagnosticDelegate::SetMaximumUnbatchedDiagnostics(int count) { - if (!ArchIsMainThread()) - return; - - const int prevValue = _batchCount.fetch_sub(1); - if (prevValue <= 0) { - TF_RUNTIME_ERROR("_EndBatch invoked before _StartBatch"); - } else if (prevValue == 1) { - // This is the last _EndBatch; print the diagnostic messages. - // and remove the batching delegates. - _FlushBatch(); - _batchedStatuses.reset(); - _batchedWarnings.reset(); - _batchedErrors.reset(); - } + if (_flusher) + _flusher->setMaximumUnbatchedDiagnostics(count); } -static void flushDiagnostics( - const std::unique_ptr& delegate, - const std::function& printer) +int UsdMayaDiagnosticDelegate::GetMaximumUnbatchedDiagnostics() { - const UsdUtilsCoalescingDiagnosticDelegateVector messages = delegate - ? delegate->TakeCoalescedDiagnostics() - : UsdUtilsCoalescingDiagnosticDelegateVector(); - for (const UsdUtilsCoalescingDiagnosticDelegateItem& item : messages) { - printer(_FormatCoalescedDiagnostic(item)); - } + if (_flusher) + return _flusher->getMaximumUnbatchedDiagnostics(); + else + return DiagnosticFlusher::getDefaultMaximumUnbatchedDiagnostics(); } -void UsdMayaDiagnosticDelegate::_FlushBatch() +UsdMayaDiagnosticBatchContext::UsdMayaDiagnosticBatchContext(int maximumUnbatchedCount) + : previousCount(UsdMayaDiagnosticDelegate::GetMaximumUnbatchedDiagnostics()) { - TF_AXIOM(ArchIsMainThread()); + if (!IsDiagnosticBatchingEnabled()) + return; - // Note that we must be in the main thread here, so it's safe to call - // displayInfo/displayWarning. - flushDiagnostics(_batchedStatuses, MGlobal::displayInfo); - flushDiagnostics(_batchedWarnings, MGlobal::displayWarning); - flushDiagnostics(_batchedErrors, MGlobal::displayError); -} + TF_DEBUG(PXRUSDMAYA_DIAGNOSTICS).Msg(">> Entering batch context\n"); -UsdMayaDiagnosticBatchContext::UsdMayaDiagnosticBatchContext() - : _delegate(_IsDiagnosticBatchingEnabled() ? _sharedDelegate : nullptr) -{ - if (ArchIsMainThread()) { - TF_DEBUG(PXRUSDMAYA_DIAGNOSTICS).Msg(">> Entering batch context\n"); - if (std::shared_ptr ptr = _delegate.lock()) { - ptr->_StartBatch(); - } - } + UsdMayaDiagnosticDelegate::SetMaximumUnbatchedDiagnostics(maximumUnbatchedCount); + + _batchedContextCount.fetch_add(1); } UsdMayaDiagnosticBatchContext::~UsdMayaDiagnosticBatchContext() { - if (ArchIsMainThread()) { - TF_DEBUG(PXRUSDMAYA_DIAGNOSTICS).Msg("!! Exiting batch context\n"); - if (std::shared_ptr ptr = _delegate.lock()) { - ptr->_EndBatch(); - } - } + if (!IsDiagnosticBatchingEnabled()) + return; + + TF_DEBUG(PXRUSDMAYA_DIAGNOSTICS).Msg("!! Exiting batch context\n"); + + UsdMayaDiagnosticDelegate::SetMaximumUnbatchedDiagnostics(previousCount); + + if (_batchedContextCount.fetch_sub(1) <= 1) + UsdMayaDiagnosticDelegate::Flush(); } PXR_NAMESPACE_CLOSE_SCOPE diff --git a/lib/mayaUsd/utils/diagnosticDelegate.h b/lib/mayaUsd/utils/diagnosticDelegate.h index b091fb399f..10957cec38 100644 --- a/lib/mayaUsd/utils/diagnosticDelegate.h +++ b/lib/mayaUsd/utils/diagnosticDelegate.h @@ -22,15 +22,8 @@ #include #include -#include - -#include -#include - PXR_NAMESPACE_OPEN_SCOPE -class UsdMayaDiagnosticBatchContext; - /// Converts Tf diagnostics into native Maya infos, warnings, and errors. /// /// Provides an optional batching mechanism for diagnostics; see @@ -46,21 +39,9 @@ class UsdMayaDiagnosticBatchContext; /// /// Installing and removing this diagnostic delegate is not thread-safe, and /// must be done only on the main thread. -class UsdMayaDiagnosticDelegate : TfDiagnosticMgr::Delegate +class UsdMayaDiagnosticDelegate { public: - MAYAUSD_CORE_PUBLIC - ~UsdMayaDiagnosticDelegate() override; - - MAYAUSD_CORE_PUBLIC - void IssueError(const TfError& err) override; - MAYAUSD_CORE_PUBLIC - void IssueStatus(const TfStatus& status) override; - MAYAUSD_CORE_PUBLIC - void IssueWarning(const TfWarning& warning) override; - MAYAUSD_CORE_PUBLIC - void IssueFatalError(const TfCallContext& context, const std::string& msg) override; - /// Installs a shared delegate globally. /// If this is invoked on a secondary thread, issues a fatal coding error. MAYAUSD_CORE_PUBLIC @@ -69,35 +50,27 @@ class UsdMayaDiagnosticDelegate : TfDiagnosticMgr::Delegate /// If this is invoked on a secondary thread, issues a fatal coding error. MAYAUSD_CORE_PUBLIC static void RemoveDelegate(); - /// Returns the number of active batch contexts associated with the global - /// delegate. 0 means no batching; 1 or more means diagnostics are batched. - /// If there is no delegate installed, issues a runtime error and returns 0. - MAYAUSD_CORE_PUBLIC - static int GetBatchCount(); - -private: - friend class UsdMayaDiagnosticBatchContext; - std::atomic_int _batchCount; - std::unique_ptr _batchedStatuses; - std::unique_ptr _batchedWarnings; - std::unique_ptr _batchedErrors; + /// @brief Write all accumulated diagnostic messages. + MAYAUSD_CORE_PUBLIC + static void Flush(); - UsdMayaDiagnosticDelegate(); + /// @brief Sets the maximum number of diagnostics messages that can be emitted in + /// one second before we start to batch messages. Default is 100. + MAYAUSD_CORE_PUBLIC + static void SetMaximumUnbatchedDiagnostics(int count); - void _StartBatch(); - void _EndBatch(); - void _FlushBatch(); + /// @brief Gets the maximum number of diagnostics messages that can be emitted in + /// one second before we start to batch messages. Default is 100. + MAYAUSD_CORE_PUBLIC + static int GetMaximumUnbatchedDiagnostics(); }; /// As long as a batch context remains alive (process-wide), the -/// UsdMayaDiagnosticDelegate will save diagnostic messages, only emitting -/// them when the last batch context is destructed. Note that errors are never -/// batched. +/// UsdMayaDiagnosticDelegate will save diagnostic messages that exceed the given +/// maximum count, which defaults to 0. /// -/// Batch contexts must only exist on the main thread (though they will apply -/// to any diagnostics issued on secondary threads while they're alive). If -/// they're constructed on secondary threads, they will do nothing. +/// The messages will be emmited when the last batch context is destructed. /// /// Batch contexts can be constructed and destructed out of "scope" order, e.g., /// this is allowed: @@ -112,7 +85,7 @@ class UsdMayaDiagnosticBatchContext /// to be batched on all threads. /// If this is invoked on a secondary thread, issues a fatal coding error. MAYAUSD_CORE_PUBLIC - UsdMayaDiagnosticBatchContext(); + UsdMayaDiagnosticBatchContext(int maximumUnbatchedCount = 0); MAYAUSD_CORE_PUBLIC ~UsdMayaDiagnosticBatchContext(); @@ -120,10 +93,7 @@ class UsdMayaDiagnosticBatchContext UsdMayaDiagnosticBatchContext& operator=(const UsdMayaDiagnosticBatchContext&) = delete; private: - /// This pointer is used to "bind" this context to a specific delegate in - /// case the global delegate is removed (and possibly re-installed) while - /// this batch context is alive. - std::weak_ptr _delegate; + int previousCount = 0; }; PXR_NAMESPACE_CLOSE_SCOPE diff --git a/test/lib/mayaUsd/utils/testDiagnosticDelegate.py b/test/lib/mayaUsd/utils/testDiagnosticDelegate.py index 6713d7011f..f5ded684df 100644 --- a/test/lib/mayaUsd/utils/testDiagnosticDelegate.py +++ b/test/lib/mayaUsd/utils/testDiagnosticDelegate.py @@ -54,6 +54,8 @@ def setUp(self): if sys.version_info[0] >= 3: self.assertItemsEqual = self.assertCountEqual + mayaUsdLib.DiagnosticDelegate.Flush() + def _OnCommandOutput(self, message, messageType, _): if (messageType == OM.MCommandMessage.kInfo or messageType == OM.MCommandMessage.kWarning @@ -66,6 +68,7 @@ def _StartRecording(self): self.messageLog = [] def _StopRecording(self): + mayaUsdLib.DiagnosticDelegate.Flush() OM.MMessage.removeCallback(self.callback) self.callback = None return list(self.messageLog) @@ -162,6 +165,41 @@ def testBatching(self): ("spam warning 0 -- and 2 similar", OM.MCommandMessage.kWarning) ]) + def testBatchingWithLimit(self): + self._StartRecording() + + with mayaUsdLib.DiagnosticBatchContext(2): + for i in range(5): + Tf.Status("repeated status %d" % i) + + log = self._StopRecording() + + # Note: we use assertItemsEqual because coalescing may re-order the + # diagnostic messages. + self.assertItemsEqual(log, [ + ("repeated status 0", OM.MCommandMessage.kInfo), + ("repeated status 1", OM.MCommandMessage.kInfo), + ("repeated status 2 -- and 2 similar", OM.MCommandMessage.kInfo), + ]) + + def testMaximumUnbatched(self): + self._StartRecording() + mayaUsdLib.DiagnosticDelegate.SetMaximumUnbatchedDiagnostics(2) + + for i in range(5): + Tf.Status("repeated status %d" % i) + + log = self._StopRecording() + mayaUsdLib.DiagnosticDelegate.SetMaximumUnbatchedDiagnostics(100) + + # Note: we use assertItemsEqual because coalescing may re-order the + # diagnostic messages. + self.assertItemsEqual(log, [ + ("repeated status 0", OM.MCommandMessage.kInfo), + ("repeated status 1", OM.MCommandMessage.kInfo), + ("repeated status 2 -- and 2 similar", OM.MCommandMessage.kInfo), + ]) + # Note: giving the test a name starting with Z so it is run last because unloading the plugin # can break other tests when they try to reload the plugin. def testZZZBatching_DelegateRemoved(self): @@ -185,15 +223,6 @@ def testZZZBatching_DelegateRemoved(self): ("this status won't be lost", OM.MCommandMessage.kInfo), ]) - def testBatching_BatchCount(self): - """Tests the GetBatchCount() debugging function.""" - count = -1 - with mayaUsdLib.DiagnosticBatchContext(): - with mayaUsdLib.DiagnosticBatchContext(): - count = mayaUsdLib.DiagnosticDelegate.GetBatchCount() - self.assertEqual(count, 2) - count = mayaUsdLib.DiagnosticDelegate.GetBatchCount() - self.assertEqual(count, 0) if __name__ == '__main__': diff --git a/test/lib/ufe/testAttribute.py b/test/lib/ufe/testAttribute.py index d127d5755f..4e2a49262b 100644 --- a/test/lib/ufe/testAttribute.py +++ b/test/lib/ufe/testAttribute.py @@ -1749,22 +1749,19 @@ def testMayaGetAttr(self): pathStr = '|transform1|proxyShape1,/Room_set/Props/Ball_35' # No attribute was specified. - self.assertRaisesRegex(RuntimeError, - 'No attribute was specified\.$', - cmds.getAttr, pathStr) + with self.assertRaisesRegex(RuntimeError, 'No attribute was specified\.$') as cm: + with mayaUsdLib.DiagnosticBatchContext(1000) as bc: + cmds.getAttr(pathStr) # Cannot evaluate more than one attribute. - self.assertRaisesRegex(RuntimeError, - 'Cannot evaluate more than one attribute\.$', - cmds.getAttr, - pathStr+'.xformOp:translate', - pathStr+'.xformOpOrder') + with self.assertRaisesRegex(RuntimeError, 'Cannot evaluate more than one attribute\.$') as cm: + with mayaUsdLib.DiagnosticBatchContext(1000) as bc: + cmds.getAttr(pathStr+'.xformOp:translate', pathStr+'.xformOpOrder') # Mixing Maya and non-Maya attributes is an error. - self.assertRaisesRegex(RuntimeError, - 'Cannot evaluate more than one attribute\.$', - cmds.getAttr, - 'proxyShape1.shareStage',pathStr+'.xformOp:translate') + with self.assertRaisesRegex(RuntimeError, 'Cannot evaluate more than one attribute\.$') as cm: + with mayaUsdLib.DiagnosticBatchContext(1000) as bc: + cmds.getAttr('proxyShape1.shareStage',pathStr+'.xformOp:translate') def createAndTestAttribute(self, materialItem, shaderDefName, shaderName, origValue, newValue, validation): surfDef = ufe.NodeDef.definition(materialItem.runTimeId(), shaderDefName) diff --git a/test/lib/ufe/testAttributes.py b/test/lib/ufe/testAttributes.py index a3e3c10769..db1ae2eb63 100644 --- a/test/lib/ufe/testAttributes.py +++ b/test/lib/ufe/testAttributes.py @@ -22,6 +22,8 @@ import usdUtils import testUtils +import mayaUsd.lib as mayaUsdLib + from pxr import UsdGeom from maya import cmds @@ -150,7 +152,8 @@ def testAddRemoveAttribute(self): self.assertNotIn("MyAttribute", ball35Attrs.attributeNames) with self.assertRaisesRegex(KeyError, "Attribute 'MyAttribute' does not exist") as cm: - attr = ball35Attrs.attribute("MyAttribute") + with mayaUsdLib.DiagnosticBatchContext(1000) as bc: + attr = ball35Attrs.attribute("MyAttribute") cmds.redo() ballObserver.assertNotificationCount(self, numAdded = 2, numRemoved = 1) @@ -166,9 +169,11 @@ def testAddRemoveAttribute(self): self.assertNotIn("MyAttribute", ball35Attrs.attributeNames) with self.assertRaisesRegex(KeyError, "Attribute 'MyAttribute' does not exist") as cm: - attr = ball35Attrs.attribute("MyAttribute") + with mayaUsdLib.DiagnosticBatchContext(1000) as bc: + attr = ball35Attrs.attribute("MyAttribute") with self.assertRaisesRegex(ValueError, "Requested attribute with empty name") as cm: - attr = ball35Attrs.attribute("") + with mayaUsdLib.DiagnosticBatchContext(1000) as bc: + attr = ball35Attrs.attribute("") cmds.undo() ballObserver.assertNotificationCount(self, numAdded = 3, numRemoved = 2) @@ -181,7 +186,8 @@ def testAddRemoveAttribute(self): self.assertNotIn("MyAttribute", ball35Attrs.attributeNames) with self.assertRaisesRegex(KeyError, "Attribute 'MyAttribute' does not exist") as cm: - attr = ball35Attrs.attribute("MyAttribute") + with mayaUsdLib.DiagnosticBatchContext(1000) as bc: + attr = ball35Attrs.attribute("MyAttribute") @unittest.skipIf(os.getenv('UFE_PREVIEW_VERSION_NUM', '0000') < '4024', 'Test for UFE preview version 0.4.24 and later') def testUniqueNameAttribute(self): diff --git a/test/lib/ufe/testConnections.py b/test/lib/ufe/testConnections.py index d51ab95810..ea0099a239 100644 --- a/test/lib/ufe/testConnections.py +++ b/test/lib/ufe/testConnections.py @@ -21,6 +21,8 @@ import usdUtils import testUtils +import mayaUsd.lib as mayaUsdLib + from maya import cmds from pxr import Sdr @@ -649,7 +651,8 @@ def testCreateStandardSurface(self): # Cleanup on disconnection should remove the MaterialX surface output. with self.assertRaisesRegex(KeyError, "Attribute 'outputs:mtlx:surface' does not exist") as cm: - materialAttrs.attribute("outputs:mtlx:surface") + with mayaUsdLib.DiagnosticBatchContext(1000) as bc: + materialAttrs.attribute("outputs:mtlx:surface") connections = connectionHandler.sourceConnections(materialItem) self.assertIsNotNone(connections) diff --git a/test/lib/usd/translators/testUsdExportStripNamespaces.py b/test/lib/usd/translators/testUsdExportStripNamespaces.py index 6bdfac3ae0..5d2663d39d 100644 --- a/test/lib/usd/translators/testUsdExportStripNamespaces.py +++ b/test/lib/usd/translators/testUsdExportStripNamespaces.py @@ -23,6 +23,8 @@ from maya import cmds from maya import standalone +import mayaUsd.lib as mayaUsdLib + from pxr import Usd import fixturesUtils @@ -55,22 +57,24 @@ def testExportWithClashStripping(self): usdFilePath = os.path.abspath('UsdExportStripNamespaces_EXPORTED.usda') - errorRegexp = "Multiple dag nodes map to the same prim path" \ - ".+|cube1 - |foo:cube1.*" + errorRegexp = "(Multiple dag nodes map to the same prim path" \ + ".+|cube1 - |foo:cube1.*)|(Maya command error)" with self.assertRaisesRegex(RuntimeError, errorRegexp) as cm: - cmds.usdExport(mergeTransformAndShape=True, - selection=False, - stripNamespaces=True, - file=usdFilePath, - shadingMode='none') + with mayaUsdLib.DiagnosticBatchContext(0) as bc: + cmds.usdExport(mergeTransformAndShape=True, + selection=False, + stripNamespaces=True, + file=usdFilePath, + shadingMode='none') with self.assertRaisesRegex(RuntimeError,errorRegexp) as cm: - cmds.usdExport(mergeTransformAndShape=False, - selection=False, - stripNamespaces=True, - file=usdFilePath, - shadingMode='none') + with mayaUsdLib.DiagnosticBatchContext(1000) as bc: + cmds.usdExport(mergeTransformAndShape=False, + selection=False, + stripNamespaces=True, + file=usdFilePath, + shadingMode='none') def testExportWithStripAndMerge(self): mayaFilePath = os.path.abspath('UsdExportStripNamespaces.ma') From 13c26fbc6650fe658c48ca2829fae86b77d247b8 Mon Sep 17 00:00:00 2001 From: Pierre Baillargeon Date: Wed, 28 Dec 2022 14:49:42 -0500 Subject: [PATCH 3/3] MAYA-104552 improve Python batch context to restore previous limit --- lib/mayaUsd/python/wrapDiagnosticDelegate.cpp | 13 ++++++++----- test/lib/mayaUsd/utils/testDiagnosticDelegate.py | 4 ++++ 2 files changed, 12 insertions(+), 5 deletions(-) diff --git a/lib/mayaUsd/python/wrapDiagnosticDelegate.cpp b/lib/mayaUsd/python/wrapDiagnosticDelegate.cpp index bb23f2ba32..040bd888b0 100644 --- a/lib/mayaUsd/python/wrapDiagnosticDelegate.cpp +++ b/lib/mayaUsd/python/wrapDiagnosticDelegate.cpp @@ -36,18 +36,19 @@ class _PyDiagnosticBatchContext public: _PyDiagnosticBatchContext() { } _PyDiagnosticBatchContext(int c) - : count(c) + : _count(c) { } - void __enter__() { UsdMayaDiagnosticDelegate::SetMaximumUnbatchedDiagnostics(count); } + void __enter__() { UsdMayaDiagnosticDelegate::SetMaximumUnbatchedDiagnostics(_count); } void __exit__(object, object, object) { UsdMayaDiagnosticDelegate::Flush(); - UsdMayaDiagnosticDelegate::SetMaximumUnbatchedDiagnostics(100); + UsdMayaDiagnosticDelegate::SetMaximumUnbatchedDiagnostics(_previousCount); } private: - int count = 0; + int _count = 0; + int _previousCount = UsdMayaDiagnosticDelegate::GetMaximumUnbatchedDiagnostics(); }; } // anonymous namespace @@ -59,7 +60,9 @@ void wrapDiagnosticDelegate() .def("Flush", &This::Flush) .staticmethod("Flush") .def("SetMaximumUnbatchedDiagnostics", &This::SetMaximumUnbatchedDiagnostics) - .staticmethod("SetMaximumUnbatchedDiagnostics"); + .staticmethod("SetMaximumUnbatchedDiagnostics") + .def("GetMaximumUnbatchedDiagnostics", &This::GetMaximumUnbatchedDiagnostics) + .staticmethod("GetMaximumUnbatchedDiagnostics"); typedef _PyDiagnosticBatchContext Context; class_("DiagnosticBatchContext") diff --git a/test/lib/mayaUsd/utils/testDiagnosticDelegate.py b/test/lib/mayaUsd/utils/testDiagnosticDelegate.py index f5ded684df..e29accbb74 100644 --- a/test/lib/mayaUsd/utils/testDiagnosticDelegate.py +++ b/test/lib/mayaUsd/utils/testDiagnosticDelegate.py @@ -168,12 +168,16 @@ def testBatching(self): def testBatchingWithLimit(self): self._StartRecording() + previousMax = mayaUsdLib.DiagnosticDelegate.GetMaximumUnbatchedDiagnostics() + with mayaUsdLib.DiagnosticBatchContext(2): for i in range(5): Tf.Status("repeated status %d" % i) log = self._StopRecording() + self.assertEqual(previousMax, mayaUsdLib.DiagnosticDelegate.GetMaximumUnbatchedDiagnostics()) + # Note: we use assertItemsEqual because coalescing may re-order the # diagnostic messages. self.assertItemsEqual(log, [