diff --git a/services/surfaceflinger/EventLog/EventLog.cpp b/services/surfaceflinger/EventLog/EventLog.cpp index 815242beb..47bab83bf 100644 --- a/services/surfaceflinger/EventLog/EventLog.cpp +++ b/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) { - EventLog::TagBuffer buffer(LOGTAG_SF_JANK); - buffer.startList(2); +void EventLog::doLogFrameDurations(const String8& window, + const int32_t* durations, size_t numDurations) { + 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) { - EventLog::getInstance().doLogJank(window, value); +void EventLog::logFrameDurations(const String8& window, + const int32_t* durations, size_t numDurations) { + EventLog::getInstance().doLogFrameDurations(window, durations, + numDurations); } // --------------------------------------------------------------------------- diff --git a/services/surfaceflinger/EventLog/EventLog.h b/services/surfaceflinger/EventLog/EventLog.h index 2f1cd9b3e..52075147e 100644 --- a/services/surfaceflinger/EventLog/EventLog.h +++ b/services/surfaceflinger/EventLog/EventLog.h @@ -30,7 +30,8 @@ class String8; class EventLog : public Singleton { 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 }; - void doLogJank(const String8& window, int32_t value); + enum { LOGTAG_SF_FRAME_DUR = 60100 }; + void doLogFrameDurations(const String8& window, const int32_t* durations, + size_t numDurations); }; // --------------------------------------------------------------------------- diff --git a/services/surfaceflinger/EventLog/EventLogTags.logtags b/services/surfaceflinger/EventLog/EventLogTags.logtags index c83692f44..791e0e408 100644 --- a/services/surfaceflinger/EventLog/EventLogTags.logtags +++ b/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 sf_jank (window|3),(value|1) +# 60100 - 60199 reserved for surfaceflinger + +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. diff --git a/services/surfaceflinger/FrameTracker.cpp b/services/surfaceflinger/FrameTracker.cpp index 9b55d4483..d40667268 100644 --- a/services/surfaceflinger/FrameTracker.cpp +++ b/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 + #include #include #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& 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(mFrameRecords); int& numFences = const_cast(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& 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(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(); diff --git a/services/surfaceflinger/FrameTracker.h b/services/surfaceflinger/FrameTracker.h index 3d122c43d..92332471f 100644 --- a/services/surfaceflinger/FrameTracker.h +++ b/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); + // 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; }; diff --git a/services/surfaceflinger/Layer.cpp b/services/surfaceflinger/Layer.cpp index 52211c22d..7f2ce2b80 100644 --- a/services/surfaceflinger/Layer.cpp +++ b/services/surfaceflinger/Layer.cpp @@ -104,6 +104,10 @@ Layer::Layer(SurfaceFlinger* flinger, const sp& 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& flinger, diff --git a/services/surfaceflinger/Layer.h b/services/surfaceflinger/Layer.h index 0ceb15ee3..9093116b0 100644 --- a/services/surfaceflinger/Layer.h +++ b/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 diff --git a/services/surfaceflinger/SurfaceFlinger.cpp b/services/surfaceflinger/SurfaceFlinger.cpp index 9adabe848..cbdcd1270 100644 --- a/services/surfaceflinger/SurfaceFlinger.cpp +++ b/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& 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& layer(drawingLayers[i]); + layer->logFrameStats(); + } + + mAnimFrameTracker.logAndResetStats(String8("")); +} + /*static*/ void SurfaceFlinger::appendSfConfigString(String8& result) { static const char* config = diff --git a/services/surfaceflinger/SurfaceFlinger.h b/services/surfaceflinger/SurfaceFlinger.h index 21d523ba7..7099b358e 100644 --- a/services/surfaceflinger/SurfaceFlinger.h +++ b/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& hw, uint32_t minLayerZ, uint32_t maxLayerZ); + void logFrameStats(); + /* ------------------------------------------------------------------------ * Attributes */