Merge "Add GPU draw stats to gfxinfo and GraphicsStatsService"

This commit is contained in:
TreeHugger Robot
2019-08-06 21:45:20 +00:00
committed by Android (Google) Code Review
13 changed files with 178 additions and 3 deletions

View File

@@ -220,7 +220,7 @@ public final class FrameMetrics {
int SWAP_BUFFERS = 12;
int FRAME_COMPLETED = 13;
int FRAME_STATS_COUNT = 16; // must always be last
int FRAME_STATS_COUNT = 17; // must always be last
}
/*

View File

@@ -51,6 +51,9 @@ message GraphicsStatsProto {
// The frame time histogram for the package.
repeated GraphicsStatsHistogramBucketProto histogram = 6;
// The gpu frame time histogram for the package
repeated GraphicsStatsHistogramBucketProto gpu_histogram = 7;
}
message GraphicsStatsJankSummaryProto {

View File

@@ -37,13 +37,14 @@ const std::string FrameInfoNames[] = {
"FrameCompleted",
"DequeueBufferDuration",
"QueueBufferDuration",
"GpuCompleted",
};
static_assert((sizeof(FrameInfoNames) / sizeof(FrameInfoNames[0])) ==
static_cast<int>(FrameInfoIndex::NumIndexes),
"size mismatch: FrameInfoNames doesn't match the enum!");
static_assert(static_cast<int>(FrameInfoIndex::NumIndexes) == 16,
static_assert(static_cast<int>(FrameInfoIndex::NumIndexes) == 17,
"Must update value in FrameMetrics.java#FRAME_STATS_COUNT (and here)");
void FrameInfo::importUiThreadInfo(int64_t* info) {

View File

@@ -51,6 +51,8 @@ enum class FrameInfoIndex {
DequeueBufferDuration,
QueueBufferDuration,
GpuCompleted,
// Must be the last value!
// Also must be kept in sync with FrameMetrics.java#FRAME_STATS_COUNT
NumIndexes
@@ -143,6 +145,13 @@ public:
return duration(FrameInfoIndex::IntendedVsync, FrameInfoIndex::FrameCompleted);
}
inline int64_t gpuDrawTime() const {
// GPU start time is approximated to the moment before swapBuffer is invoked.
// We could add an EGLSyncKHR fence at the beginning of the frame, but that is an overhead.
int64_t endTime = get(FrameInfoIndex::GpuCompleted);
return endTime > 0 ? endTime - get(FrameInfoIndex::SwapBuffers) : -1;
}
inline int64_t& set(FrameInfoIndex index) { return mFrameInfo[static_cast<int>(index)]; }
inline int64_t get(FrameInfoIndex index) const {

View File

@@ -232,5 +232,13 @@ void JankTracker::reset() {
: FrameInfoIndex::IntendedVsync;
}
void JankTracker::finishGpuDraw(const FrameInfo& frame) {
int64_t totalGPUDrawTime = frame.gpuDrawTime();
if (totalGPUDrawTime >= 0) {
mData->reportGPUFrame(totalGPUDrawTime);
(*mGlobalData)->reportGPUFrame(totalGPUDrawTime);
}
}
} /* namespace uirenderer */
} /* namespace android */

View File

@@ -58,6 +58,7 @@ public:
FrameInfo* startFrame() { return &mFrames.next(); }
void finishFrame(const FrameInfo& frame);
void finishGpuDraw(const FrameInfo& frame);
void dumpStats(int fd) { dumpData(fd, &mDescription, mData.get()); }
void dumpFrames(int fd);

View File

@@ -98,6 +98,10 @@ void ProfileData::mergeWith(const ProfileData& other) {
if (mStatStartTime > other.mStatStartTime || mStatStartTime == 0) {
mStatStartTime = other.mStatStartTime;
}
for (size_t i = 0; i < other.mGPUFrameCounts.size(); i++) {
mGPUFrameCounts[i] >>= divider;
mGPUFrameCounts[i] += other.mGPUFrameCounts[i];
}
}
void ProfileData::dump(int fd) const {
@@ -117,6 +121,14 @@ void ProfileData::dump(int fd) const {
histogramForEach([fd](HistogramEntry entry) {
dprintf(fd, " %ums=%u", entry.renderTimeMs, entry.frameCount);
});
dprintf(fd, "\n50th gpu percentile: %ums", findGPUPercentile(50));
dprintf(fd, "\n90th gpu percentile: %ums", findGPUPercentile(90));
dprintf(fd, "\n95th gpu percentile: %ums", findGPUPercentile(95));
dprintf(fd, "\n99th gpu percentile: %ums", findGPUPercentile(99));
dprintf(fd, "\nGPU HISTOGRAM:");
histogramGPUForEach([fd](HistogramEntry entry) {
dprintf(fd, " %ums=%u", entry.renderTimeMs, entry.frameCount);
});
}
uint32_t ProfileData::findPercentile(int percentile) const {
@@ -140,6 +152,7 @@ uint32_t ProfileData::findPercentile(int percentile) const {
void ProfileData::reset() {
mJankTypeCounts.fill(0);
mFrameCounts.fill(0);
mGPUFrameCounts.fill(0);
mSlowFrameCounts.fill(0);
mTotalFrameCount = 0;
mJankFrameCount = 0;
@@ -167,5 +180,40 @@ void ProfileData::histogramForEach(const std::function<void(HistogramEntry)>& ca
}
}
uint32_t ProfileData::findGPUPercentile(int percentile) const {
uint32_t totalGPUFrameCount = 0; // this is usually mTotalFrameCount - 3.
for (int i = mGPUFrameCounts.size() - 1; i >= 0; i--) {
totalGPUFrameCount += mGPUFrameCounts[i];
}
int pos = percentile * totalGPUFrameCount / 100;
int remaining = totalGPUFrameCount - pos;
for (int i = mGPUFrameCounts.size() - 1; i >= 0; i--) {
remaining -= mGPUFrameCounts[i];
if (remaining <= 0) {
return GPUFrameTimeForFrameCountIndex(i);
}
}
return 0;
}
uint32_t ProfileData::GPUFrameTimeForFrameCountIndex(uint32_t index) {
return index != 25 ? index + 1 : 4950;
}
void ProfileData::reportGPUFrame(int64_t duration) {
uint32_t index = static_cast<uint32_t>(ns2ms(duration));
if (index > 25) {
index = 25;
}
mGPUFrameCounts[index]++;
}
void ProfileData::histogramGPUForEach(const std::function<void(HistogramEntry)>& callback) const {
for (size_t i = 0; i < mGPUFrameCounts.size(); i++) {
callback(HistogramEntry{GPUFrameTimeForFrameCountIndex(i), mGPUFrameCounts[i]});
}
}
} /* namespace uirenderer */
} /* namespace android */

View File

@@ -54,8 +54,10 @@ public:
void mergeWith(const ProfileData& other);
void dump(int fd) const;
uint32_t findPercentile(int percentile) const;
uint32_t findGPUPercentile(int percentile) const;
void reportFrame(int64_t duration);
void reportGPUFrame(int64_t duration);
void reportJank() { mJankFrameCount++; }
void reportJankType(JankType type) { mJankTypeCounts[static_cast<int>(type)]++; }
@@ -69,15 +71,21 @@ public:
uint32_t frameCount;
};
void histogramForEach(const std::function<void(HistogramEntry)>& callback) const;
void histogramGPUForEach(const std::function<void(HistogramEntry)>& callback) const;
constexpr static int HistogramSize() {
return std::tuple_size<decltype(ProfileData::mFrameCounts)>::value +
std::tuple_size<decltype(ProfileData::mSlowFrameCounts)>::value;
}
constexpr static int GPUHistogramSize() {
return std::tuple_size<decltype(ProfileData::mGPUFrameCounts)>::value;
}
// Visible for testing
static uint32_t frameTimeForFrameCountIndex(uint32_t index);
static uint32_t frameTimeForSlowFrameCountIndex(uint32_t index);
static uint32_t GPUFrameTimeForFrameCountIndex(uint32_t index);
private:
// Open our guts up to unit tests
@@ -88,6 +96,9 @@ private:
std::array<uint32_t, 57> mFrameCounts;
// Holds a histogram of frame times in 50ms increments from 150ms to 5s
std::array<uint16_t, 97> mSlowFrameCounts;
// Holds a histogram of GPU draw times in 1ms increments. Frames longer than 25ms are placed in
// last bucket.
std::array<uint32_t, 26> mGPUFrameCounts;
uint32_t mTotalFrameCount;
uint32_t mJankFrameCount;

View File

@@ -46,6 +46,9 @@ message GraphicsStatsProto {
// The frame time histogram for the package
repeated GraphicsStatsHistogramBucketProto histogram = 6;
// The gpu frame time histogram for the package
repeated GraphicsStatsHistogramBucketProto gpu_histogram = 7;
}
message GraphicsStatsJankSummaryProto {

View File

@@ -147,6 +147,7 @@ void CanvasContext::setSurface(sp<Surface>&& surface) {
mNativeSurface = new ReliableSurface{std::move(surface)};
// TODO: Fix error handling & re-shorten timeout
mNativeSurface->setDequeueTimeout(4000_ms);
mNativeSurface->enableFrameTimestamps(true);
} else {
mNativeSurface = nullptr;
}
@@ -294,6 +295,7 @@ void CanvasContext::prepareTree(TreeInfo& info, int64_t* uiFrameInfo, int64_t sy
// just keep using the previous frame's structure instead
if (!wasSkipped(mCurrentFrameInfo)) {
mCurrentFrameInfo = mJankTracker.startFrame();
mLast4FrameInfos.next().first = mCurrentFrameInfo;
}
mCurrentFrameInfo->importUiThreadInfo(uiFrameInfo);
mCurrentFrameInfo->set(FrameInfoIndex::SyncQueued) = syncQueued;
@@ -445,7 +447,7 @@ void CanvasContext::draw() {
mContentDrawBounds, mOpaque, mLightInfo, mRenderNodes,
&(profiler()));
int64_t frameCompleteNr = mFrameCompleteCallbacks.size() ? getFrameNumber() : -1;
int64_t frameCompleteNr = getFrameNumber();
waitOnFences();
@@ -500,11 +502,13 @@ void CanvasContext::draw() {
}
mCurrentFrameInfo->set(FrameInfoIndex::DequeueBufferDuration) = swap.dequeueDuration;
mCurrentFrameInfo->set(FrameInfoIndex::QueueBufferDuration) = swap.queueDuration;
mLast4FrameInfos[-1].second = frameCompleteNr;
mHaveNewSurface = false;
mFrameNumber = -1;
} else {
mCurrentFrameInfo->set(FrameInfoIndex::DequeueBufferDuration) = 0;
mCurrentFrameInfo->set(FrameInfoIndex::QueueBufferDuration) = 0;
mLast4FrameInfos[-1].second = -1;
}
// TODO: Use a fence for real completion?
@@ -537,6 +541,19 @@ void CanvasContext::draw() {
mFrameMetricsReporter->reportFrameMetrics(mCurrentFrameInfo->data());
}
if (mLast4FrameInfos.size() == mLast4FrameInfos.capacity()) {
// By looking 4 frames back, we guarantee all SF stats are available. There are at
// most 3 buffers in BufferQueue. Surface object keeps stats for the last 8 frames.
FrameInfo* forthBehind = mLast4FrameInfos.front().first;
int64_t composedFrameId = mLast4FrameInfos.front().second;
nsecs_t acquireTime = -1;
mNativeSurface->getFrameTimestamps(composedFrameId, nullptr, &acquireTime, nullptr, nullptr,
nullptr, nullptr, nullptr, nullptr, nullptr);
// Ignore default -1, NATIVE_WINDOW_TIMESTAMP_INVALID and NATIVE_WINDOW_TIMESTAMP_PENDING
forthBehind->set(FrameInfoIndex::GpuCompleted) = acquireTime > 0 ? acquireTime : -1;
mJankTracker.finishGpuDraw(*forthBehind);
}
GpuMemoryTracker::onFrameCompleted();
}

View File

@@ -29,6 +29,7 @@
#include "RenderNode.h"
#include "renderthread/RenderTask.h"
#include "renderthread/RenderThread.h"
#include "utils/RingBuffer.h"
#include <SkBitmap.h>
#include <SkRect.h>
@@ -41,6 +42,7 @@
#include <future>
#include <set>
#include <string>
#include <utility>
#include <vector>
namespace android {
@@ -260,6 +262,7 @@ private:
std::vector<sp<RenderNode>> mRenderNodes;
FrameInfo* mCurrentFrameInfo = nullptr;
RingBuffer<std::pair<FrameInfo*, int64_t>, 4> mLast4FrameInfos;
std::string mName;
JankTracker mJankTracker;
FrameInfoVisualizer mProfiler;

View File

@@ -49,6 +49,21 @@ public:
return ret;
}
status_t getFrameTimestamps(uint64_t frameNumber,
nsecs_t* outRequestedPresentTime, nsecs_t* outAcquireTime,
nsecs_t* outLatchTime, nsecs_t* outFirstRefreshStartTime,
nsecs_t* outLastRefreshStartTime, nsecs_t* outGlCompositionDoneTime,
nsecs_t* outDisplayPresentTime, nsecs_t* outDequeueReadyTime,
nsecs_t* outReleaseTime) {
return mSurface->getFrameTimestamps(frameNumber, outRequestedPresentTime, outAcquireTime,
outLatchTime, outFirstRefreshStartTime, outLastRefreshStartTime,
outGlCompositionDoneTime, outDisplayPresentTime, outDequeueReadyTime, outReleaseTime);
}
void enableFrameTimestamps(bool enable) {
return mSurface->enableFrameTimestamps(enable);
}
private:
const sp<Surface> mSurface;

View File

@@ -40,6 +40,7 @@ constexpr int32_t sHeaderSize = 4;
static_assert(sizeof(sCurrentFileVersion) == sHeaderSize, "Header size is wrong");
constexpr int sHistogramSize = ProfileData::HistogramSize();
constexpr int sGPUHistogramSize = ProfileData::GPUHistogramSize();
static bool mergeProfileDataIntoProto(protos::GraphicsStatsProto* proto,
const std::string& package, int64_t versionCode,
@@ -211,6 +212,37 @@ bool mergeProfileDataIntoProto(protos::GraphicsStatsProto* proto, const std::str
bucket->set_frame_count(bucket->frame_count() + entry.frameCount);
index++;
});
if (hitMergeError) return false;
// fill in GPU frame time histogram
creatingHistogram = false;
if (proto->gpu_histogram_size() == 0) {
proto->mutable_gpu_histogram()->Reserve(sGPUHistogramSize);
creatingHistogram = true;
} else if (proto->gpu_histogram_size() != sGPUHistogramSize) {
ALOGE("GPU histogram size mismatch, proto is %d expected %d", proto->gpu_histogram_size(),
sGPUHistogramSize);
return false;
}
index = 0;
data->histogramGPUForEach([&](ProfileData::HistogramEntry entry) {
if (hitMergeError) return;
protos::GraphicsStatsHistogramBucketProto* bucket;
if (creatingHistogram) {
bucket = proto->add_gpu_histogram();
bucket->set_render_millis(entry.renderTimeMs);
} else {
bucket = proto->mutable_gpu_histogram(index);
if (bucket->render_millis() != static_cast<int32_t>(entry.renderTimeMs)) {
ALOGW("GPU frame time mistmatch %d vs. %u", bucket->render_millis(),
entry.renderTimeMs);
hitMergeError = true;
return;
}
}
bucket->set_frame_count(bucket->frame_count() + entry.frameCount);
index++;
});
return !hitMergeError;
}
@@ -226,6 +258,22 @@ static int32_t findPercentile(protos::GraphicsStatsProto* proto, int percentile)
return 0;
}
static int32_t findGPUPercentile(protos::GraphicsStatsProto* proto, int percentile) {
uint32_t totalGPUFrameCount = 0; // this is usually proto->summary().total_frames() - 3.
for (auto it = proto->gpu_histogram().rbegin(); it != proto->gpu_histogram().rend(); ++it) {
totalGPUFrameCount += it->frame_count();
}
int32_t pos = percentile * totalGPUFrameCount / 100;
int32_t remaining = totalGPUFrameCount - pos;
for (auto it = proto->gpu_histogram().rbegin(); it != proto->gpu_histogram().rend(); ++it) {
remaining -= it->frame_count();
if (remaining <= 0) {
return it->render_millis();
}
}
return 0;
}
void dumpAsTextToFd(protos::GraphicsStatsProto* proto, int fd) {
// This isn't a full validation, just enough that we can deref at will
if (proto->package_name().empty() || !proto->has_summary()) {
@@ -255,6 +303,14 @@ void dumpAsTextToFd(protos::GraphicsStatsProto* proto, int fd) {
for (const auto& it : proto->histogram()) {
dprintf(fd, " %dms=%d", it.render_millis(), it.frame_count());
}
dprintf(fd, "\n50th gpu percentile: %dms", findGPUPercentile(proto, 50));
dprintf(fd, "\n90th gpu percentile: %dms", findGPUPercentile(proto, 90));
dprintf(fd, "\n95th gpu percentile: %dms", findGPUPercentile(proto, 95));
dprintf(fd, "\n99th gpu percentile: %dms", findGPUPercentile(proto, 99));
dprintf(fd, "\nGPU HISTOGRAM:");
for (const auto& it : proto->gpu_histogram()) {
dprintf(fd, " %dms=%d", it.render_millis(), it.frame_count());
}
dprintf(fd, "\n");
}