diff --git a/filament/backend/include/private/backend/CommandBufferQueue.h b/filament/backend/include/private/backend/CommandBufferQueue.h index a33778b93323..5405915c9cbb 100644 --- a/filament/backend/include/private/backend/CommandBufferQueue.h +++ b/filament/backend/include/private/backend/CommandBufferQueue.h @@ -27,6 +27,8 @@ #include #include +#include + namespace filament::backend { /* @@ -64,7 +66,7 @@ class CommandBufferQueue { // all commands buffers (Slices) written to this point are returned by waitForCommand(). This // call blocks until the CircularBuffer has at least mRequiredSize bytes available. - void flush(); + void flush(std::function const& debugPrintHistogram = nullptr); // returns from waitForCommands() immediately. void requestExit(); diff --git a/filament/backend/include/private/backend/CommandStream.h b/filament/backend/include/private/backend/CommandStream.h index 5b288ef7bd44..a6e58676eb9b 100644 --- a/filament/backend/include/private/backend/CommandStream.h +++ b/filament/backend/include/private/backend/CommandStream.h @@ -56,6 +56,7 @@ namespace filament::backend { class CommandBase { static constexpr size_t FILAMENT_OBJECT_ALIGNMENT = alignof(std::max_align_t); + friend class CommandStream; protected: using Execute = Dispatcher::Execute; @@ -168,8 +169,8 @@ struct CommandType { class CustomCommand : public CommandBase { std::function mCommand; - static void execute(Driver&, CommandBase* base, intptr_t* next); public: + static void execute(Driver&, CommandBase* base, intptr_t* next); CustomCommand(CustomCommand&& rhs) = default; explicit CustomCommand(std::function cmd) @@ -179,11 +180,12 @@ class CustomCommand : public CommandBase { // ------------------------------------------------------------------------------------------------ class NoopCommand : public CommandBase { +public: intptr_t mNext; static void execute(Driver&, CommandBase* self, intptr_t* next) noexcept { *next = static_cast(self)->mNext; } -public: + constexpr explicit NoopCommand(void* next) noexcept : CommandBase(execute), mNext(intptr_t((char *)next - (char *)this)) { } }; @@ -219,6 +221,36 @@ class CommandStream { CircularBuffer const& getCircularBuffer() const noexcept { return mCurrentBuffer; } +#if FILAMENT_DEBUG_COMMANDS_HISTOGRAM + using Execute = Dispatcher::Execute; + struct CommandInfo { + size_t size; + const char* name; + int index; + }; + std::unordered_map mCommands; + + void initializeLookup() { + int currentIndex = 0; +#define DECL_DRIVER_API_SYNCHRONOUS(RetType, methodName, paramsDecl, params) +#define DECL_DRIVER_API(methodName, paramsDecl, params) \ + mCommands[mDispatcher.methodName##_] = { CommandBase::align(sizeof(COMMAND_TYPE(methodName))), \ + #methodName, currentIndex++ }; +#define DECL_DRIVER_API_RETURN(RetType, methodName, paramsDecl, params) \ + mCommands[mDispatcher.methodName##_] = { \ + CommandBase::align(sizeof(COMMAND_TYPE(methodName##R))), #methodName, currentIndex++ \ + }; + +#include "private/backend/DriverAPI.inc" + + mCommands[CustomCommand::execute] = { CommandBase::align(sizeof(CustomCommand)), + "CustomCommand", currentIndex++ }; + + // NoopCommands have variable size. We will handle them specially using their mNext pointer. + mCommands[NoopCommand::execute] = { 0, "NoopCommand", currentIndex++ }; + } +#endif + public: #define DECL_DRIVER_API(methodName, paramsDecl, params) \ inline void methodName(paramsDecl) noexcept { \ @@ -263,6 +295,13 @@ class CommandStream { void execute(void* buffer); +#if FILAMENT_DEBUG_COMMANDS_HISTOGRAM + void debugIterateCommands(void* head, void* tail, + std::function const& callback); + + void debugPrintHistogram(void* head, void* tail); +#endif + /* * queueCommand() allows to queue a lambda function as a command. * This is much less efficient than using the Driver* API. diff --git a/filament/backend/include/private/backend/Driver.h b/filament/backend/include/private/backend/Driver.h index ed2ff9b27c97..c2bfa19b94e9 100644 --- a/filament/backend/include/private/backend/Driver.h +++ b/filament/backend/include/private/backend/Driver.h @@ -48,6 +48,11 @@ #define FILAMENT_DEBUG_COMMANDS FILAMENT_DEBUG_COMMANDS_NONE +// Upon command stream overflow, print a histogram of commands +#ifndef FILAMENT_DEBUG_COMMANDS_HISTOGRAM +#define FILAMENT_DEBUG_COMMANDS_HISTOGRAM 0 +#endif + namespace filament::backend { class BufferDescriptor; diff --git a/filament/backend/src/CommandBufferQueue.cpp b/filament/backend/src/CommandBufferQueue.cpp index 5ea8aacd03a9..1ca8a6f04b81 100644 --- a/filament/backend/src/CommandBufferQueue.cpp +++ b/filament/backend/src/CommandBufferQueue.cpp @@ -79,7 +79,7 @@ bool CommandBufferQueue::isExitRequested() const { } -void CommandBufferQueue::flush() { +void CommandBufferQueue::flush(std::function const& debugPrintHistogram) { FILAMENT_TRACING_CALL(FILAMENT_TRACING_CATEGORY_FILAMENT); CircularBuffer& circularBuffer = mCircularBuffer; @@ -106,6 +106,13 @@ void CommandBufferQueue::flush() { std::unique_lock lock(mLock); // circular buffer is too small, we corrupted the stream +#if FILAMENT_DEBUG_COMMANDS_HISTOGRAM + if (UTILS_VERY_UNLIKELY(used > mFreeSpace)) { + if (debugPrintHistogram) { + debugPrintHistogram(begin, end); + } + } +#endif FILAMENT_CHECK_POSTCONDITION(used <= mFreeSpace) << "Backend CommandStream overflow. Commands are corrupted and unrecoverable.\n" "Please increase minCommandBufferSizeMB inside the Config passed to Engine::create.\n" diff --git a/filament/backend/src/CommandStream.cpp b/filament/backend/src/CommandStream.cpp index 4266683f6204..e3787d55074f 100644 --- a/filament/backend/src/CommandStream.cpp +++ b/filament/backend/src/CommandStream.cpp @@ -30,6 +30,11 @@ #include #include +#if FILAMENT_DEBUG_COMMANDS_HISTOGRAM +#include +#include +#endif + #include #include #include @@ -83,6 +88,10 @@ CommandStream::CommandStream(Driver& driver, CircularBuffer& buffer) noexcept __system_property_get("debug.filament.perfcounters", property); mUsePerformanceCounter = bool(atoi(property)); #endif + +#if FILAMENT_DEBUG_COMMANDS_HISTOGRAM + initializeLookup(); +#endif } void CommandStream::execute(void* buffer) { @@ -126,6 +135,71 @@ void CommandStream::execute(void* buffer) { } } +#if FILAMENT_DEBUG_COMMANDS_HISTOGRAM +void CommandStream::debugIterateCommands(void* head, void* tail, + std::function const& callback) { + CommandBase* UTILS_RESTRICT base = static_cast(head); + auto p = base; + while (UTILS_LIKELY(p)) { + if (p >= tail) { + break; + } + Execute e = p->mExecute; + + if (e == NoopCommand::execute) { + NoopCommand* noop = static_cast(p); + size_t size = noop->mNext; + int noopIndex = mCommands[NoopCommand::execute].index; + callback({ size, "NoopCommand", noopIndex }); + p = reinterpret_cast(reinterpret_cast(p) + size); + continue; + } + + if (auto it = mCommands.find(e); it != mCommands.end()) { + size_t size = it->second.size; + callback(it->second); + p = reinterpret_cast(reinterpret_cast(p) + size); + } else { + LOG(ERROR) << "Cannot find command in lookup table"; + return; + } + } +} + +void CommandStream::debugPrintHistogram(void* head, void* tail) { + std::unordered_map histogram; + std::unordered_map index_histogram; + debugIterateCommands(head, tail, [&](CommandInfo const& info) { + histogram[std::string_view(info.name)]++; + index_histogram[info.index]++; + }); + + std::vector> sorted_histogram(histogram.begin(), + histogram.end()); + std::sort(sorted_histogram.begin(), sorted_histogram.end(), + [](auto const& a, auto const& b) { return a.second > b.second; }); + + LOG(INFO) << "Command stream histogram:"; + for (auto const& [name, count]: sorted_histogram) { + LOG(INFO) << name << ": " << count; + } + + std::vector> sorted_index_histogram(index_histogram.begin(), + index_histogram.end()); + std::sort(sorted_index_histogram.begin(), sorted_index_histogram.end(), + [](auto const& a, auto const& b) { return a.second > b.second; }); + + std::string short_histogram = ""; + for (size_t i = 0, n = sorted_index_histogram.size(); i < n; ++i) { + short_histogram += std::to_string(sorted_index_histogram[i].first) + ":" + + std::to_string(sorted_index_histogram[i].second); + short_histogram += (i < n - 1) ? ";" : "."; + } + LOG(INFO) << "CS hist: " << short_histogram; + LOG(INFO) << ""; +} +#endif + void CommandStream::queueCommand(std::function command) { new(allocateCommand(CustomCommand::align(sizeof(CustomCommand)))) CustomCommand(std::move(command)); } diff --git a/filament/src/details/Engine.cpp b/filament/src/details/Engine.cpp index 4010eb30db17..bbccc8407684 100644 --- a/filament/src/details/Engine.cpp +++ b/filament/src/details/Engine.cpp @@ -920,7 +920,12 @@ int FEngine::loop() { void FEngine::flushCommandBuffer(CommandBufferQueue& commandBufferQueue) const { getDriver().purge(); - commandBufferQueue.flush(); + commandBufferQueue.flush([this](void* begin, void* end) { + UTILS_UNUSED FEngine* engine = const_cast(this); +#if FILAMENT_DEBUG_COMMANDS_HISTOGRAM + engine->getDriverApi().debugPrintHistogram(begin, end); +#endif + }); } const FMaterial* FEngine::getSkyboxMaterial() const noexcept {