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

9 files changed, 203 insertions, 131 deletions

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 @@ 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;
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 @@ 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;
 
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 @@ bool EventThread::threadLoop() {
 
             // 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 @@ 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?
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 @@ 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;
 };
 
 // ---------------------------------------------------------------------------
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::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
+{
+}
 
 // ---------------------------------------------------------------------------
 
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 @@ 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()
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 @@ 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,117 +1484,157 @@ 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
-         */
+        if (dumpAll) {
+            dumpAllLocked(result, buffer, SIZE);
+        }
 
-        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 (locked) {
+            mStateLock.unlock();
         }
+    }
+    write(fd, result.string(), result.size());
+    return NO_ERROR;
+}
 
-        /*
-         * Dump SurfaceFlinger global state
-         */
+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++;
+    }
 
-        snprintf(buffer, SIZE, "SurfaceFlinger global state:\n");
-        result.append(buffer);
+    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);
+        }
+    }
+}
 
-        const GLExtensions& extensions(GLExtensions::getInstance());
-        snprintf(buffer, SIZE, "GLES: %s, %s, %s\n",
-                extensions.getVendor(),
-                extensions.getRenderer(),
-                extensions.getVersion());
-        result.append(buffer);
+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;
 
-        snprintf(buffer, SIZE, "EGL : %s\n",
-                eglQueryString(graphicPlane(0).getEGLDisplay(),
-                        EGL_VERSION_HW_ANDROID));
-        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);
+    }
 
-        snprintf(buffer, SIZE, "EXTS: %s\n", extensions.getExtension());
-        result.append(buffer);
+    /*
+     * Dump the layers in the purgatory
+     */
 
-        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);
+    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 (inSwapBuffersDuration || !locked) {
-            snprintf(buffer, SIZE, "  eglSwapBuffers time: %f us\n",
-                    inSwapBuffersDuration/1000.0);
-            result.append(buffer);
-        }
+    /*
+     * Dump SurfaceFlinger global state
+     */
 
-        if (inTransactionDuration || !locked) {
-            snprintf(buffer, SIZE, "  transaction time: %f us\n",
-                    inTransactionDuration/1000.0);
-            result.append(buffer);
-        }
+    snprintf(buffer, SIZE, "SurfaceFlinger global state:\n");
+    result.append(buffer);
 
-        /*
-         * VSYNC state
-         */
-        mEventThread->dump(result, buffer, SIZE);
+    const GLExtensions& extensions(GLExtensions::getInstance());
+    snprintf(buffer, SIZE, "GLES: %s, %s, %s\n",
+            extensions.getVendor(),
+            extensions.getRenderer(),
+            extensions.getVersion());
+    result.append(buffer);
 
-        /*
-         * 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);
+    snprintf(buffer, SIZE, "EGL : %s\n",
+            eglQueryString(graphicPlane(0).getEGLDisplay(),
+                    EGL_VERSION_HW_ANDROID));
+    result.append(buffer);
 
-        /*
-         * Dump gralloc state
-         */
-        const GraphicBufferAllocator& alloc(GraphicBufferAllocator::get());
-        alloc.dump(result);
-        hw.dump(result);
+    snprintf(buffer, SIZE, "EXTS: %s\n", extensions.getExtension());
+    result.append(buffer);
 
-        if (locked) {
-            mStateLock.unlock();
-        }
-    }
-    write(fd, result.string(), result.size());
-    return NO_ERROR;
+    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(
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 @@ 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;