Merge changes Ib6b6da1d,I6d9a466a

* changes:
  improve SurfaceFlinger dumpsys
  hack up frame latency measurement

opengl/libs/EGL/eglApi.cpp

@@ -477,6 +477,26 @@ EGLBoolean eglQuerySurface( EGLDisplay dpy, EGLSurface surface,
     return result;
 }
 
+void EGLAPI eglBeginFrame(EGLDisplay dpy, EGLSurface surface) {
+    clearError();
+
+    egl_display_t const * const dp = validate_display(dpy);
+    if (!dp) {
+        return;
+    }
+
+    SurfaceRef _s(dp, surface);
+    if (!_s.get()) {
+        setError(EGL_BAD_SURFACE, EGL_FALSE);
+        return;
+    }
+
+    int64_t timestamp = systemTime(SYSTEM_TIME_MONOTONIC);
+
+    egl_surface_t const * const s = get_surface(surface);
+    native_window_set_buffers_timestamp(s->win.get(), timestamp);
+}
+
 // ----------------------------------------------------------------------------
 // Contexts
 // ----------------------------------------------------------------------------

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;

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;
 

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

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),
@@ -65,6 +68,17 @@ Layer::Layer(SurfaceFlinger* flinger,
     glGenTextures(1, &mTextureName);
 }
 
+void Layer::onLayerDisplayed() {
+    if (mFrameLatencyNeeded) {
+        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;
+    }
+}
+
 void Layer::onFirstRef()
 {
     LayerBaseClient::onFirstRef();
@@ -408,6 +422,7 @@ void Layer::lockPageFlip(bool& recomputeVisibleRegions)
 
         // update the active buffer
         mActiveBuffer = mSurfaceTexture->getCurrentBuffer();
+        mFrameLatencyNeeded = true;
 
         const Rect crop(mSurfaceTexture->getCurrentCrop());
         const uint32_t transform(mSurfaceTexture->getCurrentTransform());
@@ -538,11 +553,33 @@ void Layer::dump(String8& result, char* buffer, size_t SIZE) const
 
     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?

services/surfaceflinger/Layer.h

@@ -34,6 +34,7 @@
 #include "LayerBase.h"
 #include "SurfaceTextureLayer.h"
 #include "Transform.h"
+#include <utils/Timers.h>
 
 namespace android {
 
@@ -78,12 +79,15 @@ public:
     // LayerBaseClient interface
     virtual wp<IBinder> getSurfaceTextureBinder() const;
 
+    virtual void onLayerDisplayed();
+
     // only for debugging
     inline const sp<GraphicBuffer>& getActiveBuffer() const { return mActiveBuffer; }
 
 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;
@@ -110,6 +114,16 @@ private:
     uint32_t mCurrentTransform;
     uint32_t mCurrentScalingMode;
     bool mCurrentOpacity;
+    bool mFrameLatencyNeeded;
+    int mFrameLatencyOffset;
+    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;
@@ -121,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;
 };
 
 // ---------------------------------------------------------------------------

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
+{
+}
 
 // ---------------------------------------------------------------------------
 

services/surfaceflinger/LayerBase.h

@@ -205,10 +205,13 @@ public:
     /** called with the state lock when the surface is removed from the
      *  current list */
     virtual void onRemoved() { };
-    
+
+    virtual void onLayerDisplayed() { };
+
     /** 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()

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;
 }
@@ -445,6 +445,12 @@ void SurfaceFlinger::postFramebuffer()
     const nsecs_t now = systemTime();
     mDebugInSwapBuffers = now;
     hw.flip(mSwapRegion);
+
+    size_t numLayers = mVisibleLayersSortedByZ.size();
+    for (size_t i = 0; i < numLayers; i++) {
+        mVisibleLayersSortedByZ[i]->onLayerDisplayed();
+    }
+
     mLastSwapBufferTime = systemTime() - now;
     mDebugInSwapBuffers = 0;
     mSwapRegion.clear();
@@ -1463,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).
@@ -1486,111 +1484,20 @@ status_t SurfaceFlinger::dump(int fd, const Vector<String16>& args)
             result.append(buffer);
         }
 
-        /*
+        bool dumpAll = true;
-         * Dump the visible layer list
+        size_t index = 0;
-         */
+        if (args.size()) {
-        const LayerVector& currentLayers = mCurrentState.layersSortedByZ;
+            dumpAll = false;
-        const size_t count = currentLayers.size();
+            if (args[index] == String16("--latency")) {
-        snprintf(buffer, SIZE, "Visible layers (count = %d)\n", count);
+                index++;
-        result.append(buffer);
+                dumpStatsLocked(args, index, result, buffer, SIZE);
-        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");
         }
 
-        /*
+        if (dumpAll) {
-         * Dump the layers in the purgatory
+            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);
         }
 
-        /*
-         * 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();
         }
@@ -1599,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)
 {

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;