birkeh/o3de
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

Debug Trace Messages for Automation queues bus calls. (#2328)

Browse Source 
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 <moraaar@amazon.com>
This commit is contained in:
moraaar
2021-07-23 08:40:03 +01:00
committed by GitHub
parent 4268376587
commit 1a407d9a08
2 changed files with 275 additions and 27 deletions
Download Patch File Download Diff File Expand all files Collapse all files
Code/Framework/AzCore/AzCore/Debug/TraceReflection.cpp
+200 -27
View File
@@ -10,28 +10,74 @@
#include <AzCore/Debug/TraceMessageBus.h>
#include <AzCore/RTTI/BehaviorContext.h>
#include <AzCore/Script/ScriptContext.h>
#include <AzCore/Component/TickBus.h>
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<class R, class... Args>
R CallResultReturn(const R& defaultReturnValue, int index, Args&&... args) const
{
R returnVal = defaultReturnValue;
CallResult(returnVal, index, AZStd::forward<Args>(args)...);
return returnVal;
}
void QueueMessageCall(AZStd::function<void()> messageCall);
void FlushMessageCalls();
AZStd::list<AZStd::function<void()>> 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<AZ::Debug::TraceMessageBus::Handler>::Connect(this, id);
}
bool TraceMessageBusHandler::IsConnected()
{
return AZ::Internal::EBusConnector<AZ::Debug::TraceMessageBus::Handler>::IsConnected(this);
}
bool TraceMessageBusHandler::IsConnectedId(AZ::BehaviorValueParameter* id)
{
return AZ::Internal::EBusConnector<AZ::Debug::TraceMessageBus::Handler>::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<void()> messageCall)
{
AZStd::lock_guard<decltype(m_messageCallsLock)> lock(m_messageCallsLock);
m_messageCalls.push_back(messageCall);
}
void TraceMessageBusHandler::FlushMessageCalls()
{
AZStd::list<AZStd::function<void()>> messageCalls;
{
AZStd::lock_guard<decltype(m_messageCallsLock)> 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)
{
Gems/EditorPythonBindings/Code/Tests/PythonThreadingTests.cpp
+75
View File
@@ -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<int>(LogTypes::OnPrewarning);
}
}
return aznumeric_cast<int>(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<AZStd::thread> 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<int>(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<int>(LogTypes::OnPrewarning)]);
}
catch ([[maybe_unused]] const std::exception& e)
{
AZ_Error("UnitTest", false, "Failed during thread test with %s", e.what());
}
e.Deactivate();
}
}