Add logging of various important graphics events

There are 16 events logged in the event log:
SF_APP_DEQUEUE_BEFORE
SF_APP_DEQUEUE_AFTER
SF_APP_LOCK_BEFORE
SF_APP_LOCK_AFTER
SF_APP_QUEUE

SF_REPAINT
SF_COMPOSITION_COMPLETE
SF_UNLOCK_CLIENTS
SF_SWAP_BUFFERS
SF_REPAINT_DONE

SF_FB_POST_BEFORE
SF_FB_POST_AFTER
SF_FB_DEQUEUE_BEFORE
SF_FB_DEQUEUE_AFTER
SF_FB_LOCK_BEFORE
SF_FB_LOCK_AFTER

all events log the buffer conserned and a timestamp in microseconds.

by default the logging is not enabled, to turn it on:
adb shell service call SurfaceFlinger 1006 i31 1
adb shell setprop debug.graphic_log 1

The effect is immediate in SurfaceFlinger, but applications need to be
restarted.

Change-Id: Ifc2e31f7aed072d9a7dede20ff2ce59231edbec1

1 files changed, 32 insertions, 3 deletions

diff --git a/libs/ui/FramebufferNativeWindow.cpp b/libs/ui/FramebufferNativeWindow.cpp
index 6f8948d..a36d555 100644
--- a/libs/ui/FramebufferNativeWindow.cpp
+++ b/libs/ui/FramebufferNativeWindow.cpp
@@ -29,6 +29,7 @@
 
 #include <ui/Rect.h>
 #include <ui/FramebufferNativeWindow.h>
+#include <ui/GraphicLog.h>
 
 #include <EGL/egl.h>
 
@@ -174,6 +175,14 @@ int FramebufferNativeWindow::setSwapInterval(
     return fb->setSwapInterval(fb, interval);
 }
 
+// only for debugging / logging
+int FramebufferNativeWindow::getCurrentBufferIndex() const
+{
+    Mutex::Autolock _l(mutex);
+    const int index = mCurrentBufferIndex;
+    return index;
+}
+
 int FramebufferNativeWindow::dequeueBuffer(ANativeWindow* window, 
         android_native_buffer_t** buffer)
 {
@@ -181,18 +190,24 @@ int FramebufferNativeWindow::dequeueBuffer(ANativeWindow* window,
     Mutex::Autolock _l(self->mutex);
     framebuffer_device_t* fb = self->fbDev;
 
+    int index = self->mBufferHead++;
+    if (self->mBufferHead >= self->mNumBuffers)
+        self->mBufferHead = 0;
+
+    GraphicLog& logger(GraphicLog::getInstance());
+    logger.log(GraphicLog::SF_FB_DEQUEUE_BEFORE, index);
+
     // wait for a free buffer
     while (!self->mNumFreeBuffers) {
         self->mCondition.wait(self->mutex);
     }
     // get this buffer
     self->mNumFreeBuffers--;
-    int index = self->mBufferHead++;
-    if (self->mBufferHead >= self->mNumBuffers)
-        self->mBufferHead = 0;
+    self->mCurrentBufferIndex = index;
 
     *buffer = self->buffers[index].get();
 
+    logger.log(GraphicLog::SF_FB_DEQUEUE_AFTER, index);
     return 0;
 }
 
@@ -202,11 +217,17 @@ int FramebufferNativeWindow::lockBuffer(ANativeWindow* window,
     FramebufferNativeWindow* self = getSelf(window);
     Mutex::Autolock _l(self->mutex);
 
+    const int index = self->mCurrentBufferIndex;
+    GraphicLog& logger(GraphicLog::getInstance());
+    logger.log(GraphicLog::SF_FB_LOCK_BEFORE, index);
+
     // wait that the buffer we're locking is not front anymore
     while (self->front == buffer) {
         self->mCondition.wait(self->mutex);
     }
 
+    logger.log(GraphicLog::SF_FB_LOCK_AFTER, index);
+
     return NO_ERROR;
 }
 
@@ -217,7 +238,15 @@ int FramebufferNativeWindow::queueBuffer(ANativeWindow* window,
     Mutex::Autolock _l(self->mutex);
     framebuffer_device_t* fb = self->fbDev;
     buffer_handle_t handle = static_cast<NativeBuffer*>(buffer)->handle;
+
+    const int index = self->mCurrentBufferIndex;
+    GraphicLog& logger(GraphicLog::getInstance());
+    logger.log(GraphicLog::SF_FB_POST_BEFORE, index);
+
     int res = fb->post(fb, handle);
+
+    logger.log(GraphicLog::SF_FB_POST_AFTER, index);
+
     self->front = static_cast<NativeBuffer*>(buffer);
     self->mNumFreeBuffers++;
     self->mCondition.broadcast();