Add per-buffer perfetto trace points for SurfaceFlinger frame events

In order to track how buffers move through the system, we add per-buffer perfetto trace points for SurfaceFlinger.
The majority of these were already tracked through TimeStats, so the new tracing was built on top of TimeStats.

Test: atest libsurfaceflinger_unittest

Run trace with:
{ adb shell perfetto   -c - --txt   -o /data/misc/perfetto-traces/trace <<EOF
buffers: {
    size_kb: 1280
}
data_sources: {
    config {
        name: "android.surfaceflinger.timestats"
    }
}
duration_ms: 3000
EOF
} && adb pull /data/misc/perfetto-traces/trace ~/Desktop/trace

Change-Id: Ifb38c64a9966fece735f0ad72438c7c9c5e07baa
diff --git a/services/surfaceflinger/TimeStats/Android.bp b/services/surfaceflinger/TimeStats/Android.bp
new file mode 100644
index 0000000..9e1d503
--- /dev/null
+++ b/services/surfaceflinger/TimeStats/Android.bp
@@ -0,0 +1,15 @@
+cc_library_static {
+    name: "libtimestats",
+    defaults: ["surfaceflinger_defaults"],
+    srcs: [
+      "TimeStats.cpp"
+    ],
+    export_include_dirs: ["."],
+    static_libs: [
+      "libperfetto_client_experimental",
+    ],
+    shared_libs: [
+      "libtimestats_proto",
+      "libui",
+    ],
+}
diff --git a/services/surfaceflinger/TimeStats/TimeStats.cpp b/services/surfaceflinger/TimeStats/TimeStats.cpp
index 3e3ab18..b66e4cf 100644
--- a/services/surfaceflinger/TimeStats/TimeStats.cpp
+++ b/services/surfaceflinger/TimeStats/TimeStats.cpp
@@ -30,10 +30,141 @@
 #include <algorithm>
 #include <regex>
 
+PERFETTO_DEFINE_DATA_SOURCE_STATIC_MEMBERS(android::impl::TimeStats::TimeStatsDataSource);
+
 namespace android {
 
 namespace impl {
 
+void TimeStats::initializeTracing() {
+    perfetto::TracingInitArgs args;
+    args.backends = perfetto::kSystemBackend;
+    perfetto::Tracing::Initialize(args);
+    registerTracingDataSource();
+}
+
+void TimeStats::registerTracingDataSource() {
+    perfetto::DataSourceDescriptor dsd;
+    dsd.set_name(kTimeStatsDataSource);
+    TimeStatsDataSource::Register(dsd);
+}
+
+void TimeStats::traceNewLayer(int32_t layerID, const std::string& layerName) {
+    TimeStatsDataSource::Trace([this, layerID, &layerName](TimeStatsDataSource::TraceContext) {
+        if (mTraceTracker.find(layerID) == mTraceTracker.end()) {
+            std::lock_guard<std::mutex> lock(mTraceMutex);
+            mTraceTracker[layerID].layerName = layerName;
+        }
+    });
+}
+
+void TimeStats::traceTimestamp(int32_t layerID, uint64_t bufferID, uint64_t frameNumber,
+                               nsecs_t timestamp, FrameEvent::BufferEventType type,
+                               nsecs_t duration) {
+    TimeStatsDataSource::Trace([this, layerID, bufferID, frameNumber, timestamp, type,
+                                duration](TimeStatsDataSource::TraceContext ctx) {
+        std::lock_guard<std::mutex> lock(mTraceMutex);
+        if (mTraceTracker.find(layerID) == mTraceTracker.end()) {
+            return;
+        }
+
+        // Handle any pending fences for this buffer.
+        tracePendingFencesLocked(ctx, layerID, bufferID);
+
+        // Complete current trace.
+        traceLocked(ctx, layerID, bufferID, frameNumber, timestamp, type, duration);
+    });
+}
+
+void TimeStats::traceFence(int32_t layerID, uint64_t bufferID, uint64_t frameNumber,
+                           const std::shared_ptr<FenceTime>& fence,
+                           FrameEvent::BufferEventType type, nsecs_t startTime) {
+    TimeStatsDataSource::Trace([this, layerID, bufferID, frameNumber, &fence, type,
+                                startTime](TimeStatsDataSource::TraceContext ctx) {
+        const nsecs_t signalTime = fence->getSignalTime();
+        if (signalTime != Fence::SIGNAL_TIME_INVALID) {
+            std::lock_guard<std::mutex> lock(mTraceMutex);
+            if (mTraceTracker.find(layerID) == mTraceTracker.end()) {
+                return;
+            }
+
+            // Handle any pending fences for this buffer.
+            tracePendingFencesLocked(ctx, layerID, bufferID);
+
+            if (signalTime != Fence::SIGNAL_TIME_PENDING) {
+                traceSpanLocked(ctx, layerID, bufferID, frameNumber, type, startTime, signalTime);
+            } else {
+                mTraceTracker[layerID].pendingFences[bufferID].push_back(
+                        {.frameNumber = frameNumber,
+                         .type = type,
+                         .fence = fence,
+                         .startTime = startTime});
+            }
+        }
+    });
+}
+
+void TimeStats::tracePendingFencesLocked(TimeStatsDataSource::TraceContext& ctx, int32_t layerID,
+                                         uint64_t bufferID) {
+    if (mTraceTracker[layerID].pendingFences.count(bufferID)) {
+        auto& pendingFences = mTraceTracker[layerID].pendingFences[bufferID];
+        for (size_t i = 0; i < pendingFences.size(); ++i) {
+            auto& pendingFence = pendingFences[i];
+
+            nsecs_t signalTime = Fence::SIGNAL_TIME_INVALID;
+            if (pendingFence.fence && pendingFence.fence->isValid()) {
+                signalTime = pendingFence.fence->getSignalTime();
+                if (signalTime == Fence::SIGNAL_TIME_PENDING) {
+                    continue;
+                }
+            }
+
+            if (signalTime != Fence::SIGNAL_TIME_INVALID &&
+                systemTime() - signalTime < kFenceSignallingDeadline) {
+                traceSpanLocked(ctx, layerID, bufferID, pendingFence.frameNumber, pendingFence.type,
+                                pendingFence.startTime, signalTime);
+            }
+
+            pendingFences.erase(pendingFences.begin() + i);
+            --i;
+        }
+    }
+}
+
+void TimeStats::traceLocked(TimeStatsDataSource::TraceContext& ctx, int32_t layerID,
+                            uint64_t bufferID, uint64_t frameNumber, nsecs_t timestamp,
+                            FrameEvent::BufferEventType type, nsecs_t duration) {
+    auto packet = ctx.NewTracePacket();
+    packet->set_timestamp(timestamp);
+    auto* event = packet->set_graphics_frame_event()->set_buffer_event();
+    event->set_buffer_id(static_cast<uint32_t>(bufferID));
+    event->set_frame_number(frameNumber);
+    event->set_type(type);
+
+    if (mTraceTracker.find(layerID) != mTraceTracker.end() &&
+        !mTraceTracker[layerID].layerName.empty()) {
+        const std::string& layerName = mTraceTracker[layerID].layerName;
+        event->set_layer_name(layerName.c_str(), layerName.size());
+    }
+
+    if (duration > 0) {
+        event->set_duration_ns(duration);
+    }
+}
+
+void TimeStats::traceSpanLocked(TimeStatsDataSource::TraceContext& ctx, int32_t layerID,
+                                uint64_t bufferID, uint64_t frameNumber,
+                                FrameEvent::BufferEventType type, nsecs_t startTime,
+                                nsecs_t endTime) {
+    nsecs_t timestamp = endTime;
+    nsecs_t duration = 0;
+    if (startTime > 0 && startTime < endTime) {
+        timestamp = startTime;
+        duration = endTime - startTime;
+    }
+    traceLocked(ctx, layerID, bufferID, frameNumber, timestamp, type, duration);
+}
+
 void TimeStats::parseArgs(bool asProto, const Vector<String16>& args, std::string& result) {
     ATRACE_CALL();
 
@@ -76,6 +207,8 @@
                                  mTimeStatsTracker.size());
     android::base::StringAppendF(&result, "Number of layers in the stats pool is %zu\n",
                                  mTimeStats.stats.size());
+    android::base::StringAppendF(&result, "Number of layers currently being traced is %zu\n",
+                                 mTraceTracker.size());
     return result;
 }
 
@@ -407,14 +540,17 @@
 }
 
 void TimeStats::onDestroy(int32_t layerID) {
-    if (!mEnabled.load()) return;
-
     ATRACE_CALL();
     ALOGV("[%d]-onDestroy", layerID);
+    {
+        std::lock_guard<std::mutex> lock(mMutex);
+        mTimeStatsTracker.erase(layerID);
+    }
 
-    std::lock_guard<std::mutex> lock(mMutex);
-    if (!mTimeStatsTracker.count(layerID)) return;
-    mTimeStatsTracker.erase(layerID);
+    {
+        std::lock_guard<std::mutex> traceLock(mTraceMutex);
+        mTraceTracker.erase(layerID);
+    }
 }
 
 void TimeStats::removeTimeRecord(int32_t layerID, uint64_t frameNumber) {
diff --git a/services/surfaceflinger/TimeStats/TimeStats.h b/services/surfaceflinger/TimeStats/TimeStats.h
index eed7111..470137a 100644
--- a/services/surfaceflinger/TimeStats/TimeStats.h
+++ b/services/surfaceflinger/TimeStats/TimeStats.h
@@ -16,13 +16,12 @@
 
 #pragma once
 
+#include <hardware/hwcomposer_defs.h>
+#include <perfetto/trace/android/graphics_frame_event.pbzero.h>
+#include <perfetto/tracing.h>
 #include <timestatsproto/TimeStatsHelper.h>
 #include <timestatsproto/TimeStatsProtoHeader.h>
-
-#include <hardware/hwcomposer_defs.h>
-
 #include <ui/FenceTime.h>
-
 #include <utils/String16.h>
 #include <utils/Vector.h>
 
@@ -37,8 +36,32 @@
 
 class TimeStats {
 public:
+    using FrameEvent = perfetto::protos::pbzero::GraphicsFrameEvent;
+
     virtual ~TimeStats() = default;
 
+    // Sets up the perfetto tracing backend and data source.
+    virtual void initializeTracing() = 0;
+    // Registers the data source with the perfetto backend. Called as part of initializeTracing()
+    // and should not be called manually outside of tests. Public to allow for substituting a
+    // perfetto::kInProcessBackend in tests.
+    virtual void registerTracingDataSource() = 0;
+    // Starts tracking a new layer for tracing. Needs to be called once before traceTimestamp() or
+    // traceFence() for each layer.
+    virtual void traceNewLayer(int32_t layerID, const std::string& layerName) = 0;
+    // Creates a trace point at the timestamp provided.
+    virtual void traceTimestamp(int32_t layerID, uint64_t bufferID, uint64_t frameNumber,
+                                nsecs_t timestamp, FrameEvent::BufferEventType type,
+                                nsecs_t duration = 0) = 0;
+    // Creates a trace point after the provided fence has been signalled. If a startTime is provided
+    // the trace will have be timestamped from startTime until fence signalling time. If no
+    // startTime is provided, a durationless trace point will be created timestamped at fence
+    // signalling time. If the fence hasn't signalled yet, the trace point will be created the next
+    // time after signalling a trace call for this buffer occurs.
+    virtual void traceFence(int32_t layerID, uint64_t bufferID, uint64_t frameNumber,
+                            const std::shared_ptr<FenceTime>& fence,
+                            FrameEvent::BufferEventType type, nsecs_t startTime = 0) = 0;
+
     virtual void parseArgs(bool asProto, const Vector<String16>& args, std::string& result) = 0;
     virtual bool isEnabled() = 0;
     virtual std::string miniDump() = 0;
@@ -66,6 +89,13 @@
     // Source of truth is RefrehRateStats.
     virtual void recordRefreshRate(uint32_t fps, nsecs_t duration) = 0;
     virtual void setPresentFenceGlobal(const std::shared_ptr<FenceTime>& presentFence) = 0;
+
+    static constexpr char kTimeStatsDataSource[] = "android.surfaceflinger.timestats";
+
+    // The maximum amount of time a fence has to signal before it is discarded.
+    // Used to avoid fence's from previous traces generating new trace points in later ones.
+    // Public for testing.
+    static constexpr nsecs_t kFenceSignallingDeadline = 60'000'000'000; // 60 seconds
 };
 
 namespace impl {
@@ -87,6 +117,13 @@
         std::shared_ptr<FenceTime> presentFence;
     };
 
+    struct PendingFence {
+        uint64_t frameNumber;
+        FrameEvent::BufferEventType type;
+        std::shared_ptr<FenceTime> fence;
+        nsecs_t startTime;
+    };
+
     struct LayerRecord {
         std::string layerName;
         // This is the index in timeRecords, at which the timestamps for that
@@ -98,6 +135,12 @@
         std::deque<TimeRecord> timeRecords;
     };
 
+    struct TraceRecord {
+        std::string layerName;
+        using BufferID = uint64_t;
+        std::unordered_map<BufferID, std::vector<PendingFence>> pendingFences;
+    };
+
     struct PowerTime {
         int32_t powerMode = HWC_POWER_MODE_OFF;
         nsecs_t prevTime = 0;
@@ -109,8 +152,23 @@
     };
 
 public:
+    class TimeStatsDataSource : public perfetto::DataSource<TimeStatsDataSource> {
+        virtual void OnSetup(const SetupArgs&) override{};
+        virtual void OnStart(const StartArgs&) override { ALOGV("TimeStats trace started"); };
+        virtual void OnStop(const StopArgs&) override { ALOGV("TimeStats trace stopped"); };
+    };
+
     TimeStats() = default;
 
+    void initializeTracing() override;
+    void registerTracingDataSource() override;
+    void traceNewLayer(int32_t layerID, const std::string& layerName) override;
+    void traceTimestamp(int32_t layerID, uint64_t bufferID, uint64_t frameNumber, nsecs_t timestamp,
+                        FrameEvent::BufferEventType type, nsecs_t duration = 0) override;
+    void traceFence(int32_t layerID, uint64_t bufferID, uint64_t frameNumber,
+                    const std::shared_ptr<FenceTime>& fence, FrameEvent::BufferEventType type,
+                    nsecs_t startTime = 0) override;
+
     void parseArgs(bool asProto, const Vector<String16>& args, std::string& result) override;
     bool isEnabled() override;
     std::string miniDump() override;
@@ -142,6 +200,20 @@
     static const size_t MAX_NUM_TIME_RECORDS = 64;
 
 private:
+    // Checks if any pending fences for a layer and buffer have signalled and, if they have, creates
+    // trace points for them.
+    void tracePendingFencesLocked(TimeStatsDataSource::TraceContext& ctx, int32_t layerID,
+                                  uint64_t bufferID);
+    // Creates a trace point by translating a start time and an end time to a timestamp and
+    // duration. If startTime is later than end time it sets end time as the timestamp and the
+    // duration to 0. Used by traceFence().
+    void traceSpanLocked(TimeStatsDataSource::TraceContext& ctx, int32_t layerID, uint64_t bufferID,
+                         uint64_t frameNumber, FrameEvent::BufferEventType type, nsecs_t startTime,
+                         nsecs_t endTime);
+    void traceLocked(TimeStatsDataSource::TraceContext& ctx, int32_t layerID, uint64_t bufferID,
+                     uint64_t frameNumber, nsecs_t timestamp, FrameEvent::BufferEventType type,
+                     nsecs_t duration = 0);
+
     bool recordReadyLocked(int32_t layerID, TimeRecord* timeRecord);
     void flushAvailableRecordsToStatsLocked(int32_t layerID);
     void flushPowerTimeLocked();
@@ -160,6 +232,9 @@
     PowerTime mPowerTime;
     GlobalRecord mGlobalRecord;
 
+    std::mutex mTraceMutex;
+    std::unordered_map<int32_t, TraceRecord> mTraceTracker;
+
     static const size_t MAX_NUM_LAYER_RECORDS = 200;
     static const size_t MAX_NUM_LAYER_STATS = 200;
 };