surfaceflinger: add frame duration logging
Change-Id: Ib414a45e7e191f23a2726cbbbeb606e9ce68a3b5
diff --git a/services/surfaceflinger/EventLog/EventLog.cpp b/services/surfaceflinger/EventLog/EventLog.cpp
index 815242b..47bab83 100644
--- a/services/surfaceflinger/EventLog/EventLog.cpp
+++ b/services/surfaceflinger/EventLog/EventLog.cpp
@@ -31,17 +31,22 @@
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 2f1cd9b..5207514 100644
--- a/services/surfaceflinger/EventLog/EventLog.h
+++ b/services/surfaceflinger/EventLog/EventLog.h
@@ -30,7 +30,8 @@
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 @@
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 c83692f..791e0e4 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 9b55d44..d406672 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 <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 @@
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 @@
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 @@
if (records[idx].frameReadyTime < INT64_MAX) {
records[idx].frameReadyFence = NULL;
numFences--;
+ updated = true;
}
}
@@ -120,11 +143,67 @@
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();
diff --git a/services/surfaceflinger/FrameTracker.h b/services/surfaceflinger/FrameTracker.h
index 3d122c4..9233247 100644
--- a/services/surfaceflinger/FrameTracker.h
+++ b/services/surfaceflinger/FrameTracker.h
@@ -43,6 +43,8 @@
// 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 @@
// 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 @@
// 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 @@
// 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 52211c2..7f2ce2b 100644
--- a/services/surfaceflinger/Layer.cpp
+++ b/services/surfaceflinger/Layer.cpp
@@ -104,6 +104,10 @@
// 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 @@
c->detachLayer(this);
}
mFlinger->deleteTextureAsync(mTextureName);
+ mFrameTracker.logAndResetStats(mName);
}
// ---------------------------------------------------------------------------
@@ -1179,6 +1184,10 @@
mFrameTracker.clear();
}
+void Layer::logFrameStats() {
+ mFrameTracker.logAndResetStats(mName);
+}
+
// ---------------------------------------------------------------------------
Layer::LayerCleaner::LayerCleaner(const sp<SurfaceFlinger>& flinger,
diff --git a/services/surfaceflinger/Layer.h b/services/surfaceflinger/Layer.h
index 0ceb15e..9093116 100644
--- a/services/surfaceflinger/Layer.h
+++ b/services/surfaceflinger/Layer.h
@@ -298,6 +298,7 @@
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 9adabe8..cbdcd12 100644
--- a/services/surfaceflinger/SurfaceFlinger.cpp
+++ b/services/surfaceflinger/SurfaceFlinger.cpp
@@ -964,6 +964,11 @@
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 @@
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 @@
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 =
diff --git a/services/surfaceflinger/SurfaceFlinger.h b/services/surfaceflinger/SurfaceFlinger.h
index 21d523b..7099b35 100644
--- a/services/surfaceflinger/SurfaceFlinger.h
+++ b/services/surfaceflinger/SurfaceFlinger.h
@@ -132,6 +132,10 @@
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 @@
const sp<const DisplayDevice>& hw,
uint32_t minLayerZ, uint32_t maxLayerZ);
+ void logFrameStats();
+
/* ------------------------------------------------------------------------
* Attributes
*/