ADHOC
/
replicant-frameworks_native
3
0
Fork 0
Code Issues Pull Requests Releases Wiki Activity

improve SurfaceFlinger dumpsys 

It is now possible to say:

dumpsys SurfaceFlinger --latency

to print latency information about all windows

dumpsys SurfaceFlinger --latency window-name

to print the latency stats of the specified window

for instance: dumpsys SurfaceFlinger --latency SurfaceView

The data consists of one line containing global stats, followed by
128 lines of tab separated timestamps in nanosecond.

The first line currently contains the refresh period in nanosecond.
Each 128 following line contains 3 timestamps, of respectively
the app draw time, the vsync timestamp just prior the call to set and
the timestamp of the call to set.

Change-Id: Ib6b6da1d7e2e6ba49c282bdbc0b56a7dc203343a
This commit is contained in:
Mathias Agopian 2012-01-19 18:34:40 -08:00
parent e8696a40e0
commit 82d7ab6c7e
9 changed files with 209 additions and 137 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

15
services/surfaceflinger/DisplayHardware/DisplayHardware.cpp
View File

@ -350,15 +350,28 @@ uint32_t DisplayHardware::getPageFlipCount() const {
}
// this needs to be thread safe
nsecs_t DisplayHardware::waitForVSync() const {
nsecs_t DisplayHardware::waitForRefresh() const {
nsecs_t timestamp;
if (mVSync.wait(&timestamp) < 0) {
// vsync not supported!
usleep( getDelayToNextVSyncUs(&timestamp) );
}
mLastHwVSync = timestamp; // FIXME: Not thread safe
return timestamp;
}
nsecs_t DisplayHardware::getRefreshTimestamp() const {
// this returns the last refresh timestamp.
// if the last one is not available, we estimate it based on
// the refresh period and whatever closest timestamp we have.
nsecs_t now = systemTime();
return now - ((now - mLastHwVSync) % mRefreshPeriod);
}
nsecs_t DisplayHardware::getRefreshPeriod() const {
return mRefreshPeriod;
}
int32_t DisplayHardware::getDelayToNextVSyncUs(nsecs_t* timestamp) const {
Mutex::Autolock _l(mFakeVSyncMutex);
const nsecs_t period = mRefreshPeriod;

5
services/surfaceflinger/DisplayHardware/DisplayHardware.h
View File

@ -76,7 +76,9 @@ public:
uint32_t getMaxViewportDims() const;
// waits for the next vsync and returns the timestamp of when it happened
nsecs_t waitForVSync() const;
nsecs_t waitForRefresh() const;
nsecs_t getRefreshPeriod() const;
nsecs_t getRefreshTimestamp() const;
uint32_t getPageFlipCount() const;
EGLDisplay getEGLDisplay() const { return mDisplay; }
@ -119,6 +121,7 @@ private:
mutable Mutex mFakeVSyncMutex;
mutable nsecs_t mNextFakeVSync;
nsecs_t mRefreshPeriod;
mutable nsecs_t mLastHwVSync;
HWComposer* mHwc;

2
services/surfaceflinger/EventThread.cpp
View File

@ -129,7 +129,7 @@ bool EventThread::threadLoop() {
// at least one listener requested VSYNC
mLock.unlock();
timestamp = mHw.waitForVSync();
timestamp = mHw.waitForRefresh();
mLock.lock();
mDeliveredEvents++;

48
services/surfaceflinger/Layer.cpp
View File

@ -38,6 +38,7 @@
#include "Layer.h"
#include "SurfaceFlinger.h"
#include "SurfaceTextureLayer.h"
#include <math.h>
#define DEBUG_RESIZE 0
@ -54,6 +55,8 @@ Layer::Layer(SurfaceFlinger* flinger,
mCurrentTransform(0),
mCurrentScalingMode(NATIVE_WINDOW_SCALING_MODE_FREEZE),
mCurrentOpacity(true),
mFrameLatencyNeeded(false),
mFrameLatencyOffset(0),
mFormat(PIXEL_FORMAT_NONE),
mGLExtensions(GLExtensions::getInstance()),
mOpaqueLayer(true),
@ -63,19 +66,14 @@ Layer::Layer(SurfaceFlinger* flinger,
{
mCurrentCrop.makeInvalid();
glGenTextures(1, &mTextureName);
mFrameLatencyNeeded = false;
mFrameLatencyOffset = 0;
for (int i = 0; i < 128; i++) {
mFrameLatencies[i] = 0;
}
}
void Layer::onLayerDisplayed() {
if (mFrameLatencyNeeded) {
int64_t now = systemTime(SYSTEM_TIME_MONOTONIC);
mFrameLatencies[mFrameLatencyOffset] = now -
mSurfaceTexture->getTimestamp();
const DisplayHardware& hw(graphicPlane(0).displayHardware());
mFrameStats[mFrameLatencyOffset].timestamp = mSurfaceTexture->getTimestamp();
mFrameStats[mFrameLatencyOffset].set = systemTime();
mFrameStats[mFrameLatencyOffset].vsync = hw.getRefreshTimestamp();
mFrameLatencyOffset = (mFrameLatencyOffset + 1) % 128;
mFrameLatencyNeeded = false;
}
@ -555,23 +553,33 @@ void Layer::dump(String8& result, char* buffer, size_t SIZE) const
result.append(buffer);
const int64_t* l = mFrameLatencies;
int o = mFrameLatencyOffset;
for (int i = 0; i < 128; i += 8) {
snprintf(buffer, SIZE,
" "
"% 12lld % 12lld % 12lld % 12lld "
"% 12lld % 12lld % 12lld % 12lld\n",
l[(o+i+0)%128], l[(o+i+1)%128], l[(o+i+2)%128], l[(o+i+3)%128],
l[(o+i+4)%128], l[(o+i+5)%128], l[(o+i+6)%128], l[(o+i+7)%128]);
result.append(buffer);
}
LayerBase::dumpStats(result, buffer, SIZE);
if (mSurfaceTexture != 0) {
mSurfaceTexture->dump(result, " ", buffer, SIZE);
}
}
void Layer::dumpStats(String8& result, char* buffer, size_t SIZE) const
{
LayerBaseClient::dumpStats(result, buffer, SIZE);
const size_t o = mFrameLatencyOffset;
const DisplayHardware& hw(graphicPlane(0).displayHardware());
const nsecs_t period = hw.getRefreshPeriod();
result.appendFormat("%lld\n", period);
for (size_t i=0 ; i<128 ; i++) {
const size_t index = (o+i) % 128;
const nsecs_t time_app = mFrameStats[index].timestamp;
const nsecs_t time_set = mFrameStats[index].set;
const nsecs_t time_vsync = mFrameStats[index].vsync;
result.appendFormat("%lld\t%lld\t%lld\n",
time_app,
time_vsync,
time_set);
}
result.append("\n");
}
uint32_t Layer::getEffectiveUsage(uint32_t usage) const
{
// TODO: should we do something special if mSecure is set?

14
services/surfaceflinger/Layer.h
View File

@ -34,6 +34,7 @@
#include "LayerBase.h"
#include "SurfaceTextureLayer.h"
#include "Transform.h"
#include <utils/Timers.h>
namespace android {
@ -86,6 +87,7 @@ public:
protected:
virtual void onFirstRef();
virtual void dump(String8& result, char* scratch, size_t size) const;
virtual void dumpStats(String8& result, char* buffer, size_t SIZE) const;
private:
friend class SurfaceTextureLayer;
@ -114,7 +116,14 @@ private:
bool mCurrentOpacity;
bool mFrameLatencyNeeded;
int mFrameLatencyOffset;
int64_t mFrameLatencies[128];
struct Statistics {
Statistics() : timestamp(0), set(0), vsync(0) { }
nsecs_t timestamp; // buffer timestamp
nsecs_t set; // buffer displayed timestamp
nsecs_t vsync; // vsync immediately before set
};
// protected by mLock
Statistics mFrameStats[128];
// constants
PixelFormat mFormat;
@ -126,9 +135,6 @@ private:
bool mSecure; // no screenshots
bool mProtectedByApp; // application requires protected path to external sink
Region mPostedDirtyRegion;
// binder thread, transaction thread
mutable Mutex mLock;
};
// ---------------------------------------------------------------------------

6
services/surfaceflinger/LayerBase.cpp
View File

@ -471,6 +471,9 @@ void LayerBase::drawWithOpenGL(const Region& clip) const
void LayerBase::dump(String8& result, char* buffer, size_t SIZE) const
{
const Layer::State& s(drawingState());
s.transparentRegion.dump(result, "transparentRegion");
transparentRegionScreen.dump(result, "transparentRegionScreen");
visibleRegionScreen.dump(result, "visibleRegionScreen");
snprintf(buffer, SIZE,
"+ %s %p (%s)\n"
" "
@ -491,6 +494,9 @@ void LayerBase::shortDump(String8& result, char* scratch, size_t size) const
LayerBase::dump(result, scratch, size);
}
void LayerBase::dumpStats(String8& result, char* scratch, size_t SIZE) const
{
}
// ---------------------------------------------------------------------------

1
services/surfaceflinger/LayerBase.h
View File

@ -211,6 +211,7 @@ public:
/** always call base class first */
virtual void dump(String8& result, char* scratch, size_t size) const;
virtual void shortDump(String8& result, char* scratch, size_t size) const;
virtual void dumpStats(String8& result, char* buffer, size_t SIZE) const;
enum { // flags for doTransaction()

252
services/surfaceflinger/SurfaceFlinger.cpp
View File

@ -431,7 +431,7 @@ bool SurfaceFlinger::threadLoop()
} else {
// pretend we did the post
hw.compositionComplete();
hw.waitForVSync();
hw.waitForRefresh();
}
return true;
}
@ -1469,14 +1469,6 @@ status_t SurfaceFlinger::dump(int fd, const Vector<String16>& args)
IPCThreadState::self()->getCallingUid());
result.append(buffer);
} else {
// figure out if we're stuck somewhere
const nsecs_t now = systemTime();
const nsecs_t inSwapBuffers(mDebugInSwapBuffers);
const nsecs_t inTransaction(mDebugInTransaction);
nsecs_t inSwapBuffersDuration = (inSwapBuffers) ? now-inSwapBuffers : 0;
nsecs_t inTransactionDuration = (inTransaction) ? now-inTransaction : 0;
// Try to get the main lock, but don't insist if we can't
// (this would indicate SF is stuck, but we want to be able to
// print something in dumpsys).
@ -1492,111 +1484,20 @@ status_t SurfaceFlinger::dump(int fd, const Vector<String16>& args)
result.append(buffer);
}
/*
* Dump the visible layer list
*/
const LayerVector& currentLayers = mCurrentState.layersSortedByZ;
const size_t count = currentLayers.size();
snprintf(buffer, SIZE, "Visible layers (count = %d)\n", count);
result.append(buffer);
for (size_t i=0 ; i<count ; i++) {
const sp<LayerBase>& layer(currentLayers[i]);
layer->dump(result, buffer, SIZE);
const Layer::State& s(layer->drawingState());
s.transparentRegion.dump(result, "transparentRegion");
layer->transparentRegionScreen.dump(result, "transparentRegionScreen");
layer->visibleRegionScreen.dump(result, "visibleRegionScreen");
bool dumpAll = true;
size_t index = 0;
if (args.size()) {
dumpAll = false;
if (args[index] == String16("--latency")) {
index++;
dumpStatsLocked(args, index, result, buffer, SIZE);
}
}
/*
* Dump the layers in the purgatory
*/
const size_t purgatorySize = mLayerPurgatory.size();
snprintf(buffer, SIZE, "Purgatory state (%d entries)\n", purgatorySize);
result.append(buffer);
for (size_t i=0 ; i<purgatorySize ; i++) {
const sp<LayerBase>& layer(mLayerPurgatory.itemAt(i));
layer->shortDump(result, buffer, SIZE);
if (dumpAll) {
dumpAllLocked(result, buffer, SIZE);
}
/*
* Dump SurfaceFlinger global state
*/
snprintf(buffer, SIZE, "SurfaceFlinger global state:\n");
result.append(buffer);
const GLExtensions& extensions(GLExtensions::getInstance());
snprintf(buffer, SIZE, "GLES: %s, %s, %s\n",
extensions.getVendor(),
extensions.getRenderer(),
extensions.getVersion());
result.append(buffer);
snprintf(buffer, SIZE, "EGL : %s\n",
eglQueryString(graphicPlane(0).getEGLDisplay(),
EGL_VERSION_HW_ANDROID));
result.append(buffer);
snprintf(buffer, SIZE, "EXTS: %s\n", extensions.getExtension());
result.append(buffer);
mWormholeRegion.dump(result, "WormholeRegion");
const DisplayHardware& hw(graphicPlane(0).displayHardware());
snprintf(buffer, SIZE,
" orientation=%d, canDraw=%d\n",
mCurrentState.orientation, hw.canDraw());
result.append(buffer);
snprintf(buffer, SIZE,
" last eglSwapBuffers() time: %f us\n"
" last transaction time : %f us\n"
" refresh-rate : %f fps\n"
" x-dpi : %f\n"
" y-dpi : %f\n",
mLastSwapBufferTime/1000.0,
mLastTransactionTime/1000.0,
hw.getRefreshRate(),
hw.getDpiX(),
hw.getDpiY());
result.append(buffer);
if (inSwapBuffersDuration || !locked) {
snprintf(buffer, SIZE, " eglSwapBuffers time: %f us\n",
inSwapBuffersDuration/1000.0);
result.append(buffer);
}
if (inTransactionDuration || !locked) {
snprintf(buffer, SIZE, " transaction time: %f us\n",
inTransactionDuration/1000.0);
result.append(buffer);
}
/*
* VSYNC state
*/
mEventThread->dump(result, buffer, SIZE);
/*
* Dump HWComposer state
*/
HWComposer& hwc(hw.getHwComposer());
snprintf(buffer, SIZE, "h/w composer state:\n");
result.append(buffer);
snprintf(buffer, SIZE, " h/w composer %s and %s\n",
hwc.initCheck()==NO_ERROR ? "present" : "not present",
(mDebugDisableHWC || mDebugRegion) ? "disabled" : "enabled");
result.append(buffer);
hwc.dump(result, buffer, SIZE, mVisibleLayersSortedByZ);
/*
* Dump gralloc state
*/
const GraphicBufferAllocator& alloc(GraphicBufferAllocator::get());
alloc.dump(result);
hw.dump(result);
if (locked) {
mStateLock.unlock();
}
@ -1605,6 +1506,137 @@ status_t SurfaceFlinger::dump(int fd, const Vector<String16>& args)
return NO_ERROR;
}
void SurfaceFlinger::dumpStatsLocked(const Vector<String16>& args, size_t& index,
String8& result, char* buffer, size_t SIZE) const
{
String8 name;
if (index < args.size()) {
name = String8(args[index]);
index++;
}
const LayerVector& currentLayers = mCurrentState.layersSortedByZ;
const size_t count = currentLayers.size();
for (size_t i=0 ; i<count ; i++) {
const sp<LayerBase>& layer(currentLayers[i]);
if (name.isEmpty()) {
snprintf(buffer, SIZE, "%s\n", layer->getName().string());
result.append(buffer);
}
if (name.isEmpty() || (name == layer->getName())) {
layer->dumpStats(result, buffer, SIZE);
}
}
}
void SurfaceFlinger::dumpAllLocked(
String8& result, char* buffer, size_t SIZE) const
{
// figure out if we're stuck somewhere
const nsecs_t now = systemTime();
const nsecs_t inSwapBuffers(mDebugInSwapBuffers);
const nsecs_t inTransaction(mDebugInTransaction);
nsecs_t inSwapBuffersDuration = (inSwapBuffers) ? now-inSwapBuffers : 0;
nsecs_t inTransactionDuration = (inTransaction) ? now-inTransaction : 0;
/*
* Dump the visible layer list
*/
const LayerVector& currentLayers = mCurrentState.layersSortedByZ;
const size_t count = currentLayers.size();
snprintf(buffer, SIZE, "Visible layers (count = %d)\n", count);
result.append(buffer);
for (size_t i=0 ; i<count ; i++) {
const sp<LayerBase>& layer(currentLayers[i]);
layer->dump(result, buffer, SIZE);
}
/*
* Dump the layers in the purgatory
*/
const size_t purgatorySize = mLayerPurgatory.size();
snprintf(buffer, SIZE, "Purgatory state (%d entries)\n", purgatorySize);
result.append(buffer);
for (size_t i=0 ; i<purgatorySize ; i++) {
const sp<LayerBase>& layer(mLayerPurgatory.itemAt(i));
layer->shortDump(result, buffer, SIZE);
}
/*
* Dump SurfaceFlinger global state
*/
snprintf(buffer, SIZE, "SurfaceFlinger global state:\n");
result.append(buffer);
const GLExtensions& extensions(GLExtensions::getInstance());
snprintf(buffer, SIZE, "GLES: %s, %s, %s\n",
extensions.getVendor(),
extensions.getRenderer(),
extensions.getVersion());
result.append(buffer);
snprintf(buffer, SIZE, "EGL : %s\n",
eglQueryString(graphicPlane(0).getEGLDisplay(),
EGL_VERSION_HW_ANDROID));
result.append(buffer);
snprintf(buffer, SIZE, "EXTS: %s\n", extensions.getExtension());
result.append(buffer);
mWormholeRegion.dump(result, "WormholeRegion");
const DisplayHardware& hw(graphicPlane(0).displayHardware());
snprintf(buffer, SIZE,
" orientation=%d, canDraw=%d\n",
mCurrentState.orientation, hw.canDraw());
result.append(buffer);
snprintf(buffer, SIZE,
" last eglSwapBuffers() time: %f us\n"
" last transaction time : %f us\n"
" refresh-rate : %f fps\n"
" x-dpi : %f\n"
" y-dpi : %f\n",
mLastSwapBufferTime/1000.0,
mLastTransactionTime/1000.0,
hw.getRefreshRate(),
hw.getDpiX(),
hw.getDpiY());
result.append(buffer);
snprintf(buffer, SIZE, " eglSwapBuffers time: %f us\n",
inSwapBuffersDuration/1000.0);
result.append(buffer);
snprintf(buffer, SIZE, " transaction time: %f us\n",
inTransactionDuration/1000.0);
result.append(buffer);
/*
* VSYNC state
*/
mEventThread->dump(result, buffer, SIZE);
/*
* Dump HWComposer state
*/
HWComposer& hwc(hw.getHwComposer());
snprintf(buffer, SIZE, "h/w composer state:\n");
result.append(buffer);
snprintf(buffer, SIZE, " h/w composer %s and %s\n",
hwc.initCheck()==NO_ERROR ? "present" : "not present",
(mDebugDisableHWC || mDebugRegion) ? "disabled" : "enabled");
result.append(buffer);
hwc.dump(result, buffer, SIZE, mVisibleLayersSortedByZ);
/*
* Dump gralloc state
*/
const GraphicBufferAllocator& alloc(GraphicBufferAllocator::get());
alloc.dump(result);
hw.dump(result);
}
status_t SurfaceFlinger::onTransact(
uint32_t code, const Parcel& data, Parcel* reply, uint32_t flags)
{

3
services/surfaceflinger/SurfaceFlinger.h
View File

@ -337,6 +337,9 @@ private:
void debugFlashRegions();
void drawWormhole() const;
void dumpStatsLocked(const Vector<String16>& args, size_t& index,
String8& result, char* buffer, size_t SIZE) const;
void dumpAllLocked(String8& result, char* buffer, size_t SIZE) const;
mutable MessageQueue mEventQueue;