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;
};