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

9 files changed, 233 insertions, 6 deletions

diff --git a/include/ui/FramebufferNativeWindow.h b/include/ui/FramebufferNativeWindow.h
index 0f4594ffbd..c9133557a3 100644
--- a/include/ui/FramebufferNativeWindow.h
+++ b/include/ui/FramebufferNativeWindow.h
@@ -56,6 +56,9 @@ public:
     status_t setUpdateRectangle(const Rect& updateRect);
     status_t compositionComplete();
     
+    // for debugging only
+    int getCurrentBufferIndex() const;
+
 private:
     friend class LightRefBase<FramebufferNativeWindow>;    
     ~FramebufferNativeWindow(); // this class cannot be overloaded
@@ -77,6 +80,7 @@ private:
     int32_t mNumBuffers;
     int32_t mNumFreeBuffers;
     int32_t mBufferHead;
+    int32_t mCurrentBufferIndex;
     bool mUpdateOnDemand;
 };
     
diff --git a/include/ui/GraphicLog.h b/include/ui/GraphicLog.h
new file mode 100644
index 0000000000..f929e6a1da
--- /dev/null
+++ b/include/ui/GraphicLog.h
@@ -0,0 +1,70 @@
+/*
+ * Copyright (C) 2010 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#ifndef _UI_GRAPHIC_LOG_H
+#define _UI_GRAPHIC_LOG_H
+
+#include <utils/Singleton.h>
+#include <cutils/compiler.h>
+
+namespace android {
+
+class GraphicLog : public Singleton<GraphicLog>
+{
+    int32_t mEnabled;
+    static void logImpl(int32_t tag, int32_t buffer);
+    static void logImpl(int32_t tag, int32_t identity, int32_t buffer);
+
+public:
+    enum {
+        SF_APP_DEQUEUE_BEFORE   = 60000,
+        SF_APP_DEQUEUE_AFTER    = 60001,
+        SF_APP_LOCK_BEFORE      = 60002,
+        SF_APP_LOCK_AFTER       = 60003,
+        SF_APP_QUEUE            = 60004,
+
+        SF_REPAINT              = 60005,
+        SF_COMPOSITION_COMPLETE = 60006,
+        SF_UNLOCK_CLIENTS       = 60007,
+        SF_SWAP_BUFFERS         = 60008,
+        SF_REPAINT_DONE         = 60009,
+
+        SF_FB_POST_BEFORE       = 60010,
+        SF_FB_POST_AFTER        = 60011,
+        SF_FB_DEQUEUE_BEFORE    = 60012,
+        SF_FB_DEQUEUE_AFTER     = 60013,
+        SF_FB_LOCK_BEFORE       = 60014,
+        SF_FB_LOCK_AFTER        = 60015,
+    };
+
+    inline void log(int32_t tag, int32_t buffer) {
+        if (CC_UNLIKELY(mEnabled))
+            logImpl(tag, buffer);
+    }
+    inline void log(int32_t tag, int32_t identity, int32_t buffer) {
+        if (CC_UNLIKELY(mEnabled))
+            logImpl(tag, identity, buffer);
+    }
+
+    GraphicLog();
+
+    void setEnabled(bool enable);
+};
+
+}
+
+#endif // _UI_GRAPHIC_LOG_H
+
diff --git a/libs/surfaceflinger_client/Surface.cpp b/libs/surfaceflinger_client/Surface.cpp
index cb76091763..560ea67de2 100644
--- a/libs/surfaceflinger_client/Surface.cpp
+++ b/libs/surfaceflinger_client/Surface.cpp
@@ -32,6 +32,7 @@
 #include <ui/DisplayInfo.h>
 #include <ui/GraphicBuffer.h>
 #include <ui/GraphicBufferMapper.h>
+#include <ui/GraphicLog.h>
 #include <ui/Rect.h>
 
 #include <surfaceflinger/Surface.h>
@@ -568,7 +569,13 @@ int Surface::dequeueBuffer(android_native_buffer_t** buffer)
     if (err != NO_ERROR)
         return err;
 
+    GraphicLog& logger(GraphicLog::getInstance());
+    logger.log(GraphicLog::SF_APP_DEQUEUE_BEFORE, mIdentity, -1);
+
     ssize_t bufIdx = mSharedBufferClient->dequeue();
+
+    logger.log(GraphicLog::SF_APP_DEQUEUE_AFTER, mIdentity, bufIdx);
+
     if (bufIdx < 0) {
         LOGE("error dequeuing a buffer (%s)", strerror(bufIdx));
         return bufIdx;
@@ -617,13 +624,20 @@ int Surface::lockBuffer(android_native_buffer_t* buffer)
         return err;
 
     int32_t bufIdx = getBufferIndex(GraphicBuffer::getSelf(buffer));
+
+    GraphicLog& logger(GraphicLog::getInstance());
+    logger.log(GraphicLog::SF_APP_LOCK_BEFORE, mIdentity, bufIdx);
+
     err = mSharedBufferClient->lock(bufIdx);
+
+    logger.log(GraphicLog::SF_APP_LOCK_AFTER, mIdentity, bufIdx);
+
     LOGE_IF(err, "error locking buffer %d (%s)", bufIdx, strerror(-err));
     return err;
 }
 
 int Surface::queueBuffer(android_native_buffer_t* buffer)
-{   
+{
     status_t err = validate();
     if (err != NO_ERROR)
         return err;
@@ -633,6 +647,9 @@ int Surface::queueBuffer(android_native_buffer_t* buffer)
     }
     
     int32_t bufIdx = getBufferIndex(GraphicBuffer::getSelf(buffer));
+
+    GraphicLog::getInstance().log(GraphicLog::SF_APP_QUEUE, mIdentity, bufIdx);
+
     mSharedBufferClient->setTransform(bufIdx, mNextBufferTransform);
     mSharedBufferClient->setCrop(bufIdx, mNextBufferCrop);
     mSharedBufferClient->setDirtyRegion(bufIdx, mDirtyRegion);
diff --git a/libs/ui/Android.mk b/libs/ui/Android.mk
index 9f493483bf..c4a09d67d4 100644
--- a/libs/ui/Android.mk
+++ b/libs/ui/Android.mk
@@ -9,6 +9,7 @@ LOCAL_SRC_FILES:= \
 	GraphicBuffer.cpp \
 	GraphicBufferAllocator.cpp \
 	GraphicBufferMapper.cpp \
+	GraphicLog.cpp \
 	KeyLayoutMap.cpp \
 	KeyCharacterMap.cpp \
 	Input.cpp \
diff --git a/libs/ui/FramebufferNativeWindow.cpp b/libs/ui/FramebufferNativeWindow.cpp
index 6f8948d70e..a36d555f07 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();
diff --git a/libs/ui/GraphicLog.cpp b/libs/ui/GraphicLog.cpp
new file mode 100644
index 0000000000..b55ce2342b
--- /dev/null
+++ b/libs/ui/GraphicLog.cpp
@@ -0,0 +1,84 @@
+/*
+ * Copyright (C) 2010 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+
+#include <stdlib.h>
+#include <unistd.h>
+#include <cutils/log.h>
+#include <cutils/properties.h>
+#include <utils/Endian.h>
+#include <utils/Timers.h>
+
+#include <ui/GraphicLog.h>
+
+namespace android {
+
+ANDROID_SINGLETON_STATIC_INSTANCE(GraphicLog)
+
+static inline
+void writeInt32(uint8_t* base, size_t& pos, int32_t value) {
+    int32_t v = htole32(value);
+    base[pos] = EVENT_TYPE_INT;
+    memcpy(&base[pos+1], &v, sizeof(int32_t));
+    pos += 1+sizeof(int32_t);
+}
+
+static inline
+void writeInt64(uint8_t* base,  size_t& pos, int64_t value) {
+    int64_t v = htole64(value);
+    base[pos] = EVENT_TYPE_LONG;
+    memcpy(&base[pos+1], &v, sizeof(int64_t));
+    pos += 1+sizeof(int64_t);
+}
+
+void GraphicLog::logImpl(int32_t tag, int32_t buffer)
+{
+    uint8_t scratch[2 + 2 + sizeof(int32_t) + sizeof(int64_t)];
+    size_t pos = 0;
+    scratch[pos++] = EVENT_TYPE_LIST;
+    scratch[pos++] = 2;
+    writeInt32(scratch, pos, buffer);
+    writeInt64(scratch, pos, ns2ms( systemTime( SYSTEM_TIME_MONOTONIC ) ));
+    android_bWriteLog(tag, scratch, sizeof(scratch));
+}
+
+void GraphicLog::logImpl(int32_t tag, int32_t identity, int32_t buffer)
+{
+    uint8_t scratch[2 + 3 + sizeof(int32_t) + sizeof(int32_t) + sizeof(int64_t)];
+    size_t pos = 0;
+    scratch[pos++] = EVENT_TYPE_LIST;
+    scratch[pos++] = 3;
+    writeInt32(scratch, pos, buffer);
+    writeInt32(scratch, pos, identity);
+    writeInt64(scratch, pos, ns2ms( systemTime( SYSTEM_TIME_MONOTONIC ) ));
+    android_bWriteLog(tag, scratch, sizeof(scratch));
+}
+
+GraphicLog::GraphicLog()
+    : mEnabled(0)
+{
+    char property[PROPERTY_VALUE_MAX];
+    if (property_get("debug.graphic_log", property, NULL) > 0) {
+        mEnabled = atoi(property);
+    }
+}
+
+void GraphicLog::setEnabled(bool enable)
+{
+    mEnabled = enable;
+}
+
+}
diff --git a/services/surfaceflinger/DisplayHardware/DisplayHardware.cpp b/services/surfaceflinger/DisplayHardware/DisplayHardware.cpp
index 2eac0a80a0..051511027b 100644
--- a/services/surfaceflinger/DisplayHardware/DisplayHardware.cpp
+++ b/services/surfaceflinger/DisplayHardware/DisplayHardware.cpp
@@ -296,6 +296,10 @@ status_t DisplayHardware::compositionComplete() const {
     return mNativeWindow->compositionComplete();
 }
 
+int DisplayHardware::getCurrentBufferIndex() const {
+    return mNativeWindow->getCurrentBufferIndex();
+}
+
 void DisplayHardware::flip(const Region& dirty) const
 {
     checkGLErrors();
diff --git a/services/surfaceflinger/DisplayHardware/DisplayHardware.h b/services/surfaceflinger/DisplayHardware/DisplayHardware.h
index 66bf5215d5..2d7900c350 100644
--- a/services/surfaceflinger/DisplayHardware/DisplayHardware.h
+++ b/services/surfaceflinger/DisplayHardware/DisplayHardware.h
@@ -87,6 +87,9 @@ public:
         return Rect(mWidth, mHeight);
     }
 
+    // only for debugging
+    int getCurrentBufferIndex() const;
+
 private:
     void init(uint32_t displayIndex) __attribute__((noinline));
     void fini() __attribute__((noinline));
diff --git a/services/surfaceflinger/SurfaceFlinger.cpp b/services/surfaceflinger/SurfaceFlinger.cpp
index 637ae48277..f199ca9f96 100644
--- a/services/surfaceflinger/SurfaceFlinger.cpp
+++ b/services/surfaceflinger/SurfaceFlinger.cpp
@@ -38,6 +38,7 @@
 #include <utils/StopWatch.h>
 
 #include <ui/GraphicBufferAllocator.h>
+#include <ui/GraphicLog.h>
 #include <ui/PixelFormat.h>
 
 #include <pixelflinger/pixelflinger.h>
@@ -371,15 +372,25 @@ bool SurfaceFlinger::threadLoop()
     const DisplayHardware& hw(graphicPlane(0).displayHardware());
     if (LIKELY(hw.canDraw() && !isFrozen())) {
         // repaint the framebuffer (if needed)
+
+        const int index = hw.getCurrentBufferIndex();
+        GraphicLog& logger(GraphicLog::getInstance());
+
+        logger.log(GraphicLog::SF_REPAINT, index);
         handleRepaint();
 
         // inform the h/w that we're done compositing
+        logger.log(GraphicLog::SF_COMPOSITION_COMPLETE, index);
         hw.compositionComplete();
 
         // release the clients before we flip ('cause flip might block)
+        logger.log(GraphicLog::SF_UNLOCK_CLIENTS, index);
         unlockClients();
 
+        logger.log(GraphicLog::SF_SWAP_BUFFERS, index);
         postFramebuffer();
+
+        logger.log(GraphicLog::SF_REPAINT_DONE, index);
     } else {
         // pretend we did the post
         unlockClients();
@@ -1470,8 +1481,7 @@ status_t SurfaceFlinger::onTransact(
         int n;
         switch (code) {
             case 1000: // SHOW_CPU, NOT SUPPORTED ANYMORE
-                return NO_ERROR;
-            case 1001:  // SHOW_FPS, NOT SUPPORTED ANYMORE
+            case 1001: // SHOW_FPS, NOT SUPPORTED ANYMORE
                 return NO_ERROR;
             case 1002:  // SHOW_UPDATES
                 n = data.readInt32();
@@ -1492,6 +1502,11 @@ status_t SurfaceFlinger::onTransact(
                 setTransactionFlags(eTransactionNeeded|eTraversalNeeded);
                 return NO_ERROR;
             }
+            case 1006:{ // enable/disable GraphicLog
+                int enabled = data.readInt32();
+                GraphicLog::getInstance().setEnabled(enabled);
+                return NO_ERROR;
+            }
             case 1007: // set mFreezeCount
                 mFreezeCount = data.readInt32();
                 mFreezeDisplayTime = 0;