diff --git a/lib/mayaUsd/nodes/proxyShapeBase.cpp b/lib/mayaUsd/nodes/proxyShapeBase.cpp index f986b5d395..5c0aea28a5 100644 --- a/lib/mayaUsd/nodes/proxyShapeBase.cpp +++ b/lib/mayaUsd/nodes/proxyShapeBase.cpp @@ -23,6 +23,7 @@ #include #include #include +#include #include #include #include diff --git a/lib/mayaUsd/python/wrapDiagnosticDelegate.cpp b/lib/mayaUsd/python/wrapDiagnosticDelegate.cpp index a95b661dd2..040bd888b0 100644 --- a/lib/mayaUsd/python/wrapDiagnosticDelegate.cpp +++ b/lib/mayaUsd/python/wrapDiagnosticDelegate.cpp @@ -28,16 +28,27 @@ 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(_previousCount); + } private: - std::unique_ptr _context; + int _count = 0; + int _previousCount = UsdMayaDiagnosticDelegate::GetMaximumUnbatchedDiagnostics(); }; } // anonymous namespace @@ -46,11 +57,16 @@ 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") + .def("GetMaximumUnbatchedDiagnostics", &This::GetMaximumUnbatchedDiagnostics) + .staticmethod("GetMaximumUnbatchedDiagnostics"); 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 bb153a2999..eeef13557b 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 diff --git a/lib/mayaUsd/utils/diagnosticDelegate.cpp b/lib/mayaUsd/utils/diagnosticDelegate.cpp index d017377376..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,241 +78,408 @@ 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 { } }; -} // anonymous namespace - -static MString _FormatDiagnostic(const TfDiagnosticBase& d) +/// @brief USD diagnostic delegate that accumulates all error messages. +class ErrorOnlyDelegate : public UsdUtilsCoalescingDiagnosticDelegate { - 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(); + void IssueWarning(const TfWarning&) override { } + void IssueStatus(const TfStatus&) 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(); + } +}; -static MString _FormatCoalescedDiagnostic(const UsdUtilsCoalescingDiagnosticDelegateItem& item) +/// @brief Periodically flushes the accumulated messages. +class DiagnosticFlusher { - 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()); +public: + DiagnosticFlusher() { } - return message.c_str(); -} + ~DiagnosticFlusher() { } -static bool _IsDiagnosticBatchingEnabled() { return TfGetEnvSetting(PIXMAYA_DIAGNOSTICS_BATCH); } + /// @brief Force all mesage to be immediately flushed. + void forceFlush() + { + _burstDiagnosticCount = 0; + resetLastFlushTime(); + triggerFlushInMainThread(); + } -UsdMayaDiagnosticDelegate::UsdMayaDiagnosticDelegate() - : _batchCount(0) -{ - TfDiagnosticMgr::GetInstance().AddDelegate(this); -} + /// @brief Sets the maximum number of consecutive messages before they + /// are considered a burst. + void setMaximumUnbatchedDiagnostics(int count) { _maximumUnbatchedDiagnostics = count; } -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); -} + /// @brief Gets the maximum number of consecutive messages before they + /// are considered a burst. + int getMaximumUnbatchedDiagnostics() const { return _maximumUnbatchedDiagnostics; } -void UsdMayaDiagnosticDelegate::IssueError(const TfError& err) -{ - // Errors are never batched. They should be rare, and in those cases, we - // want to see them separately. + /// @brief Gets the default maximum number of consecutive messages + /// before they are considered a burst. + static int getDefaultMaximumUnbatchedDiagnostics() + { + return TfGetEnvSetting(MAYAUSD_MAXIMUM_UNBATCHED_DIAGNOSTICS); + } + + /// @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; + } + + triggerFlushInMainThreadIfNeeded(); + } + +private: + using Clock = std::chrono::steady_clock; + using TimePoint = Clock::time_point; + using Sec = std::chrono::seconds; - const auto diagnosticMessage = _FormatDiagnostic(err); + 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()); - if (ArchIsMainThread()) { - MGlobal::displayError(diagnosticMessage); - } else { - std::cerr << diagnosticMessage << std::endl; + return message.c_str(); } -} -void UsdMayaDiagnosticDelegate::IssueStatus(const TfStatus& status) -{ - if (_batchCount.load() > 0) { - return; // Batched. + 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(); + } } - const auto diagnosticMessage = _FormatDiagnostic(status); + 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 flushPerformedInMainThread() + { + TF_AXIOM(ArchIsMainThread()); + + _triggeredFlush = false; + const bool printBatched + = _pendingDiagnosticCount.fetch_and(0) > _maximumUnbatchedDiagnostics; - if (ArchIsMainThread()) { - MGlobal::displayInfo(diagnosticMessage); - } else { - std::cerr << diagnosticMessage << std::endl; + 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); } -} -void UsdMayaDiagnosticDelegate::IssueWarning(const TfWarning& warning) -{ - if (_batchCount.load() > 0) { - return; // Batched. + static void flushPerformedInMainThreadCallback(void* data) + { + DiagnosticFlusher* self = static_cast(data); + self->flushPerformedInMainThread(); } - const auto diagnosticMessage = _FormatDiagnostic(warning); + 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(); + } - if (ArchIsMainThread()) { - MGlobal::displayWarning(diagnosticMessage); - } else { - std::cerr << diagnosticMessage << std::endl; + void triggerFlushInMainThreadIfNeeded() + { + if (_triggeredFlush) + return; + _triggeredFlush = true; + triggerFlushInMainThread(); + } + + void triggerFlushInMainThread() + { + if (ArchIsMainThread()) { + flushPerformedInMainThread(); + } else { + MGlobal::executeTaskOnIdle(flushPerformedInMainThreadCallback, this); + } + } + + static TimePoint getElapsedTimePoint() { return Clock::now(); } + + void updateLastFlushTime() + { + const TimePoint now = getElapsedTimePoint(); + std::unique_lock lock(_pendingDiagnosticsMutex); + _lastFlushTime = now; } -} -void UsdMayaDiagnosticDelegate::IssueFatalError( - const TfCallContext& context, - const std::string& msg) + 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(); + } + + 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()) { - 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) { 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()) { - 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) { 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() { - TF_AXIOM(ArchIsMainThread()); - - if (_batchCount.fetch_add(1) == 0) { - // This is the first _StartBatch; add the batching delegates. - _batchedStatuses.reset(new _StatusOnlyDelegate()); - _batchedWarnings.reset(new _WarningOnlyDelegate()); - } + if (_flusher) + _flusher->forceFlush(); } -void UsdMayaDiagnosticDelegate::_EndBatch() +void UsdMayaDiagnosticDelegate::SetMaximumUnbatchedDiagnostics(int count) { - TF_AXIOM(ArchIsMainThread()); - - const int prevValue = _batchCount.fetch_sub(1); - if (prevValue <= 0) { - TF_FATAL_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(); - } + if (_flusher) + _flusher->setMaximumUnbatchedDiagnostics(count); } -void UsdMayaDiagnosticDelegate::_FlushBatch() +int UsdMayaDiagnosticDelegate::GetMaximumUnbatchedDiagnostics() { - 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)); - } + if (_flusher) + return _flusher->getMaximumUnbatchedDiagnostics(); + else + return DiagnosticFlusher::getDefaultMaximumUnbatchedDiagnostics(); } -UsdMayaDiagnosticBatchContext::UsdMayaDiagnosticBatchContext() - : _delegate(_IsDiagnosticBatchingEnabled() ? _sharedDelegate : nullptr) +UsdMayaDiagnosticBatchContext::UsdMayaDiagnosticBatchContext(int maximumUnbatchedCount) + : previousCount(UsdMayaDiagnosticDelegate::GetMaximumUnbatchedDiagnostics()) { + if (!IsDiagnosticBatchingEnabled()) + return; + 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(); - } + + UsdMayaDiagnosticDelegate::SetMaximumUnbatchedDiagnostics(maximumUnbatchedCount); + + _batchedContextCount.fetch_add(1); } UsdMayaDiagnosticBatchContext::~UsdMayaDiagnosticBatchContext() { + if (!IsDiagnosticBatchingEnabled()) + return; + 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(); - } + + 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 df52c1e2f6..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; + /// @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 issue a fatal coding -/// error. +/// 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..e29accbb74 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,45 @@ def testBatching(self): ("spam warning 0 -- and 2 similar", OM.MCommandMessage.kWarning) ]) + 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, [ + ("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 +227,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')