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
diff --git a/services/surfaceflinger/DisplayHardware/DisplayHardware.cpp b/services/surfaceflinger/DisplayHardware/DisplayHardware.cpp
index 438a6da..986aec5 100644
--- a/services/surfaceflinger/DisplayHardware/DisplayHardware.cpp
+++ b/services/surfaceflinger/DisplayHardware/DisplayHardware.cpp
@@ -350,15 +350,28 @@
}
// this needs to be thread safe
-nsecs_t DisplayHardware::waitForVSync() const {
+nsecs_t DisplayHardware::waitForRefresh() const {
nsecs_t timestamp;
if (mVSync.wait(×tamp) < 0) {
// vsync not supported!
usleep( getDelayToNextVSyncUs(×tamp) );
}
+ 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;
diff --git a/services/surfaceflinger/DisplayHardware/DisplayHardware.h b/services/surfaceflinger/DisplayHardware/DisplayHardware.h
index 77da272..02be4dc 100644
--- a/services/surfaceflinger/DisplayHardware/DisplayHardware.h
+++ b/services/surfaceflinger/DisplayHardware/DisplayHardware.h
@@ -76,7 +76,9 @@
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 @@
mutable Mutex mFakeVSyncMutex;
mutable nsecs_t mNextFakeVSync;
nsecs_t mRefreshPeriod;
+ mutable nsecs_t mLastHwVSync;
HWComposer* mHwc;
diff --git a/services/surfaceflinger/EventThread.cpp b/services/surfaceflinger/EventThread.cpp
index 80ab519..6796d7d 100644
--- a/services/surfaceflinger/EventThread.cpp
+++ b/services/surfaceflinger/EventThread.cpp
@@ -129,7 +129,7 @@
// at least one listener requested VSYNC
mLock.unlock();
- timestamp = mHw.waitForVSync();
+ timestamp = mHw.waitForRefresh();
mLock.lock();
mDeliveredEvents++;
diff --git a/services/surfaceflinger/Layer.cpp b/services/surfaceflinger/Layer.cpp
index 51efdc2..a294281 100644
--- a/services/surfaceflinger/Layer.cpp
+++ b/services/surfaceflinger/Layer.cpp
@@ -38,6 +38,7 @@
#include "Layer.h"
#include "SurfaceFlinger.h"
#include "SurfaceTextureLayer.h"
+#include <math.h>
#define DEBUG_RESIZE 0
@@ -54,6 +55,8 @@
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 @@
{
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 @@
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?
diff --git a/services/surfaceflinger/Layer.h b/services/surfaceflinger/Layer.h
index 9686259..b3fa5e7 100644
--- a/services/surfaceflinger/Layer.h
+++ b/services/surfaceflinger/Layer.h
@@ -34,6 +34,7 @@
#include "LayerBase.h"
#include "SurfaceTextureLayer.h"
#include "Transform.h"
+#include <utils/Timers.h>
namespace android {
@@ -86,6 +87,7 @@
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 @@
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 @@
bool mSecure; // no screenshots
bool mProtectedByApp; // application requires protected path to external sink
Region mPostedDirtyRegion;
-
- // binder thread, transaction thread
- mutable Mutex mLock;
};
// ---------------------------------------------------------------------------
diff --git a/services/surfaceflinger/LayerBase.cpp b/services/surfaceflinger/LayerBase.cpp
index 37879f1..1e2c4cb 100644
--- a/services/surfaceflinger/LayerBase.cpp
+++ b/services/surfaceflinger/LayerBase.cpp
@@ -471,6 +471,9 @@
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 @@
LayerBase::dump(result, scratch, size);
}
+void LayerBase::dumpStats(String8& result, char* scratch, size_t SIZE) const
+{
+}
// ---------------------------------------------------------------------------
diff --git a/services/surfaceflinger/LayerBase.h b/services/surfaceflinger/LayerBase.h
index 0c1b228..03d2cc6 100644
--- a/services/surfaceflinger/LayerBase.h
+++ b/services/surfaceflinger/LayerBase.h
@@ -211,6 +211,7 @@
/** 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()
diff --git a/services/surfaceflinger/SurfaceFlinger.cpp b/services/surfaceflinger/SurfaceFlinger.cpp
index b295201..883b642 100644
--- a/services/surfaceflinger/SurfaceFlinger.cpp
+++ b/services/surfaceflinger/SurfaceFlinger.cpp
@@ -431,7 +431,7 @@
} else {
// pretend we did the post
hw.compositionComplete();
- hw.waitForVSync();
+ hw.waitForRefresh();
}
return true;
}
@@ -1469,14 +1469,6 @@
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 @@
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 @@
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)
{
diff --git a/services/surfaceflinger/SurfaceFlinger.h b/services/surfaceflinger/SurfaceFlinger.h
index 7f6c90c..c976e5a 100644
--- a/services/surfaceflinger/SurfaceFlinger.h
+++ b/services/surfaceflinger/SurfaceFlinger.h
@@ -337,6 +337,9 @@
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;