Metal: log slow buffer allocation times (#7834)

google · May 8, 2024 · a1dea7b · a1dea7b
1 parent 744708b
commit a1dea7b
Show file tree

Hide file tree

Showing 4 changed files with 53 additions and 6 deletions.
diff --git a/filament/backend/src/metal/MetalBuffer.h b/filament/backend/src/metal/MetalBuffer.h
@@ -29,9 +29,42 @@
 #include <utility>
 #include <memory>
 #include <atomic>
+#include <chrono>
 
 namespace filament::backend {
 
+class ScopedAllocationTimer {
+public:
+    ScopedAllocationTimer(const char* name) : mBeginning(clock_t::now()), mName(name) {}
+    ~ScopedAllocationTimer() {
+        using namespace std::literals::chrono_literals;
+        static constexpr std::chrono::seconds LONG_TIME_THRESHOLD = 10s;
+
+        auto end = clock_t::now();
+        std::chrono::duration<double, std::micro> allocationTimeMicroseconds = end - mBeginning;
+
+        if (UTILS_UNLIKELY(allocationTimeMicroseconds > LONG_TIME_THRESHOLD)) {
+            if (platform && platform->hasDebugUpdateStatFunc()) {
+                char buffer[64];
+                snprintf(buffer, sizeof(buffer), "filament.metal.long_buffer_allocation_time.%s",
+                        mName);
+                platform->debugUpdateStat(
+                        buffer, static_cast<uint64_t>(allocationTimeMicroseconds.count()));
+            }
+        }
+    }
+
+    static void setPlatform(MetalPlatform* p) { platform = p; }
+
+private:
+    typedef std::chrono::steady_clock clock_t;
+
+    static MetalPlatform* platform;
+
+    std::chrono::time_point<clock_t> mBeginning;
+    const char* mName;
+};
+
 class TrackedMetalBuffer {
 public:
 
@@ -220,6 +253,7 @@ class MetalRingBuffer {
           mBufferOptions(options),
           mSlotSizeBytes(computeSlotSize(layout)),
           mSlotCount(slotCount) {
+        ScopedAllocationTimer timer("ring");
         mBuffer = { [device newBufferWithLength:mSlotSizeBytes * mSlotCount options:mBufferOptions],
             TrackedMetalBuffer::Type::RING };
         assert_invariant(mBuffer);
@@ -239,8 +273,11 @@ class MetalRingBuffer {
             // If we already have an aux buffer, it will get freed here, unless it has been retained
             // by a MTLCommandBuffer. In that case, it will be freed when the command buffer
             // finishes executing.
-            mAuxBuffer = { [mDevice newBufferWithLength:mSlotSizeBytes options:mBufferOptions],
-                TrackedMetalBuffer::Type::RING };
+            {
+                ScopedAllocationTimer timer("ring");
+                mAuxBuffer = { [mDevice newBufferWithLength:mSlotSizeBytes options:mBufferOptions],
+                    TrackedMetalBuffer::Type::RING };
+            }
             assert_invariant(mAuxBuffer);
             return { mAuxBuffer.get(), 0 };
         }

diff --git a/filament/backend/src/metal/MetalBuffer.mm b/filament/backend/src/metal/MetalBuffer.mm
@@ -24,6 +24,7 @@
 
 std::array<uint64_t, TrackedMetalBuffer::TypeCount> TrackedMetalBuffer::aliveBuffers = { 0 };
 MetalPlatform* TrackedMetalBuffer::platform = nullptr;
+MetalPlatform* ScopedAllocationTimer::platform = nullptr;
 
 MetalBuffer::MetalBuffer(MetalContext& context, BufferObjectBinding bindingType, BufferUsage usage,
         size_t size, bool forceGpuBuffer) : mBufferSize(size), mContext(context) {
@@ -38,8 +39,11 @@
     }
 
     // Otherwise, we allocate a private GPU buffer.
-    mBuffer = { [context.device newBufferWithLength:size options:MTLResourceStorageModePrivate],
-        TrackedMetalBuffer::Type::GENERIC };
+    {
+        ScopedAllocationTimer timer("generic");
+        mBuffer = { [context.device newBufferWithLength:size options:MTLResourceStorageModePrivate],
+            TrackedMetalBuffer::Type::GENERIC };
+    }
     ASSERT_POSTCONDITION(mBuffer, "Could not allocate Metal buffer of size %zu.", size);
 }
 

diff --git a/filament/backend/src/metal/MetalBufferPool.mm b/filament/backend/src/metal/MetalBufferPool.mm
@@ -42,8 +42,12 @@
     }
 
     // We were not able to find a sufficiently large stage, so create a new one.
-    id<MTLBuffer> buffer = [mContext.device newBufferWithLength:numBytes
-                                                        options:MTLResourceStorageModeShared];
+    id<MTLBuffer> buffer = nil;
+    {
+        ScopedAllocationTimer timer("staging");
+        buffer = [mContext.device newBufferWithLength:numBytes
+                                              options:MTLResourceStorageModeShared];
+    }
     ASSERT_POSTCONDITION(buffer, "Could not allocate Metal staging buffer of size %zu.", numBytes);
     MetalBufferPoolEntry* stage = new MetalBufferPoolEntry {
         .buffer = { buffer, TrackedMetalBuffer::Type::STAGING },

diff --git a/filament/backend/src/metal/MetalDriver.mm b/filament/backend/src/metal/MetalDriver.mm
@@ -106,6 +106,7 @@
     mContext->driver = this;
 
     TrackedMetalBuffer::setPlatform(platform);
+    ScopedAllocationTimer::setPlatform(platform);
 
     mContext->device = mPlatform.createDevice();
     assert_invariant(mContext->device);
@@ -201,6 +202,7 @@
 
 MetalDriver::~MetalDriver() noexcept {
     TrackedMetalBuffer::setPlatform(nullptr);
+    ScopedAllocationTimer::setPlatform(nullptr);
     mContext->device = nil;
     mContext->emptyTexture = nil;
     CFRelease(mContext->textureCache);