Print command stream histogram before crashing

filament/backend/include/private/backend/CommandBufferQueue.h

@@ -27,6 +27,8 @@
 #include <stddef.h>
 #include <stdint.h>
 
+#include <functional>
+
 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<void(void*, void*)> const& debugPrintHistogram = nullptr);
 
     // returns from waitForCommands() immediately.
     void requestExit();

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<void (Driver::*)(ARGS...)> {
 
 class CustomCommand : public CommandBase {
     std::function<void()> 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<void()> 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<NoopCommand*>(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<Execute, CommandInfo> 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<void(CommandInfo const& info)> 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.

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;

filament/backend/src/CommandBufferQueue.cpp

@@ -79,7 +79,7 @@ bool CommandBufferQueue::isExitRequested() const {
 }
 
 
-void CommandBufferQueue::flush() {
+void CommandBufferQueue::flush(std::function<void(void*, void*)> 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"

filament/backend/src/CommandStream.cpp

@@ -30,6 +30,11 @@
 #include <utils/ostream.h>
 #include <utils/sstream.h>
 
+#if FILAMENT_DEBUG_COMMANDS_HISTOGRAM
+#include <algorithm>
+#include <vector>
+#endif
+
 #include <cstddef>
 #include <functional>
 #include <string>
@@ -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<void(CommandInfo const& info)> const& callback) {
+    CommandBase* UTILS_RESTRICT base = static_cast<CommandBase*>(head);
+    auto p = base;
+    while (UTILS_LIKELY(p)) {
+        if (p >= tail) {
+            break;
+        }
+        Execute e = p->mExecute;
+
+        if (e == NoopCommand::execute) {
+            NoopCommand* noop = static_cast<NoopCommand*>(p);
+            size_t size = noop->mNext;
+            int noopIndex = mCommands[NoopCommand::execute].index;
+            callback({ size, "NoopCommand", noopIndex });
+            p = reinterpret_cast<CommandBase*>(reinterpret_cast<char*>(p) + size);
+            continue;
+        }
+
+        if (auto it = mCommands.find(e); it != mCommands.end()) {
+            size_t size = it->second.size;
+            callback(it->second);
+            p = reinterpret_cast<CommandBase*>(reinterpret_cast<char*>(p) + size);
+        } else {
+            LOG(ERROR) << "Cannot find command in lookup table";
+            return;
+        }
+    }
+}
+
+void CommandStream::debugPrintHistogram(void* head, void* tail) {
+    std::unordered_map<std::string_view, int> histogram;
+    std::unordered_map<int, int> index_histogram;
+    debugIterateCommands(head, tail, [&](CommandInfo const& info) {
+        histogram[std::string_view(info.name)]++;
+        index_histogram[info.index]++;
+    });
+
+    std::vector<std::pair<std::string_view, int>> 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<std::pair<int, int>> 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<void()> command) {
     new(allocateCommand(CustomCommand::align(sizeof(CustomCommand)))) CustomCommand(std::move(command));
 }

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<FEngine*>(this);
+#if FILAMENT_DEBUG_COMMANDS_HISTOGRAM
+        engine->getDriverApi().debugPrintHistogram(begin, end);
+#endif
+    });
 }
 
 const FMaterial* FEngine::getSkyboxMaterial() const noexcept {