surfaceflinger: add frame duration logging

Change-Id: Ib414a45e7e191f23a2726cbbbeb606e9ce68a3b5

services/surfaceflinger/EventLog/EventLog.cpp

@@ -31,17 +31,22 @@ ANDROID_SINGLETON_STATIC_INSTANCE(EventLog)
 EventLog::EventLog() {
 }
 
-void EventLog::doLogJank(const String8& window, int32_t value) {
+void EventLog::doLogFrameDurations(const String8& window,
-    EventLog::TagBuffer buffer(LOGTAG_SF_JANK);
+        const int32_t* durations, size_t numDurations) {
-    buffer.startList(2);
+    EventLog::TagBuffer buffer(LOGTAG_SF_FRAME_DUR);
+    buffer.startList(1 + numDurations);
     buffer.writeString8(window);
-    buffer.writeInt32(value);
+    for (size_t i = 0; i < numDurations; i++) {
+        buffer.writeInt32(durations[i]);
+    }
     buffer.endList();
     buffer.log();
 }
 
-void EventLog::logJank(const String8& window, int32_t value) {
+void EventLog::logFrameDurations(const String8& window,
-    EventLog::getInstance().doLogJank(window, value);
+        const int32_t* durations, size_t numDurations) {
+    EventLog::getInstance().doLogFrameDurations(window, durations,
+            numDurations);
 }
 
 // ---------------------------------------------------------------------------

services/surfaceflinger/EventLog/EventLog.h

@@ -30,7 +30,8 @@ class String8;
 class EventLog : public Singleton<EventLog> {
 
 public:
-    static void logJank(const String8& window, int32_t value);
+    static void logFrameDurations(const String8& window,
+            const int32_t* durations, size_t numDurations);
 
 protected:
     EventLog();
@@ -72,8 +73,9 @@ private:
     EventLog(const EventLog&);
     EventLog& operator =(const EventLog&);
 
-    enum { LOGTAG_SF_JANK = 60100 };
+    enum { LOGTAG_SF_FRAME_DUR = 60100 };
-    void doLogJank(const String8& window, int32_t value);
+    void doLogFrameDurations(const String8& window, const int32_t* durations,
+            size_t numDurations);
 };
 
 // ---------------------------------------------------------------------------

services/surfaceflinger/EventLog/EventLogTags.logtags

@@ -30,9 +30,12 @@
 # 5: Id
 # 6: Percent
 # Default value for data of type int/long is 2 (bytes).
+#
+# See system/core/logcat/event.logtags for the master copy of the tags.
 
-# surfaceflinger
+# 60100 - 60199 reserved for surfaceflinger
-60100 sf_jank (window|3),(value|1)
+
+60100 sf_frame_dur (window|3),(dur0|1),(dur1|1),(dur2|1),(dur3|1),(dur4|1),(dur5|1),(dur6|1)
 
 # NOTE - the range 1000000-2000000 is reserved for partners and others who
 # want to define their own log tags without conflicting with the core platform.

services/surfaceflinger/FrameTracker.cpp

@@ -17,17 +17,22 @@
 // This is needed for stdint.h to define INT64_MAX in C++
 #define __STDC_LIMIT_MACROS
 
+#include <cutils/log.h>
+
 #include <ui/Fence.h>
 
 #include <utils/String8.h>
 
 #include "FrameTracker.h"
+#include "EventLog/EventLog.h"
 
 namespace android {
 
 FrameTracker::FrameTracker() :
         mOffset(0),
-        mNumFences(0) {
+        mNumFences(0),
+        mDisplayPeriod(0) {
+    resetFrameCountersLocked();
 }
 
 void FrameTracker::setDesiredPresentTime(nsecs_t presentTime) {
@@ -57,8 +62,18 @@ void FrameTracker::setActualPresentFence(const sp<Fence>& readyFence) {
     mNumFences++;
 }
 
+void FrameTracker::setDisplayRefreshPeriod(nsecs_t displayPeriod) {
+    Mutex::Autolock lock(mMutex);
+    mDisplayPeriod = displayPeriod;
+}
+
 void FrameTracker::advanceFrame() {
     Mutex::Autolock lock(mMutex);
+
+    // Update the statistic to include the frame we just finished.
+    updateStatsLocked(mOffset);
+
+    // Advance to the next frame.
     mOffset = (mOffset+1) % NUM_FRAME_RECORDS;
     mFrameRecords[mOffset].desiredPresentTime = INT64_MAX;
     mFrameRecords[mOffset].frameReadyTime = INT64_MAX;
@@ -98,12 +113,19 @@ void FrameTracker::clear() {
     mFrameRecords[mOffset].actualPresentTime = INT64_MAX;
 }
 
+void FrameTracker::logAndResetStats(const String8& name) {
+    Mutex::Autolock lock(mMutex);
+    logStatsLocked(name);
+    resetFrameCountersLocked();
+}
+
 void FrameTracker::processFencesLocked() const {
     FrameRecord* records = const_cast<FrameRecord*>(mFrameRecords);
     int& numFences = const_cast<int&>(mNumFences);
 
     for (int i = 1; i < NUM_FRAME_RECORDS && numFences > 0; i++) {
         size_t idx = (mOffset+NUM_FRAME_RECORDS-i) % NUM_FRAME_RECORDS;
+        bool updated = false;
 
         const sp<Fence>& rfence = records[idx].frameReadyFence;
         if (rfence != NULL) {
@@ -111,6 +133,7 @@ void FrameTracker::processFencesLocked() const {
             if (records[idx].frameReadyTime < INT64_MAX) {
                 records[idx].frameReadyFence = NULL;
                 numFences--;
+                updated = true;
             }
         }
 
@@ -120,11 +143,67 @@ void FrameTracker::processFencesLocked() const {
             if (records[idx].actualPresentTime < INT64_MAX) {
                 records[idx].actualPresentFence = NULL;
                 numFences--;
+                updated = true;
             }
         }
+
+        if (updated) {
+            updateStatsLocked(idx);
+        }
     }
 }
 
+void FrameTracker::updateStatsLocked(size_t newFrameIdx) const {
+    int* numFrames = const_cast<int*>(mNumFrames);
+
+    if (mDisplayPeriod > 0 && isFrameValidLocked(newFrameIdx)) {
+        size_t prevFrameIdx = (newFrameIdx+NUM_FRAME_RECORDS-1) %
+                NUM_FRAME_RECORDS;
+
+        if (isFrameValidLocked(prevFrameIdx)) {
+            nsecs_t newPresentTime =
+                    mFrameRecords[newFrameIdx].actualPresentTime;
+            nsecs_t prevPresentTime =
+                    mFrameRecords[prevFrameIdx].actualPresentTime;
+
+            nsecs_t duration = newPresentTime - prevPresentTime;
+            int numPeriods = int((duration + mDisplayPeriod/2) /
+                    mDisplayPeriod);
+
+            for (int i = 0; i < NUM_FRAME_BUCKETS-1; i++) {
+                int nextBucket = 1 << (i+1);
+                if (numPeriods < nextBucket) {
+                    numFrames[i]++;
+                    return;
+                }
+            }
+
+            // The last duration bucket is a catch-all.
+            numFrames[NUM_FRAME_BUCKETS-1]++;
+        }
+    }
+}
+
+void FrameTracker::resetFrameCountersLocked() {
+    for (int i = 0; i < NUM_FRAME_BUCKETS; i++) {
+        mNumFrames[i] = 0;
+    }
+}
+
+void FrameTracker::logStatsLocked(const String8& name) const {
+    for (int i = 0; i < NUM_FRAME_BUCKETS; i++) {
+        if (mNumFrames[i] > 0) {
+            EventLog::logFrameDurations(name, mNumFrames, NUM_FRAME_BUCKETS);
+            return;
+        }
+    }
+}
+
+bool FrameTracker::isFrameValidLocked(size_t idx) const {
+    return mFrameRecords[idx].actualPresentTime > 0 &&
+            mFrameRecords[idx].actualPresentTime < INT64_MAX;
+}
+
 void FrameTracker::dump(String8& result) const {
     Mutex::Autolock lock(mMutex);
     processFencesLocked();

services/surfaceflinger/FrameTracker.h

@@ -43,6 +43,8 @@ public:
     // frame time history.
     enum { NUM_FRAME_RECORDS = 128 };
 
+    enum { NUM_FRAME_BUCKETS = 7 };
+
     FrameTracker();
 
     // setDesiredPresentTime sets the time at which the current frame
@@ -68,12 +70,21 @@ public:
     // at which the current frame became visible to the user.
     void setActualPresentFence(const sp<Fence>& fence);
 
+    // setDisplayRefreshPeriod sets the display refresh period in nanoseconds.
+    // This is used to compute frame presentation duration statistics relative
+    // to this period.
+    void setDisplayRefreshPeriod(nsecs_t displayPeriod);
+
     // advanceFrame advances the frame tracker to the next frame.
     void advanceFrame();
 
     // clear resets all the tracked frame data to zero.
     void clear();
 
+    // logAndResetStats dumps the current statistics to the binary event log
+    // and then resets the accumulated statistics to their initial values.
+    void logAndResetStats(const String8& name);
+
     // dump appends the current frame display time history to the result string.
     void dump(String8& result) const;
 
@@ -99,6 +110,21 @@ private:
     // change.  This allows it to be called from the dump method.
     void processFencesLocked() const;
 
+    // updateStatsLocked updates the running statistics that are gathered
+    // about the frame times.
+    void updateStatsLocked(size_t newFrameIdx) const;
+
+    // resetFrameCounteresLocked sets all elements of the mNumFrames array to
+    // 0.
+    void resetFrameCountersLocked();
+
+    // logStatsLocked dumps the current statistics to the binary event log.
+    void logStatsLocked(const String8& name) const;
+
+    // isFrameValidLocked returns true if the data for the given frame index is
+    // valid and has all arrived (i.e. there are no oustanding fences).
+    bool isFrameValidLocked(size_t idx) const;
+
     // mFrameRecords is the circular buffer storing the tracked data for each
     // frame.
     FrameRecord mFrameRecords[NUM_FRAME_RECORDS];
@@ -115,6 +141,17 @@ private:
     // doesn't grow with NUM_FRAME_RECORDS.
     int mNumFences;
 
+    // mNumFrames keeps a count of the number of frames with a duration in a
+    // particular range of vsync periods.  Element n of the array stores the
+    // number of frames with duration in the half-inclusive range
+    // [2^n, 2^(n+1)).  The last element of the array contains the count for
+    // all frames with duration greater than 2^(NUM_FRAME_BUCKETS-1).
+    int32_t mNumFrames[NUM_FRAME_BUCKETS];
+
+    // mDisplayPeriod is the display refresh period of the display for which
+    // this FrameTracker is gathering information.
+    nsecs_t mDisplayPeriod;
+
     // mMutex is used to protect access to all member variables.
     mutable Mutex mMutex;
 };

services/surfaceflinger/Layer.cpp

@@ -104,6 +104,10 @@ Layer::Layer(SurfaceFlinger* flinger, const sp<Client>& client,
 
     // drawing state & current state are identical
     mDrawingState = mCurrentState;
+
+    nsecs_t displayPeriod =
+            flinger->getHwComposer().getRefreshPeriod(HWC_DISPLAY_PRIMARY);
+    mFrameTracker.setDisplayRefreshPeriod(displayPeriod);
 }
 
 void Layer::onFirstRef()
@@ -134,6 +138,7 @@ Layer::~Layer() {
         c->detachLayer(this);
     }
     mFlinger->deleteTextureAsync(mTextureName);
+    mFrameTracker.logAndResetStats(mName);
 }
 
 // ---------------------------------------------------------------------------
@@ -1179,6 +1184,10 @@ void Layer::clearStats() {
     mFrameTracker.clear();
 }
 
+void Layer::logFrameStats() {
+    mFrameTracker.logAndResetStats(mName);
+}
+
 // ---------------------------------------------------------------------------
 
 Layer::LayerCleaner::LayerCleaner(const sp<SurfaceFlinger>& flinger,

services/surfaceflinger/Layer.h

@@ -298,6 +298,7 @@ public:
     void dump(String8& result, Colorizer& colorizer) const;
     void dumpStats(String8& result) const;
     void clearStats();
+    void logFrameStats();
 
 protected:
     // constant

services/surfaceflinger/SurfaceFlinger.cpp

@@ -964,6 +964,11 @@ void SurfaceFlinger::postFramebuffer()
 
     mLastSwapBufferTime = systemTime() - now;
     mDebugInSwapBuffers = 0;
+
+    uint32_t flipCount = getDefaultDisplayDevice()->getPageFlipCount();
+    if (flipCount % LOG_FRAME_STATS_PERIOD == 0) {
+        logFrameStats();
+    }
 }
 
 void SurfaceFlinger::handleTransaction(uint32_t transactionFlags)
@@ -1972,6 +1977,10 @@ void SurfaceFlinger::onInitializeDisplays() {
     displays.add(d);
     setTransactionState(state, displays, 0);
     onScreenAcquired(getDefaultDisplayDevice());
+
+    const nsecs_t period =
+            getHwComposer().getRefreshPeriod(HWC_DISPLAY_PRIMARY);
+    mAnimFrameTracker.setDisplayRefreshPeriod(period);
 }
 
 void SurfaceFlinger::initializeDisplays() {
@@ -2205,6 +2214,19 @@ void SurfaceFlinger::clearStatsLocked(const Vector<String16>& args, size_t& inde
     mAnimFrameTracker.clear();
 }
 
+// This should only be called from the main thread.  Otherwise it would need
+// the lock and should use mCurrentState rather than mDrawingState.
+void SurfaceFlinger::logFrameStats() {
+    const LayerVector& drawingLayers = mDrawingState.layersSortedByZ;
+    const size_t count = drawingLayers.size();
+    for (size_t i=0 ; i<count ; i++) {
+        const sp<Layer>& layer(drawingLayers[i]);
+        layer->logFrameStats();
+    }
+
+    mAnimFrameTracker.logAndResetStats(String8("<win-anim>"));
+}
+
 /*static*/ void SurfaceFlinger::appendSfConfigString(String8& result)
 {
     static const char* config =

services/surfaceflinger/SurfaceFlinger.h

@@ -132,6 +132,10 @@ private:
     friend class Layer;
     friend class SurfaceTextureLayer;
 
+    // This value is specified in number of frames.  Log frame stats at most
+    // every half hour.
+    enum { LOG_FRAME_STATS_PERIOD =  30*60*60 };
+
     // We're reference counted, never destroy SurfaceFlinger directly
     virtual ~SurfaceFlinger();
 
@@ -392,6 +396,8 @@ private:
             const sp<const DisplayDevice>& hw,
             uint32_t minLayerZ, uint32_t maxLayerZ);
 
+    void logFrameStats();
+
     /* ------------------------------------------------------------------------
      * Attributes
      */