From 1a407d9a0842128dd18d83542bd5d7d8982a9c96 Mon Sep 17 00:00:00 2001 From: moraaar Date: Fri, 23 Jul 2021 08:40:03 +0100 Subject: [PATCH] Debug Trace Messages for Automation queues bus calls. (#2328) Since TraceMessageBus will be called from multiple threads and python interpreter is single threaded, all the bus calls are queued into a list and called at the end of the frame in the main thread. Signed-off-by: moraaar --- .../AzCore/AzCore/Debug/TraceReflection.cpp | 227 +++++++++++++++--- .../Code/Tests/PythonThreadingTests.cpp | 75 ++++++ 2 files changed, 275 insertions(+), 27 deletions(-) diff --git a/Code/Framework/AzCore/AzCore/Debug/TraceReflection.cpp b/Code/Framework/AzCore/AzCore/Debug/TraceReflection.cpp index 4e9d7a698b..debbea5235 100644 --- a/Code/Framework/AzCore/AzCore/Debug/TraceReflection.cpp +++ b/Code/Framework/AzCore/AzCore/Debug/TraceReflection.cpp @@ -10,28 +10,74 @@ #include #include #include +#include namespace AZ { namespace Debug { + //! Trace Message Event Handler for Automation. + //! Since TraceMessageBus will be called from multiple threads and + //! python interpreter is single threaded, all the bus calls are + //! queued into a list and called at the end of the frame in the main thread. + //! @note this class is not using the usual AZ_EBUS_BEHAVIOR_BINDER + //! macro as the signature needs to be changed to connect to Tick bus. class TraceMessageBusHandler : public AZ::Debug::TraceMessageBus::Handler , public AZ::BehaviorEBusHandler + , public AZ::TickBus::Handler { public: + AZ_CLASS_ALLOCATOR(TraceMessageBusHandler, AZ::SystemAllocator, 0); + AZ_RTTI(TraceMessageBusHandler, "{5CDBAF09-5EB0-48AC-B327-2AF8601BB550}", AZ::BehaviorEBusHandler); - AZ_EBUS_BEHAVIOR_BINDER(TraceMessageBusHandler, "{5CDBAF09-5EB0-48AC-B327-2AF8601BB550}", AZ::SystemAllocator - , OnPreAssert - , OnPreError - , OnPreWarning - , OnAssert - , OnError - , OnWarning - , OnException - , OnPrintf - , OnOutput - ); + TraceMessageBusHandler(); + + using EventFunctionsParameterPack = AZStd::Internal::pack_traits_arg_sequence< + decltype(&TraceMessageBusHandler::OnPreAssert), + decltype(&TraceMessageBusHandler::OnPreError), + decltype(&TraceMessageBusHandler::OnPreWarning), + decltype(&TraceMessageBusHandler::OnAssert), + decltype(&TraceMessageBusHandler::OnError), + decltype(&TraceMessageBusHandler::OnWarning), + decltype(&TraceMessageBusHandler::OnException), + decltype(&TraceMessageBusHandler::OnPrintf), + decltype(&TraceMessageBusHandler::OnOutput) + >; + + enum + { + FN_OnPreAssert = 0, + FN_OnPreError, + FN_OnPreWarning, + FN_OnAssert, + FN_OnError, + FN_OnWarning, + FN_OnException, + FN_OnPrintf, + FN_OnOutput, + FN_MAX + }; + + static inline constexpr const char* m_functionNames[FN_MAX] = + { + "OnPreAssert", + "OnPreError", + "OnPreWarning", + "OnAssert", + "OnError", + "OnWarning", + "OnException", + "OnPrintf", + "OnOutput" + }; + + // AZ::BehaviorEBusHandler overrides... + int GetFunctionIndex(const char* functionName) const override; + void Disconnect() override; + bool Connect(AZ::BehaviorValueParameter* id = nullptr) override; + bool IsConnected() override; + bool IsConnectedId(AZ::BehaviorValueParameter* id) override; // TraceMessageBus /* @@ -48,63 +94,190 @@ namespace AZ bool OnPrintf(const char* window, const char* message) override; bool OnOutput(const char* window, const char* message) override; + // AZ::TickBus::Handler overrides ... + void OnTick(float deltaTime, AZ::ScriptTimePoint time) override; + int GetTickOrder() override; + private: - template - R CallResultReturn(const R& defaultReturnValue, int index, Args&&... args) const - { - R returnVal = defaultReturnValue; - CallResult(returnVal, index, AZStd::forward(args)...); - return returnVal; - } + void QueueMessageCall(AZStd::function messageCall); + void FlushMessageCalls(); + + AZStd::list> m_messageCalls; + AZStd::mutex m_messageCallsLock; }; + TraceMessageBusHandler::TraceMessageBusHandler() + { + m_events.resize(FN_MAX); + + SetEvent(&TraceMessageBusHandler::OnPreAssert, m_functionNames[FN_OnPreAssert]); + SetEvent(&TraceMessageBusHandler::OnPreError, m_functionNames[FN_OnPreError]); + SetEvent(&TraceMessageBusHandler::OnPreWarning, m_functionNames[FN_OnPreWarning]); + SetEvent(&TraceMessageBusHandler::OnAssert, m_functionNames[FN_OnAssert]); + SetEvent(&TraceMessageBusHandler::OnError, m_functionNames[FN_OnError]); + SetEvent(&TraceMessageBusHandler::OnWarning, m_functionNames[FN_OnWarning]); + SetEvent(&TraceMessageBusHandler::OnException, m_functionNames[FN_OnException]); + SetEvent(&TraceMessageBusHandler::OnPrintf, m_functionNames[FN_OnPrintf]); + SetEvent(&TraceMessageBusHandler::OnOutput, m_functionNames[FN_OnOutput]); + } + + int TraceMessageBusHandler::GetFunctionIndex(const char* functionName) const + { + for (int i = 0; i < FN_MAX; ++i) + { + if (azstricmp(functionName, m_functionNames[i]) == 0) + { + return i; + } + } + return -1; + } + + void TraceMessageBusHandler::Disconnect() + { + AZ::Debug::TraceMessageBus::Handler::BusDisconnect(); + AZ::TickBus::Handler::BusDisconnect(); + } + + bool TraceMessageBusHandler::Connect(AZ::BehaviorValueParameter* id) + { + AZ::TickBus::Handler::BusConnect(); + return AZ::Internal::EBusConnector::Connect(this, id); + } + + bool TraceMessageBusHandler::IsConnected() + { + return AZ::Internal::EBusConnector::IsConnected(this); + } + + bool TraceMessageBusHandler::IsConnectedId(AZ::BehaviorValueParameter* id) + { + return AZ::Internal::EBusConnector::IsConnectedId(this, id); + } + ////////////////////////////////////////////////////////////////////////// // TraceMessageBusHandler Implementation inline bool TraceMessageBusHandler::OnPreAssert(const char* fileName, int line, const char* func, const char* message) { - return CallResultReturn(false, FN_OnPreAssert, fileName, line, func, message); + QueueMessageCall( + [this, fileNameString = AZStd::string(fileName), line, funcString = AZStd::string(func), messageString = AZStd::string(message)]() + { + Call(FN_OnPreAssert, fileNameString.c_str(), line, funcString.c_str(), messageString.c_str()); + }); + return false; } inline bool TraceMessageBusHandler::OnPreError(const char* window, const char* fileName, int line, const char* func, const char* message) { - return CallResultReturn(false, FN_OnPreError, window, fileName, line, func, message); + QueueMessageCall( + [this, windowString = AZStd::string(window), fileNameString = AZStd::string(fileName), line, funcString = AZStd::string(func), messageString = AZStd::string(message)]() + { + Call(FN_OnPreError, windowString.c_str(), fileNameString.c_str(), line, funcString.c_str(), messageString.c_str()); + }); + return false; } inline bool TraceMessageBusHandler::OnPreWarning(const char* window, const char* fileName, int line, const char* func, const char* message) { - return CallResultReturn(false, FN_OnPreWarning, window, fileName, line, func, message); + QueueMessageCall( + [this, windowString = AZStd::string(window), fileNameString = AZStd::string(fileName), line, funcString = AZStd::string(func), messageString = AZStd::string(message)]() + { + return Call(FN_OnPreWarning, windowString.c_str(), fileNameString.c_str(), line, funcString.c_str(), messageString.c_str()); + }); + return false; } inline bool TraceMessageBusHandler::OnAssert(const char* message) { - return CallResultReturn(false, FN_OnAssert, message); + QueueMessageCall( + [this, messageString = AZStd::string(message)]() + { + return Call(FN_OnAssert, messageString.c_str()); + }); + return false; } inline bool TraceMessageBusHandler::OnError(const char* window, const char* message) { - return CallResultReturn(false, FN_OnError, window, message); + QueueMessageCall( + [this, windowString = AZStd::string(window), messageString = AZStd::string(message)]() + { + return Call(FN_OnError, windowString.c_str(), messageString.c_str()); + }); + return false; } inline bool TraceMessageBusHandler::OnWarning(const char* window, const char* message) { - return CallResultReturn(false, FN_OnWarning, window, message); + QueueMessageCall( + [this, windowString = AZStd::string(window), messageString = AZStd::string(message)]() + { + return Call(FN_OnWarning, windowString.c_str(), messageString.c_str()); + }); + return false; } inline bool TraceMessageBusHandler::OnException(const char* message) { - return CallResultReturn(false, FN_OnException, message); + QueueMessageCall( + [this, messageString = AZStd::string(message)]() + { + return Call(FN_OnException, messageString.c_str()); + }); + return false; } inline bool TraceMessageBusHandler::OnPrintf(const char* window, const char* message) { - return CallResultReturn(false, FN_OnPrintf, window, message); + QueueMessageCall( + [this, windowString = AZStd::string(window), messageString = AZStd::string(message)]() + { + return Call(FN_OnPrintf, windowString.c_str(), messageString.c_str()); + }); + return false; } inline bool TraceMessageBusHandler::OnOutput(const char* window, const char* message) { - return CallResultReturn(false, FN_OnOutput, window, message); + QueueMessageCall( + [this, windowString = AZStd::string(window), messageString = AZStd::string(message)]() + { + return Call(FN_OnOutput, windowString.c_str(), messageString.c_str()); + }); + return false; } + void TraceMessageBusHandler::OnTick( + [[maybe_unused]] float deltaTime, + [[maybe_unused]] AZ::ScriptTimePoint time) + { + FlushMessageCalls(); + } + + int TraceMessageBusHandler::GetTickOrder() + { + return AZ::TICK_LAST; + } + + void TraceMessageBusHandler::QueueMessageCall(AZStd::function messageCall) + { + AZStd::lock_guard lock(m_messageCallsLock); + m_messageCalls.push_back(messageCall); + } + + void TraceMessageBusHandler::FlushMessageCalls() + { + AZStd::list> messageCalls; + { + AZStd::lock_guard lock(m_messageCallsLock); + m_messageCalls.swap(messageCalls); // Move calls to a new list to release the lock as soon as possible + } + + for (auto& messageCall : messageCalls) + { + messageCall(); + } + } void TraceReflect(ReflectContext* context) { diff --git a/Gems/EditorPythonBindings/Code/Tests/PythonThreadingTests.cpp b/Gems/EditorPythonBindings/Code/Tests/PythonThreadingTests.cpp index b1cb2ef162..b2e18265cb 100644 --- a/Gems/EditorPythonBindings/Code/Tests/PythonThreadingTests.cpp +++ b/Gems/EditorPythonBindings/Code/Tests/PythonThreadingTests.cpp @@ -217,4 +217,79 @@ namespace UnitTest e.Deactivate(); } + TEST_F(PythonThreadingTest, PythonInterface_DebugTrace_CallsOnTick) + { + enum class LogTypes + { + Skip = 0, + OnPrewarning + }; + + m_testSink.m_evaluateMessage = [](const char* window, const char* message) -> int + { + if (AzFramework::StringFunc::Equal(window, "python")) + { + if (AzFramework::StringFunc::StartsWith(message, "OnPrewarning")) + { + return aznumeric_cast(LogTypes::OnPrewarning); + } + } + return aznumeric_cast(LogTypes::Skip); + }; + + AZ::Entity e; + Activate(e); + SimulateEditorBecomingInitialized(); + + try + { + // prepare handler on this thread + pybind11::exec(R"( + import azlmbr.debug + + def on_prewarning(args): + print ('OnPrewarning: ' + args[0]) + + handler = azlmbr.debug.TraceMessageBusHandler() + handler.connect() + handler.add_callback('OnPreWarning', on_prewarning) + )"); + + const size_t numWarnings = 64; + auto doWarning = []() + { + AZ_Warning("PythonThreadingTest", false, "This is a warning message"); + }; + + // start threads. In thread issue a warning. + AZStd::vector threads; + threads.reserve(numWarnings); + for (size_t i = 0; i < numWarnings; ++i) + { + threads.emplace_back(doWarning); + } + for (AZStd::thread& thread : threads) + { + thread.join(); + } + + // No prewarning calls should have happened because all of them were queued + EXPECT_EQ(0, m_testSink.m_evaluationMap[aznumeric_cast(LogTypes::OnPrewarning)]); + + // Do one tick + const float timeOneFrameSeconds = 0.016f; //approx 60 fps + AZ::TickBus::Broadcast(&AZ::TickEvents::OnTick, + timeOneFrameSeconds, + AZ::ScriptTimePoint(AZStd::chrono::system_clock::now())); + + // After one tick all the queued calls should have been processed + EXPECT_EQ(numWarnings, m_testSink.m_evaluationMap[aznumeric_cast(LogTypes::OnPrewarning)]); + } + catch ([[maybe_unused]] const std::exception& e) + { + AZ_Error("UnitTest", false, "Failed during thread test with %s", e.what()); + } + + e.Deactivate(); + } }