From 35b48d10bc9e064201d3d54d2d476314684a7a05 Mon Sep 17 00:00:00 2001 From: Mathias Agopian Date: Mon, 13 Sep 2010 22:57:58 -0700 Subject: [PATCH] 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 --- include/ui/FramebufferNativeWindow.h | 4 + include/ui/GraphicLog.h | 70 ++++++++++++++++ libs/surfaceflinger_client/Surface.cpp | 19 ++++- libs/ui/Android.mk | 1 + libs/ui/FramebufferNativeWindow.cpp | 35 +++++++- libs/ui/GraphicLog.cpp | 84 +++++++++++++++++++ .../DisplayHardware/DisplayHardware.cpp | 4 + .../DisplayHardware/DisplayHardware.h | 3 + services/surfaceflinger/SurfaceFlinger.cpp | 19 ++++- 9 files changed, 233 insertions(+), 6 deletions(-) create mode 100644 include/ui/GraphicLog.h create mode 100644 libs/ui/GraphicLog.cpp diff --git a/include/ui/FramebufferNativeWindow.h b/include/ui/FramebufferNativeWindow.h index 0f4594ffb..c9133557a 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(); // 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 000000000..f929e6a1d --- /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 +#include + +namespace android { + +class GraphicLog : public Singleton +{ + 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 cb7609176..560ea67de 100644 --- a/libs/surfaceflinger_client/Surface.cpp +++ b/libs/surfaceflinger_client/Surface.cpp @@ -32,6 +32,7 @@ #include #include #include +#include #include #include @@ -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 9f493483b..c4a09d67d 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 6f8948d70..a36d555f0 100644 --- a/libs/ui/FramebufferNativeWindow.cpp +++ b/libs/ui/FramebufferNativeWindow.cpp @@ -29,6 +29,7 @@ #include #include +#include #include @@ -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(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(buffer); self->mNumFreeBuffers++; self->mCondition.broadcast(); diff --git a/libs/ui/GraphicLog.cpp b/libs/ui/GraphicLog.cpp new file mode 100644 index 000000000..b55ce2342 --- /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 +#include +#include +#include +#include +#include + +#include + +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 2eac0a80a..051511027 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 66bf5215d..2d7900c35 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 637ae4827..f199ca9f9 100644 --- a/services/surfaceflinger/SurfaceFlinger.cpp +++ b/services/surfaceflinger/SurfaceFlinger.cpp @@ -38,6 +38,7 @@ #include #include +#include #include #include @@ -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;