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
diff --git a/libs/surfaceflinger_client/Surface.cpp b/libs/surfaceflinger_client/Surface.cpp
index cb76091..560ea67 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 @@
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 @@
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 @@
}
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 9f49348..c4a09d6 100644
--- a/libs/ui/Android.mk
+++ b/libs/ui/Android.mk
@@ -9,6 +9,7 @@
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 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 @@
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 @@
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 @@
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 @@
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 0000000..b55ce23
--- /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;
+}
+
+}